I'm running a set of tests with py.test. They pass. Yippie! But I'm getting this message:
Exception KeyError: KeyError(4427427920,) in <module 'threading' from '/System/Library/Frameworks/Python.framework/Versions/2.7/lib/python2.7/threading.pyc'> ignored
How should I go about tracking down the source of that? (I'm not using threading directly, but am using gevent.)
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.
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 threading
import 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.
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 sys
if '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 :)