KeyError in module 'threading' after a successful py.test run

I observed a similar issue and decided to see what's going on exactly - let me describe my findings. I hope someone will find it useful.

Short story

It is indeed related to monkey-patching the threading module. In fact, I can easily trigger the exception by importing the threading module before monkey-patching threads. The following 2 lines are enough:

import threadingimport gevent.monkey; gevent.monkey.patch_thread()

When executed it spits the message about ignored KeyError:

(env)czajnik@autosan:~$ python test.py Exception KeyError: KeyError(139924387112272,) in <module 'threading' from '/usr/lib/python2.7/threading.pyc'> ignored

If you swap the import lines, the problem is gone.

Long story

I could stop my debugging here, but I decided it's worth to understand the exact cause of the problem.

First step was to find the code that prints the message about ignored exception. It was a little hard for me to find it (grepping for Exception.*ignored yielded nothing), but grepping around CPython source code I've eventually found a function called void PyErr_WriteUnraisable(PyObject *obj) in Python/error.c, with a very interesting comment:

/* Call when an exception has occurred but there is no way for Python   to handle it.  Examples: exception in __del__ or during GC. */

I decided to check who's calling it, with a little help from gdb, just to get the following C-level stack trace:

#0  0x0000000000542c40 in PyErr_WriteUnraisable ()#1  0x00000000004af2d3 in Py_Finalize ()#2  0x00000000004aa72e in Py_Main ()#3  0x00007ffff68e576d in __libc_start_main (main=0x41b980 <main>, argc=2,    ubp_av=0x7fffffffe5f8, init=<optimized out>, fini=<optimized out>,     rtld_fini=<optimized out>, stack_end=0x7fffffffe5e8) at libc-start.c:226#4  0x000000000041b9b1 in _start ()

Now we can clearly see that the exception is thrown while Py_Finalize executes - this call is responsible for shutting down the Python interpreter, freeing allocated memory, etc. It's called just before exitting.

Next step was to look at Py_Finalize() code (it's in Python/pythonrun.c). The very first call it makes is wait_for_thread_shutdown() - worth looking at, as we know the problem is related to threading. This function in turn calls _shutdown callable in the threading module. Good, we can go back to python code now.

Looking at threading.py I've found the following interesting parts:

class _MainThread(Thread):    def _exitfunc(self):        self._Thread__stop()        t = _pickSomeNonDaemonThread()        if t:            if __debug__:                self._note("%s: waiting for other threads", self)        while t:            t.join()            t = _pickSomeNonDaemonThread()        if __debug__:            self._note("%s: exiting", self)        self._Thread__delete()# Create the main thread object,# and make it available for the interpreter# (Py_Main) as threading._shutdown._shutdown = _MainThread()._exitfunc

Clearly, the responsibility of threading._shutdown() call is to join all non-daemon threads and delete main thread (whatever that means exactly). I decided to patch threading.py a bit - wrap the whole _exitfunc() body with try/except and print the stack trace with traceback module. This gave the following trace:

Traceback (most recent call last):  File "/usr/lib/python2.7/threading.py", line 785, in _exitfunc    self._Thread__delete()  File "/usr/lib/python2.7/threading.py", line 639, in __delete    del _active[_get_ident()]KeyError: 26805584

Now we know the exact place where the exception is thrown - inside Thread.__delete() method.

The rest of the story is obvious after reading threading.py for a while. The _active dictionary maps thread IDs (as returned by _get_ident()) to Thread instances, for all threads created. When threading module is loaded, an instance of _MainThread class is always created and added to _active (even if no other threads are explicitly created).

The problem is that one of the methods patched by gevent's monkey-patching is _get_ident() - original one maps to thread.get_ident(), monkey-patching replaces it with green_thread.get_ident(). Obviously both calls return different IDs for main thread.

Now, if threading module is loaded before monkey-patching, _get_ident() call returns one value when _MainThread instance is created and added to _active, and another value at the time _exitfunc() is called - hence KeyError in del _active[_get_ident()].

On the contrary, if monkey-patching is done before threading is loaded, all is fine - at the time _MainThread instance is being added to _active, _get_ident() is already patched, and the same thread ID is returned at cleanup time. That's it!

To make sure I import modules in the right order, I added the following snippet to my code, just before monkey-patching call:

import sysif 'threading' in sys.modules:        raise Exception('threading module loaded before patching!')import gevent.monkey; gevent.monkey.patch_thread()

I hope you find my debugging story useful :)

You could use this:

import sysif 'threading' in sys.modules:    del sys.modules['threading']import geventimport gevent.socketimport gevent.monkeygevent.monkey.patch_all()

I had a similar problem with a gevent prototype script.

The Greenlet callback was executing fine and I was synchronizing back to the main thread via g.join(). For my problem, I had to call gevent.shutdown() to shutdown (what I assume is) the Hub. After I manually shutdown the event loop, the program terminates properly without that error.