[2.7] test_threading.ConditionTests.test_notify() hangs randomly on Python 2.7

[vstinner]

BPO	30727
Nosy	@pitrou, @kristjanvalur, @vstinner, @serhiy-storchaka
PRs	[2.7] bpo-8799: Reduce timing sensitivity of condition test by explicitly #2320 bpo-30727: Fix a race condition in test_threading. #2334 [3.6] bpo-30727: Fix a race condition in test_threading. (GH-2334) #2351 [3.5] bpo-30727: Fix a race condition in test_threading. (GH-2334) #2352 [2.7] bpo-30727: Fix a race condition in test_threading. (GH-2334). #2353
Files	notify_bug.py

^{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-06-23.11:17:09.188>
created_at = <Date 2017-06-21.22:20:05.546>
labels = ['3.7', 'tests']
title = '[2.7] test_threading.ConditionTests.test_notify() hangs randomly on Python 2.7'
updated_at = <Date 2017-06-26.23:04:03.761>
user = 'https://github.com/vstinner'

bugs.python.org fields:

activity = <Date 2017-06-26.23:04:03.761>
actor = 'vstinner'
assignee = 'none'
closed = True
closed_date = <Date 2017-06-23.11:17:09.188>
closer = 'serhiy.storchaka'
components = ['Tests']
creation = <Date 2017-06-21.22:20:05.546>
creator = 'vstinner'
dependencies = []
files = ['46966']
hgrepos = []
issue_num = 30727
keywords = []
message_count = 18.0
messages = ['296591', '296593', '296594', '296598', '296601', '296604', '296606', '296621', '296622', '296623', '296653', '296695', '296698', '296699', '296700', '296701', '296706', '296968']
nosy_count = 4.0
nosy_names = ['pitrou', 'kristjan.jonsson', 'vstinner', 'serhiy.storchaka']
pr_nums = ['2320', '2334', '2351', '2352', '2353']
priority = 'normal'
resolution = 'fixed'
stage = 'resolved'
status = 'closed'
superseder = None
type = None
url = 'https://bugs.python.org/issue30727'
versions = ['Python 2.7', 'Python 3.5', 'Python 3.6', 'Python 3.7']

[vstinner]

Example where the test hangs after at the 48th run:
----
[haypo@freebsd ~/prog/python/2.7]$ ./python -m test -F -m test.test_threading.ConditionTests.test_notify -v test_threading
(...)
0:00:10 [ 47] test_threading
test_notify (test.test_threading.ConditionTests) ... ok
(...)
0:00:10 [ 48] test_threading
test_notify (test.test_threading.ConditionTests) ...
----

It looks like a timing issue / race condition since the likehood of the bug seems to depend on the system load.

Traceback using my watchdog:
#2317

---
0:00:57 [285] test_threading
test_notify (test.test_threading.ConditionTests) ... *** STACKTRACE - START ***
# ThreadID: 34391913984
File: "/usr/home/haypo/prog/python/2.7/Lib/test/lock_tests.py", line 37, in task
f()
File: "/usr/home/haypo/prog/python/2.7/Lib/test/lock_tests.py", line 360, in f
cond.wait()
File: "/usr/home/haypo/prog/python/2.7/Lib/threading.py", line 340, in wait
waiter.acquire()

# ThreadID: 34392086528
File: "/usr/home/haypo/prog/python/2.7/Lib/test/lock_tests.py", line 37, in task
f()
File: "/usr/home/haypo/prog/python/2.7/Lib/test/lock_tests.py", line 360, in f
cond.wait()
File: "/usr/home/haypo/prog/python/2.7/Lib/threading.py", line 340, in wait
waiter.acquire()

# ThreadID: 34384994304
File: "/usr/home/haypo/prog/python/2.7/Lib/runpy.py", line 174, in _run_module_as_main
"__main__", fname, loader, pkg_name)
File: "/usr/home/haypo/prog/python/2.7/Lib/runpy.py", line 72, in _run_code
exec code in run_globals
File: "/usr/home/haypo/prog/python/2.7/Lib/test/main.py", line 3, in <module>
regrtest.main_in_temp_cwd()
File: "/usr/home/haypo/prog/python/2.7/Lib/test/regrtest.py", line 2030, in main_in_temp_cwd
main()
File: "/usr/home/haypo/prog/python/2.7/Lib/test/regrtest.py", line 812, in main
result = local_runtest()
File: "/usr/home/haypo/prog/python/2.7/Lib/test/regrtest.py", line 798, in local_runtest
testdir=testdir)
File: "/usr/home/haypo/prog/python/2.7/Lib/test/regrtest.py", line 1007, in runtest
return runtest_inner(test, verbose, quiet, huntrleaks, pgo, testdir)
File: "/usr/home/haypo/prog/python/2.7/Lib/test/regrtest.py", line 1196, in runtest_inner
indirect_test()
File: "/usr/home/haypo/prog/python/2.7/Lib/test/test_threading.py", line 929, in test_main
ThreadingExceptionTests,
File: "/usr/home/haypo/prog/python/2.7/Lib/test/support/init.py", line 1571, in run_unittest
_run_suite(suite)
File: "/usr/home/haypo/prog/python/2.7/Lib/test/support/init.py", line 1530, in _run_suite
result = runner.run(suite)
File: "/usr/home/haypo/prog/python/2.7/Lib/unittest/runner.py", line 151, in run
test(result)
File: "/usr/home/haypo/prog/python/2.7/Lib/unittest/suite.py", line 70, in __call__
return self.run(*args, **kwds)
File: "/usr/home/haypo/prog/python/2.7/Lib/unittest/suite.py", line 108, in run
test(result)
File: "/usr/home/haypo/prog/python/2.7/Lib/unittest/suite.py", line 70, in __call__
return self.run(*args, **kwds)
File: "/usr/home/haypo/prog/python/2.7/Lib/unittest/suite.py", line 108, in run
test(result)
File: "/usr/home/haypo/prog/python/2.7/Lib/unittest/case.py", line 393, in __call__
return self.run(*args, **kwds)
File: "/usr/home/haypo/prog/python/2.7/Lib/unittest/case.py", line 329, in run
testMethod()
File: "/usr/home/haypo/prog/python/2.7/Lib/test/lock_tests.py", line 401, in test_notify
self._check_notify(cond)
File: "/usr/home/haypo/prog/python/2.7/Lib/test/lock_tests.py", line 384, in _check_notify
_wait()
File: "/usr/home/haypo/prog/python/2.7/Lib/test/lock_tests.py", line 16, in _wait
time.sleep(0.01)

# ThreadID: 34384996864
File: "/usr/home/haypo/prog/python/2.7/Lib/threading.py", line 774, in __bootstrap
self.__bootstrap_inner()
File: "/usr/home/haypo/prog/python/2.7/Lib/threading.py", line 801, in __bootstrap_inner
self.run()
File: "/usr/home/haypo/prog/python/2.7/Lib/test/regrtest.py", line 1971, in run
self.dump_threads()
File: "/usr/home/haypo/prog/python/2.7/Lib/test/regrtest.py", line 1997, in dump_threads
self.dump_thread(stack)

# ThreadID: 34392083968
File: "/usr/home/haypo/prog/python/2.7/Lib/test/lock_tests.py", line 37, in task
f()
File: "/usr/home/haypo/prog/python/2.7/Lib/test/lock_tests.py", line 360, in f
cond.wait()
File: "/usr/home/haypo/prog/python/2.7/Lib/threading.py", line 340, in wait
waiter.acquire()

# ThreadID: 34392080128
File: "/usr/home/haypo/prog/python/2.7/Lib/test/lock_tests.py", line 37, in task
f()
File: "/usr/home/haypo/prog/python/2.7/Lib/test/lock_tests.py", line 360, in f
cond.wait()
File: "/usr/home/haypo/prog/python/2.7/Lib/threading.py", line 340, in wait
waiter.acquire()

*** STACKTRACE - END ***
---

[vstinner]

test.test_threading.ConditionTests.test_notify() tests the threading._Condition.

threading._Condition uses internally a threading._RLock.

threading._RLock uses an internal lock created with thread.allocate_lock().

thread.allocate_lock() calls internally PyThread_allocate_lock(). On my Linux (Fedora 25) and FreeBSD (FreeBSD 11 VM) machines, PyThread_allocate_lock() calls sem_init(): POSIX pthread semaphores.

In Python 3, RLock was implemented in C for speed (the new Python 3.0 io module was slow because of RLock performance): see bpo-3001.

I know at least one race condition in Python 2.7 RLock: bpo-13697, RLock bug with signals.

[vstinner]

Oh, I reproduced the bug on Linux as well by running "./python -m test -F -m test.test_threading.ConditionTests.test_notify -v test_threading" 6 times in different terminals: the test hangs in two terminal after 2508 and 2262 runs.

[vstinner]

notify_bug.py: script close totest.test_threading.ConditionTests.test_notify() but different:

• _wait() sleeps 1 nanosecond rather than 10 ms
• log many messages into stdout (file descriptor 1) using os.write()

It's quite easy to reproduce the bug with this script.

[vstinner]

See also bpo-8799 "Hang in lib/test/test_threading.py" and the commit 020af2a which added two _wait() calls to ConditionTests._check_notify().

[vstinner]

The bug occurs when notify(n) is called while less than n threads are waiting in cond.wait(): when some threads didn't reach cond.wait() yet. The synchronization code is very fragile and depends on time. The issue was worked again in the master banch by adding more _wait() calls...

To really fix the race condition, reliable synchronization primitives should be used, like threading.Event.

[vstinner]

It's getting late here, so I chose to first backport the commit 020af2a to Python 2.7, to reduce the likehood of this bug on 2.7 buildbots.

[kristjanvalur]

My favorite topic :)

You could use threading.Barrier() which is designed to synchronize N threads doing this kind of lock-step processing. The problem is that the Barrier() is implemented using Condition variables, so for unit-testing, Condition Variables, this presents a conundrum...

[pitrou]

Yes, the whole reason I wrote the tests like this is to avoid depending on Python synchronization primitives inside the tests for Python synchronization primitives.

[serhiy-storchaka]

I still didn't see a code, but perhaps we could use a spin-lock. Every child thread increases the global counter, and the main thread waits until the counter equal to the number of child threads (sleeping for short time in a loop) before calling notify().

[serhiy-storchaka]

Actually this approach already is used in this test. PR 2334 uses it to ensure all workers into cond.wait().

[serhiy-storchaka]

New changeset 32cb968 by Serhiy Storchaka in branch 'master':
bpo-30727: Fix a race condition in test_threading. (bpo-2334)
32cb968

[serhiy-storchaka]

New changeset c1d5345 by Serhiy Storchaka in branch '3.6':
[3.6] bpo-30727: Fix a race condition in test_threading. (GH-2334) (bpo-2351)
c1d5345