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.

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.

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

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

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

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

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.

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.

Couldn't repro this on my debian 5.

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

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

This appears to be happening in a child process when the parent process is running:
  Lib/multiprocessing/util.py, line 255, in _exit_function ()

Liberally adding printf() and getpid() calls in various places, seems to always happen when parent process is within "call_py_exitfuncs()" within Py_Finalize; error is from the child process that was created last.

Using gdb with a breakpoint on "call_py_exitfuncs" and single-stepping seems to confirm a single exitfunc:
  Lib/multiprocessing/util.py, line 255, in _exit_function ()
and that the child dies as that bytecode function is executed.

$ ./python -c "import multiprocessing.managers ; mpp = multiprocessing.Pool(4); sm = multiprocessing.managers.SyncManager(); sm.start()"
Py_InitializeEx called for PID 27824
posix_fork called by PID 27824
child of posix_fork has PID 27825
posix_fork called by PID 27824
child of posix_fork has PID 27826
posix_fork called by PID 27824
child of posix_fork has PID 27827
posix_fork called by PID 27824
child of posix_fork has PID 27828
posix_fork called by PID 27824
child of posix_fork has PID 27832
Py_Finalize called for PID 27824
wait_for_thread_shutdown() finished for PID 27824
Fatal Python error for PID 27832: Invalid thread state for this thread
call_py_exitfuncs() finished for PID 27824
PyOS_FiniInterrupts() finished for PID 27824
[64240 refs]

Is someone still able to replicate this crash? I'm not, with a fresh built 3.2 and default (3.3), --with-pydebug enabled. Brian confirmed on msg132418 that he can't any longer replicate it.

I tried again, and I'm still able to reproduce this bug on a RHEL5 box with cpython --with-pydebug as of a recent checkout (69030:00217100b9e7 as it happens):

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

What is the line that the parent process is executing?  Line numbers don't seem to match any more.
And is it possible to set a breakpoint in the child process where the fatal error is triggered?  It would be good to know what is being run at that point.

This is due to a bug in the TLS key management when mixed with fork.
Here's what happens:
When a thread is created, a tstate is allocated and stored in the thread's TLS:
thread_PyThread_start_new_thread -> t_bootstrap -> _PyThreadState_Init -> _PyGILState_NoteThreadState:

    if (PyThread_set_key_value(autoTLSkey, (void *)tstate) < 0)
        Py_FatalError("Couldn't create autoTLSkey mapping");

where 
int
PyThread_set_key_value(int key, void *value)
{
    int fail;
    void *oldValue = pthread_getspecific(key);
    if (oldValue != NULL)
        return 0;
    fail = pthread_setspecific(key, value);
    return fail;
}

A pthread_getspecific(key) is performed to see if there was already a value associated to this key.
The problem is that, if a process has a thread with a given thread ID (and a tstate stored in its TLS), and then the process forks (from another thread), if a new thread is created with the same thread ID as the thread in the child process, pthread_getspecific(key) will return the value stored by the other thread (with the same thread ID). In short, thread-specific values are inherited across fork, and if you're unlucky and create a thread with a thread ID already existing in the parent process, you're screwed.
To conclude, PyGILState_GetThisThreadState, which calls PyThread_get_key_value(autoTLSkey) will return the other thread's tstate, which will triggers this fatal error in PyThreadState_Swap.

The patch attached fixes this issue by removing the call to pthread_getspecific(key) from PyThread_set_key_value. This solves the problem and doesn't seem to cause any regression in test_threading and test_multiprocessing, and I think that if we were to call PyThread_set_key_value twice on the same key it's either an error, or we want the last version to be stored, not the old one.
test_threading and test_multiprocessing now run fine without any fatal error.

Note that this is probably be a bug in RHEL pthread's implementation, but given how widespread RHEL and derived distros are, I think this should be fixed.
I've attached a patch and a small test program to check if thread-specific data is inherited across a fork.
Here's a sample run on a RHEL4U8 box:

$ /tmp/test
PID: 17922, TID: 3086187424, init value: (nil)
PID: 17924, TID: 3086187424, init value: 0xdeadbeef

The second thread has been created in the child process and inherited the first thread's (created by the parent) key's value (one condition for this to happen is of course that the second thread is allocated the same thread ID as the first one).

Note: this seems to be fixed in RHEL6.
(Sorry for the noise).

Now, I'd be super happy to see this strange semantics of PyThread_set_key_value go away.  Its very un-standard and complicates the mapping from an native implementation to the python one.
But I think I did once bring up this issue, and was told that it was a bad idea.
But your logic is sound.  Doing two Sets, is an error regardless.  Hiding the error by ignoring the second set is arbitrarily as bad as ignoring the first thing.
So, if it is possible to fix this and remove this weird special case and cast it into the abyss, then by all means, you have my 10 thumbs up.  Not that it counts for much :)

> So, if it is possible to fix this and remove this weird special case and cast it into the abyss, then by all means, you have my 10 thumbs up.  Not that it counts for much :)

Me too.
We still have a couple hundred RHEL4/5 boxes at work, and I guess we're not alone in this case. It's a really specific case, but I think it would be nice to fix it, especially since it also makes the code more understandable and less error-prone. Unless of course this special treatment is really necessary, in which case I'll have to think of another solution or just drop it.
I'm adding Antoine to the noisy list, since he's noted as thread expert in the Experts Index.

> I think that if we were to call PyThread_set_key_value twice on the
> same key it's either an error, or we want the last version to be
> stored, not the old one.

Not necessarily. You can have several interpreters (and therefore several thread states) in a single thread, using Py_NewInterpreter(). It's used by mod_wsgi and probably other software. If you overwrite the old value with the new one, it may break such software.

Would it be possible to cleanup the autoTLS mappings in PyOS_AfterFork() instead?

> Not necessarily. You can have several interpreters (and therefore several thread states) in a single thread, using Py_NewInterpreter(). It's used by mod_wsgi and probably other software. If you overwrite the old value with the new one, it may break such software.
>

OK, I didn't know. Better not to change that in that case.

> Would it be possible to cleanup the autoTLS mappings in PyOS_AfterFork() instead?
>

Well, after fork, all threads have exited, so you'll be running on the
behalf of the child process' main - and only - thread, so by
definition you can't access other threads' thread-specific data, no?
As an alternate solution, I was thinking of calling
PyThread_delete_key_value(autoTLSkey) in the path of thread bootstrap,
i.e. starting in Modules/_threadmodule.c t_bootstrap. Obviously, this
should be done before calling _PyThreadState_Init, since it can also
be called from Py_NewInterpreter.
The problem is that it would require exporting autoTLSkey whose scope
is now limited to pystate.c (we could also create a small wrapper
function in pystate.c to delete the autoTLSkey, since it's already
done in PyThreadState_DeleteCurrent and PyThreadState_Delete).

> Well, after fork, all threads have exited, so you'll be running on the
> behalf of the child process' main - and only - thread, so by
> definition you can't access other threads' thread-specific data, no?

A rather good point :)
How about deleting the mapping (pthread_key_delete) and recreating it
from scratch, then?

> As an alternate solution, I was thinking of calling
> PyThread_delete_key_value(autoTLSkey) in the path of thread bootstrap,
> i.e. starting in Modules/_threadmodule.c t_bootstrap.

That would somewhat alleviate the problem, but only for Python-created
threads. Threads created through other means (for example mod_wsgi, or
database wrappers having their own thread pools) would still face the
original issue.

> How about deleting the mapping (pthread_key_delete) and recreating it
> from scratch, then?

Sounds good.
So the idea would be to retrieve the current thread's tstate, destroy the current autoTLSkey, re-create it, and re-associate the current tstate to this new key. I just did a quick test on RHEL4 and it works.
PyThread_ReinitTLS looks like a good candidate for that, but it's the same problem, autoTLSkey scope is limited to pystates.c (and I'm not sure that the tstate should be exposed to platform thread implementations).
There's also PyEval_ReinitThreads in ceval.c, exposing the autoTLSkey would make more sense (and it already knows about tstate, of course).
Where would you put it?

> > How about deleting the mapping (pthread_key_delete) and recreating it
> > from scratch, then?
> 
> Sounds good.
> So the idea would be to retrieve the current thread's tstate, destroy
> the current autoTLSkey, re-create it, and re-associate the current
> tstate to this new key. I just did a quick test on RHEL4 and it works.
> PyThread_ReinitTLS looks like a good candidate for that, but it's the
> same problem, autoTLSkey scope is limited to pystates.c (and I'm not
> sure that the tstate should be exposed to platform thread
> implementations).
> There's also PyEval_ReinitThreads in ceval.c, exposing the autoTLSkey
> would make more sense (and it already knows about tstate, of course).
> Where would you put it?

You could add a new _PyGILState_ReInit() function and call it from
PyOS_AfterFork() or PyEval_ReInitThreads().

(perhaps you also need to add a TLS-destroying function to thread.c, I
haven't looked)

Antoine, I wonder if we can restore PyThread_set_key_value to behave like a canonical TLS api function (always setting) but fix the cases that want to "set if it has not already been set" like the cases you mention.
It is very unorthodox to have such "only set if it hasn't been set before" built into your only TLS function.  This wart on python's TLS api has bugged me for yearsand it would be cool to fix it.

The init functions (that internally call the python TLS apis) could simply do a TLS get explicitly themselves, to make it explicit and clear that they _want_ to use any pre-existing tls value.

Of course, that won't fix _this_ problem (which is that the main thread's tls value gets inherited on fork).  The right way to do that is to explicitly clearthe main thread's TLS value after fork...

> Antoine, I wonder if we can restore PyThread_set_key_value to behave
> like a canonical TLS api function (always setting) but fix the cases
> that want to "set if it has not already been set" like the cases you
> mention.
> It is very unorthodox to have such "only set if it hasn't been set
> before" built into your only TLS function.  This wart on python's TLS
> api has bugged me for yearsand it would be cool to fix it.

Well, these functions are supposed to be private so, while I agree their
behaviour is a bit unusual, I'm not sure there's any point to "fix" them
if it shifts the burden of reproducing the old behaviour on another part
of our code.

> The init functions (that internally call the python TLS apis) could
> simply do a TLS get explicitly themselves, to make it explicit and
> clear that they _want_ to use any pre-existing tls value.

Granted.

> Of course, that won't fix _this_ problem (which is that the main
> thread's tls value gets inherited on fork).  The right way to do that
> is to explicitly clearthe main thread's TLS value after fork...

The main thread is fine, actually, it's the other (disappeared) threads
which cause this problem when the same TID is re-used.

Ah, using the fallback implementation of tls?  Surely this isn't a problem with the pthreads tls, I'd be surprised if it retains TLS values after fork.

> Ah, using the fallback implementation of tls?  Surely this isn't a 
> problem with the pthreads tls, I'd be surprised if it retains TLS values 
> after fork.

It surprised me too when I found that out, but it's really with the pthread TLS, on RHEL 4 and 5 (fixed in RHEL6).
See the attached test_specific.c test script.

> You could add a new _PyGILState_ReInit() function and call it from
> PyOS_AfterFork() or PyEval_ReInitThreads().

See attached tls_reinit.diff patch.
But I really find this redundant with PyThread_ReInitTLS, because what we're really doing is reinit the TLS.
Also, this calls this for every thread implementation, while it's only necessary for pthreads (and for other implementation it will redo the work done by PyThread_ReInitTLS).
So I've written another patch which does this in pthread's PyThread_ReInitTLS.

You've got much more experience than me, so it's really your call.
Actually, I kind of feel bad for adding such a hack for a pthread's bug affecting only RHEL 4 and 5, I'm wondering whether it's really worth fixing it.

> > You could add a new _PyGILState_ReInit() function and call it from
> > PyOS_AfterFork() or PyEval_ReInitThreads().
> 
> See attached tls_reinit.diff patch.

Thank you. I like this patch, except that _PyGILState_ReInit() should be
declared in the appropriate .h file, not in signalmodule.c.

> Thank you. I like this patch, except that _PyGILState_ReInit() should be
> declared in the appropriate .h file, not in signalmodule.c.

I asked myself this question when writing the patch: what's the convention  regarding functions ? Should they always be declared in a header with PyAPI_FUNC, or should this be reserved to functions exported through the API?
I've seen a couple external function declarations in several places, so I was wondering (and since this one isn't meant to be exported, I chose the later option).

> > Thank you. I like this patch, except that _PyGILState_ReInit() should be
> > declared in the appropriate .h file, not in signalmodule.c.
> 
> I asked myself this question when writing the patch: what's the
> convention  regarding functions ? Should they always be declared in a
> header with PyAPI_FUNC, or should this be reserved to functions
> exported through the API?

IMO they should always be exposed in header files. It makes them easier
to discover and re-use than with some "extern" decls sprinkled in .c
files. As for PyAPI_FUNC, I think we always use it out of convention,
although it's probably not useful for private API functions.

Here's an updated patch, tested on RHEL4U8.

New changeset f6feed6ec3f9 by Antoine Pitrou in branch '2.7':
Issue #10517: After fork(), reinitialize the TLS used by the PyGILState_*
http://hg.python.org/cpython/rev/f6feed6ec3f9

New changeset 7b7ad9a88451 by Antoine Pitrou in branch '3.2':
Issue #10517: After fork(), reinitialize the TLS used by the PyGILState_*
http://hg.python.org/cpython/rev/7b7ad9a88451

New changeset c8f283cd3e6e by Antoine Pitrou in branch 'default':
Issue #10517: After fork(), reinitialize the TLS used by the PyGILState_*
http://hg.python.org/cpython/rev/c8f283cd3e6e

It should be fixed now! Thank you.

Did anyone test this fix for case of fork() being called from Python sub interpreter?

Getting a report of fork() failing in sub interpreters under mod_wsgi that may be caused by this change. Still investigating.

Specifically throwing up error:

  Couldn't create autoTLSkey mapping

Hello,

> Did anyone test this fix for case of fork() being called from Python sub interpreter?
>

Not specifically, unless it's part of the test suite.
Anyway, unless this problem is systematic - which I doubt - it
probably wouldn't have helped.

> Getting a report of fork() failing in sub interpreters under mod_wsgi that may be caused by this change. Still investigating.
>
> Specifically throwing up error:
>
>  Couldn't create autoTLSkey mapping
>

Hmmm.
If you can, try strace or instrument the code (perror() should be
enough) to see why it's failing.
pthread_setspecific() can fail with:
- EINVAL, if the TLS key is invalid (which would be strange since we
call pthread_key_delete()/pthread_key_create() just before)
- or ENOMEM, if you run out of memory/address space

The later seems much more likely (e.g. if many child processes and
subinterpreters are created).
BTW, if this is a bug report from someone else, tell him to post here,
it'll be easier.
And we don't byte :-)

I did a quick test (calling fork() from a subinterpreter), and as
expected, I couldn't reproduce the problem.
So I still favor an OOM condition making pthread_setspecific bail out
with ENOMEM, othe other option being a nasty libc bug.
If the problem persists, please open a new issue.