test_concurrent_futures crashes with "--with-pydebug" on RHEL5 with "Fatal Python error: Invalid thread state for this thread"

[ambv]

BPO	10517
Nosy	@jcea, @brianquinlan, @pitrou, @kristjanvalur, @davidmalcolm, @sandrotosi, @ambv
Files	concurrent-futures-freeze.tar.bz2: Diagnostic logs test_specific.c: test program tls_reinit.diff

^{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 = 'https://github.com/brianquinlan'
closed_at = <Date 2011-04-27.17:39:09.499>
created_at = <Date 2010-11-24.00:24:17.168>
labels = ['extension-modules', 'type-crash']
title = 'test_concurrent_futures crashes with "--with-pydebug" on RHEL5 with "Fatal Python error: Invalid thread state for this thread"'
updated_at = <Date 2013-02-04.19:18:25.175>
user = 'https://github.com/ambv'

bugs.python.org fields:

activity = <Date 2013-02-04.19:18:25.175>
actor = 'jcea'
assignee = 'bquinlan'
closed = True
closed_date = <Date 2011-04-27.17:39:09.499>
closer = 'pitrou'
components = ['Extension Modules']
creation = <Date 2010-11-24.00:24:17.168>
creator = 'lukasz.langa'
dependencies = []
files = ['19792', '21677', '21804']
hgrepos = []
issue_num = 10517
keywords = ['patch']
message_count = 38.0
messages = ['122254', '122255', '122287', '122288', '122290', '122295', '122320', '123434', '123604', '128329', '128330', '128343', '132428', '132444', '132477', '133864', '133865', '133866', '134415', '134418', '134448', '134471', '134475', '134476', '134570', '134573', '134577', '134580', '134582', '134585', '134587', '134589', '134599', '134604', '134605', '145160', '145164', '145354']
nosy_count = 12.0
nosy_names = ['jcea', 'bquinlan', 'pitrou', 'kristjan.jonsson', 'jnoller', 'grahamd', 'dmalcolm', 'sandro.tosi', 'ysj.ray', 'neologix', 'lukasz.langa', 'python-dev']
pr_nums = []
priority = 'critical'
resolution = 'fixed'
stage = 'resolved'
status = 'closed'
superseder = None
type = 'crash'
url = 'https://bugs.python.org/issue10517'
versions = ['Python 2.7', 'Python 3.2', 'Python 3.3']

[ambv]

py3k built from trunk on Centos 5.5 freezes during regrtest on test_concurrent_futures with "Fatal Python error: Invalid thread state for this thread".

A set of hopefully useful diagnostic logs attached as patch.

[ambv]

A colorful example: http://bpaste.net/show/11493/

(just in case if downloading and extracting logs is not feasible)

Some clarification: as in a typical concurrent problem, subsequent calls freeze in different test cases, but the freeze itself is always reproducible and always during this test.

[davidmalcolm]

I'm able to reliably reproduce this on a RHEL 5 box (i386 in this case).

All of the "ProcessPool*" unittest subclasses within Lib/test/test_concurrent_futures.py exhibit this hang, each printing out just the name of the first test (so presumably either within the first test method, or in shared setup/teardown).

None of the other subclasses hang.

You need to build with --with-pydebug to see this: the error message is coming from this code in PyThreadState_Swap in Python/pystate.c:

390 #if defined(Py_DEBUG) && defined(WITH_THREAD)
391 if (newts) {
392 /* This can be called from PyEval_RestoreThread(). Similar
393 to it, we need to ensure errno doesn't change.
394 */
395 int err = errno;
396 PyThreadState *check = PyGILState_GetThisThreadState();
397 if (check && check->interp == newts->interp && check != newts)

>>398 Py_FatalError("Invalid thread state for this thread");
399 errno = err;
400 }
401 #endif

[davidmalcolm]

Minimal reproducer:
$ ./python -c "from concurrent.futures import * ; e = ProcessPoolExecutor() ; e.submit(pow, 2, 5)"
Fatal Python error: Invalid thread state for this thread

[davidmalcolm]

Seems to be an issue within (or triggered by) multiprocessing (test_threads and test_threading pass OK, fwiw):
$ ./python -m test.test_multiprocessing
Fatal Python error: Invalid thread state for this thread
Traceback (most recent call last):
  File "/home/dmalcolm/coding/python-svn/py3k-clean/Lib/runpy.py", line 160, in _run_module_as_main
    "__main__", fname, loader, pkg_name)
  File "/home/dmalcolm/coding/python-svn/py3k-clean/Lib/runpy.py", line 73, in _run_code
    exec(code, run_globals)
  File "/home/dmalcolm/coding/python-svn/py3k-clean/Lib/test/test_multiprocessing.py", line 2127, in <module>
    main()
  File "/home/dmalcolm/coding/python-svn/py3k-clean/Lib/test/test_multiprocessing.py", line 2124, in main
    test_main(unittest.TextTestRunner(verbosity=2).run)
  File "/home/dmalcolm/coding/python-svn/py3k-clean/Lib/test/test_multiprocessing.py", line 2103, in test_main
    ManagerMixin.pool = ManagerMixin.manager.Pool(4)
  File "/home/dmalcolm/coding/python-svn/py3k-clean/Lib/multiprocessing/managers.py", line 644, in temp
    token, exp = self._create(typeid, *args, **kwds)
  File "/home/dmalcolm/coding/python-svn/py3k-clean/Lib/multiprocessing/managers.py", line 542, in _create
    conn = self._Client(self._address, authkey=self._authkey)
  File "/home/dmalcolm/coding/python-svn/py3k-clean/Lib/multiprocessing/connection.py", line 149, in Client
    answer_challenge(c, authkey)
  File "/home/dmalcolm/coding/python-svn/py3k-clean/Lib/multiprocessing/connection.py", line 383, in answer_challenge
    message = connection.recv_bytes(256)         # reject large message
EOFError

[davidmalcolm]

By strategically adding print() and input() calls, I was able to isolate the error to this line in test_multiprocessing.py's test_main:
ManagerMixin.pool = ManagerMixin.manager.Pool(4)

specifically, to the construction:
ManagerMixin.manager.Pool(4)

Minimal reproducer seems to be:
>>> import multiprocessing.managers
>>> mpp = multiprocessing.Pool(4)
>>> sm = multiprocessing.managers.SyncManager()
>>> sm.start()

i.e.:

$ ./python -c "import multiprocessing.managers ; mpp = multiprocessing.Pool(4); sm = multiprocessing.managers.SyncManager(); sm.start()"
Fatal Python error: Invalid thread state for this thread

[davidmalcolm]

FWIW, I was able to do an almost full run of regrtest on this box with:
-x test_multiprocessing test_concurrent_futures

Other than those two, all tests pass.

So _something_ is going wrong w.r.t. threads, though I'm not sure what at this stage.

[brianquinlan]

I've filed a new bug (http://bugs.python.org/issue10632) against multiprocessing and this bug dependent on it.

In the meantime, I can't repro this on ubuntu 10.04 LTS so I'm going to install Centos and give that a go.

[ysjray]

Couldn't repro this on my debian 5.

[davidmalcolm]

I spent some time bisecting the SVN history in the py3k branch, and believe that r84914 is the commit that introduced this issue.

Details:

Trying on 4-core i386 RHEL 5 box
$ svn up -r REV
$ make clean ; make
(configured --with-pydebug)

Reproducer:

./python -c "import multiprocessing.managers ; mpp = multiprocessing.Pool(4); sm = multiprocessing.managers.SyncManager(); sm.start()"

(running it 3 times; each time, at each build I see it either successfully completing 3 times, or having the Py_FatalError 3 times)

Bisecting:
r86720: CRASHES with r86729 --with-pydebug (from when I was investigating this before)
r73573: Runs OK with r73573 --with-pydebug (r73573 was origin for 3.1 tag)

=> somewhere in 73572..86729

r76195: Runs OK with r76195 --with-pydebug (r76195 added the new GIL)

=> somewhere in 76195..86729

r80724: Runs OK with r80724 --with-pydebug (changed threading code to "Make (most of) Python's tests pass under Thread Sanitizer.")

=> somewhere in 80724..86729

r83722: Runs OK with r80724 --with-pydebug (touched multiprocessing)

=> somewhere in 83722..86729

r85222: CRASHES with r85222 --with-pydebug (rough midpoint)

=> somewhere in 83722..85222

r84472: Runs OK with r84472 --with-pydebug (arbitrary midpoint)

=> somewhere in 84472..85222

r84847: Runs OK with r84847 --with-pydebug (arbitrary midpoint)

 => somewhere in 84847..85222

r85033: CRASHES with r85033 --with-pydebug (arbitrary midpoint)

 => somewhere in 84847..85033

r84938: CRASHES with r84938 --with-pydebug (arbitrary midpoint)

 => somewhere in 84847..84938

r84892: Runs OK with r84892 --with-pydebug (arbitrary midpoint)

 => somewhere in 84892..84938

r84915: CRASHES with r84915 --with-pydebug (arbitrary midpoint)

 => somewhere in 84892..84915

r84903: Runs OK with r84903 --with-pydebug (arbitrary midpoint)

 => somewhere in 84903..84915

r84914: CRASHES with r84914 --with-pydebug (affects threads)

 => somewhere in 84903..84914

r84913: Runs OK with r84913 --with-pydebug (previous commit before 84914)

 => r84914 is the commit that triggered this issue

[davidmalcolm]

r84914 was the implementation of bpo-9786 (Native TLS support for pthreads)