Repository navigation
Intermittent CI failures in test_local.py on PyPy #379
Description
As originally tracked in #200, we've been seeing an intermittent freeze in test_local.py on PyPy:
-
2017-06-16: happened on PyPy nightly but didn't save logs; failed to reproduce locally
-
2017-09-07 on PyPy 5.8 in
test_run_local_simultaneous_runs: https://travis-ci.org/python-trio/trio/jobs/272763511 -
2017-12-20 on PyPy nightly in
test_run_local_simultaneous_runs: https://travis-ci.org/python-trio/trio/jobs/319497598
The test uses threads + blocking queue operations to control sequencing, so it's the sort of thing where you're not shocked to see some weird little freeze, but after staring at it for a while I can't see any bug in the test itself.
Activity
Enable pytest-faulthandler
njsmith commentedon Feb 14, 2018
Here's another one, on PyPy 5.8 in
test_run_local_simultaneous_runs: https://travis-ci.org/python-trio/trio/jobs/341367598I'll paste the key bits below in case something happens to the Travis log:
So we see two threads both blocked in
get. Unfortunately the line numbers intest_local.pyjust refer to thedef test_run_local_simultaneous_runsand theasync def mainlines – there's no information on which call togetis blocked.The weird thing though is that there are only two threads there: the main thread and one other. We ought to have 3 threads: the main thread and two others. We can't tell which of the two workers is missing, but if it's the one the test calls
t1, then it would explain the lockup:t2waits for the main thread, the main thread waits fort1, and... ift1is missing that's a deadlock.One possibility is that
t1is somehow crashing with an exception, but pytest is hiding the traceback.njsmith commentedon Feb 15, 2018
Here's another fun example – pypy nightly this time, and faulthandler segfaults instead of printing a backtrace: https://travis-ci.org/python-trio/trio/jobs/341720284
I managed to reproduce it once locally, by running
I wasn't able to get much debugging info out, but when I hit control-C, it printed a backtrace claiming that it was actually stuck at:
which I guess doesn't say much useful – that's what would happen e.g. if
t2somehow disappeared.Rework test_run_local_simultaneous_runs to be more reliable
njsmith commentedon Feb 15, 2018
As usual, I feel very silly after having found it.
Trick to tracking it down: for whatever reason, this time I was able to reproduce it by running
pytestin a loop (specifically:for X in $(seq 1000000); do echo $X; ~/pypy/pypy3.5-5.8-beta-linux_x86_64-portable/bin/pypy3.5 -u -m pytest -vs trio -k test_run_local_simultaneous_runs; done, which would freeze after maybe 50 iterations). And then I added a bunch of print statements, and immediately went wtf, because the threads weren't executing in the order I expected at all, on any of the executions, including the ones that passed. (This is a test where we have threads but we manually control the scheduling in a very strict way... or so I thought.) And then the issue became obvious.In the process I noticed that the test was written in a very fragile way, because we don't have a nursery abstraction for threads. Maybe it would be worth rewriting that test using a parent trio + two
run_sync_in_worker_threadcalls that each invoke their own trio, just for that? Probably the work needed to control the sequencing after that is too annoying to be worthwhile though (currently it involves both threads making blocking calls, which will also mess up the nice trio properties).pquentin commentedon Feb 15, 2018
I can't comment on the trio/run_sync_in_worker_thread rewrite, but I wanted to know: are we going to keep this test after #420 is done?
njsmith commentedon Feb 15, 2018
Yeah. The details will change because we'll probably replace
RunLocalwith some kind ofRunContextVar, but the same thing still needs to be tested for.