pytest-dev/pytest-asyncio

pytest fails while using version asyncio-0.15.0

Kruszylo opened this issue · 20 comments

Python: 3.8 (docker image)

My pytest setup:

...
============================= test session starts ==============================
platform linux -- Python 3.8.9, pytest-6.2.3, py-1.10.0, pluggy-0.13.1 -- /builds/.../venv/bin/python3
cachedir: .pytest_cache
hypothesis profile 'default' -> database=DirectoryBasedExampleDatabase('/builds/.../.hypothesis/examples')
rootdir: /builds/..., configfile: pytest.ini
plugins: hypothesis-6.9.2, asyncio-0.15.0
...

an error:

...
==================================== ERRORS ====================================
_____________________ ERROR at setup of test_async_ticker ______________________

fixturedef = <FixtureDef argname='event_loop' scope='function' baseid=''>
request = <SubRequest 'event_loop' for <Function test_async_ticker>>

    @pytest.hookimpl(hookwrapper=True)
    def pytest_fixture_setup(fixturedef, request):
        """Adjust the event loop policy when an event loop is produced."""
        if fixturedef.argname == "event_loop":
            outcome = yield
            loop = outcome.get_result()
            policy = asyncio.get_event_loop_policy()
>           old_loop = policy.get_event_loop()

venv/lib/python3.8/site-packages/pytest_asyncio/plugin.py:94: 
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 

self = <asyncio.unix_events._UnixDefaultEventLoopPolicy object at 0x7f07326b2bb0>

    def get_event_loop(self):
        """Get the event loop for the current context.
    
        Returns an instance of EventLoop or raises an exception.
        """
        if (self._local._loop is None and
                not self._local._set_called and
                isinstance(threading.current_thread(), threading._MainThread)):
            self.set_event_loop(self.new_event_loop())
    
        if self._local._loop is None:
>           raise RuntimeError('There is no current event loop in thread %r.'
                               % threading.current_thread().name)
E           RuntimeError: There is no current event loop in thread 'MainThread'.

/usr/local/lib/python3.8/asyncio/events.py:639: RuntimeError
...

The error appears when I run:

python -m pytest tests/test_dates.py::test_async_ticker -vv -duration=6  

where the test_async_ticker is:

import asyncio

import pytest

@pytest.mark.asyncio
async def test_async_ticker():
    async with dates.AsyncTicker() as ticker:
        await asyncio.sleep(0.001)

    assert ticker.time_elapsed().total_seconds() > 0

and AsyncTicker:

class AsyncTicker:
    '''Measures time between entering and exiting `async with` block.'''
    def __init__(self):
        self._start = None
        self._end = None

    async def __aenter__(self, *args, **kwargs):
        self._start = current_utc_instant()
        return self

    async def __aexit__(self, *args, **kwargs):
        self._end = current_utc_instant()

    def time_elapsed(self):
        return self._end - self._start

I have this exact same problem, and from the looks of it, I've been diagnosing it at the exact same time. I can make the problem occur both in the docker image and in a local virtualenv, and I can reliably toggle it off or on by pip installing pytest-asyncio versions 0.14.0 or 0.15.0.

Ah, must have been caused by the loop cleanup changes in 0.15.0. Can be fixed relatively easily, just need to understand what exactly is going on first.

Thank you for the swift response!

I cannot repro this with this test (tried 3.8.9 and 3.9.2):

import asyncio

import pytest

class AsyncTicker:
    '''Measures time between entering and exiting `async with` block.'''
    def __init__(self):
        self._start = None
        self._end = None

    async def __aenter__(self, *args, **kwargs):
        self._start = 1
        return self

    async def __aexit__(self, *args, **kwargs):
        self._end = 2

    def time_elapsed(self):
        return self._end - self._start

@pytest.mark.asyncio
async def test_async_ticker():
    async with AsyncTicker() as ticker:
        await asyncio.sleep(0.001)

    assert True

So would appreciate a minimal repro example!

I'm dealing with a client's proprietary code base and cannot easily extract a reproducible sample. The most exciting thing here afaict is an asyncio.gather of a bunch of network calls issued at the same time.

To me it looks like something in your codebase is making asyncio produce the event loop for the main thread and then setting it to None. Then when pytest-asyncio takes over the event loop management the error pops out. Any chance of something like this happening?

I have extracted the test, in the same docker image with necessary requirements it works without error, but when I run it in my project it fails. I'll investigate further to find out what is happening.

I have a similar issue. So far I have noted that prior tests on code that calls asyncio.run(...) leaves the loop on main closed and self._local._set_called set to True. The first time this plugin tries to setup for the marked function, get_event_loop fails due to set having already been called by the prior call to run. I did not experience this previously using this combo however

Edit: subsequent tests using the decorator do still pass though, it is only the first time it is used after asyncio.run(...) was used elsewhere

Edit 2: Swapped back to 0.14.0 and the tests pass in the same run order & environment

I think I have a code that reproduces the error. You will need to write docker file:

Dockerfile:

FROM python:3.8 as base

RUN apt-get update

RUN python3 -m venv venv
RUN /bin/bash -c "source venv/bin/activate"

RUN pip3 install pytest
RUN pip3 install hypothesis==6.9.2
RUN pip3 install pytest-asyncio==0.15.0

RUN /bin/bash -c "source venv/bin/activate"

# fix stdout & stderr missing from `docker logs`
ENV PYTHONUNBUFFERED=1

COPY tests.py .
CMD ["python3", "-m", "pytest", "tmp.py"]

write python script for tests:

tests.py:

import datetime
import asyncio
import queue
import threading

import pytest


def current_utc_instant() -> datetime.datetime:
    '''Datetime representing current UTC instant, with time zone'''
    return datetime.datetime.now(datetime.timezone.utc)



def _run_in_fresh_loop(coro, result_queue):
    loop = asyncio.new_event_loop()
    asyncio.set_event_loop(loop)

    try:
        result = loop.run_until_complete(coro)
        msg = {'success': True,
               'result': result}
    except Exception as e:
        msg = {'success': False,
               'exception': e}

    loop.close()
    result_queue.put(msg)


def run_in_thread(coro):
    '''Workaround for running async coroutine from a synchronous context  inside other async code,
    like `async(sync(async ()))`.

    Runs the coroutine in a separate thread with new event loop and blocks until the coroutine is completed.
    '''
    result_queue = queue.Queue()
    th = threading.Thread(target=_run_in_fresh_loop, args=(coro, result_queue))
    th.start()
    th.join()

    msg = result_queue.get()

    if msg['success']:
        return msg['result']
    else:
        raise msg['exception']


async def _async_division(x, y):
    await asyncio.sleep(0.001)
    return x / y


async def _async_wrapper_fn(x, y):
    # do async stuff
    await asyncio.sleep(0.001)

    # call sync subroutine that triggers a coroutine in another thread
    result = run_in_thread(_async_division(x, y))

    # do async stuff
    await asyncio.sleep(0.001)

    return result


class TestRunInThread:
    # def test_with_no_loop_success(self):
    #     assert 2 == run_in_thread(_async_division(6, 3))

    # def test_no_loop_exception(self):
    #     with pytest.raises(ZeroDivisionError):
    #         run_in_thread(_async_division(1, 0))

    def test_already_present_loop_success(self):
        assert 2 == asyncio.run(_async_wrapper_fn(6, 3))

    # def test_already_present_loop_exception(self):
    #     with pytest.raises(ZeroDivisionError):
    #         asyncio.run(_async_wrapper_fn(1, 0))


class AsyncTicker:
    '''Measures time between entering and exiting `async with` block.'''
    def __init__(self):
        self._start = None
        self._end = None

    async def __aenter__(self, *args, **kwargs):
        self._start = current_utc_instant()
        return self

    async def __aexit__(self, *args, **kwargs):
        self._end = current_utc_instant()

    def time_elapsed(self):
        return self._end - self._start

@pytest.mark.asyncio
async def test_async_ticker():
    async with AsyncTicker() as ticker:
        await asyncio.sleep(0.001)

    assert ticker.time_elapsed().total_seconds() > 0

build the image:

docker build -f Dockerfile -t 'pytest-issue-209' .

and run:

docker run 'pytest-issue-209'

Output:

============================= test session starts ==============================
platform linux -- Python 3.8.9, pytest-6.2.3, py-1.10.0, pluggy-0.13.1
rootdir: /
plugins: asyncio-0.15.0, hypothesis-6.9.2
collected 2 items

tmp.py .E                                                                [100%]

==================================== ERRORS ====================================
_____________________ ERROR at setup of test_async_ticker ______________________

fixturedef = <FixtureDef argname='event_loop' scope='function' baseid=''>
request = <SubRequest 'event_loop' for <Function test_async_ticker>>

    @pytest.hookimpl(hookwrapper=True)
    def pytest_fixture_setup(fixturedef, request):
        """Adjust the event loop policy when an event loop is produced."""
        if fixturedef.argname == "event_loop":
            outcome = yield
            loop = outcome.get_result()
            policy = asyncio.get_event_loop_policy()
>           old_loop = policy.get_event_loop()

usr/local/lib/python3.8/site-packages/pytest_asyncio/plugin.py:94: 
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 

self = <asyncio.unix_events._UnixDefaultEventLoopPolicy object at 0x7eff64c52700>

    def get_event_loop(self):
        """Get the event loop for the current context.
    
        Returns an instance of EventLoop or raises an exception.
        """
        if (self._local._loop is None and
                not self._local._set_called and
                isinstance(threading.current_thread(), threading._MainThread)):
            self.set_event_loop(self.new_event_loop())
    
        if self._local._loop is None:
>           raise RuntimeError('There is no current event loop in thread %r.'
                               % threading.current_thread().name)
E           RuntimeError: There is no current event loop in thread 'MainThread'.

usr/local/lib/python3.8/asyncio/events.py:639: RuntimeError
=========================== short test summary info ============================
ERROR tmp.py::test_async_ticker - RuntimeError: There is no current event loo...
========================== 1 passed, 1 error in 0.10s ==========================

Could people from this thread try the latest commit on the master branch and report if it fixes it?

It looks like 94c2560 results in tests hanging, without any error message.

[EDIT] Trying multiple times to see what's going on, and see if I can isolate the issue. Curious if anyone else is seeing similar issues.

[2nd EDIT] I'm now getting errors, Event loop is closed again, e.g.

tests/test_production.py::test_verify_production_cot[fenix production] Exception ignored in: <function BaseSubprocessTransport.__del__ at 0x10fbb5790>
Traceback (most recent call last):
  File "/Users/asasaki/.pyenv/versions/3.8.0/lib/python3.8/asyncio/base_subprocess.py", line 126, in __del__
    self.close()
  File "/Users/asasaki/.pyenv/versions/3.8.0/lib/python3.8/asyncio/base_subprocess.py", line 104, in close
    proto.pipe.close()
  File "/Users/asasaki/.pyenv/versions/3.8.0/lib/python3.8/asyncio/unix_events.py", line 536, in close
    self._close(None)
  File "/Users/asasaki/.pyenv/versions/3.8.0/lib/python3.8/asyncio/unix_events.py", line 560, in _close
    self._loop.call_soon(self._call_connection_lost, exc)
  File "/Users/asasaki/.pyenv/versions/3.8.0/lib/python3.8/asyncio/base_events.py", line 711, in call_soon
    self._check_closed()
  File "/Users/asasaki/.pyenv/versions/3.8.0/lib/python3.8/asyncio/base_events.py", line 504, in _check_closed
    raise RuntimeError('Event loop is closed')
RuntimeError: Event loop is closed

This is largely in a complex test decorated with @pytest.mark.asyncio and @pytest.mark.parametrize, without an event_loop fixture, with many coroutines awaiting on other coroutines.

Could people from this thread try the latest commit on the master branch and report if it fixes it?

I can confirm that the error disappeared after the introduction of the exception handling.

Could people from this thread try the latest commit on the master branch and report if it fixes it?

I can confirm, the try clause fixes the problem.

I also encountered the same issue since the 0.15 release and confirm that the latest main branch with exception handling fixes the problem, without changing my tests & fixtures.
Some of my fixtures also have been using asyncio.run() to initialize and finalize stuffs.

Ok, this will be going out soon as 0.15.1.

Could people from this thread try the latest commit on the master branch and report if it fixes it?

Same as the others. The problem is fixed when I run against that version.

0.15.1 is out! Give it a test.

Still broken for me. I'll pin to <15.0.

@escapewindow feel free to open a different issue, I think yours is something else. A minimal repro would be nice

This issue is about pytest-asyncio-0.15.0 and there hasn't been any progress in this issue for almost a year. The following v0.15.1 release seemed to fix the problem for most of the participants of this discussion, as well as for the django/channels project.

A lot has happened since v0.15.0 and pytest-asyncio is now at v0.18.2. Please file a new bug, if you encounter any issues.

@escapewindow If you're still affected by a pytest-asyncio problem, I encourage you to try the latest version. Any feedback would be appreciated!