Question or problem about Python programming:
I’m running a set of tests with py.test. They pass. Yippie! But I’m getting this message:
Exception KeyError: KeyError(4427427920,) in ignored
How should I go about tracking down the source of that? (I’m not using threading directly, but am using gevent.)
How to solve the problem:
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
(env)[email protected]:~$ python test.py Exception KeyError: KeyError(139924387112272,) in 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
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.
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
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
The rest of the story is obvious after reading
threading.py for a while. The
_active dictionary maps thread IDs (as returned by
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.
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
On the contrary, if monkey-patching is done before
threading is loaded, all is fine – at the time
_MainThread instance is being added to
_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 🙂
You could use this:
import sys if 'threading' in sys.modules: del sys.modules['threading'] import gevent import gevent.socket import gevent.monkey gevent.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.