Warning not getting raised within test

[Dreamsorcerer]

When running pytest on aiojobs, I get a warning printed out in the output, but it fails to trigger anything in the test that caused it. We have warnings set to error, so this should result in a test failure. As far as I can tell, the warning appears to be happening outside the test run, even though it is clearly something that was caused inside the test.

I've tried to reproduce it without the aiojobs code, but simpler reproducers always result in the correct behaviour, with the test failing. I've got no idea what might be causing this test to get handled differently (also not sure if this might be an issue with pytest itself).

Output from the test run looks like:

============ test session starts ========
platform linux -- Python 3.10.4, pytest-7.1.2, pluggy-1.0.0
rootdir: /home/ubuntu/hacking/aiojobs, configfile: setup.cfg, testpaths: tests/
plugins: anyio-3.6.1, cov-3.0.0, mock-3.6.1, asyncio-0.19.0, timeout-2.1.0, aiohttp-1.0.4
asyncio: mode=auto
collected 46 items                                                                                                                                                                                                  

tests/test_aiohttp.py .......
tests/test_job.py ...............
tests/test_scheduler.py ........................
/usr/lib/python3.10/sre_parse.py:433: RuntimeWarning: coroutine 'Scheduler._wait_failed' was never awaited
  return list(dict.fromkeys(items))
RuntimeWarning: Enable tracemalloc to get the object allocation traceback

=========== 46 passed in 1.72s ============

The cause is the last test (https://github.com/aio-libs/aiojobs/pull/352/files#diff-7cab305a6a78540131fcce1fafb912ccf6b52aa50b4a0a2b794aea71004d5a95R433):

def test_scheduler_must_be_created_within_running_loop() -> None:
    with pytest.raises(RuntimeError) as exc_info:
        Scheduler(close_timeout=0, limit=0, pending_limit=0, exception_handler=None)

Within Scheduler it runs asyncio.create_task(coro()), which causes the RuntimeError we are testing for due to there being no loop. Then when coro() is garbage collected, the RuntimeWarning would be triggered due to it never getting awaited.

Expected behaviour is for that last test to fail due to the warning.

[seifertm]

Thanks for the report. I believe you couldn't get a minimal reproducible example, because the behaviour is non-deterministic. I tried as well. I started with the aiojobs repository and removed pieces of code. Eventually I ended up with this:

import asyncio
import pytest

async def my_task():
    pass

def test_scheduler_must_be_created_within_running_loop() -> None:
    with pytest.raises(RuntimeError):
        asyncio.create_task(my_task())

Pytest didn't show a warning in the report, but the console clearly printed a warning:

$ pytest -p no:asyncio -W error test_a.py
===== test session starts =====
platform linux -- Python 3.10.8, pytest-7.1.3, pluggy-1.0.0
rootdir: /tmp/a
collected 1 item

test_a.py .            [100%]

===== 1 passed in 0.02s =====
sys:1: RuntimeWarning: coroutine 'my_task' was never awaited
RuntimeWarning: Enable tracemalloc to get the object allocation traceback

When I changed the test name to test_warns_about_unawaited_task, the behaviour changed and I ended up with the following output:

$ pytest -p no:asyncio
============================================================================================================================ test session starts =============================================================================================================================
platform linux -- Python 3.10.8, pytest-7.1.3, pluggy-1.0.0
rootdir: /tmp/a
collected 1 item

test_a.py .     [100%]

===== warnings summary ====
test_a.py::test_scheduler_must_be_created_within_running_loop
  /tmp/a/test_a.py:10: RuntimeWarning: coroutine 'my_task' was never awaited
    with pytest.raises(RuntimeError):
  Enable tracemalloc to get traceback where the object was allocated.
  See https://docs.pytest.org/en/stable/how-to/capture-warnings.html#resource-warnings for more info.

-- Docs: https://docs.pytest.org/en/stable/how-to/capture-warnings.html
===== 1 passed, 1 warning in 0.02s =====

I tried going back to the old behaviour by re-adding the -W error flag and prepending rm -R .pytest_cache/ __pycache__/ before each test run to no avail.

I am quite certain that this has nothing to do with pytest-asyncio. You can see that I have disabled the plugin entirely for the example.

Luckily, I recently checked out the CPython repo, so I could start sleuthing there :)
It seems that warnings._warn_unawaited_coroutine is triggered by a C function _PyErr_WarnUnawaitedCoroutine. Coroutines seem to be implemented as specialized generators. The warning is printed when the coroutine/generator is cleaned up via _PyGen_Finalize which, in turn, happens when a frame is cleared. Unfortunately, I don't understand the internals enough to draw a conclusion what pytest has to do to deterministically raise the warning inside its session.

[seifertm]

It seems that asyncio.create_task results in a task object with a ridiculous amount of references, even when it raises a RuntimeError. Compare this two distinct function calls to loop = asyncio.get_running_loop() and a subsequent loop.create_task(my_task()):

import sys
import asyncio

import pytest

async def my_task():
    pass

def test_coro_ref_count() -> None:
    loop = None
    with pytest.raises(RuntimeError):
        loop = asyncio.get_running_loop()
    coro = my_task()
    print(">>>>>" + str(sys.getrefcount(coro)))

def test_create_task_ref_count() -> None:
    task = None
    with pytest.raises(RuntimeError):
        task = asyncio.create_task(my_task())
    print(">>>>>" + str(sys.getrefcount(task)))

The above code prints:

>>>>>2
>>>>>15599

I assume that the task generally outlives the pytest session, because it is still referenced somewhere. That also explains why an explicit call to gc.collect() after the test does not change anything. It doesn't explain why the behaviour is non-deterministic.

We can try raising this issue to pytest, but it's unlikely they can do anything about it. Maybe they have more ideas, though.

@Dreamsorcerer As a workaround, you can try the following patch to aiojobs, which circumvents the reported issue by provoking a RuntimeError before creating a coroutine.

diff --git a/aiojobs/_scheduler.py b/aiojobs/_scheduler.py
index 331f60c..6f7f528 100644
--- a/aiojobs/_scheduler.py
+++ b/aiojobs/_scheduler.py
@@ -39,7 +39,8 @@ class Scheduler(Collection[Job[object]]):
         self._failed_tasks: asyncio.Queue[
             Optional[asyncio.Task[object]]
         ] = asyncio.Queue()
-        self._failed_task = asyncio.create_task(self._wait_failed())
+        event_loop = asyncio.get_running_loop()
+        self._failed_task = event_loop.create_task(self._wait_failed())
         self._pending: asyncio.Queue[Job[object]] = asyncio.Queue(maxsize=pending_limit)
         self._closed = False

[Dreamsorcerer]

2
15599

That does seem like an awful lot. The first example just creates a coroutine object though, without scheduling it in the event loop, so it obviously wouldn't have references elsewhere.

[seifertm]

I agree, the comparison is wrong. The day was long… :)

[seifertm]

There has been work in pytest to correctly treat warnings like the one reported: pytest-dev/pytest#8021

Pytest tries to catch these warnings with the unraisableexception plugin..

I could see a difference when running this code with pytest -s -p no:unraisableexception -W error and pytest -s -W error, respectively.

However, I couldn't see different behaviour in aiojobs. I disabled all pytest configuration in setup.cfg, commented out all tests in test_scheduler.py except the one exhibiting the issue and ran pytest --cache-clear -s -p no:cov -p no:sugar -p no:aiohttp -p no:asyncio -W error tests/test_scheduler.py. Even with all external plugins disabled, the warning is not raised inside the test case.

[seifertm]

I managed to create a reproducible example and reported the bug to upstream:
pytest-dev/pytest#10404

[Dreamsorcerer]

Thanks for delving into that in such depth.