classification
Title: Azure Pipeline 3.8 CI: multiple tests hung and timed out on macOS 10.13
Type: Stage:
Components: macOS, Tests Versions: Python 3.8
process
Status: open Resolution:
Dependencies: Superseder:
Assigned To: Nosy List: ned.deily, ronaldoussoren, steve.dower, vstinner
Priority: normal Keywords:

Created on 2019-06-12 11:57 by vstinner, last changed 2019-06-17 23:00 by steve.dower.

Messages (4)
msg345325 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2019-06-12 11:57
I backported a change to 3.8:
https://github.com/python/cpython/pull/14000

The macOS job of Azure Pipelines failed badly:
https://dev.azure.com/Python/cpython/_build/results?buildId=45071&view=results

* test_importlib/test_locks.py: test_deadlock() => TIMEOUT
* test_multiprocessing_spawn: test_thread_safety() => TIMEOUT
* test_concurrent_futures: test_pending_calls_race() => TIMEOUT
* test_functools: test_threaded() => TIMEOUT
* test_multiprocessing_forkserver: test_thread_safety() => TIMEOUT
* test_threading: test_is_alive_after_fork() => TIMEOUT



0:20:21 load avg: 4.55 [155/423/1] test_importlib crashed (Exit code 1) -- running: test_concurrent_futures (16 min 12 sec), test_functools (13 min 30 sec), test_multiprocessing_spawn (18 min 51 sec)
Timeout (0:20:00)!
Thread 0x0000700004627000 (most recent call first):

Thread 0x00007fff96f1a380 (most recent call first):
  File "/Users/vsts/agent/2.152.1/work/1/s/Lib/test/lock_tests.py", line 49 in __init__
  File "/Users/vsts/agent/2.152.1/work/1/s/Lib/test/test_importlib/test_locks.py", line 84 in run_deadlock_avoidance_test
  File "/Users/vsts/agent/2.152.1/work/1/s/Lib/test/test_importlib/test_locks.py", line 89 in test_deadlock
  ...

0:21:30 load avg: 4.76 [160/423/2] test_multiprocessing_spawn crashed (Exit code 1) -- running: test_concurrent_futures (17 min 21 sec), test_functools (14 min 39 sec), test_threading (35 sec 923 ms)
Timeout (0:20:00)!
Thread 0x0000700000ff1000 (most recent call first):

Thread 0x00007fff96f1a380 (most recent call first):
  File "/Users/vsts/agent/2.152.1/work/1/s/Lib/threading.py", line 847 in start
  File "/Users/vsts/agent/2.152.1/work/1/s/Lib/test/support/__init__.py", line 2299 in start_threads
  File "/Users/vsts/agent/2.152.1/work/1/s/Lib/contextlib.py", line 113 in __enter__
  File "/Users/vsts/agent/2.152.1/work/1/s/Lib/test/_test_multiprocessing.py", line 4138 in test_thread_safety
  ...

0:24:09 load avg: 4.11 [207/423/3] test_concurrent_futures crashed (Exit code 1) -- running: test_functools (17 min 18 sec), test_timeout (34 sec 14 ms), test_threading (3 min 14 sec)
Timeout (0:20:00)!
Thread 0x0000700006644000 (most recent call first):
  File "/Users/vsts/agent/2.152.1/work/1/s/Lib/concurrent/futures/thread.py", line 78 in _worker
  File "/Users/vsts/agent/2.152.1/work/1/s/Lib/threading.py", line 865 in run
  File "/Users/vsts/agent/2.152.1/work/1/s/Lib/threading.py", line 923 in _bootstrap_inner
  File "/Users/vsts/agent/2.152.1/work/1/s/Lib/threading.py", line 885 in _bootstrap

Thread 0x0000700006141000 (most recent call first):
  File "/Users/vsts/agent/2.152.1/work/1/s/Lib/concurrent/futures/thread.py", line 78 in _worker
  File "/Users/vsts/agent/2.152.1/work/1/s/Lib/threading.py", line 865 in run
  File "/Users/vsts/agent/2.152.1/work/1/s/Lib/threading.py", line 923 in _bootstrap_inner
  File "/Users/vsts/agent/2.152.1/work/1/s/Lib/threading.py", line 885 in _bootstrap

Thread 0x0000700005c3e000 (most recent call first):
  File "/Users/vsts/agent/2.152.1/work/1/s/Lib/concurrent/futures/thread.py", line 78 in _worker
  File "/Users/vsts/agent/2.152.1/work/1/s/Lib/threading.py", line 865 in run
  File "/Users/vsts/agent/2.152.1/work/1/s/Lib/threading.py", line 923 in _bootstrap_inner
  File "/Users/vsts/agent/2.152.1/work/1/s/Lib/threading.py", line 885 in _bootstrap

Thread 0x000070000573b000 (most recent call first):
  File "/Users/vsts/agent/2.152.1/work/1/s/Lib/concurrent/futures/thread.py", line 78 in _worker
  File "/Users/vsts/agent/2.152.1/work/1/s/Lib/threading.py", line 865 in run
  File "/Users/vsts/agent/2.152.1/work/1/s/Lib/threading.py", line 923 in _bootstrap_inner
  File "/Users/vsts/agent/2.152.1/work/1/s/Lib/threading.py", line 885 in _bootstrap

Thread 0x0000700005238000 (most recent call first):
  File "/Users/vsts/agent/2.152.1/work/1/s/Lib/concurrent/futures/thread.py", line 78 in _worker
  File "/Users/vsts/agent/2.152.1/work/1/s/Lib/threading.py", line 865 in run
  File "/Users/vsts/agent/2.152.1/work/1/s/Lib/threading.py", line 923 in _bootstrap_inner
  File "/Users/vsts/agent/2.152.1/work/1/s/Lib/threading.py", line 885 in _bootstrap

Thread 0x00007fff96f1a380 (most recent call first):
  File "/Users/vsts/agent/2.152.1/work/1/s/Lib/test/libregrtest/setup.py", line 92 in _test_audit_hook
  File "/Users/vsts/agent/2.152.1/work/1/s/Lib/concurrent/futures/_base.py", line 146 in __init__
  File "/Users/vsts/agent/2.152.1/work/1/s/Lib/concurrent/futures/_base.py", line 288 in wait
  File "/Users/vsts/agent/2.152.1/work/1/s/Lib/test/test_concurrent_futures.py", line 565 in test_pending_calls_race
  File "/Users/vsts/agent/2.152.1/work/1/s/Lib/unittest/case.py", line 628 in _callTestMethod
  File "/Users/vsts/agent/2.152.1/work/1/s/Lib/unittest/case.py", line 671 in run
  File "/Users/vsts/agent/2.152.1/work/1/s/Lib/unittest/case.py", line 731 in __call__
  File "/Users/vsts/agent/2.152.1/work/1/s/Lib/unittest/suite.py", line 122 in run
  File "/Users/vsts/agent/2.152.1/work/1/s/Lib/unittest/suite.py", line 84 in __call__
  File "/Users/vsts/agent/2.152.1/work/1/s/Lib/unittest/suite.py", line 122 in run
  File "/Users/vsts/agent/2.152.1/work/1/s/Lib/unittest/suite.py", line 84 in __call__
  File "/Users/vsts/agent/2.152.1/work/1/s/Lib/unittest/suite.py", line 122 in run
  File "/Users/vsts/agent/2.152.1/work/1/s/Lib/unittest/suite.py", line 84 in __call__
  File "/Users/vsts/agent/2.152.1/work/1/s/Lib/unittest/runner.py", line 176 in run
  File "/Users/vsts/agent/2.152.1/work/1/s/Lib/test/support/__init__.py", line 1984 in _run_suite
  File "/Users/vsts/agent/2.152.1/work/1/s/Lib/test/support/__init__.py", line 2080 in run_unittest
  File "/Users/vsts/agent/2.152.1/work/1/s/Lib/test/test_concurrent_futures.py", line 1300 in test_main
  File "/Users/vsts/agent/2.152.1/work/1/s/Lib/test/support/__init__.py", line 2212 in decorator
  File "/Users/vsts/agent/2.152.1/work/1/s/Lib/test/libregrtest/runtest.py", line 228 in _runtest_inner2
  File "/Users/vsts/agent/2.152.1/work/1/s/Lib/test/libregrtest/runtest.py", line 264 in _runtest_inner
  File "/Users/vsts/agent/2.152.1/work/1/s/Lib/test/libregrtest/runtest.py", line 135 in _runtest
  File "/Users/vsts/agent/2.152.1/work/1/s/Lib/test/libregrtest/runtest.py", line 187 in runtest
  File "/Users/vsts/agent/2.152.1/work/1/s/Lib/test/libregrtest/runtest_mp.py", line 66 in run_tests_worker
  File "/Users/vsts/agent/2.152.1/work/1/s/Lib/test/libregrtest/main.py", line 611 in _main
  File "/Users/vsts/agent/2.152.1/work/1/s/Lib/test/libregrtest/main.py", line 588 in main
  File "/Users/vsts/agent/2.152.1/work/1/s/Lib/test/libregrtest/main.py", line 663 in main
  File "/Users/vsts/agent/2.152.1/work/1/s/Lib/test/regrtest.py", line 46 in _main
  File "/Users/vsts/agent/2.152.1/work/1/s/Lib/test/regrtest.py", line 50 in <module>
  File "/Users/vsts/agent/2.152.1/work/1/s/Lib/runpy.py", line 85 in _run_code
  File "/Users/vsts/agent/2.152.1/work/1/s/Lib/runpy.py", line 192 in _run_module_as_main

0:26:51 load avg: 5.14 [259/423/4] test_functools crashed (Exit code 1) -- running: test_io (1 min 11 sec), test_threading (5 min 56 sec)
Timeout (0:20:00)!
Thread 0x000070000666f000 (most recent call first):

Thread 0x00007fff96f1a380 (most recent call first):
  File "/Users/vsts/agent/2.152.1/work/1/s/Lib/threading.py", line 847 in start
  File "/Users/vsts/agent/2.152.1/work/1/s/Lib/test/support/__init__.py", line 2299 in start_threads
  File "/Users/vsts/agent/2.152.1/work/1/s/Lib/contextlib.py", line 113 in __enter__
  File "/Users/vsts/agent/2.152.1/work/1/s/Lib/test/test_functools.py", line 2464 in test_threaded
...
0:47:26 load avg: 1.71 [423/423/6] test_multiprocessing_forkserver crashed (Exit code 1)
Timeout (0:20:00)!
Thread 0x0000700009471000 (most recent call first):

Thread 0x00007fff96f1a380 (most recent call first):
  File "/Users/vsts/agent/2.152.1/work/1/s/Lib/threading.py", line 246 in __enter__
  File "/Users/vsts/agent/2.152.1/work/1/s/Lib/threading.py", line 555 in wait
  File "/Users/vsts/agent/2.152.1/work/1/s/Lib/threading.py", line 852 in start
  File "/Users/vsts/agent/2.152.1/work/1/s/Lib/test/support/__init__.py", line 2299 in start_threads
  File "/Users/vsts/agent/2.152.1/work/1/s/Lib/contextlib.py", line 113 in __enter__
  File "/Users/vsts/agent/2.152.1/work/1/s/Lib/test/_test_multiprocessing.py", line 4138 in test_thread_safety
...

6 tests failed:
    test_concurrent_futures test_functools test_importlib
    test_multiprocessing_forkserver test_multiprocessing_spawn
    test_threading


--

pythoninfo:

2019-06-12T02:45:41.9759180Z Py_DEBUG: Yes (sys.gettotalrefcount() present)
2019-06-12T02:45:41.9784500Z datetime.datetime.now: 2019-06-12 02:45:40.875495
2019-06-12T02:45:41.9806170Z platform.architecture: 64bit
2019-06-12T02:45:41.9797810Z os.environ[MACOSX_DEPLOYMENT_TARGET]: 10.13
2019-06-12T02:45:41.9806990Z platform.platform: macOS-10.13.6-x86_64-i386-64bit
2019-06-12T02:45:41.9801150Z os.login: _spotlight
2019-06-12T02:45:41.9817220Z socket.hostname: Mac-483.local
2019-06-12T02:45:41.9835490Z sys.version: 3.8.0b1+ (remotes/pull/14000/merge:ce71235d6, Jun 12 2019, 02:45:09)  [Clang 10.0.0 (clang-1000.11.45.5)]
msg345326 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2019-06-12 11:57
os.uname: posix.uname_result(sysname='Darwin', nodename='Mac-483.local', release='17.7.0', version='Darwin Kernel Version 17.7.0: Wed Apr 24 21:17:24 PDT 2019; root:xnu-4570.71.45~1/RELEASE_X86_64', machine='x86_64')
msg345458 - (view) Author: Ned Deily (ned.deily) * (Python committer) Date: 2019-06-13 06:21
FWIW, I tried reproducing with 3.8 at 996e52623af3854552d41751e0c2522bc0a7e84f (the PR 14000 checkin) on both a current 10.14.5 Mojave system and on a 10.13.6 High Sierra system (the version used in the failed Azure test) and did not see any unusual failures.  I don't recall seeing a timeout like in test_concurrent_futures, at least recently!, but, if it is due to some race condition, there might be a more significant difference, like number of CPUs available, that might precipitate the failure.  I'll leave it up to you, Victor, on whether or how long to leave this issue open but I don't see that there is anything practical to do until it can be reproduced.
msg345936 - (view) Author: Steve Dower (steve.dower) * (Python committer) Date: 2019-06-17 23:00
I'm still seeing this, maybe 1 in 20 builds, so it's semi-random. A new deadlock, maybe?
History
Date User Action Args
2019-06-17 23:00:25steve.dowersetnosy: + steve.dower
messages: + msg345936
2019-06-13 06:21:29ned.deilysetmessages: + msg345458
title: Azure Pipeline: sick macOS job on Python 3.8? -> Azure Pipeline 3.8 CI: multiple tests hung and timed out on macOS 10.13
2019-06-12 11:57:58vstinnersetmessages: + msg345326
2019-06-12 11:57:02vstinnercreate