getting failures on slower machines since 3.3.0 release

[zzzeek]

hi -

i dont have a local reproducer here but since pytest-xdist 3.3.0 was released SQLAlchemy is seeing failures on github action nodes that use the virtualized "arm64" architecture - example failures:

https://github.com/sqlalchemy/sqlalchemy/actions/runs/4962771769/jobs/8881240949

https://github.com/sqlalchemy/sqlalchemy/actions/runs/4964655654/jobs/8884945438

https://github.com/sqlalchemy/sqlalchemy/actions/runs/4973604221/jobs/8899553346

stack traces look like this:

=========================== sqlalchemy installation ============================
SQLAlchemy 2.0.14 (no user site)
Path: /github/workspace/.tox/github-nocext/lib/python3.10/site-packages/sqlalchemy/__init__.py
compiled extension not enabled; cannot import name 'collections' from 'sqlalchemy.cyextension' (/github/workspace/.tox/github-nocext/lib/python3.10/site-packages/sqlalchemy/cyextension/__init__.py)
============================= test session starts ==============================
platform linux -- Python 3.10.11, pytest-7.3.1, pluggy-1.0.0
cachedir: .tox/github-nocext/.pytest_cache
rootdir: /github/workspace
configfile: pyproject.toml
plugins: xdist-3.3.0
created: 2/2 workers
INTERNALERROR> def worker_internal_error(self, node, formatted_error):
INTERNALERROR>         """
INTERNALERROR>         pytest_internalerror() was called on the worker.
INTERNALERROR>     
INTERNALERROR>         pytest_internalerror() arguments are an excinfo and an excrepr, which can't
INTERNALERROR>         be serialized, so we go with a poor man's solution of raising an exception
INTERNALERROR>         here ourselves using the formatted message.
INTERNALERROR>         """
INTERNALERROR>         self._active_nodes.remove(node)
INTERNALERROR>         try:
INTERNALERROR> >           assert False, formatted_error
INTERNALERROR> E           AssertionError: Traceback (most recent call last):
INTERNALERROR> E               File "/github/workspace/.tox/github-nocext/lib/python3.10/site-packages/sqlalchemy/util/_concurrency_py3k.py", line 259, in get_event_loop
INTERNALERROR> E                 return asyncio.get_running_loop()
INTERNALERROR> E             RuntimeError: no running event loop
INTERNALERROR> E             
INTERNALERROR> E             During handling of the above exception, another exception occurred:
INTERNALERROR> E             
INTERNALERROR> E             Traceback (most recent call last):
INTERNALERROR> E               File "/github/workspace/.tox/github-nocext/lib/python3.10/site-packages/_pytest/main.py", line 267, in wrap_session
INTERNALERROR> E                 config.hook.pytest_sessionstart(session=session)
INTERNALERROR> E               File "/github/workspace/.tox/github-nocext/lib/python3.10/site-packages/pluggy/_hooks.py", line 265, in __call__
INTERNALERROR> E                 return self._hookexec(self.name, self.get_hookimpls(), kwargs, firstresult)
INTERNALERROR> E               File "/github/workspace/.tox/github-nocext/lib/python3.10/site-packages/pluggy/_manager.py", line 80, in _hookexec
INTERNALERROR> E                 return self._inner_hookexec(hook_name, methods, kwargs, firstresult)
INTERNALERROR> E               File "/github/workspace/.tox/github-nocext/lib/python3.10/site-packages/pluggy/_callers.py", line 60, in _multicall
INTERNALERROR> E                 return outcome.get_result()
INTERNALERROR> E               File "/github/workspace/.tox/github-nocext/lib/python3.10/site-packages/pluggy/_result.py", line 60, in get_result
INTERNALERROR> E                 raise ex[1].with_traceback(ex[2])
INTERNALERROR> E               File "/github/workspace/.tox/github-nocext/lib/python3.10/site-packages/pluggy/_callers.py", line 39, in _multicall
INTERNALERROR> E                 res = hook_impl.function(*args)
INTERNALERROR> E               File "/github/workspace/test/../lib/sqlalchemy/testing/plugin/pytestplugin.py", line 163, in pytest_sessionstart
INTERNALERROR> E                 asyncio._assume_async(plugin_base.post_begin)
INTERNALERROR> E               File "/github/workspace/.tox/github-nocext/lib/python3.10/site-packages/sqlalchemy/testing/asyncio.py", line 53, in _assume_async
INTERNALERROR> E                 return _util_async_run(fn, *args, **kwargs)
INTERNALERROR> E               File "/github/workspace/.tox/github-nocext/lib/python3.10/site-packages/sqlalchemy/util/_concurrency_py3k.py", line 243, in _util_async_run
INTERNALERROR> E                 loop = get_event_loop()
INTERNALERROR> E               File "/github/workspace/.tox/github-nocext/lib/python3.10/site-packages/sqlalchemy/util/_concurrency_py3k.py", line 261, in get_event_loop
INTERNALERROR> E                 return asyncio.get_event_loop_policy().get_event_loop()
INTERNALERROR> E               File "/opt/_internal/cpython-3.10.11/lib/python3.10/asyncio/events.py", line 656, in get_event_loop
INTERNALERROR> E                 raise RuntimeError('There is no current event loop in thread %r.'
INTERNALERROR> E             RuntimeError: There is no current event loop in thread 'Dummy-1'.
INTERNALERROR> E           assert False
INTERNALERROR> 
INTERNALERROR> .tox/github-nocext/lib/python3.10/site-packages/xdist/dsession.py:197: AssertionError
[gw1] node down: Not properly terminated

replacing crashed worker gw1
INTERNALERROR> Traceback (most recent call last):
INTERNALERROR>   File "/github/workspace/.tox/github-nocext/lib/python3.10/site-packages/_pytest/main.py", line 269, in wrap_session
INTERNALERROR>     session.exitstatus = doit(config, session) or 0
INTERNALERROR>   File "/github/workspace/.tox/github-nocext/lib/python3.10/site-packages/_pytest/main.py", line 323, in _main
INTERNALERROR>     config.hook.pytest_runtestloop(session=session)
INTERNALERROR>   File "/github/workspace/.tox/github-nocext/lib/python3.10/site-packages/pluggy/_hooks.py", line 265, in __call__
INTERNALERROR>     return self._hookexec(self.name, self.get_hookimpls(), kwargs, firstresult)
INTERNALERROR>   File "/github/workspace/.tox/github-nocext/lib/python3.10/site-packages/pluggy/_manager.py", line 80, in _hookexec
INTERNALERROR>     return self._inner_hookexec(hook_name, methods, kwargs, firstresult)
INTERNALERROR>   File "/github/workspace/.tox/github-nocext/lib/python3.10/site-packages/pluggy/_callers.py", line 60, in _multicall
INTERNALERROR>     return outcome.get_result()
INTERNALERROR>   File "/github/workspace/.tox/github-nocext/lib/python3.10/site-packages/pluggy/_result.py", line 60, in get_result
INTERNALERROR>     raise ex[1].with_traceback(ex[2])
INTERNALERROR>   File "/github/workspace/.tox/github-nocext/lib/python3.10/site-packages/pluggy/_callers.py", line 39, in _multicall
INTERNALERROR>     res = hook_impl.function(*args)
INTERNALERROR>   File "/github/workspace/.tox/github-nocext/lib/python3.10/site-packages/xdist/dsession.py", line 122, in pytest_runtestloop
INTERNALERROR>     self.loop_once()
INTERNALERROR>   File "/github/workspace/.tox/github-nocext/lib/python3.10/site-packages/xdist/dsession.py", line 145, in loop_once
INTERNALERROR>     call(**kwargs)
INTERNALERROR>   File "/github/workspace/.tox/github-nocext/lib/python3.10/site-packages/xdist/dsession.py", line 235, in worker_errordown
INTERNALERROR>     self._active_nodes.remove(node)
INTERNALERROR> KeyError: <WorkerController gw1>

[zzzeek]

now obviously this involves our own code and such and it's not clear where the problem is, but it seems the 3.3.0 release was the catalyst. cc @CaselIT

[zzzeek]

I think what's strange here is that pytest_sessionstart seems to be getting called in a thread that is not "MainThread", it's an arbitrary thread "Dummy-1" or something, and there's no event loop there. This does not happen if I try to reproduce locally though, pytest_sessionstart is called in the main thread up front and there's an event loop.

is pytest_sessionstart called within the workers or before the workers are spun up?

[CaselIT]

seems somewhat connected to this issue #620

still the issue here is also that the failed worker cannot be cleaned up and replaced

[nicoddemus]

Hey folks,

About this failing only in 3.3.0, that's really strange, because the changes from 3.2.1 to 3.3.0 were just to the collection report, which only changed how we display the collection information, but not really changed anything related to communication to workers:

v3.2.1...v3.3.0

As for the failure, it does seem like a known execnet bug: pytest-dev/execnet#96, which got improved by pytest-dev/execnet#118, but other folks still report the same problem even after updating to execnet-1.8.0 (in #620, as @CaselIT mentioned) .

I also see that you are using execnet 1.9.0...

[CaselIT]

I've also looked at changes and I too found it very strange, but it seems fairly consistent, since after adding a constraint !=3.3.0 the test stopped failing.

The fails is fairly consistent but it's only happening on the arm builds. The only difference that they have is that they are quite a bit slower than the normal builds since they run under emulation.

Is is possible that the changes in 3.3.0 made reporting a bit slower and that surfaced a race condition or other timing related issue in xdist? It's still strange that a thread would be created randomly though,

[nicoddemus]

Is is possible that the changes in 3.3.0 made reporting a bit slower and that surfaced a race condition or other timing related issue in xdist? It's still strange that a thread would be created randomly though,

I can't think of other explanation for that, however the "refresh rate" is the same as before, in fact we even write a few less characters now at each update. 🤔

[nicoddemus]

Ahh found a difference which might have impacted this some how:

Previously we would only ask for the "remote information" only if verbosity > 0 (default is 0):

    @pytest.hookimpl
    def pytest_xdist_newgateway(self, gateway):
        if self.config.option.verbose > 0:
            rinfo = gateway._rinfo()

But now the information is asked even with verbosity==0:

    @pytest.hookimpl
    def pytest_xdist_newgateway(self, gateway) -> None:
        rinfo = gateway._rinfo()
        is_local = rinfo.executable == sys.executable
        if self.config.option.verbose > 0 and not is_local:

Can you folks try to run with -q and see if this resolves the problem? If it does, this might be causing it. I will be happy to make a new releasing changing this to only get the remote info if needed.

However it definitely is still a bug with execnet, it seems.

[zzzeek]

we're already running with -q, this is our commandline:

python -m pytest -n2 -m 'not memory_intensive and not mypy' -q --nomemory --notimingintensive

our plugin adds those additional two flags

[zzzeek]

also it would be good if the whole issue could be fixed, not just a workaround that gets less info, should we post an issue w/ execnet?

[nicoddemus]

also it would be good if the whole issue could be fixed, not just a workaround that gets less info, should we post an issue w/ execnet?

Definitely, I'm thinking of a workaround because this is a known issue with execnet (pytest-dev/execnet#96) which has been open for years and nobody found a solution so far. 😞

[zzzeek]

weird !

[david-engelmann]

I'm having this issue in my pipelines as well, changing to pip install pytest-xdist==3.2.1 for now

[nicoddemus]

@david-engelmann the exact same traceback?