When testing my happy eyeballs library, I occasionally run into issues with async generators seemingly not finalizing. After setting loop.set_debug(True), I have been seeing log entries like these:
Exception ignored in: <async_generator object builtin_resolver at 0x7fca945c8158>
Traceback (most recent call last):
File "/opt/Python3.7.0/lib/python3.7/asyncio/base_events.py", line 466, in _asyncgen_finalizer_hook
self.create_task(agen.aclose())
File "/opt/Python3.7.0/lib/python3.7/asyncio/base_events.py", line 386, in create_task
task = tasks.Task(coro, loop=self)
File "/opt/Python3.7.0/lib/python3.7/asyncio/base_events.py", line 674, in call_soon
self._check_thread()
File "/opt/Python3.7.0/lib/python3.7/asyncio/base_events.py", line 712, in _check_thread
"Non-thread-safe operation invoked on an event loop other "
RuntimeError: Non-thread-safe operation invoked on an event loop other than the current one
ERROR asyncio Task was destroyed but it is pending!
source_traceback: Object created at (most recent call last):
File "/opt/Python3.7.0/lib/python3.7/threading.py", line 885, in _bootstrap
self._bootstrap_inner()
File "/opt/Python3.7.0/lib/python3.7/threading.py", line 917, in _bootstrap_inner
self.run()
File "/opt/Python3.7.0/lib/python3.7/threading.py", line 865, in run
self._target(*self._args, **self._kwargs)
File "/opt/Python3.7.0/lib/python3.7/concurrent/futures/thread.py", line 80, in _worker
work_item.run()
File "/opt/Python3.7.0/lib/python3.7/concurrent/futures/thread.py", line 57, in run
result = self.fn(*self.args, **self.kwargs)
File "/opt/Python3.7.0/lib/python3.7/asyncio/base_events.py", line 746, in _getaddrinfo_debug
msg.append(f'type={type!r}')
File "/opt/Python3.7.0/lib/python3.7/enum.py", line 572, in __repr__
self.__class__.__name__, self._name_, self._value_)
File "/opt/Python3.7.0/lib/python3.7/asyncio/base_events.py", line 466, in _asyncgen_finalizer_hook
self.create_task(agen.aclose())
File "/opt/Python3.7.0/lib/python3.7/asyncio/base_events.py", line 386, in create_task
task = tasks.Task(coro, loop=self)
task: <Task pending coro=<<async_generator_athrow without __name__>()> created at /opt/Python3.7.0/lib/python3.7/asyncio/base_events.py:386>
This is a typical instance. Usually several instances like this occur at once.
I'll try to reproduce these errors in a simple program. Meanwhile, here are some details about the actual program, which may or may not be related to the errors:
* I have several nested async generators (async for item in asyncgen: yield do_something(item); ), and when the errors appear, the above error messages and stack traces repeat several times, with the object names mentioned in "Exception ignored in: ..." being each of the nested async generators. Other parts of the error messages, including the stack traces, are exactly the same.
* I never used threads or loop.run_in_executor() explicitly in the program. However, the innermost async generator calls loop.getaddrinfo(), and that is implemented by running a Python function, socket.getaddrinfo(), with loop.run_in_executor(), so the program implicitly uses threads. (socket.getaddrinfo() is a Python function that calls a C function, _socket.getaddrinfo().)
* The outermost async generator is not iterated using `async for`. Instead, it is iterated by calling its `__aiter__` method, saving the returned async iterator object, and then awaiting on the `__anext__` method of the async iterator repeatedly. Of course, all of these are done in the same event loop.
Environment: Python 3.7.0 compiled from source, on Debian stretch.
|
I have finally managed to reproduce this one reliably. The issue happens when i) async generators are not finalized immediately and must be garbage collected in the future, and ii) the garbage collector happens to run in a different thread than the one running the event loop. (Obviously, if there are more than one Python threads, eventually gc will run in those other threads, causing problems.)
I have attached a script reproducing the problem. I tried several ways of using async generators (the use_agen_*() coroutines), and the only way to make them not finalize immediately is use_agen_anext_separate_tasks(), which is the pattern used in my Happy Eyeballs library.
|
I’m now convinced that the bug we’re fixing and the original bug with debug mode off are two separate bugs. With the fix in place and debug mode off, I’m still seeing the original buggy behavior. Bummer.
In my actual program, I have an async generator that spawns two tasks. In the finally clause I cancel and wait for them, then check and log any exceptions. The program ran on Python 3.7. The symptom of the original bug is occasional “Task exception was never retrieved” log entries about one of the spawned tasks. After I patched 3.7 with the fix, the symptom remains, so the fix does not actually fix the original bug.
Running the same program on master, there are additional error and warning messages about open stream objects being garbage collected, unclosed sockets, etc. Are these logging messages new to 3.8? If not, perhaps 3.8 introduced additional bugs?
|