Test freezes in CI after upgrade to v2.13.0 from v2.12.0

[moritz89]

Python Version

3.10.13

pytest Version

No response

Package Version

2.13.0

Description

When upgrading from 2.12 to 2.13 one Django (4.2.5) test always freezes, but only in the CI environment. It is a test that uses TransactionTestCase as well as Django Channels.

What actions can be taken to help triage the core issue?

[rikroe]

The same happens on one test case for us as well, in a Github Actions runner on all python versions from 3.8 to 3.12.

Github actions log: https://github.com/bimmerconnected/bimmer_connected/actions/runs/6247430371/job/16999245011?pr=568
Test case: https://github.com/bimmerconnected/bimmer_connected/blob/master/bimmer_connected/tests/test_remote_services.py#L352

[adamchainz]

Thanks for the exact test case @rikroe . Can either of you reproduce the freeze locally? If you run tests with Python Development Mode on and kill the process, faulthandler will report a stack trace, which would help massively. Otherwise we could try a git bisect.

[rikroe]

Upgraded all packages in my venv and now I'm able to reproduce the issue locally as well.

However, when running only the test that seems to be the culprit, it just works perfectly:

(venv3.11) richard@RICHARD-PC:~/bimmer_connected$ python3 -m pytest bimmer_connected/tests/test_remote_services.py -k "test_get_remote_position_too_old"
================================================================== test session starts ===================================================================
platform linux -- Python 3.11.0, pytest-7.4.2, pluggy-1.0.0
rootdir: /home/richard/bimmer_connected
configfile: pyproject.toml
plugins: cov-4.1.0, anyio-3.6.2, respx-0.20.2, timeout-2.1.0, time-machine-2.13.0, asyncio-0.21.1
asyncio: mode=Mode.STRICT
collected 16 items / 15 deselected / 1 selected                                                                                                          

bimmer_connected/tests/test_remote_services.py .                                                                                                   [100%]

============================================================ 1 passed, 15 deselected in 0.70s ============================================================

Also, with time-machine==0.12.0 test run successfully:

(venv3.11) richard@RICHARD-PC:~/bimmer_connected$ pip install time-machine==2.12.0
Collecting time-machine==2.12.0
  Downloading time_machine-2.12.0-cp311-cp311-manylinux_2_5_x86_64.manylinux1_x86_64.manylinux_2_17_x86_64.manylinux2014_x86_64.whl (31 kB)
Requirement already satisfied: python-dateutil in ./venv3.11/lib/python3.11/site-packages (from time-machine==2.12.0) (2.8.2)
Requirement already satisfied: six>=1.5 in ./venv3.11/lib/python3.11/site-packages (from python-dateutil->time-machine==2.12.0) (1.16.0)
Installing collected packages: time-machine
  Attempting uninstall: time-machine
    Found existing installation: time-machine 2.13.0
    Uninstalling time-machine-2.13.0:
      Successfully uninstalled time-machine-2.13.0
Successfully installed time-machine-2.12.0

[notice] A new release of pip available: 22.3 -> 23.2.1
[notice] To update, run: pip install --upgrade pip
(venv3.11) richard@RICHARD-PC:~/bimmer_connected$ python3 -m pytest bimmer_connected/tests/test_remote_services.py 
================================================================== test session starts ===================================================================
platform linux -- Python 3.11.0, pytest-7.4.2, pluggy-1.0.0
rootdir: /home/richard/bimmer_connected
configfile: pyproject.toml
plugins: cov-4.1.0, anyio-3.6.2, respx-0.20.2, timeout-2.1.0, asyncio-0.21.1, time-machine-2.12.0
asyncio: mode=Mode.STRICT
collected 16 items                                                                                                                                       

bimmer_connected/tests/test_remote_services.py ................                                                                                    [100%]

================================================================== 16 passed in 16.02s ===================================================================

Stack trace with 0.13.0 (full stack trace)

python3 -X dev -m pytest bimmer_connected/tests/test_remote_services.py --full-trace

(venv3.11) richard@RICHARD-PC:~/bimmer_connected$ python3 -X dev -m pytest bimmer_connected/tests/test_remote_services.py --full-trace
================================================================== test session starts ===================================================================
platform linux -- Python 3.11.0, pytest-7.4.2, pluggy-1.0.0
rootdir: /home/richard/bimmer_connected
configfile: pyproject.toml
plugins: cov-4.1.0, anyio-3.6.2, respx-0.20.2, timeout-2.1.0, time-machine-2.13.0, asyncio-0.21.1
asyncio: mode=Mode.STRICT
collected 16 items                                                                                                                                       

bimmer_connected/tests/test_remote_services.py .............^C

!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!! KeyboardInterrupt !!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!

config = <_pytest.config.Config object at 0x7fcfc6d36900>, doit = <function _main at 0x7fcfc6effac0>

    def wrap_session(
        config: Config, doit: Callable[[Config, "Session"], Optional[Union[int, ExitCode]]]
    ) -> Union[int, ExitCode]:
        """Skeleton command line program."""
        session = Session.from_config(config)
        session.exitstatus = ExitCode.OK
        initstate = 0
        try:
            try:
                config._do_configure()
                initstate = 1
                config.hook.pytest_sessionstart(session=session)
                initstate = 2
>               session.exitstatus = doit(config, session) or 0

venv3.11/lib/python3.11/site-packages/_pytest/main.py:271: 
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 

config = <_pytest.config.Config object at 0x7fcfc6d36900>
session = <Session bimmer_connected exitstatus=<ExitCode.OK: 0> testsfailed=0 testscollected=16>

    def _main(config: Config, session: "Session") -> Optional[Union[int, ExitCode]]:
        """Default command line protocol for initialization, session,
        running tests and reporting."""
        config.hook.pytest_collection(session=session)
>       config.hook.pytest_runtestloop(session=session)

venv3.11/lib/python3.11/site-packages/_pytest/main.py:325: 
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 

self = <_HookCaller 'pytest_runtestloop'>, args = ()
kwargs = {'session': <Session bimmer_connected exitstatus=<ExitCode.OK: 0> testsfailed=0 testscollected=16>}, argname = 'session', firstresult = True

    def __call__(self, *args, **kwargs):
        if args:
            raise TypeError("hook calling supports only keyword arguments")
        assert not self.is_historic()
    
        # This is written to avoid expensive operations when not needed.
        if self.spec:
            for argname in self.spec.argnames:
                if argname not in kwargs:
                    notincall = tuple(set(self.spec.argnames) - kwargs.keys())
                    warnings.warn(
                        "Argument(s) {} which are declared in the hookspec "
                        "can not be found in this hook call".format(notincall),
                        stacklevel=2,
                    )
                    break
    
            firstresult = self.spec.opts.get("firstresult")
        else:
            firstresult = False
    
>       return self._hookexec(self.name, self.get_hookimpls(), kwargs, firstresult)

venv3.11/lib/python3.11/site-packages/pluggy/_hooks.py:265: 
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 

self = <_pytest.config.PytestPluginManager object at 0x7fcfc7985640>, hook_name = 'pytest_runtestloop'
methods = [<HookImpl plugin_name='main', plugin=<module '_pytest.main' from '/home/richard/bimmer_connected/venv3.11/lib/python3...t/main.py'>>, <HookImpl plugin_name='logging-plugin', plugin=<_pytest.logging.LoggingPlugin object at 0x7fcfc54c89c0>>]
kwargs = {'session': <Session bimmer_connected exitstatus=<ExitCode.OK: 0> testsfailed=0 testscollected=16>}, firstresult = True

    def _hookexec(self, hook_name, methods, kwargs, firstresult):
        # called from all hookcaller instances.
        # enable_tracing will set its own wrapping function at self._inner_hookexec
>       return self._inner_hookexec(hook_name, methods, kwargs, firstresult)

venv3.11/lib/python3.11/site-packages/pluggy/_manager.py:80: 
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 

session = <Session bimmer_connected exitstatus=<ExitCode.OK: 0> testsfailed=0 testscollected=16>

    def pytest_runtestloop(session: "Session") -> bool:
        if session.testsfailed and not session.config.option.continue_on_collection_errors:
            raise session.Interrupted(
                "%d error%s during collection"
                % (session.testsfailed, "s" if session.testsfailed != 1 else "")
            )
    
        if session.config.option.collectonly:
            return True
    
        for i, item in enumerate(session.items):
            nextitem = session.items[i + 1] if i + 1 < len(session.items) else None
>           item.config.hook.pytest_runtest_protocol(item=item, nextitem=nextitem)

venv3.11/lib/python3.11/site-packages/_pytest/main.py:350: 
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 

self = <_HookCaller 'pytest_runtest_protocol'>, args = (), kwargs = {'item': <Function test_get_remote_position_too_old>, 'nextitem': <Function test_poi>}
argname = 'nextitem', firstresult = True

    def __call__(self, *args, **kwargs):
        if args:
            raise TypeError("hook calling supports only keyword arguments")
        assert not self.is_historic()
    
        # This is written to avoid expensive operations when not needed.
        if self.spec:
            for argname in self.spec.argnames:
                if argname not in kwargs:
                    notincall = tuple(set(self.spec.argnames) - kwargs.keys())
                    warnings.warn(
                        "Argument(s) {} which are declared in the hookspec "
                        "can not be found in this hook call".format(notincall),
                        stacklevel=2,
                    )
                    break
    
            firstresult = self.spec.opts.get("firstresult")
        else:
            firstresult = False
    
>       return self._hookexec(self.name, self.get_hookimpls(), kwargs, firstresult)

venv3.11/lib/python3.11/site-packages/pluggy/_hooks.py:265: 
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 

self = <_pytest.config.PytestPluginManager object at 0x7fcfc7985640>, hook_name = 'pytest_runtest_protocol'
methods = [<HookImpl plugin_name='runner', plugin=<module '_pytest.runner' from '/home/richard/bimmer_connected/venv3.11/lib/pyt...e '_pytest.warnings' from '/home/richard/bimmer_connected/venv3.11/lib/python3.11/site-packages/_pytest/warnings.py'>>]
kwargs = {'item': <Function test_get_remote_position_too_old>, 'nextitem': <Function test_poi>}, firstresult = True

    def _hookexec(self, hook_name, methods, kwargs, firstresult):
        # called from all hookcaller instances.
        # enable_tracing will set its own wrapping function at self._inner_hookexec
>       return self._inner_hookexec(hook_name, methods, kwargs, firstresult)

venv3.11/lib/python3.11/site-packages/pluggy/_manager.py:80: 
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 

item = <Function test_get_remote_position_too_old>, nextitem = <Function test_poi>

    def pytest_runtest_protocol(item: Item, nextitem: Optional[Item]) -> bool:
        ihook = item.ihook
        ihook.pytest_runtest_logstart(nodeid=item.nodeid, location=item.location)
>       runtestprotocol(item, nextitem=nextitem)

venv3.11/lib/python3.11/site-packages/_pytest/runner.py:114: 
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 

item = <Function test_get_remote_position_too_old>, log = True, nextitem = <Function test_poi>

    def runtestprotocol(
        item: Item, log: bool = True, nextitem: Optional[Item] = None
    ) -> List[TestReport]:
        hasrequest = hasattr(item, "_request")
        if hasrequest and not item._request:  # type: ignore[attr-defined]
            # This only happens if the item is re-run, as is done by
            # pytest-rerunfailures.
            item._initrequest()  # type: ignore[attr-defined]
        rep = call_and_report(item, "setup", log)
        reports = [rep]
        if rep.passed:
            if item.config.getoption("setupshow", False):
                show_test_item(item)
            if not item.config.getoption("setuponly", False):
>               reports.append(call_and_report(item, "call", log))

venv3.11/lib/python3.11/site-packages/_pytest/runner.py:133: 
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 

item = <Function test_get_remote_position_too_old>, when = 'call', log = True, kwds = {}

    def call_and_report(
        item: Item, when: "Literal['setup', 'call', 'teardown']", log: bool = True, **kwds
    ) -> TestReport:
>       call = call_runtest_hook(item, when, **kwds)

venv3.11/lib/python3.11/site-packages/_pytest/runner.py:222: 
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 

item = <Function test_get_remote_position_too_old>, when = 'call', kwds = {}, reraise = (<class '_pytest.outcomes.Exit'>, <class 'KeyboardInterrupt'>)

    def call_runtest_hook(
        item: Item, when: "Literal['setup', 'call', 'teardown']", **kwds
    ) -> "CallInfo[None]":
        if when == "setup":
            ihook: Callable[..., None] = item.ihook.pytest_runtest_setup
        elif when == "call":
            ihook = item.ihook.pytest_runtest_call
        elif when == "teardown":
            ihook = item.ihook.pytest_runtest_teardown
        else:
            assert False, f"Unhandled runtest hook case: {when}"
        reraise: Tuple[Type[BaseException], ...] = (Exit,)
        if not item.config.getoption("usepdb", False):
            reraise += (KeyboardInterrupt,)
>       return CallInfo.from_call(
            lambda: ihook(item=item, **kwds), when=when, reraise=reraise
        )

venv3.11/lib/python3.11/site-packages/_pytest/runner.py:261: 
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 

cls = <class '_pytest.runner.CallInfo'>, func = <function call_runtest_hook.<locals>.<lambda> at 0x7fcfc5527a10>, when = 'call'
reraise = (<class '_pytest.outcomes.Exit'>, <class 'KeyboardInterrupt'>)

    @classmethod
    def from_call(
        cls,
        func: "Callable[[], TResult]",
        when: "Literal['collect', 'setup', 'call', 'teardown']",
        reraise: Optional[
            Union[Type[BaseException], Tuple[Type[BaseException], ...]]
        ] = None,
    ) -> "CallInfo[TResult]":
        """Call func, wrapping the result in a CallInfo.
    
        :param func:
            The function to call. Called without arguments.
        :param when:
            The phase in which the function is called.
        :param reraise:
            Exception or exceptions that shall propagate if raised by the
            function, instead of being wrapped in the CallInfo.
        """
        excinfo = None
        start = timing.time()
        precise_start = timing.perf_counter()
        try:
>           result: Optional[TResult] = func()

venv3.11/lib/python3.11/site-packages/_pytest/runner.py:341: 
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 

>       lambda: ihook(item=item, **kwds), when=when, reraise=reraise
    )

venv3.11/lib/python3.11/site-packages/_pytest/runner.py:262: 
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 

self = <_HookCaller 'pytest_runtest_call'>, args = (), kwargs = {'item': <Function test_get_remote_position_too_old>}, argname = 'item'
firstresult = False

    def __call__(self, *args, **kwargs):
        if args:
            raise TypeError("hook calling supports only keyword arguments")
        assert not self.is_historic()
    
        # This is written to avoid expensive operations when not needed.
        if self.spec:
            for argname in self.spec.argnames:
                if argname not in kwargs:
                    notincall = tuple(set(self.spec.argnames) - kwargs.keys())
                    warnings.warn(
                        "Argument(s) {} which are declared in the hookspec "
                        "can not be found in this hook call".format(notincall),
                        stacklevel=2,
                    )
                    break
    
            firstresult = self.spec.opts.get("firstresult")
        else:
            firstresult = False
    
>       return self._hookexec(self.name, self.get_hookimpls(), kwargs, firstresult)

venv3.11/lib/python3.11/site-packages/pluggy/_hooks.py:265: 
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 

self = <_pytest.config.PytestPluginManager object at 0x7fcfc7985640>, hook_name = 'pytest_runtest_call'
methods = [<HookImpl plugin_name='runner', plugin=<module '_pytest.runner' from '/home/richard/bimmer_connected/venv3.11/lib/pyt...ion' from '/home/richard/bimmer_connected/venv3.11/lib/python3.11/site-packages/_pytest/unraisableexception.py'>>, ...]
kwargs = {'item': <Function test_get_remote_position_too_old>}, firstresult = False

    def _hookexec(self, hook_name, methods, kwargs, firstresult):
        # called from all hookcaller instances.
        # enable_tracing will set its own wrapping function at self._inner_hookexec
>       return self._inner_hookexec(hook_name, methods, kwargs, firstresult)

venv3.11/lib/python3.11/site-packages/pluggy/_manager.py:80: 
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 

item = <Function test_get_remote_position_too_old>

    def pytest_runtest_call(item: Item) -> None:
        _update_current_test_var(item, "call")
        try:
            del sys.last_type
            del sys.last_value
            del sys.last_traceback
        except AttributeError:
            pass
        try:
>           item.runtest()

venv3.11/lib/python3.11/site-packages/_pytest/runner.py:169: 
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 

self = <Function test_get_remote_position_too_old>

    def runtest(self) -> None:
        """Execute the underlying test function."""
>       self.ihook.pytest_pyfunc_call(pyfuncitem=self)

venv3.11/lib/python3.11/site-packages/_pytest/python.py:1792: 
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 

self = <_HookCaller 'pytest_pyfunc_call'>, args = (), kwargs = {'pyfuncitem': <Function test_get_remote_position_too_old>}, argname = 'pyfuncitem'
firstresult = True

    def __call__(self, *args, **kwargs):
        if args:
            raise TypeError("hook calling supports only keyword arguments")
        assert not self.is_historic()
    
        # This is written to avoid expensive operations when not needed.
        if self.spec:
            for argname in self.spec.argnames:
                if argname not in kwargs:
                    notincall = tuple(set(self.spec.argnames) - kwargs.keys())
                    warnings.warn(
                        "Argument(s) {} which are declared in the hookspec "
                        "can not be found in this hook call".format(notincall),
                        stacklevel=2,
                    )
                    break
    
            firstresult = self.spec.opts.get("firstresult")
        else:
            firstresult = False
    
>       return self._hookexec(self.name, self.get_hookimpls(), kwargs, firstresult)

venv3.11/lib/python3.11/site-packages/pluggy/_hooks.py:265: 
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 

self = <_pytest.config.PytestPluginManager object at 0x7fcfc7985640>, hook_name = 'pytest_pyfunc_call'
methods = [<HookImpl plugin_name='python', plugin=<module '_pytest.python' from '/home/richard/bimmer_connected/venv3.11/lib/pyt...asyncio.plugin' from '/home/richard/bimmer_connected/venv3.11/lib/python3.11/site-packages/pytest_asyncio/plugin.py'>>]
kwargs = {'pyfuncitem': <Function test_get_remote_position_too_old>}, firstresult = True

    def _hookexec(self, hook_name, methods, kwargs, firstresult):
        # called from all hookcaller instances.
        # enable_tracing will set its own wrapping function at self._inner_hookexec
>       return self._inner_hookexec(hook_name, methods, kwargs, firstresult)

venv3.11/lib/python3.11/site-packages/pluggy/_manager.py:80: 
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 

pyfuncitem = <Function test_get_remote_position_too_old>

    @hookimpl(trylast=True)
    def pytest_pyfunc_call(pyfuncitem: "Function") -> Optional[object]:
        testfunction = pyfuncitem.obj
        if is_async_function(testfunction):
            async_warn_and_skip(pyfuncitem.nodeid)
        funcargs = pyfuncitem.funcargs
        testargs = {arg: funcargs[arg] for arg in pyfuncitem._fixtureinfo.argnames}
>       result = testfunction(**testargs)

venv3.11/lib/python3.11/site-packages/_pytest/python.py:194: 
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 

args = (), kwargs = {'bmw_fixture': <bimmer_connected.tests.common.MyBMWMockRouter object at 0x7fcfc519b670>}
coro = <coroutine object test_get_remote_position_too_old at 0x7fcfc5513790>
task = <Task pending name='Task-13' coro=<test_get_remote_position_too_old() running at /home/richard/bimmer_connected/venv3....ted at /usr/local/lib/python3.11/asyncio/base_events.py:427> created at /usr/local/lib/python3.11/asyncio/tasks.py:670>

    @functools.wraps(func)
    def inner(*args, **kwargs):
        coro = func(*args, **kwargs)
        if not inspect.isawaitable(coro):
            pyfuncitem.warn(
                pytest.PytestWarning(
                    f"The test {pyfuncitem} is marked with '@pytest.mark.asyncio' "
                    "but it is not an async function. "
                    "Please remove asyncio marker. "
                    "If the test is not marked explicitly, "
                    "check for global markers applied via 'pytestmark'."
                )
            )
            return
        task = asyncio.ensure_future(coro, loop=_loop)
        try:
>           _loop.run_until_complete(task)

venv3.11/lib/python3.11/site-packages/pytest_asyncio/plugin.py:532: 
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 

self = <_UnixSelectorEventLoop running=False closed=False debug=True>
future = <Task pending name='Task-13' coro=<test_get_remote_position_too_old() running at /home/richard/bimmer_connected/venv3....ted at /usr/local/lib/python3.11/asyncio/base_events.py:427> created at /usr/local/lib/python3.11/asyncio/tasks.py:670>

    def run_until_complete(self, future):
        """Run until the Future is done.
    
        If the argument is a coroutine, it is wrapped in a Task.
    
        WARNING: It would be disastrous to call run_until_complete()
        with the same coroutine twice -- it would wrap it in two
        different Tasks and that can't be good.
    
        Return the Future's result, or raise its exception.
        """
        self._check_closed()
        self._check_running()
    
        new_task = not futures.isfuture(future)
        future = tasks.ensure_future(future, loop=self)
        if new_task:
            # An exception is raised if the future didn't complete, so there
            # is no need to log the "destroy pending task" message
            future._log_destroy_pending = False
    
        future.add_done_callback(_run_until_complete_cb)
        try:
>           self.run_forever()

/usr/local/lib/python3.11/asyncio/base_events.py:637: 
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 

self = <_UnixSelectorEventLoop running=False closed=False debug=True>

    def run_forever(self):
        """Run until stop() is called."""
        self._check_closed()
        self._check_running()
        self._set_coroutine_origin_tracking(self._debug)
        self._thread_id = threading.get_ident()
    
        old_agen_hooks = sys.get_asyncgen_hooks()
        sys.set_asyncgen_hooks(firstiter=self._asyncgen_firstiter_hook,
                               finalizer=self._asyncgen_finalizer_hook)
        try:
            events._set_running_loop(self)
            while True:
>               self._run_once()

/usr/local/lib/python3.11/asyncio/base_events.py:604: 
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 

self = <_UnixSelectorEventLoop running=False closed=False debug=True>

    def _run_once(self):
        """Run one full iteration of the event loop.
    
        This calls all currently ready callbacks, polls for I/O,
        schedules the resulting callbacks, and finally schedules
        'call_later' callbacks.
        """
    
        sched_count = len(self._scheduled)
        if (sched_count > _MIN_SCHEDULED_TIMER_HANDLES and
            self._timer_cancelled_count / sched_count >
                _MIN_CANCELLED_TIMER_HANDLES_FRACTION):
            # Remove delayed calls that were cancelled if their number
            # is too high
            new_scheduled = []
            for handle in self._scheduled:
                if handle._cancelled:
                    handle._scheduled = False
                else:
                    new_scheduled.append(handle)
    
            heapq.heapify(new_scheduled)
            self._scheduled = new_scheduled
            self._timer_cancelled_count = 0
        else:
            # Remove delayed calls that were cancelled from head of queue.
            while self._scheduled and self._scheduled[0]._cancelled:
                self._timer_cancelled_count -= 1
                handle = heapq.heappop(self._scheduled)
                handle._scheduled = False
    
        timeout = None
        if self._ready or self._stopping:
            timeout = 0
        elif self._scheduled:
            # Compute the desired timeout.
            when = self._scheduled[0]._when
            timeout = min(max(0, when - self.time()), MAXIMUM_SELECT_TIMEOUT)
    
>       event_list = self._selector.select(timeout)

/usr/local/lib/python3.11/asyncio/base_events.py:1873: 
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 

self = <selectors.EpollSelector object at 0x7fcfc4faeef0>, timeout = 1.0

    def select(self, timeout=None):
        if timeout is None:
            timeout = -1
        elif timeout <= 0:
            timeout = 0
        else:
            # epoll_wait() has a resolution of 1 millisecond, round away
            # from zero to wait *at least* timeout seconds.
            timeout = math.ceil(timeout * 1e3) * 1e-3
    
        # epoll_wait() expects `maxevents` to be greater than zero;
        # we want to make sure that `select()` can be called when no
        # FD is registered.
        max_ev = max(len(self._fd_to_key), 1)
    
        ready = []
        try:
>           fd_event_list = self._selector.poll(timeout, max_ev)
E           KeyboardInterrupt

/usr/local/lib/python3.11/selectors.py:468: KeyboardInterrupt
============================================================== 13 passed in -117576135.07s ===============================================================
Exception ignored in: <coroutine object test_get_remote_position_too_old at 0x7fcfc5513790>
Traceback (most recent call last):
  File "/home/richard/bimmer_connected/venv3.11/lib/python3.11/site-packages/time_machine/__init__.py", line 326, in wrapper
    return await wrapped(*args, **kwargs)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/richard/bimmer_connected/bimmer_connected/tests/test_remote_services.py", line 359, in test_get_remote_position_too_old
    await vehicle.remote_services.trigger_remote_vehicle_finder()
  File "/home/richard/bimmer_connected/bimmer_connected/vehicle/remote_services.py", line 312, in trigger_remote_vehicle_finder
    status = await self.trigger_remote_service(Services.VEHICLE_FINDER)
             ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/richard/bimmer_connected/bimmer_connected/vehicle/remote_services.py", line 116, in trigger_remote_service
    async with MyBMWClient(self._account.config, brand=self._vehicle.brand) as client:
  File "/home/richard/bimmer_connected/venv3.11/lib/python3.11/site-packages/httpx/_client.py", line 2003, in __aexit__
    await self._transport.__aexit__(exc_type, exc_value, traceback)
  File "/home/richard/bimmer_connected/venv3.11/lib/python3.11/site-packages/httpx/_transports/default.py", line 345, in __aexit__
    await self._pool.__aexit__(exc_type, exc_value, traceback)
  File "/home/richard/bimmer_connected/venv3.11/lib/python3.11/site-packages/httpcore/_async/connection_pool.py", line 327, in __aexit__
    await self.aclose()
  File "/home/richard/bimmer_connected/venv3.11/lib/python3.11/site-packages/httpcore/_async/connection_pool.py", line 312, in aclose
    async with self._pool_lock:
  File "/home/richard/bimmer_connected/venv3.11/lib/python3.11/site-packages/httpcore/_synchronization.py", line 48, in __aenter__
    self.setup()
  File "/home/richard/bimmer_connected/venv3.11/lib/python3.11/site-packages/httpcore/_synchronization.py", line 32, in setup
    self._backend = sniffio.current_async_library()
                    ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/richard/bimmer_connected/venv3.11/lib/python3.11/site-packages/sniffio/_impl.py", line 93, in current_async_library
    raise AsyncLibraryNotFoundError(
sniffio._impl.AsyncLibraryNotFoundError: unknown async library, or not in async context
Task was destroyed but it is pending!
source_traceback: Object created at (most recent call last):
  File "<frozen runpy>", line 198, in _run_module_as_main
  File "<frozen runpy>", line 88, in _run_code
  File "/home/richard/bimmer_connected/venv3.11/lib/python3.11/site-packages/pytest/__main__.py", line 5, in <module>
    raise SystemExit(pytest.console_main())
  File "/home/richard/bimmer_connected/venv3.11/lib/python3.11/site-packages/_pytest/config/__init__.py", line 192, in console_main
    code = main()
  File "/home/richard/bimmer_connected/venv3.11/lib/python3.11/site-packages/_pytest/config/__init__.py", line 169, in main
    ret: Union[ExitCode, int] = config.hook.pytest_cmdline_main(
  File "/home/richard/bimmer_connected/venv3.11/lib/python3.11/site-packages/pluggy/_hooks.py", line 265, in __call__
    return self._hookexec(self.name, self.get_hookimpls(), kwargs, firstresult)
  File "/home/richard/bimmer_connected/venv3.11/lib/python3.11/site-packages/pluggy/_manager.py", line 80, in _hookexec
    return self._inner_hookexec(hook_name, methods, kwargs, firstresult)
  File "/home/richard/bimmer_connected/venv3.11/lib/python3.11/site-packages/pluggy/_callers.py", line 39, in _multicall
    res = hook_impl.function(*args)
  File "/home/richard/bimmer_connected/venv3.11/lib/python3.11/site-packages/_pytest/main.py", line 318, in pytest_cmdline_main
    return wrap_session(config, _main)
  File "/home/richard/bimmer_connected/venv3.11/lib/python3.11/site-packages/_pytest/main.py", line 271, in wrap_session
    session.exitstatus = doit(config, session) or 0
  File "/home/richard/bimmer_connected/venv3.11/lib/python3.11/site-packages/_pytest/main.py", line 325, in _main
    config.hook.pytest_runtestloop(session=session)
  File "/home/richard/bimmer_connected/venv3.11/lib/python3.11/site-packages/pluggy/_hooks.py", line 265, in __call__
    return self._hookexec(self.name, self.get_hookimpls(), kwargs, firstresult)
  File "/home/richard/bimmer_connected/venv3.11/lib/python3.11/site-packages/pluggy/_manager.py", line 80, in _hookexec
    return self._inner_hookexec(hook_name, methods, kwargs, firstresult)
  File "/home/richard/bimmer_connected/venv3.11/lib/python3.11/site-packages/pluggy/_callers.py", line 39, in _multicall
    res = hook_impl.function(*args)
  File "/home/richard/bimmer_connected/venv3.11/lib/python3.11/site-packages/_pytest/main.py", line 350, in pytest_runtestloop
    item.config.hook.pytest_runtest_protocol(item=item, nextitem=nextitem)
  File "/home/richard/bimmer_connected/venv3.11/lib/python3.11/site-packages/pluggy/_hooks.py", line 265, in __call__
    return self._hookexec(self.name, self.get_hookimpls(), kwargs, firstresult)
  File "/home/richard/bimmer_connected/venv3.11/lib/python3.11/site-packages/pluggy/_manager.py", line 80, in _hookexec
    return self._inner_hookexec(hook_name, methods, kwargs, firstresult)
  File "/home/richard/bimmer_connected/venv3.11/lib/python3.11/site-packages/pluggy/_callers.py", line 39, in _multicall
    res = hook_impl.function(*args)
  File "/home/richard/bimmer_connected/venv3.11/lib/python3.11/site-packages/_pytest/runner.py", line 114, in pytest_runtest_protocol
    runtestprotocol(item, nextitem=nextitem)
  File "/home/richard/bimmer_connected/venv3.11/lib/python3.11/site-packages/_pytest/runner.py", line 133, in runtestprotocol
    reports.append(call_and_report(item, "call", log))
  File "/home/richard/bimmer_connected/venv3.11/lib/python3.11/site-packages/_pytest/runner.py", line 222, in call_and_report
    call = call_runtest_hook(item, when, **kwds)
  File "/home/richard/bimmer_connected/venv3.11/lib/python3.11/site-packages/_pytest/runner.py", line 261, in call_runtest_hook
    return CallInfo.from_call(
  File "/home/richard/bimmer_connected/venv3.11/lib/python3.11/site-packages/_pytest/runner.py", line 341, in from_call
    result: Optional[TResult] = func()
  File "/home/richard/bimmer_connected/venv3.11/lib/python3.11/site-packages/_pytest/runner.py", line 262, in <lambda>
    lambda: ihook(item=item, **kwds), when=when, reraise=reraise
  File "/home/richard/bimmer_connected/venv3.11/lib/python3.11/site-packages/pluggy/_hooks.py", line 265, in __call__
    return self._hookexec(self.name, self.get_hookimpls(), kwargs, firstresult)
  File "/home/richard/bimmer_connected/venv3.11/lib/python3.11/site-packages/pluggy/_manager.py", line 80, in _hookexec
    return self._inner_hookexec(hook_name, methods, kwargs, firstresult)
  File "/home/richard/bimmer_connected/venv3.11/lib/python3.11/site-packages/pluggy/_callers.py", line 39, in _multicall
    res = hook_impl.function(*args)
  File "/home/richard/bimmer_connected/venv3.11/lib/python3.11/site-packages/_pytest/runner.py", line 169, in pytest_runtest_call
    item.runtest()
  File "/home/richard/bimmer_connected/venv3.11/lib/python3.11/site-packages/_pytest/python.py", line 1792, in runtest
    self.ihook.pytest_pyfunc_call(pyfuncitem=self)
  File "/home/richard/bimmer_connected/venv3.11/lib/python3.11/site-packages/pluggy/_hooks.py", line 265, in __call__
    return self._hookexec(self.name, self.get_hookimpls(), kwargs, firstresult)
  File "/home/richard/bimmer_connected/venv3.11/lib/python3.11/site-packages/pluggy/_manager.py", line 80, in _hookexec
    return self._inner_hookexec(hook_name, methods, kwargs, firstresult)
  File "/home/richard/bimmer_connected/venv3.11/lib/python3.11/site-packages/pluggy/_callers.py", line 39, in _multicall
    res = hook_impl.function(*args)
  File "/home/richard/bimmer_connected/venv3.11/lib/python3.11/site-packages/_pytest/python.py", line 194, in pytest_pyfunc_call
    result = testfunction(**testargs)
  File "/home/richard/bimmer_connected/venv3.11/lib/python3.11/site-packages/pytest_asyncio/plugin.py", line 530, in inner
    task = asyncio.ensure_future(coro, loop=_loop)
  File "/usr/local/lib/python3.11/asyncio/tasks.py", line 649, in ensure_future
    return _ensure_future(coro_or_future, loop=loop)
  File "/usr/local/lib/python3.11/asyncio/tasks.py", line 670, in _ensure_future
    return loop.create_task(coro_or_future)
task: <Task pending name='Task-13' coro=<test_get_remote_position_too_old() done, defined at /home/richard/bimmer_connected/venv3.11/lib/python3.11/site-packages/time_machine/__init__.py:323> wait_for=<Future pending cb=[Task.task_wakeup()] created at /usr/local/lib/python3.11/asyncio/base_events.py:427> created at /usr/local/lib/python3.11/asyncio/tasks.py:670>
(venv3.11) richard@RICHARD-PC:~/bimmer_connected$

[adamchainz]

It sounds like you have some test pollution, where one test affects this one. The detect-test-pollution tool could help. Without a project to test on myself, I can’t be much more help.

[rikroe]

Appreciate your help, many thanks! You're right, there seems to be a test pollution (thanks for the hint to detect-test-pollution!):

task: <Task pending name='Task-2' coro=<test_get_remote_position_too_old() done, defined at /home/richard/bimmer_connected/venv3.9/lib/python3.9/site-packages/time_machine/__init__.py:323> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7f13ca9057f0>()]>>
-> the polluting test is: bimmer_connected/tests/test_remote_services.py::test_fail_with_timeout

The test case test_fail_with_timeout() seems to be polluting test_get_remote_position_too_old().

However I don't understand why it is working perfectly with 2.12.0 and not working with 2.13.0.

To reproduce you should be able to use the repo:

git clone https://github.com/bimmerconnected/bimmer_connected.git
pip install -r requirements.txt -r requirements-text.txt
pip install -e .
export PYTEST_TIMEOUT=10

# this works
python3 -m pytest bimmer_connected/tests/

# this doesn't work anymore
pip install time-machine==2.13.0
python3 -m pytest bimmer_connected/tests/

[stanevicius1]

same problem with python 3.11.5 and 2.13.0 time-machine

[jabesq]

Same problem here, looks like it fails to get out asyncio method

[mtomilov]

Can confirm and I'm testing on just one test id.
Will try to come up with a minimal example but have a feeling that it's coming from base_events.py.
I get that we want to move monotonic times too but it seems to be getting in the way of event loop.

thinking out loud
We've been using tick=False in our tests and in the hindsight that might've been not the best idea. So either sticking to 2.12.0 or making our tests tick in the right places are the options at hand?
And time_machine not affecting the loop before wasn't intentional?

[natanael-silvamt]

Same problem with python 3.11.1 and 2.13.0 time-machine.

[robsdedude]

This problem got fixed (but the fix is not yet released) in freezegun: spulec/freezegun#470

So maybe inspiration can bet taken from there.

[llucax]

We are also experiencing freezes on some tests that prevents us from upgrading. In our case, we are using also async-solipsism to test async code, which messes up with the monotonic clock.

Since time-machine also started intercepting the monotonic clock in 2.12.0 (and we are using the option to not let the clock tick automatically), I assumed that was the issue (async-solipsism never firing any events in the event loop because the monotonic clock doesn't move) .

I didn't have the time to investigate yet. But now that I see other people are experiencing freezes, I wonder if that's really the issue.

I guess there is no test and no guarantees that time-machine plays nicely with async-solipsism, right? Both utilities complement themself pretty nicely, so it would be good if they can be used together.

[RobMcKiernan]

Same issue here on Python 3.11.1 with my async tests.
time-machine 2.12.0 works fine, but 2.13.0 with tick=False causes my tests to hang.

[marcinsulikowski]

This problem got fixed (but the fix is not yet released) in freezegun: spulec/freezegun#470

I was responsible for the changes in freezegun fix but I think I changed my mind about the issue since then :). The more I was using libraries like time-machine or freezegun in tests of asyncio code, the more I am leaning towards the conclusion that tick=False is simply never going to work when testing any non-trivial asyncio code. The problem is that even though the developer who uses that mode would like their tested code to see the frozen time, there are still things that rely on correctly working monotocnic clocks, like the asyncio event loop. When the tested code and the asyncio event loop use the same clock routines, it's not possible to make both work at the same time. tick=False with monotonic clocks affected by it works only when testing very simple code.

tick=False works in more cases when monotonic clocks are left unpatched, so that asynctio event loop continues to work in a predictable way (which is the v2.12.0 behavior), but IMO patching all clocks but not freezeing them completely is generally going to cause less problems overall, and work in even more cases.

[llucax]

Maybe the best compromise is to have an option to decide if one wants to patch the monotonic clock or not.

[tamird]

Hey this is a pretty big show stopper - my tests run fine locally but hang in Github Actions. Can we make mocking the monotonic clock optional?