asyncio gets stuck on event loop close

[fabioz]

Bug report

Bug description:

Ok, so, the issue I'm facing is happening when using playwright-python, which uses asyncio under the hood (which is where the problem seems to lie according to my investigation).

What happens is the following:

playwright-python launches a node process using asyncio using code as:

            self._proc = await asyncio.create_subprocess_exec(
                str(self._driver_executable),
                "run-driver",
                stdin=asyncio.subprocess.PIPE,
                stdout=asyncio.subprocess.PIPE,
                stderr=_get_stderr_fileno(),
                limit=32768,
                env=env,
                startupinfo=startupinfo,
            )

Then, later on it goes on to finish the process, but after finishing the process asyncio never appears to get a notification that the process finishes and it gets stuck in the close forever due to that.

Turning on debug on the asyncio event loop shows messages such as:

DEBUG:asyncio:<IocpProactor overlapped#=2 result#=0> is running after closing for 81.1 seconds

and it never leaves the asyncio IocpProactor.close because the while self._cache: always has 2 elements there.

The elements are:

{1744745874048: (
    <_WaitHandleFuture cancelled handle=0x424 signaled>, 
    <_overlapped.Overlapped object at 0x000001963AF54270>, 0, <function IocpProactor._wait_for_handle.<locals>.finish_wait_for_handle at 0x000001963AF54160>), 
1744791716192: (
    <_WaitCancelFuture pending created at py39\lib\asyncio\windows_events.py:699 handle=0x438 signaled wait_handle=0x1963a2f4580>, 
    <_overlapped.Overlapped object at 0x000001963DB0C150>, 0, <function IocpProactor._wait_for_handle.<locals>.finish_wait_for_handle at 0x000001963DB0CD30>)
}

Those seem to be created at:

  File "py39\lib\site-packages\playwright\_impl\_transport.py", line 123, in connect
    self._proc = await asyncio.create_subprocess_exec(
  File "py39\lib\asyncio\subprocess.py", line 236, in create_subprocess_exec
    transport, protocol = await loop.subprocess_exec(
  File "py39\lib\asyncio\base_events.py", line 1676, in subprocess_exec
    transport = await self._make_subprocess_transport(
  File "py39\lib\asyncio\windows_events.py", line 394, in _make_subprocess_transport
    transp = _WindowsSubprocessTransport(self, protocol, args, shell,
  File "py39\lib\asyncio\base_subprocess.py", line 36, in __init__
    self._start(args=args, shell=shell, stdin=stdin, stdout=stdout,
  File "py39\lib\asyncio\windows_events.py", line 904, in _start
    f = self._loop._proactor.wait_for_handle(int(self._proc._handle))
  File "py39\lib\asyncio\windows_events.py", line 675, in wait_for_handle
    return self._wait_for_handle(handle, timeout, False)
  File "py39\lib\asyncio\windows_events.py", line 687, in _wait_for_handle
    traceback.print_stack()

and

  File "py39\lib\asyncio\base_events.py", line 634, in run_until_complete
    self.run_forever()
  File "py39\lib\asyncio\windows_events.py", line 321, in run_forever
    super().run_forever()
  File "py39\lib\asyncio\base_events.py", line 601, in run_forever
    self._run_once()
  File "py39\lib\asyncio\base_events.py", line 1869, in _run_once
    event_list = self._selector.select(timeout)
  File "py39\lib\asyncio\windows_events.py", line 439, in select
    self._poll(timeout)
  File "py39\lib\asyncio\windows_events.py", line 825, in _poll
    f.set_result(value)
  File "py39\lib\asyncio\windows_events.py", line 166, in set_result
    self._unregister_wait()
  File "py39\lib\asyncio\windows_events.py", line 242, in _unregister_wait
    self._event_fut = self._proactor._wait_cancel(self._event,
  File "py39\lib\asyncio\windows_events.py", line 678, in _wait_cancel
    fut = self._wait_for_handle(event, None, True)
  File "py39\lib\asyncio\windows_events.py", line 687, in _wait_for_handle
    traceback.print_stack()

This doesn't always happen. The only difference I can see from both cases is that in one case the callback registered in _WindowsSubprocessTransport is called when it works and when it fails it's not called, but on both cases the subprocess exited.

So, the actual bug seems to be that the function registered in the _WindowsSubprocessTransport:

        f = self._loop._proactor.wait_for_handle(int(self._proc._handle))
        f.add_done_callback(callback)

is never called in one case but it's called in the other, but I can't see a reason for that to happen (and so far I couldn't find any workaround that doesn't involve doing really nasty things to asyncio internals).

Not sure if it makes any difference, but this is on a Windows server 2022. Reproduced with Python 3.9, 3.10 and 3.11 (unable to check it for 3.12 as it misses some other dependencies needed).

CPython versions tested on:

3.9, 3.10, 3.11

Operating systems tested on:

Windows

[terryjreedy]

Can you minimally expand your example code, with no 3rd party imports, so it can be* tested on main and 3.12?

[fabioz]

I'm trying to get a better reproducible case.

Meanwhile I ended up getting a bit more info just to be sure of what's the info on the cache. The output is below (repeated forever on the event loop close):

----- key= 2246330755840
  value= (<_WaitHandleFuture pending cb=[_WindowsSubprocessTransport._start.<locals>.callback() at py311\Lib\asyncio\windows_events.py:933]>, <_overlapped.Overlapped object at 0x0000020B03BF2AF0>, 0, <function IocpProactor._wait_for_handle.<locals>.finish_wait_for_handle at 0x0000020B04187420>)
  _WaitHandleFuture handle info:
  Handle: 1176
    WAIT_OBJECT_0
----- key= 2246330756608
  value= (<_OverlappedFuture pending cb=[BaseProactorEventLoop._loop_self_reading()]>, <_overlapped.Overlapped object at 0x0000020B03BF2DF0>, <socket.socket fd=884, family=2, type=1, proto=0, laddr=('127.0.0.1', 55526), raddr=('127.0.0.1', 55527)>, <function IocpProactor.recv.<locals>.finish_recv at 0x0000020B04187920>)
--- Transport:
Process pid: 23144 is no longer alive
pw._impl_obj._connection._transport._proc._transport._proc._handle handle info:
  Handle: Handle(1176)
    WAIT_OBJECT_0

The snippet of code for that output is below (just with just that without running more of playwright I still haven't been able to reproduce it):

It does show that the handle referenced in the loop._proactor._cache does have handles which are no longer valid and it's the same one which playwright launched (though I'm still not sure how to reproduce that in a shorter code -- playwright does seem to have a mixture of greenlet + asyncio which is suspicious, but I can't wrap my head around why this happens and whenever I try to put a debugger in the middle things work, so, it does seem to be some kind of racing condition).

Playing with it I saw that if _winapi.CloseHandle is used in the handle in one of the handles in the cache, asyncio will always halt when closing (which I guess is expected in the current implementation -- the mistery is why sometimes a signal doesn't seem to be gotten from _overlapped.GetQueuedCompletionStatus when the process exits... note: I didn't find any place which actually calls that CloseHandle)

@contextmanager
def playwright():
    import asyncio
    import _winapi
    import psutil
    from playwright.sync_api import sync_playwright
    pw = sync_playwright().start()
    yield pw
    loop = asyncio.get_running_loop()
    
    def print_handle_repr(handle):
        print('  Handle:', handle)
        try:
            v = _winapi.WaitForSingleObject(handle, 0)
        except Exception as e:
            print(f'    Unable to WaitForSingleObject: {e}')
        else:
            if v == _winapi.WAIT_OBJECT_0:
                print('    WAIT_OBJECT_0')
            elif v == _winapi.WAIT_ABANDONED_0:
                print('    WAIT_ABANDONED_0')
            elif v == _winapi.WAIT_TIMEOUT:
                print('    WAIT_TIMEOUT')
            else:
                print(f'    WAIT: Unexpected: {v}')
                
    def callback():
        print("--- Cache:")
        for k, v in loop._proactor._cache.items():
            print("----- key=", k)
            print("  value=", v)
            if isinstance(v, tuple) and v:
                v = v[0]
                if v.__class__.__name__ == '_WaitHandleFuture':
                    print('  _WaitHandleFuture handle info:')
                    print_handle_repr(v._handle)
            
        print('--- Transport:')
        try:
            handle = pw._impl_obj._connection._transport._proc._transport._proc._handle
        except AttributeError:
            print('AttributeError (expected on proper teardown)')
        else:
            pid = pw._impl_obj._connection._transport._proc._transport._proc.pid
            try:
                p = psutil.Process(pid)
            except:
                print(f'Process pid: {pid} is no longer alive')
            else:
                print(f'Process pid: {pid} running: {p.is_running()}')
            
            # The process is still alive.
            print('pw._impl_obj._connection._transport._proc._transport._proc._handle handle info:')
            print_handle_repr(handle)

        loop.call_later(2, callback)

    loop.call_later(2, callback)

    pw.stop()

[fabioz]

I'm working on trimming down the way to reproduce. Still haven't gone up to just plain python, but I'm getting there.

The current way to reproduce is with the code below.

Note that this reproduces only with Windows Server 2022, not Windows 11 (it fails quite often for me on Windows Server 2022 though, something like once every 5 runs).

from playwright.sync_api import sync_playwright

# This is from pywinauto
import comtypes.client
UIA_dll = comtypes.client.GetModule('UIAutomationCore.dll')
ui_automation_client = comtypes.gen.UIAutomationClient
iuia = comtypes.CoCreateInstance(
        ui_automation_client.CUIAutomation().IPersist_GetClassID(),
        interface=ui_automation_client.IUIAutomation,
        clsctx=comtypes.CLSCTX_INPROC_SERVER
        )
true_condition = iuia.CreateTrueCondition()
root = iuia.GetRootElement()

if __name__ == '__main__':
    print('start pw')
    pw = sync_playwright().start()
    print('stop pw')
    pw.stop()
    print('stopped pw')

[fabioz]

Well, apparently if _ole32.CoInitializeEx(None, flags) is initialized with COINIT_MULTITHREADED instead of COINIT_APARTMENTTHREADED this fixes the problem.

So, the fix which appears to work for me is adding the lines below to the top of the script:

import sys

COINIT_MULTITHREADED     = 0x0
sys.coinit_flags = COINIT_MULTITHREADED

I don't know why this makes a difference though and why using COINIT_APARTMENTTHREADED (which is the default for comtypes) breaks asyncio, maybe this is a windows bug or uiautomation bug (really hard to know without actually knowing more about windows internals here), as this definitely breaks asyncio on Windows with Windows Server 2022, but at least I have a workaround now, so, not a blocker for me anymore.