(via xdist) Intermittently ending up on non-main thread

[boxed]

This issue has been plaguing us for months since we started using xdist. We have a big test suite that extremely rarely fails with ValueError: signal only works in main thread. I have managed to get the full traceback of all threads in a normal run and in this case where it crashes.

Normal:

Thread 0x000070000fd66000 (most recent call first):
 File "/Users/andersh/triresolve/venv/lib/python3.6/site-packages/kazoo/handlers/threading.py", line 192 in _select
 File "/Users/andersh/triresolve/venv/lib/python3.6/site-packages/kazoo/handlers/threading.py", line 178 in select
 File "/Users/andersh/triresolve/venv/lib/python3.6/site-packages/kazoo/protocol/connection.py", line 553 in _connect_attempt
 File "/Users/andersh/triresolve/venv/lib/python3.6/site-packages/kazoo/protocol/connection.py", line 512 in _connect_loop
 File "/Users/andersh/triresolve/venv/lib/python3.6/site-packages/kazoo/retry.py", line 124 in __call__
 File "/Users/andersh/triresolve/venv/lib/python3.6/site-packages/kazoo/protocol/connection.py", line 473 in zk_loop
 File "/usr/local/Cellar/python@3.6.5/3.6.5_1/Frameworks/Python.framework/Versions/3.6/lib/python3.6/threading.py", line 864 in run
 File "/usr/local/Cellar/python@3.6.5/3.6.5_1/Frameworks/Python.framework/Versions/3.6/lib/python3.6/threading.py", line 916 in _bootstrap_inner
 File "/usr/local/Cellar/python@3.6.5/3.6.5_1/Frameworks/Python.framework/Versions/3.6/lib/python3.6/threading.py", line 884 in _bootstrap

Thread 0x000070000f863000 (most recent call first):
 File "/usr/local/Cellar/python@3.6.5/3.6.5_1/Frameworks/Python.framework/Versions/3.6/lib/python3.6/threading.py", line 295 in wait
 File "/usr/local/Cellar/python@3.6.5/3.6.5_1/Frameworks/Python.framework/Versions/3.6/lib/python3.6/queue.py", line 164 in get
 File "/Users/andersh/triresolve/venv/lib/python3.6/site-packages/kazoo/handlers/threading.py", line 120 in _thread_worker
 File "/usr/local/Cellar/python@3.6.5/3.6.5_1/Frameworks/Python.framework/Versions/3.6/lib/python3.6/threading.py", line 864 in run
 File "/usr/local/Cellar/python@3.6.5/3.6.5_1/Frameworks/Python.framework/Versions/3.6/lib/python3.6/threading.py", line 916 in _bootstrap_inner
 File "/usr/local/Cellar/python@3.6.5/3.6.5_1/Frameworks/Python.framework/Versions/3.6/lib/python3.6/threading.py", line 884 in _bootstrap

Thread 0x000070000f360000 (most recent call first):
 File "/usr/local/Cellar/python@3.6.5/3.6.5_1/Frameworks/Python.framework/Versions/3.6/lib/python3.6/threading.py", line 295 in wait
 File "/usr/local/Cellar/python@3.6.5/3.6.5_1/Frameworks/Python.framework/Versions/3.6/lib/python3.6/queue.py", line 164 in get
 File "/Users/andersh/triresolve/venv/lib/python3.6/site-packages/kazoo/handlers/threading.py", line 120 in _thread_worker
 File "/usr/local/Cellar/python@3.6.5/3.6.5_1/Frameworks/Python.framework/Versions/3.6/lib/python3.6/threading.py", line 864 in run
 File "/usr/local/Cellar/python@3.6.5/3.6.5_1/Frameworks/Python.framework/Versions/3.6/lib/python3.6/threading.py", line 916 in _bootstrap_inner
 File "/usr/local/Cellar/python@3.6.5/3.6.5_1/Frameworks/Python.framework/Versions/3.6/lib/python3.6/threading.py", line 884 in _bootstrap

Thread 0x000070000ee5d000 (most recent call first):
 File "/Users/andersh/triresolve/venv/lib/python3.6/site-packages/execnet/gateway_base.py", line 386 in read
 File "/Users/andersh/triresolve/venv/lib/python3.6/site-packages/execnet/gateway_base.py", line 418 in from_io
 File "/Users/andersh/triresolve/venv/lib/python3.6/site-packages/execnet/gateway_base.py", line 954 in _thread_receiver
 File "/Users/andersh/triresolve/venv/lib/python3.6/site-packages/execnet/gateway_base.py", line 213 in run
 File "/Users/andersh/triresolve/venv/lib/python3.6/site-packages/execnet/gateway_base.py", line 277 in _perform_spawn

Current thread 0x000000011088f5c0 (most recent call first):
 File "/Users/andersh/triresolve/triresolve/matcher/matcher.py", line 1128 in go
 File "/Users/andersh/triresolve/triresolve/matcher/matcher.py", line 3717 in match
 File "/Users/andersh/triresolve/triresolve/matcher/cmdline.py", line 58 in update_match_view
 File "/Users/andersh/triresolve/triresolve/matcher/test/integrationtest/test_3w_linking.py", line 304 in run_end_to_end_3w_linking_one_to_one
 File "/Users/andersh/triresolve/triresolve/matcher/test/integrationtest/test_3w_linking.py", line 271 in test_end_to_end_3w_linking_one_to_one_normal_rec_trades_on_sub_entity
 File "/Users/andersh/triresolve/venv/lib/python3.6/site-packages/_pytest/python.py", line 166 in pytest_pyfunc_call
 File "/Users/andersh/triresolve/venv/lib/python3.6/site-packages/pluggy/callers.py", line 187 in _multicall
 File "/Users/andersh/triresolve/venv/lib/python3.6/site-packages/pluggy/manager.py", line 61 in <lambda>
 File "/Users/andersh/triresolve/venv/lib/python3.6/site-packages/pluggy/manager.py", line 67 in _hookexec
 File "/Users/andersh/triresolve/venv/lib/python3.6/site-packages/pluggy/hooks.py", line 284 in __call__
 File "/Users/andersh/triresolve/venv/lib/python3.6/site-packages/_pytest/python.py", line 1425 in runtest
 File "/Users/andersh/triresolve/venv/lib/python3.6/site-packages/_pytest/runner.py", line 122 in pytest_runtest_call
 File "/Users/andersh/triresolve/venv/lib/python3.6/site-packages/pluggy/callers.py", line 187 in _multicall
 File "/Users/andersh/triresolve/venv/lib/python3.6/site-packages/pluggy/manager.py", line 61 in <lambda>
 File "/Users/andersh/triresolve/venv/lib/python3.6/site-packages/pluggy/manager.py", line 67 in _hookexec
 File "/Users/andersh/triresolve/venv/lib/python3.6/site-packages/pluggy/hooks.py", line 284 in __call__
 File "/Users/andersh/triresolve/venv/lib/python3.6/site-packages/_pytest/runner.py", line 194 in <lambda>
 File "/Users/andersh/triresolve/venv/lib/python3.6/site-packages/_pytest/runner.py", line 212 in __init__
 File "/Users/andersh/triresolve/venv/lib/python3.6/site-packages/_pytest/runner.py", line 196 in call_runtest_hook
 File "/Users/andersh/triresolve/venv/lib/python3.6/site-packages/_pytest/runner.py", line 172 in call_and_report
 File "/Users/andersh/triresolve/venv/lib/python3.6/site-packages/_pytest/runner.py", line 92 in runtestprotocol
 File "/Users/andersh/triresolve/venv/lib/python3.6/site-packages/_pytest/runner.py", line 77 in pytest_runtest_protocol
 File "/Users/andersh/triresolve/venv/lib/python3.6/site-packages/pluggy/callers.py", line 187 in _multicall
 File "/Users/andersh/triresolve/venv/lib/python3.6/site-packages/pluggy/manager.py", line 61 in <lambda>
 File "/Users/andersh/triresolve/venv/lib/python3.6/site-packages/pluggy/manager.py", line 67 in _hookexec
 File "/Users/andersh/triresolve/venv/lib/python3.6/site-packages/pluggy/hooks.py", line 284 in __call__
 File "<remote exec>", line 83 in run_one_test
 File "<remote exec>", line 69 in pytest_runtestloop
 File "/Users/andersh/triresolve/venv/lib/python3.6/site-packages/pluggy/callers.py", line 187 in _multicall
 File "/Users/andersh/triresolve/venv/lib/python3.6/site-packages/pluggy/manager.py", line 61 in <lambda>
 File "/Users/andersh/triresolve/venv/lib/python3.6/site-packages/pluggy/manager.py", line 67 in _hookexec
 File "/Users/andersh/triresolve/venv/lib/python3.6/site-packages/pluggy/hooks.py", line 284 in __call__
 File "/Users/andersh/triresolve/venv/lib/python3.6/site-packages/_pytest/main.py", line 225 in _main
 File "/Users/andersh/triresolve/venv/lib/python3.6/site-packages/_pytest/main.py", line 185 in wrap_session
 File "/Users/andersh/triresolve/venv/lib/python3.6/site-packages/_pytest/main.py", line 218 in pytest_cmdline_main
 File "/Users/andersh/triresolve/venv/lib/python3.6/site-packages/pluggy/callers.py", line 187 in _multicall
 File "/Users/andersh/triresolve/venv/lib/python3.6/site-packages/pluggy/manager.py", line 61 in <lambda>
 File "/Users/andersh/triresolve/venv/lib/python3.6/site-packages/pluggy/manager.py", line 67 in _hookexec
 File "/Users/andersh/triresolve/venv/lib/python3.6/site-packages/pluggy/hooks.py", line 284 in __call__
 File "<remote exec>", line 270 in <module>
 File "<string>", line 1 in do_exec
 File "/Users/andersh/triresolve/venv/lib/python3.6/site-packages/execnet/gateway_base.py", line 1072 in executetask
 File "/Users/andersh/triresolve/venv/lib/python3.6/site-packages/execnet/gateway_base.py", line 213 in run
 File "/Users/andersh/triresolve/venv/lib/python3.6/site-packages/execnet/gateway_base.py", line 277 in _perform_spawn
 File "/Users/andersh/triresolve/venv/lib/python3.6/site-packages/execnet/gateway_base.py", line 259 in integrate_as_primary_thread
 File "/Users/andersh/triresolve/venv/lib/python3.6/site-packages/execnet/gateway_base.py", line 1047 in serve
 File "/Users/andersh/triresolve/venv/lib/python3.6/site-packages/execnet/gateway_base.py", line 1534 in serve
 File "<string>", line 8 in <module>
 File "<string>", line 1 in <module>

Incorrect:

Thread 0x00007fc9108ba700 (most recent call first)://
 File "/tmp/venv/lib/python3.6/site-packages/kazoo/handlers/threading.py", line 192 in _select//
 File "/tmp/venv/lib/python3.6/site-packages/kazoo/handlers/threading.py", line 178 in select//
 File "/tmp/venv/lib/python3.6/site-packages/kazoo/protocol/connection.py", line 553 in _connect_attempt//
 File "/tmp/venv/lib/python3.6/site-packages/kazoo/protocol/connection.py", line 512 in _connect_loop//
 File "/tmp/venv/lib/python3.6/site-packages/kazoo/retry.py", line 124 in __call__//
 File "/tmp/venv/lib/python3.6/site-packages/kazoo/protocol/connection.py", line 473 in zk_loop//
 File "/usr/lib64/python3.6/threading.py", line 864 in run//
 File "/usr/lib64/python3.6/threading.py", line 916 in _bootstrap_inner//
 File "/usr/lib64/python3.6/threading.py", line 884 in _bootstrap

Thread 0x00007fc9110bb700 (most recent call first)://
 File "/usr/lib64/python3.6/threading.py", line 295 in wait//
 File "/usr/lib64/python3.6/queue.py", line 164 in get//
 File "/tmp/venv/lib/python3.6/site-packages/kazoo/handlers/threading.py", line 120 in _thread_worker//
 File "/usr/lib64/python3.6/threading.py", line 864 in run//
 File "/usr/lib64/python3.6/threading.py", line 916 in _bootstrap_inner//
 File "/usr/lib64/python3.6/threading.py", line 884 in _bootstrap

Thread 0x00007fc9118bc700 (most recent call first)://
 File "/usr/lib64/python3.6/threading.py", line 295 in wait//
 File "/usr/lib64/python3.6/queue.py", line 164 in get//
 File "/tmp/venv/lib/python3.6/site-packages/kazoo/handlers/threading.py", line 120 in _thread_worker//
 File "/usr/lib64/python3.6/threading.py", line 864 in run//
 File "/usr/lib64/python3.6/threading.py", line 916 in _bootstrap_inner//
 File "/usr/lib64/python3.6/threading.py", line 884 in _bootstrap

Thread 0x00007fc912ffd700 (most recent call first)://
 File "/usr/lib64/python3.6/threading.py", line 295 in wait//
 File "/usr/lib64/python3.6/queue.py", line 164 in get//
 File "/usr/lib64/python3.6/concurrent/futures/thread.py", line 67 in _worker//
 File "/usr/lib64/python3.6/threading.py", line 864 in run//
 File "/usr/lib64/python3.6/threading.py", line 916 in _bootstrap_inner//
 File "/usr/lib64/python3.6/threading.py", line 884 in _bootstrap

Thread 0x00007fc9137fe700 (most recent call first)://
 File "/usr/lib64/python3.6/threading.py", line 295 in wait//
 File "/usr/lib64/python3.6/queue.py", line 164 in get//
 File "/usr/lib64/python3.6/concurrent/futures/thread.py", line 67 in _worker//
 File "/usr/lib64/python3.6/threading.py", line 864 in run//
 File "/usr/lib64/python3.6/threading.py", line 916 in _bootstrap_inner//
 File "/usr/lib64/python3.6/threading.py", line 884 in _bootstrap

Thread 0x00007fc913fff700 (most recent call first)://
 File "/usr/lib64/python3.6/threading.py", line 299 in wait//
 File "/usr/lib64/python3.6/threading.py", line 551 in wait//
 File "/usr/lib64/python3.6/threading.py", line 916 in _bootstrap_inner//
 File "/usr/lib64/python3.6/threading.py", line 884 in _bootstrap

Thread 0x00007fc918d1e700 (most recent call first)://
 File "/usr/lib64/python3.6/asyncore.py", line 183 in poll2//
 File "/usr/lib64/python3.6/asyncore.py", line 207 in loop//
 File "/tmp/venv/lib/python3.6/site-packages/cassandra/io/asyncorereactor.py", line 119 in loop//
 File "/tmp/venv/lib/python3.6/site-packages/cassandra/io/asyncorereactor.py", line 258 in _run_loop//
 File "/usr/lib64/python3.6/threading.py", line 864 in run//
 File "/usr/lib64/python3.6/threading.py", line 916 in _bootstrap_inner//
 File "/usr/lib64/python3.6/threading.py", line 884 in _bootstrap

Thread 0x00007fc921a79700 (most recent call first)://
 File "/usr/lib64/python3.6/threading.py", line 295 in wait//
 File "/usr/lib64/python3.6/queue.py", line 164 in get//
 File "/usr/lib64/python3.6/threading.py", line 916 in _bootstrap_inner//
 File "/usr/lib64/python3.6/threading.py", line 884 in _bootstrap

Current thread 0x00007fc94637f700 (most recent call first)://
 File "/opt/trioptima/triresolve/triresolve/matcher/matcher.py", line 1124 in go//
 File "/opt/trioptima/triresolve/triresolve/matcher/matcher.py", line 3713 in match//
 File "/opt/trioptima/triresolve/triresolve/matcher/cmdline.py", line 58 in update_match_view//
 File "/opt/trioptima/triresolve/triresolve/matcher/test/integrationtest/test_3w_linking.py", line 304 in run_end_to_end_3w_linking_one_to_one
 File "/opt/trioptima/triresolve/triresolve/matcher/test/integrationtest/test_3w_linking.py", line 271 in// test_end_to_end_3w_linking_one_to_one_normal_rec_trades_on_sub_entity//
 File "/tmp/venv/lib/python3.6/site-packages/_pytest/python.py", line 166 in pytest_pyfunc_call//
 File "/tmp/venv/lib/python3.6/site-packages/pluggy/callers.py", line 187 in _multicall//
 File "/tmp/venv/lib/python3.6/site-packages/pluggy/manager.py", line 61 in <lambda>//
 File "/tmp/venv/lib/python3.6/site-packages/pluggy/manager.py", line 67 in _hookexec//
 File "/tmp/venv/lib/python3.6/site-packages/pluggy/hooks.py", line 284 in __call__//
 File "/tmp/venv/lib/python3.6/site-packages/_pytest/python.py", line 1425 in runtest//
 File "/tmp/venv/lib/python3.6/site-packages/_pytest/runner.py", line 122 in pytest_runtest_call//
 File "/tmp/venv/lib/python3.6/site-packages/pluggy/callers.py", line 187 in _multicall//
 File "/tmp/venv/lib/python3.6/site-packages/pluggy/manager.py", line 61 in <lambda>//
 File "/tmp/venv/lib/python3.6/site-packages/pluggy/manager.py", line 67 in _hookexec//
 File "/tmp/venv/lib/python3.6/site-packages/pluggy/hooks.py", line 284 in __call__//
 File "/tmp/venv/lib/python3.6/site-packages/_pytest/runner.py", line 194 in <lambda>//
 File "/tmp/venv/lib/python3.6/site-packages/_pytest/runner.py", line 212 in __init__//
 File "/tmp/venv/lib/python3.6/site-packages/_pytest/runner.py", line 196 in call_runtest_hook//
 File "/tmp/venv/lib/python3.6/site-packages/_pytest/runner.py", line 172 in call_and_report//
 File "/tmp/venv/lib/python3.6/site-packages/_pytest/runner.py", line 92 in runtestprotocol//
 File "/tmp/venv/lib/python3.6/site-packages/_pytest/runner.py", line 77 in pytest_runtest_protocol//
 File "/tmp/venv/lib/python3.6/site-packages/pluggy/callers.py", line 187 in _multicall//
 File "/tmp/venv/lib/python3.6/site-packages/pluggy/manager.py", line 61 in <lambda>//
 File "/tmp/venv/lib/python3.6/site-packages/pluggy/manager.py", line 67 in _hookexec//
 File "/tmp/venv/lib/python3.6/site-packages/pluggy/hooks.py", line 284 in __call__//
 File "<remote exec>", line 83 in run_one_test//
 File "<remote exec>", line 66 in pytest_runtestloop//
 File "/tmp/venv/lib/python3.6/site-packages/pluggy/callers.py", line 187 in _multicall//
 File "/tmp/venv/lib/python3.6/site-packages/pluggy/manager.py", line 61 in <lambda>//
 File "/tmp/venv/lib/python3.6/site-packages/pluggy/manager.py", line 67 in _hookexec//
 File "/tmp/venv/lib/python3.6/site-packages/pluggy/hooks.py", line 284 in __call__//
 File "/tmp/venv/lib/python3.6/site-packages/_pytest/main.py", line 225 in _main//
 File "/tmp/venv/lib/python3.6/site-packages/_pytest/main.py", line 185 in wrap_session//
 File "/tmp/venv/lib/python3.6/site-packages/_pytest/main.py", line 218 in pytest_cmdline_main//
 File "/tmp/venv/lib/python3.6/site-packages/pluggy/callers.py", line 187 in _multicall//
 File "/tmp/venv/lib/python3.6/site-packages/pluggy/manager.py", line 61 in <lambda>//
 File "/tmp/venv/lib/python3.6/site-packages/pluggy/manager.py", line 67 in _hookexec//
 File "/tmp/venv/lib/python3.6/site-packages/pluggy/hooks.py", line 284 in __call__//
 File "<remote exec>", line 270 in <module>//
 File "<string>", line 1 in do_exec//
 File "/tmp/venv/lib/python3.6/site-packages/execnet/gateway_base.py", line 1072 in executetask//
 File "/tmp/venv/lib/python3.6/site-packages/execnet/gateway_base.py", line 213 in run//
 File "/tmp/venv/lib/python3.6/site-packages/execnet/gateway_base.py", line 277 in _perform_spawn

Thread 0x00007fc946bc0700 (most recent call first)://
 File "/tmp/venv/lib/python3.6/site-packages/execnet/gateway_base.py", line 386 in read//
 File "/tmp/venv/lib/python3.6/site-packages/execnet/gateway_base.py", line 418 in from_io//
 File "/tmp/venv/lib/python3.6/site-packages/execnet/gateway_base.py", line 954 in _thread_receiver//
 File "/tmp/venv/lib/python3.6/site-packages/execnet/gateway_base.py", line 213 in run//
 File "/tmp/venv/lib/python3.6/site-packages/execnet/gateway_base.py", line 277 in _perform_spawn

Thread 0x00007fc9484c0740 (most recent call first)://
 File "/usr/lib64/python3.6/threading.py", line 295 in wait//
 File "/usr/lib64/python3.6/threading.py", line 551 in wait//
 File "/tmp/venv/lib/python3.6/site-packages/execnet/gateway_base.py", line 255 in integrate_as_primary_thread//
 File "/tmp/venv/lib/python3.6/site-packages/execnet/gateway_base.py", line 1047 in serve//
 File "/tmp/venv/lib/python3.6/site-packages/execnet/gateway_base.py", line 1534 in serve//
 File "<string>", line 8 in <module>
 File "<string>", line 1 in <module>mysql strict mode! at least in tests://

Digging through the code it looks to me like _try_send_to_primary_thread fails for some reason, even though we are running in process mode. This is obviously a guess though, as I don't understand this code very well.

Help! :)

[robholt]

I'm having this same issue and I think I figured it out. It happens for me when I add extra environment variables to a spec. If spec.chdir, spec.nice, or spec.env are set it triggers an extra remote_exec before the xdist remote function is run. This can trigger a race in the WorkerPool (where the _try_send_to_primary_thread is). The race is this:

1. The first remote_exec is received. The main thread is not busy so it picks this up
2. Picking it up sets the _primary_thread_task_ready event.
3. The exec completes, and a reply is sent back to the caller. (Note that the event is not unset yet!)
4. The master, having received a reply, continues on and calls remote_exec with the xdist remote module.
5. The worker processes this, and if the _primary_thread_task_ready event has not been unset yet it won't be assigned to the main thread.

The problem lies here:

execnet/execnet/gateway_base.py

Lines 267 to 272 in f923a3e

	self._perform_spawn(reply)
	# we are concurrent with trigger_shutdown and spawn
	with self._running_lock:
	if self._shuttingdown:
	break
	primary_thread_task_ready.clear()

The _perform_spawn method sends the reply back, but the primary_thread_task_ready event is not unset until later, and requires the _running_lock lock to unset it. Processing incoming exec requests also uses the _running_lock lock, and if that thread acquires the lock before the main thread does (so it could unset the event) then the incoming exec is guaranteed to not run on the main thread. I confirmed this by adding time.sleep(1) right after _perform_spawn, with that the issue triggers every time.

I think I know how to fix this, hopefully I will have a PR soon.

[robholt]

This turned out to be a lot more complicated. What really happens is that the master uses the channel closing to indicate the worker is done executing, and that happens well before the WorkerPool sees the main thread as done. Some changes could be made to decrease this gap, but I don't think it could be eliminated without a significant refactor.

I've been testing out the eventlet execmodel and I believe it will eliminate the problem (since everything will run on the main thread) and signals will work. To use it with xdist you can replace -n NUM with --dist=load --tx='NUM*popen//execmodel=eventlet'

[boxed]

Great investigating!

[mattgodbolt]

Hey folks. This is a fairly dormant-looking thread, but I wondered if it might explain a super-intermittant issue we see.

We're using xdist 1.32, and execnet 1.7.1.

In async tests super rarely we get errors saying RuntimeError: There is no current event loop in thread 'Dummy-1' - which I've traced back to the tests not running on the main thread (and thus not having a default event loop). It seems like this is the same issue - a rare case where tests get run on the "wrong" thread.

Would you concur, and do you have any advice for how to work around it? Thanks in advance.

[nicoddemus]

@mattgodbolt please try updating to 1.8.0: #118 seems to tackle exactly that problem.

[nicoddemus]

I just confirmed: before 1.8.0, we would get this an error related to dummy threads a few times per week. Since updating to 1.8.0 in late January, we never got the error again.

Closing this as solved now then. All credits go to @graingert for finding the problem and providing a PR. 👍

[nicoddemus]

Reopening given the problem still persists:

• pytest-xdist breaks asyncio-based code expecting to be run in the main thread pytest-xdist#620
• getting failures on slower machines since 3.3.0 release pytest-xdist#907

[nicoddemus]

I wonder if we can create a new configuration option which would cause the remote worker to never open a new thread for remote execution, always executing them serially in the main thread? I think this would solve the problem, at least for pytest-xdist's use case.

[zzzeek]

yeah why is this spinning up threads, just turning that off would solve the issue we are having