68

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.)

3 Answers 3

222

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 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.

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 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 :)

2
  • 5
    Great answer, but TLDR; your imports are in the wrong order, make sure your very first imports are import gevent.monkey; gevent.monkey.patch_all() then whatever else you want to import
    – cerberos
    Commented Apr 18, 2013 at 20:00
  • 10
    That's exactly what I state above - import order is important. Commented Apr 18, 2013 at 20:20
19

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()
2
1

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.

5
  • 2
    +1 -- but I'm asking about how to track down the source of the issue, not how to pave over the issue.
    – kkurian
    Commented Feb 6, 2012 at 22:08
  • 2
    I'm seeing the same thing with gevent while running tests with nose. Oddly enough, when the tests all pass I don't see the error, but when a test fails I see it. I'm using monkey.patch_all(). Notably, when I do monkey.patch_all(thread=False) the errors go away.
    – millerdev
    Commented Feb 9, 2012 at 2:50
  • Tracking down the error could be fairly difficult. If I'm understanding this problem, it has to do with the background thread that is running. It seems like the problem is coming from the main loop terminating before the background thread has the ability to finish what it's doing. The interrupt from the main thread terminating must be causing the program to throw the exception. I think the best way to solve this problem is to make sure all threads have finished processing before shutting down the main process.
    – Kris
    Commented Feb 11, 2012 at 1:48
  • @Kris I agree both about the difficutly and what's likely causing the issue. What's not clear to me what's firing off threads, what the threads are doing, and why they're not properly finishing. I guess I'll just assume that it's something in gevent, that everything I'm doing is fine, and that gevent.shutdown() will just do the right thing. Thanks for your help!
    – kkurian
    Commented Feb 14, 2012 at 17:28
  • @Daniel: you may want to see my post: blog.codepainters.com/2012/11/20/… Commented Nov 20, 2012 at 13:30

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service and acknowledge you have read our privacy policy.

Not the answer you're looking for? Browse other questions tagged or ask your own question.