Loop is closed before fixture teardown completes

[jpwright]

I am looking to use pytest-asyncio to create a fixture that spawns a subprocess and then kills the subprocess when the fixture teardown is complete. I've noticed that the event loop can be closed before the fixture teardown is complete, which can lead to the subprocess kill not working.

Here is a simple example (tested using pytest-asyncio 0.23.2):

import asyncio
import pytest
import pytest_asyncio

import logging
logger = logging.getLogger(__name__)

@pytest_asyncio.fixture
async def echo():
    p = await asyncio.create_subprocess_shell(
        f"sleep 2"
    )
    yield p
    p.kill()

@pytest.mark.asyncio
async def test_echo(echo):
    logger.info(echo)

Which produces the following output:

================================ test session starts =================================
platform linux -- Python 3.11.6, pytest-7.4.3, pluggy-1.3.0
rootdir: /home/jason/pytest-asyncio
plugins: asyncio-0.23.2
asyncio: mode=Mode.STRICT
collected 1 item                                                                     

test.py::test_echo 
----------------------------------- live log call ------------------------------------
INFO     test:test.py:18 <Process 756596>
PASSED                                                                         [100%]
--------------------------------- live log teardown ----------------------------------
WARNING  asyncio:unix_events.py:1427 Loop <_UnixSelectorEventLoop running=False closed=True debug=False> that handles pid 756596 is closed


================================= 1 passed in 0.00s ==================================

I am invoking the test using python3 -m pytest --log-cli-level=INFO ./test.py. I noticed that the issue is intermittent without logging to CLI... perhaps timing-related.

In my actual use case the warning cannot be ignored as the subprocess will not terminate on its own.

[jpwright]

Thinking this over a bit more, I guess what I need is a way to insert my fixture's finalizer before the event_loop finalizer to the pytest request.

[tonal]

also #706 (comment)

[seifertm]

Thanks. This topic was briefly touched in #705.

I haven't looked into the specific example of the OP, yet. I did look into the reproducer provided in the referenced issue, though. Here is @albertferras-vrf 's reproducer for reference:

import pytest
import asyncio


@pytest.fixture
def get_marks(request):
    marks = [repr(m) for m in request.node.iter_markers()]
    if request.node.parent:
        marks += [repr(m) for m in request.node.parent.iter_markers()]
    yield marks


@pytest.fixture(scope="session")
async def myfixture():
    await asyncio.sleep(0.1)
    yield 5


async def test_one(get_marks, myfixture):
    print(get_marks)
    await asyncio.sleep(0.1)
    assert True


async def test_two(get_marks, myfixture):
    print(get_marks)
    await asyncio.sleep(0.1)
    assert True

In this case, myfixture runs in a session-scoped loop, which is setup at the beginning of the test run and torn down at the end. The fixture finalizer is run during teardown. The test cases run in a function-scoped loop. For backwards compatibility, whenever a function-scoped loop is used, pytest-asyncio v0.23 uses event_loop.

pytest-asyncio tries to close any event loop before installing the loop provided by the event_loop fixture. This causes the session-scoped loop to be closed when the tests run and raises an error when the finalizer for the session loop should be run.

This loop closing behavior was deprecated in v0.21.

I think it's possible to address this in a patch release. I'll also want to look at the OP's example, because it doesn't involve different loop scopes.

[seifertm]

@jpwright Can you confirm that your issue is resolved with pytest-asyncio==0.23.3a0?

[jpwright]

I do still get the WARNING asyncio:unix_events.py:1427 Loop <_UnixSelectorEventLoop running=False closed=True debug=False> that handles pid <...> is closed message with pytest-asyncio==0.23.3a0.

[wosc]

I've seen a similar issue, possibly more similar to this description #706 (comment), namely RuntimeError: Event loop is closed in teardown, and I can confirm that 0.23.3a0 fixes that for me.

[seifertm]

@jpwright I fixed a different issue (related to larger-scoped fixtures and function-scoped tests) and pinged the wrong person while I was travelling.

Thank you for testing, but sorry for taking your time.

I'll reopen this issue for the time being.

[seifertm]

@jpwright I got a chance to look at the issue. I was able to reproduce the error for certain Python versions (3.10, 3.11), but not for others (e.g. 3.12). The output of --setup-show displayed fixture setup and teardown in the correct order. However, adding --setup-show to the pytest invocation caused the issue to disappear as well, which suggests some kind of race condition.

Here's my understanding of what happens: asyncio.create_subprocess_* needs a way to monitor the spawned processes, in order to clean up the remaining Python resources when a subprocess exits (e.g. crashes). This is done by a so called child watcher. There are all kinds of different child watcher implementations, but in your specific case Python uses a ThreadedChildWatcher. This watcher spawns a new thread per subprocess, each of which waits for the subprocess to complete and then performs the resource cleanup. This cleanup routine uses the event loop and is responsible for the warning message you see in your reproducer.

When you call p.kill() on the created subprocess, the Linux OS's process scheduler doesn't assign any more CPU time to that subprocess. However, if the killed process is currently running in kernel space or it's waiting for I/O, it's possible that the killed process is not immediately terminated upon SIGKILL. I assume this is the case in your example.

If my assumption is correct, it means that the pytest run (i.e. the parent process) cleans up the event loop before the subprocess is fully killed. When the subprocess is eventually killed, the child watcher thread monitoring the subprocess tries to run the cleanup callbacks, but the loop has already been closed. You can try adding time.sleep(3) after p.kill() in your fixture and the warning message will disappear, which supports my theory.

In my opinion, the correct way to terminate your subprocess is to call p.kill() and then follow up with await p.wait() to block until the process is gone. Even better, you could allow the process to shut down gracefully by sending SIGINT and/or SIGTERM and waiting for a set amount of time before resorting to killing it.

I cannot confirm that the error wasn't there with pytest-asyncio v0.21.1. In fact, I could reproduce the error with that version of pytest-asyncio:

$ python3 -m pytest --log-cli-level=INFO test_a.py
===== test session starts =====
platform linux -- Python 3.11.7, pytest-7.4.3, pluggy-1.3.0
rootdir: /tmp/tst
plugins: asyncio-0.21.1
asyncio: mode=Mode.STRICT
collected 1 item                                                                                                                    

test_a.py::test_echo 
----- live log call -----INFO     test_a:test_a.py:21 <Process 33072>
PASSED                                                                                                                        [100%]
----- live log teardown -----WARNING  asyncio:unix_events.py:1420 Loop <_UnixSelectorEventLoop running=False closed=True debug=False> that handles pid 33072 is closed


===== 1 passed in 0.01s =====```

Given this information, I'll close this issue as invalid, because it's unrelated to pytest-asyncio. Let me know if you have a different opinion.