classification
Title: _asyncgen_finalizer_hook running in wrong thread
Type: behavior Stage: resolved
Components: asyncio Versions: Python 3.8, Python 3.7, Python 3.6
process
Status: closed Resolution: fixed
Dependencies: Superseder:
Assigned To: Nosy List: asvetlov, miss-islington, twisteroid ambassador, yselivanov
Priority: normal Keywords: patch

Created on 2018-09-22 14:39 by twisteroid ambassador, last changed 2019-08-25 22:36 by asvetlov. This issue is now closed.

Files
File name Uploaded Description Edit
asyncgen_test.py twisteroid ambassador, 2018-10-01 15:33 Script to reproduce problem
Pull Requests
URL Status Linked Edit
PR 9716 merged twisteroid ambassador, 2018-10-05 15:06
PR 9772 merged miss-islington, 2018-10-09 15:30
PR 9773 closed miss-islington, 2018-10-09 15:30
PR 9792 merged twisteroid ambassador, 2018-10-10 16:27
PR 15492 merged asvetlov, 2019-08-25 22:36
PR 15492 merged asvetlov, 2019-08-25 22:36
PR 15492 merged asvetlov, 2019-08-25 22:36
Messages (10)
msg326090 - (view) Author: twisteroid ambassador (twisteroid ambassador) * Date: 2018-09-22 14:39
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.
msg326806 - (view) Author: twisteroid ambassador (twisteroid ambassador) * Date: 2018-10-01 15:33
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.
msg326807 - (view) Author: Yury Selivanov (yselivanov) * (Python committer) Date: 2018-10-01 15:43
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)?
msg326809 - (view) Author: Yury Selivanov (yselivanov) * (Python committer) Date: 2018-10-01 15:59
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.
msg327140 - (view) Author: twisteroid ambassador (twisteroid ambassador) * Date: 2018-10-05 15:04
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.
msg327251 - (view) Author: twisteroid ambassador (twisteroid ambassador) * Date: 2018-10-06 16:27
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?
msg327419 - (view) Author: Yury Selivanov (yselivanov) * (Python committer) Date: 2018-10-09 15:30
New changeset c880ffe7d2ce2fedb1831918c8a36e3623e0fb76 by Yury Selivanov (twisteroid ambassador) in branch 'master':
bpo-34769: Thread safety for _asyncgen_finalizer_hook(). (GH-9716)
https://github.com/python/cpython/commit/c880ffe7d2ce2fedb1831918c8a36e3623e0fb76
msg327422 - (view) Author: miss-islington (miss-islington) Date: 2018-10-09 16:03
New changeset 41e5ec377b36aa951ac095839d2f74f66ee1e665 by Miss Islington (bot) in branch '3.7':
bpo-34769: Thread safety for _asyncgen_finalizer_hook(). (GH-9716)
https://github.com/python/cpython/commit/41e5ec377b36aa951ac095839d2f74f66ee1e665
msg327483 - (view) Author: Yury Selivanov (yselivanov) * (Python committer) Date: 2018-10-10 17:26
New changeset a14dda5df62369d01db6c7519e73aae71d0e7cfe by Yury Selivanov (twisteroid ambassador) in branch '3.6':
[3.6] bpo-34769: Thread safety for _asyncgen_finalizer_hook(). (GH-9716) (GH-9792)
https://github.com/python/cpython/commit/a14dda5df62369d01db6c7519e73aae71d0e7cfe
msg327485 - (view) Author: Yury Selivanov (yselivanov) * (Python committer) Date: 2018-10-10 17:26
I'll close this issue now.  If you find another bug in how asyncio handles async generators please open a new one. Thanks!
History
Date User Action Args
2019-08-25 22:36:03asvetlovsetpull_requests: + pull_request15185
2019-08-25 22:36:03asvetlovsetpull_requests: + pull_request15184
2019-08-25 22:36:03asvetlovsetpull_requests: + pull_request15183
2019-08-25 16:15:24asvetlovsetpull_requests: - pull_request15179
2019-08-25 15:12:05asvetlovsetpull_requests: + pull_request15179
2018-10-10 17:27:07yselivanovsetstatus: open -> closed
stage: patch review -> resolved
resolution: fixed
versions: + Python 3.6
2018-10-10 17:26:47yselivanovsetmessages: + msg327485
2018-10-10 17:26:07yselivanovsetmessages: + msg327483
2018-10-10 16:27:09twisteroid ambassadorsetpull_requests: + pull_request9174
2018-10-09 16:03:40miss-islingtonsetnosy: + miss-islington
messages: + msg327422
2018-10-09 15:30:57miss-islingtonsetpull_requests: + pull_request9161
2018-10-09 15:30:43miss-islingtonsetpull_requests: + pull_request9160
2018-10-09 15:30:27yselivanovsetmessages: + msg327419
2018-10-06 16:27:27twisteroid ambassadorsetmessages: + msg327251
2018-10-05 15:06:39twisteroid ambassadorsetkeywords: + patch
stage: patch review
pull_requests: + pull_request9099
2018-10-05 15:04:40twisteroid ambassadorsetmessages: + msg327140
2018-10-01 15:59:10yselivanovsetmessages: + msg326809
2018-10-01 15:43:53yselivanovsetmessages: + msg326807
2018-10-01 15:33:11twisteroid ambassadorsetfiles: + asyncgen_test.py

messages: + msg326806
2018-09-22 14:39:44twisteroid ambassadorcreate