Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

_asyncgen_finalizer_hook running in wrong thread #78950

Closed
twisteroidambassador mannequin opened this issue Sep 22, 2018 · 10 comments
Closed

_asyncgen_finalizer_hook running in wrong thread #78950

twisteroidambassador mannequin opened this issue Sep 22, 2018 · 10 comments
Labels
3.7 (EOL) end of life 3.8 only security fixes topic-asyncio type-bug An unexpected behavior, bug, or error

Comments

@twisteroidambassador
Copy link
Mannequin

twisteroidambassador mannequin commented Sep 22, 2018

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
    Copy link
    Mannequin Author

    twisteroidambassador mannequin commented Sep 22, 2018

    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 twisteroidambassador mannequin added 3.7 (EOL) end of life 3.8 only security fixes topic-asyncio type-bug An unexpected behavior, bug, or error labels Sep 22, 2018
    @twisteroidambassador
    Copy link
    Mannequin Author

    twisteroidambassador mannequin commented Oct 1, 2018

    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
    Copy link
    Member

    1st1 commented Oct 1, 2018

    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
    Copy link
    Member

    1st1 commented Oct 1, 2018

    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
    Copy link
    Mannequin Author

    twisteroidambassador mannequin commented Oct 5, 2018

    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
    Copy link
    Mannequin Author

    twisteroidambassador mannequin commented Oct 6, 2018

    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
    Copy link
    Member

    1st1 commented Oct 9, 2018

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

    @miss-islington
    Copy link
    Contributor

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

    @1st1
    Copy link
    Member

    1st1 commented Oct 10, 2018

    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
    Copy link
    Member

    1st1 commented Oct 10, 2018

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

    @1st1 1st1 closed this as completed Oct 10, 2018
    @ezio-melotti ezio-melotti transferred this issue from another repository Apr 10, 2022
    Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
    Labels
    3.7 (EOL) end of life 3.8 only security fixes topic-asyncio type-bug An unexpected behavior, bug, or error
    Projects
    None yet
    Development

    No branches or pull requests

    2 participants