Non-reentrant signal handler (test_multiprocessing_forkserver hangs)

[vstinner]

BPO	30703
Nosy	@ronaldoussoren, @pitrou, @kristjanvalur, @vstinner, @ned-deily, @njsmith, @ericsnowcurrently, @mattbillenstein
PRs	[WIP] bpo-30703: More reentrant signal handler #2408 bpo-30703: Improve signal delivery #2415 [3.6] bpo-30703: Improve signal delivery (GH-2415) #2527 bpo-30854: Fix compile error when --without-threads #2581

^{Note: these values reflect the state of the issue at the time it was migrated and might not reflect the current state.}

Show more details

GitHub fields:

assignee = None
closed_at = <Date 2017-07-01.17:14:23.115>
created_at = <Date 2017-06-19.15:20:56.969>
labels = ['OS-mac', 'type-bug', 'tests', '3.7']
title = 'Non-reentrant signal handler (test_multiprocessing_forkserver hangs)'
updated_at = <Date 2019-03-29.16:08:52.590>
user = 'https://github.com/vstinner'

bugs.python.org fields:

activity = <Date 2019-03-29.16:08:52.590>
actor = 'eric.snow'
assignee = 'none'
closed = True
closed_date = <Date 2017-07-01.17:14:23.115>
closer = 'pitrou'
components = ['macOS', 'Tests']
creation = <Date 2017-06-19.15:20:56.969>
creator = 'vstinner'
dependencies = []
files = []
hgrepos = []
issue_num = 30703
keywords = ['buildbot']
message_count = 25.0
messages = ['296348', '296376', '296419', '296420', '296460', '296641', '296774', '296775', '296777', '296778', '296824', '296876', '296879', '296881', '296895', '296897', '296903', '296905', '297208', '297234', '297361', '297405', '297413', '297418', '297484']
nosy_count = 9.0
nosy_names = ['ronaldoussoren', 'pitrou', 'kristjan.jonsson', 'vstinner', 'ned.deily', 'njs', 'neologix', 'eric.snow', 'mattbillenstein']
pr_nums = ['2408', '2415', '2527', '2581']
priority = 'normal'
resolution = 'fixed'
stage = 'resolved'
status = 'closed'
superseder = None
type = 'behavior'
url = 'https://bugs.python.org/issue30703'
versions = ['Python 3.6', 'Python 3.7']

[vstinner]

regrtest hangs while running test_multiprocessing_forkserver in a worker process on the "x86-64 Sierra 3.x" buildbot.

Bug seen twice: build 343 and 337.

http://buildbot.python.org/all/builders/x86-64%20Sierra%203.x/builds/337/steps/test/logs/stdio

Run tests in parallel using 2 child processes
...
0:29:36 load avg: 5.24 [402/406] test_deque passed -- running: test_multiprocessing_forkserver (1346 sec)
0:29:37 load avg: 5.24 [403/406] test_descrtut passed -- running: test_multiprocessing_forkserver (1346 sec)
0:29:37 load avg: 4.90 [404/406] test_weakset passed -- running: test_multiprocessing_forkserver (1347 sec)
0:29:40 load avg: 4.90 [405/406] test_distutils passed -- running: test_multiprocessing_forkserver (1350 sec)

command timed out: 1200 seconds without output running ['make', 'buildbottest', 'TESTOPTS=-j2', 'TESTPYTHONOPTS=', 'TESTTIMEOUT=900'], attempting to kill
process killed by signal 9
program finished with exit code -1
elapsedTime=2983.908679

[vstinner]

Different issue, but same behaviour: test hangs and then killed by buildbot, whereas a single test was still running.

See also bpo-30351 which tracks similar bugs, but on Python 2.7.

I really hate such bugs :-(

http://buildbot.python.org/all/builders/AMD64%20Debian%20root%203.x/builds/928/steps/test/logs/stdio

...
0:15:10 load avg: 0.52 [404/406] test_unicodedata passed -- running: test_pydoc (401 sec)
0:15:10 load avg: 0.52 [405/406] test_exception_hierarchy passed -- running: test_pydoc (401 sec)

command timed out: 1200 seconds without output running ['make', 'buildbottest', 'TESTOPTS=-j2', 'TESTPYTHONOPTS=', 'TESTTIMEOUT=900'], attempting to kill
process killed by signal 9
program finished with exit code -1
elapsedTime=2111.415970

[mattbillenstein]

I've been debugging this and I can repro on El Capitan on a different machine as well -- it's an infrequent hang, I've been running in a loop:

mattb@mattb-mbp:~/src/misc/cpython master$ for i in $(seq 1000); do echo "Run: $i -- $(date)"; time./python.exe -m test --timeout 180 test_multiprocessing_forkserver || break; sleep 10; done

And in this case after ~30 successful runs:

Run: 31 -- Tue Jun 20 05:12:19 PDT 2017
Run tests sequentially
0:00:00 load avg: 4.28 [1/1] test_multiprocessing_forkserver
Timeout (0:03:00)!
Thread 0x00007fffa1b3a3c0 (most recent call first):
File "/Users/mattb/src/misc/cpython/Lib/selectors.py", line 415 in select
File "/Users/mattb/src/misc/cpython/Lib/multiprocessing/connection.py", line 916 in wait
File "/Users/mattb/src/misc/cpython/Lib/multiprocessing/popen_fork.py", line 45 in wait
File "/Users/mattb/src/misc/cpython/Lib/multiprocessing/process.py", line 121 in join
File "/Users/mattb/src/misc/cpython/Lib/test/test_multiprocessing.py", line 431 in test_many_processes
File "/Users/mattb/src/misc/cpython/Lib/unittest/case.py", line 605 in run
File "/Users/mattb/src/misc/cpython/Lib/unittest/case.py", line 653 in __call_
File "/Users/mattb/src/misc/cpython/Lib/unittest/suite.py", line 122 in run
File "/Users/mattb/src/misc/cpython/Lib/unittest/suite.py", line 84 in __call__
File "/Users/mattb/src/misc/cpython/Lib/unittest/suite.py", line 122 in run
File "/Users/mattb/src/misc/cpython/Lib/unittest/suite.py", line 84 in __call__
File "/Users/mattb/src/misc/cpython/Lib/unittest/suite.py", line 122 in run
File "/Users/mattb/src/misc/cpython/Lib/unittest/suite.py", line 84 in __call__
File "/Users/mattb/src/misc/cpython/Lib/test/support/init.py", line 1772 in run
File "/Users/mattb/src/misc/cpython/Lib/test/support/init.py", line 1896 in _run_suite
File "/Users/mattb/src/misc/cpython/Lib/test/support/init.py", line 1936 in run_unittest
File "/Users/mattb/src/misc/cpython/Lib/test/libregrtest/runtest.py", line 168 in test_runner
File "/Users/mattb/src/misc/cpython/Lib/test/libregrtest/runtest.py", line 169 in runtest_inner
File "/Users/mattb/src/misc/cpython/Lib/test/libregrtest/runtest.py", line 137 in runtest
File "/Users/mattb/src/misc/cpython/Lib/test/libregrtest/main.py", line 374 in run_tests_sequential
File "/Users/mattb/src/misc/cpython/Lib/test/libregrtest/main.py", line 454 in run_tests
File "/Users/mattb/src/misc/cpython/Lib/test/libregrtest/main.py", line 530 in _main
File "/Users/mattb/src/misc/cpython/Lib/test/libregrtest/main.py", line 504 in main
File "/Users/mattb/src/misc/cpython/Lib/test/libregrtest/main.py", line 573 in main
File "/Users/mattb/src/misc/cpython/Lib/test/main.py", line 2 in <module>
File "/Users/mattb/src/misc/cpython/Lib/runpy.py", line 85 in _run_code
File "/Users/mattb/src/misc/cpython/Lib/runpy.py", line 193 in _run_module_as_main

real 3m0.115s
user 0m5.804s
sys 0m0.683s

I also ran ~600 passes overnight on this test on an Ubuntu 16.04 machine without a hang, so it seems to be OSX specific.

[vstinner]

I've been debugging this and I can repro on El Capitan on a different machine as well -- it's an infrequent hang, I've been running in a loop:

Hum, a timeout of 3 minutes seems short for test_multiprocessing_forkserver. How long does it take *usually* to run this test?

At least, we have a first clue: test_many_processes() of Lib/test/_test_multiprocessing.py.

[mattbillenstein]

It consistently takes between ~61 and ~73 seconds with this setup.

[pitrou]

Matt, if you try the following command, it will run the specific test in a loop in verbose mode:

$ ./python -m test --timeout=30 -F -m test_many_processes -v test_multiprocessing_forkserver

[mattbillenstein]

Cool -- do you need me to do something more to help debug this?

[pitrou]

It would be nice to know if there is additional output (for example exceptions happening in other threads or processes) when you run that command and manage to trigger a hang.

[mattbillenstein]

I don't see anything odd -- it runs for awhile and then times out once it's deadlocked:

0:03:18 load avg: 3.20 [224] test_multiprocessing_forkserver
test_many_processes (test.test_multiprocessing_forkserver.WithProcessesTestProcess) ... ok
test_many_processes (test.test_multiprocessing_forkserver.WithThreadsTestProcess) ... skipped 'test not appropriate for threads'

----------------------------------------------------------------------
Ran 2 tests in 0.849s

OK (skipped=1)
0:03:18 load avg: 3.11 [225] test_multiprocessing_forkserver
test_many_processes (test.test_multiprocessing_forkserver.WithProcessesTestProcess) ... ok
test_many_processes (test.test_multiprocessing_forkserver.WithThreadsTestProcess) ... skipped 'test not appropriate for threads'

----------------------------------------------------------------------
Ran 2 tests in 0.865s

OK (skipped=1)
0:03:19 load avg: 3.11 [226] test_multiprocessing_forkserver
test_many_processes (test.test_multiprocessing_forkserver.WithProcessesTestProcess) ... Timeout (0:00:30)!
Thread 0x00007fff790c1000 (most recent call first):
File "/Users/mattb/src/misc/cpython/Lib/selectors.py", line 415 in select
File "/Users/mattb/src/misc/cpython/Lib/multiprocessing/connection.py", line 916 in wait
File "/Users/mattb/src/misc/cpython/Lib/multiprocessing/popen_fork.py", line 45 in wait
File "/Users/mattb/src/misc/cpython/Lib/multiprocessing/process.py", line 121 in join
File "/Users/mattb/src/misc/cpython/Lib/test/test_multiprocessing.py", line 431 in test_many_processes
File "/Users/mattb/src/misc/cpython/Lib/unittest/case.py", line 605 in run
File "/Users/mattb/src/misc/cpython/Lib/unittest/case.py", line 653 in __call_
File "/Users/mattb/src/misc/cpython/Lib/unittest/suite.py", line 122 in run
File "/Users/mattb/src/misc/cpython/Lib/unittest/suite.py", line 84 in __call__
File "/Users/mattb/src/misc/cpython/Lib/unittest/suite.py", line 122 in run
File "/Users/mattb/src/misc/cpython/Lib/unittest/suite.py", line 84 in __call__
File "/Users/mattb/src/misc/cpython/Lib/unittest/suite.py", line 122 in run
File "/Users/mattb/src/misc/cpython/Lib/unittest/suite.py", line 84 in __call__
File "/Users/mattb/src/misc/cpython/Lib/unittest/runner.py", line 176 in run
File "/Users/mattb/src/misc/cpython/Lib/test/support/init.py", line 1896 in _run_suite
File "/Users/mattb/src/misc/cpython/Lib/test/support/init.py", line 1936 in run_unittest
File "/Users/mattb/src/misc/cpython/Lib/test/libregrtest/runtest.py", line 168 in test_runner
File "/Users/mattb/src/misc/cpython/Lib/test/libregrtest/runtest.py", line 169 in runtest_inner
File "/Users/mattb/src/misc/cpython/Lib/test/libregrtest/runtest.py", line 137 in runtest
File "/Users/mattb/src/misc/cpython/Lib/test/libregrtest/main.py", line 374 in run_tests_sequential
File "/Users/mattb/src/misc/cpython/Lib/test/libregrtest/main.py", line 454 in run_tests
File "/Users/mattb/src/misc/cpython/Lib/test/libregrtest/main.py", line 530 in _main
File "/Users/mattb/src/misc/cpython/Lib/test/libregrtest/main.py", line 504 in main
File "/Users/mattb/src/misc/cpython/Lib/test/libregrtest/main.py", line 573 in main
File "/Users/mattb/src/misc/cpython/Lib/test/main.py", line 2 in <module>
File "/Users/mattb/src/misc/cpython/Lib/runpy.py", line 85 in _run_code
File "/Users/mattb/src/misc/cpython/Lib/runpy.py", line 193 in _run_module_as_main

[pitrou]

Thanks for trying :-) Hmm, that's annoying. I don't know if you'd like to give me shell access to the machine (and a CPython checkout I can play with, perhaps)?