pytest-dev / pytest-asyncio

Asyncio support for pytest
https://pytest-asyncio.readthedocs.io
Apache License 2.0
1.36k stars 140 forks source link

ResourceWarning: unclosed event loop #724

Open graingert opened 6 months ago

graingert commented 6 months ago

using pytest-asyncio asyncio 0.23.2

import pytest

import pytest_asyncio

@pytest_asyncio.fixture()
async def demo():
    yield

@pytest.mark.asyncio
async def test_aiohttp_test_client_json(demo):
    pass

def test_redirect():

    import asyncio
    async def amain():
        pass
    asyncio.run(amain())

    import gc
    gc.collect()

results in

REQUESTS_CA_BUNDLE=/home/graingert/projects/vcrpy/.tox/py311-aiohttp/lib/python3.11/site-packages/pytest_httpbin/certs/cacert.pem ./.tox/py311-aiohttp/bin/pytest tests/integration/test_aiohttp.py -s
================================================================================ test session starts =================================================================================
platform linux -- Python 3.11.7+, pytest-7.4.3, pluggy-1.3.0
rootdir: /home/graingert/projects/vcrpy
configfile: pyproject.toml
plugins: aiohttp-1.0.5, httpbin-2.0.0, cov-4.1.0, asyncio-0.23.2
asyncio: mode=Mode.STRICT
collected 2 items                                                                                                                                                                    

tests/integration/test_aiohttp.py ..

================================================================================== warnings summary ==================================================================================
tests/integration/test_aiohttp.py::test_redirect
  /usr/lib/python3.11/asyncio/base_events.py:692: ResourceWarning: unclosed event loop <_UnixSelectorEventLoop running=False closed=False debug=False>
    _warn(f"unclosed event loop {self!r}", ResourceWarning, source=self)
  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
============================================================================ 2 passed, 1 warning in 0.02s ===========================================================================
graingert commented 6 months ago

full demo here https://github.com/kevin1024/vcrpy/commit/d0093369e43519a15ac785bf5961abbafc711be5

more minimal reproducer here https://github.com/graingert/asyncio_unclosed_loop

graingert commented 6 months ago

I repeated this with e1415c1

phillipuniverse commented 6 months ago

I have the same issue in versions 0.22.0+, including 0.23.0a0.

I first spent a ton of time trying to hunt down a new ResourceWarning I seemingly randomly started getting in my tests (maybe due to the more tests I added and thus more time to fail with the resource warning, unsure):

>               warnings.warn(pytest.PytestUnraisableExceptionWarning(msg))
E               pytest.PytestUnraisableExceptionWarning: Exception ignored in: <socket.socket fd=-1, family=1, type=1, proto=0>
E               
E               Traceback (most recent call last):
E                 File "/Users/phillip/.pyenv/versions/3.11.6/lib/python3.11/json/decoder.py", line 353, in raw_decode
E                   obj, end = self.scan_once(s, idx)
E                              ^^^^^^^^^^^^^^^^^^^^^^
E               ResourceWarning: unclosed <socket.socket fd=13, family=1, type=1, proto=0>

I couldn't for the life of me figure out where I had an unclosed socket. So I finally admitted defeat and silenced the ResourceWarning, only to have this next error happen:

>               warnings.warn(pytest.PytestUnraisableExceptionWarning(msg))
E               pytest.PytestUnraisableExceptionWarning: Exception ignored in: <function BaseEventLoop.__del__ at 0x104bed760>
E               
E               Traceback (most recent call last):
E                 File "/Users/phillip/.pyenv/versions/3.11.6/lib/python3.11/asyncio/base_events.py", line 692, in __del__
E                   _warn(f"unclosed event loop {self!r}", ResourceWarning, source=self)
E               ResourceWarning: unclosed event loop <_UnixSelectorEventLoop running=False closed=False debug=False>

The results seemed to change depending on how many tests I was running in my test suite.

Downgrading to 0.21.1 fixed both problems.

seifertm commented 6 months ago

Thanks for the report! I can reproduce the issue with pytest-asyncio v0.23.2. I can also reproduce it with pytest-asyncio v0.21.1, though:

$ python -X dev -m pytest --setup-show
===== test session starts =====
platform linux -- Python 3.12.1, pytest-7.4.3, pluggy-1.3.0
rootdir: /tmp/tst
plugins: asyncio-0.21.1
asyncio: mode=Mode.STRICT
collected 2 items                                                                                                                   

test_a.py 
        SETUP    F event_loop
        SETUP    F demo (fixtures used: event_loop)
        test_a.py::test_aiohttp_test_client_json (fixtures used: demo, event_loop, request).
        TEARDOWN F demo
        TEARDOWN F event_loop
        test_a.py::test_redirect.

===== warnings summary =====test_a.py::test_redirect
  /usr/lib/python3.12/asyncio/base_events.py:723: ResourceWarning: unclosed event loop <_UnixSelectorEventLoop running=False closed=False debug=True>
    _warn(f"unclosed event loop {self!r}", ResourceWarning, source=self)
  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
===== 2 passed, 1 warning in 0.02s =====

This means it's probably not directly related to the v0.23 release.

Based on the console output above, my current understanding is that pytest(-asyncio) runs the async test normally. When the event_loop fixture is torn down, a fixture finalizer creates a new event loop to prevent subsequent non-async tests from having to deal with a closed loop:

https://github.com/pytest-dev/pytest-asyncio/blob/b614c77dec6df7414fba78d2fbe7989c6ee16828/pytest_asyncio/plugin.py#L824-L833

When the sync test calls asyncio.run, the loop created by the fixture finalizer is not closed by the asyncio Runner. I very recently encountered the same problem in a different issue.

@graingert I'm aware you're involved in upstream asyncio development. Do you think it's worth filing an enhancement issue for asyncio.run (or rather asyncio.Runner) to close any existing loop before setting a new loop?

@phillipuniverse If you don't use asyncio.run, it's possible that your issue has a separate cause. I can help more, if you provide a reproducer for you specific issue.

graingert commented 6 months ago

@seifertm currently I'm trying to remove the policy system and get/set event loop in favour of loop_factory so this becomes a non-issue.

I think to fix this instead of using _provide_clean_event_loop you should call set_event_loop_policy(None) so asyncio.get_event_loop() returns to its original behaviour

phillipuniverse commented 2 months ago

@seifertm I ran into this problem again and now realize that I do indeed have the same problem as @graingert with asyncio.run(). The MRE included at https://github.com/graingert/asyncio_unclosed_loop would replicate my issue as well. Although, same as you described the MRE also fails on 0.21.1...

Maybe 1 more data point - the issue for me only popped up in Python 3.12.2. I had a test suite that ran fine with Python 3.11.4 and when I went to 3.12.2 I got the failure.

I ended up hunting it down to executing Alembic migrations which was super non-obvious. [The recommended approach]9https://alembic.sqlalchemy.org/en/latest/cookbook.html#using-asyncio-with-alembic) for asyncio with alembic involves using asyncio.run(). The really confusing part is that even when I narrowed it down to this code path, it was still flaky. For instance I could add/remove a particular migration file and sometimes it would fail, sometimes it wouldn't. The migration files didn't do anything interesting just created some database columns.

It makes me think there is some sort of timing thing going on too, like maybe the event loop has to hang around for long enough such that it exhibits this problem, maybe some sort of race condition somewhere.