_asyncgen_finalizer_hook running in wrong thread

[twisteroidambassador]

BPO	34769
Nosy	@asvetlov, @1st1, @twisteroidambassador, @miss-islington
PRs	bpo-34769: Thread safety for _asyncgen_finalizer_hook(). #9716 [3.7] bpo-34769: Thread safety for _asyncgen_finalizer_hook(). (GH-9716) #9772 [3.6] bpo-34769: Thread safety for _asyncgen_finalizer_hook(). (GH-9716) #9773 [3.6] bpo-34769: Thread safety for _asyncgen_finalizer_hook(). (GH-9716) #9792 bpo-34679: Restore instantiation Windows IOCP event loop from non-main thread #15492 bpo-34679: Restore instantiation Windows IOCP event loop from non-main thread #15492 bpo-34679: Restore instantiation Windows IOCP event loop from non-main thread #15492
Files	asyncgen_test.py: Script to reproduce problem

^{Note: these values reflect the state of the issue at the time it was migrated and might not reflect the current state.}

Show more details

GitHub fields:

assignee = None
closed_at = <Date 2018-10-10.17:27:07.906>
created_at = <Date 2018-09-22.14:39:44.728>
labels = ['3.8', 'type-bug', '3.7', 'expert-asyncio']
title = '_asyncgen_finalizer_hook running in wrong thread'
updated_at = <Date 2019-08-25.22:36:03.760>
user = 'https://github.com/twisteroidambassador'

bugs.python.org fields:

activity = <Date 2019-08-25.22:36:03.760>
actor = 'asvetlov'
assignee = 'none'
closed = True
closed_date = <Date 2018-10-10.17:27:07.906>
closer = 'yselivanov'
components = ['asyncio']
creation = <Date 2018-09-22.14:39:44.728>
creator = 'twisteroid ambassador'
dependencies = []
files = ['47838']
hgrepos = []
issue_num = 34769
keywords = ['patch']
message_count = 10.0
messages = ['326090', '326806', '326807', '326809', '327140', '327251', '327419', '327422', '327483', '327485']
nosy_count = 4.0
nosy_names = ['asvetlov', 'yselivanov', 'twisteroid ambassador', 'miss-islington']
pr_nums = ['9716', '9772', '9773', '9792', '15492', '15492', '15492']
priority = 'normal'
resolution = 'fixed'
stage = 'resolved'
status = 'closed'
superseder = None
type = 'behavior'
url = 'https://bugs.python.org/issue34769'
versions = ['Python 3.6', 'Python 3.7', 'Python 3.8']

[twisteroidambassador]

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.

[twisteroidambassador]

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.

[1st1]

Wow. Thanks so much for figuring this out, I know how hard it is to debug issues like this.

Now I see it clearly: _asyncgen_finalizer_hook should be using loop.call_soon_threadsafe. Interestingly, I used _write_to_self there, so I knew about the issue, but figured that using call_soon() + _write_to_self is safe enough; evidently I was wrong.

Anyways, here's the diff that fixed it for me: https://gist.github.com/1st1/c1c9fc853cac1fadb7102ccc6201fb70

Could you please create a PR (ideally with a unittest)?

[1st1]

Rereading your first message:

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:

The bug we are fixing now is that async generators were not finalizing properly *in debug mode*.

The "I occasionally run into issues with async generators seemingly not finalizing" part will need further investigation if you experienced it with debug mode off.

[twisteroidambassador]

I'll open a PR with your diff soon, but I don't have a reliable unit test yet. Also, it does not seem to fix the old problem with debug mode off. :-( I had hoped that the problem with debug mode off is nothing more than _asyncgen_finalizer_hook not running reliably each time, but that doesn't seem to be the case.

[twisteroidambassador]

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?

[1st1]

New changeset c880ffe by Yury Selivanov (twisteroid ambassador) in branch 'master':
bpo-34769: Thread safety for _asyncgen_finalizer_hook(). (GH-9716)
c880ffe

[miss-islington]

New changeset 41e5ec3 by Miss Islington (bot) in branch '3.7':
bpo-34769: Thread safety for _asyncgen_finalizer_hook(). (GH-9716)
41e5ec3

[1st1]

New changeset a14dda5 by Yury Selivanov (twisteroid ambassador) in branch '3.6':
[3.6] bpo-34769: Thread safety for _asyncgen_finalizer_hook(). (GH-9716) (GH-9792)
a14dda5

[1st1]

I'll close this issue now. If you find another bug in how asyncio handles async generators please open a new one. Thanks!