_shutdown AttributeError (ignored) when linting code that uses M2Crypto

Question

I'm running lint as follows:

$ python -m pylint.lint m2test.py

with this code:

import M2Crypto
def f():
    M2Crypto.RSA.new_pub_key("").as_pem(cipher=None).split("\n")

The lint output ends with:

Exception AttributeError: '_shutdown' in <module 'threading' from '/usr/lib/python2.7/site-packages/M2Crypto-0.21.1-py2.7-linux-x86_64.egg/M2Crypto/threading.pyc'> ignored

This code works fine when run (the above is actually a minimal test case; but the full version does work). The exception is ignored, but Bitten considers this a failure, so stops on this step.

I've tried adding 'M2Crypto.threading.init()'/'M2Crypto.threading.cleanup()' around the definition of the function, but that didn't fix the problem.

How can I prevent this problem from occurring?

I'm using M2Crypto 0.21.1, pylint 0.24 and Python 2.7 (also tried 2.7.2) on Debian Lenny x86_64.

Answer 1

The exception that you are seeing is caused by a bug in the astng package (presumably “Abstract Syntax Tree, Next Generation”?) which is a toolkit on which pylint depends, written by the same people. I should note in passing that I always encourage people to use pyflakes instead of pylint when possible, because it is quick, simple, fast, and predictable, whereas pylint tries to do several kinds of deep magic that are not only slow but that can get it into exactly this kind of trouble. :)

Here are the two packages on PyPI:

http://pypi.python.org/pypi/pylint

http://pypi.python.org/pypi/astng

And note that this problem had to be, necessarily, a bug in pylint and not in your code, because pylint does not run your code in order to produce its report — imagine the havoc that could be wreaked if it did (since code being linted might delete files, etcetera)! Since your code does not get run, no amount of caution, like protecting your call with threading init() or cleanup() functions, could possibly have prevented this error — unless the code snippets happened, for other reasons, to alter the behavior we are about to investigate.

So, on to your actual exception.

I had never actually heard of _shutdown before! A quick search of the Python standard library showed its definition in threading.py but not a call of the function from anywhere; only by searching the Python C source code did I discover where in pythonrun.c, during interpreter shutdown, the function is actually called:

static void
wait_for_thread_shutdown(void)
{
    ...
    PyObject *threading = PyMapping_GetItemString(tstate->interp->modules,
                                                  "threading");
    if (threading == NULL) {
        /* threading not imported */
        PyErr_Clear();
        return;
    }
    result = PyObject_CallMethod(threading, "_shutdown", "");
    if (result == NULL) {
        PyErr_WriteUnraisable(threading);
    }
    ...
}

Apparently it is some sort of cleanup function that the threading Standard Library module requires, and they have special-cased the Python interpreter itself to make sure that it gets called.

As you can see from the code above, Python quietly and without complaint handles the case where the threading module never gets imported during a program's run. But if threading does get imported, and still exists at shutdown time, then the interpreter looks inside for a _shutdown function and goes so far as to print an error message — and then return a non-zero exit status, the cause of your problems — if it cannot call it.

So we have to discover why the threading module exists but has no _shutdown method at the moment when pylint is done examining your program and Python is exiting. Some instrumention is called for. Can we print out what the module looks like as pylint exits? We can! The pylint/lint.py module, in its last few lines, runs its “main program” by instantiating a Run class it has defined:

if __name__ == '__main__':
    Run(sys.argv[1:])

So I opened lint.py in my editor — one of the magnificent things about having each little project installed in a Python Virual Environment is that I can jump in and edit third-party code for quick experiments — and added the following print statement down at the bottom of the Run class's __init__() method:

    sys.path.pop(0)
    print "*****", sys.modules['threading'].__file__  # added by me!
    if exit:
        sys.exit(self.linter.msg_status)

I re-ran the command:

python -m pylint.lint m2test.py

And out came the __file__ string of the threading module:

***** /home/brandon/venv/lib/python2.7/site-packages/M2Crypto/threading.pyc

Well, look at that.

This is the problem!

According to this path, there actually exists an M2Crypto/threading.py module that, under all normal circumstances, should just be called M2Crypto.threading, and therefore sit in the sys.modules dictionary under the name:

sys.modules['M2Crypto.threading']

But somehow that file is also getting loaded as the main Python threading module, shadowing the official threading module that sits in the Standard Library. Because of this, the Python exit logic is quite correctly complaining that the Standard Library _shutdown() function is missing.

How could this happen? Top-level modules can only appear in paths that are listed explicitly in sys.path, not in sub-directories beneath them. This leads to a new question: is there any point during the pylint run that the …/M2Crypto/ directory itself is getting put on sys.path as though it contained top-level modules? Let's see!

We need more instrumentation: we need to have Python tell us the moment that a directory with M2Crypto in the name appears in sys.path. It will really slow things down, but let's add a trace function to pylint's __init__.py — because that is the first module that gets imported when you run -m pylint.lint — that will write an output file telling us, for every line of code executed, whether sys.path has any bad values in it:

def install_tracer():
    import sys
    output = open('mytracer.out', 'w')
    def mytracer(frame, event, arg):
        broken = any(p.endswith('M2Crypto') for p in sys.path)
        output.write('{} {}:{} {}\n'.format(
                broken, frame.f_code.co_filename, frame.f_lineno, event))
        return mytracer
    sys.settrace(mytracer)

install_tracer()
del install_tracer

Note how careful I am here: I define only one name in the module's namespace, and then carefully delete it to clean up after myself before I let pylint continue loading! And all of the resources that the trace function itself needs — namely, the sys module and the output open file — are available in the install_tracer() closure so that, from the outside, pylint looks exactly the same as always. Just in case anyone tries to introspect it, like pylint might!

This generates a file mytracer.out of about 800k lines, that each look something like this:

False /home/brandon/venv/lib/python2.7/posixpath.py:118 call

The False says that sys.path looks clean, the filename and line number are the line of code being executed, and call indicates what stage of execution the interpreter is in.

So does sys.path ever get poisoned? Let's look at just the first True or False on each line, and see how many successive lines start with each value:

$ awk '{print$1}' mytracer.out | uniq -c
 607997 False
   3173 True
   4558 False
  33217 True
   4304 False
  41699 True
   2953 False
 110503 True
  52575 False

Wow! That's a problem! For runs of several thousand lines at a time, our test case is True, which means that the interpreter is running with …/M2Crypto/ — or some variant of a pathname with M2Crypto in it — on the path, where it should not be; only the directory that contains …/M2Crypto should ever be on the path. Looking for the first False to True transition in the file, I see this:

False /home/brandon/venv/lib/python2.7/site-packages/logilab/astng/builder.py:132 line
False /home/brandon/venv/lib/python2.7/posixpath.py:118 call
...
False /home/brandon/venv/lib/python2.7/posixpath.py:124 line
False /home/brandon/venv/lib/python2.7/posixpath.py:124 return
True /home/brandon/venv/lib/python2.7/site-packages/logilab/astng/builder.py:133 line

And looking at lines 132 and 133 in the builder.py file reveals our culprit:

130    # build astng representation
131    try:
132        sys.path.insert(0, dirname(path)) # XXX (syt) iirk
133        node = self.string_build(data, modname, path)
134    finally:
135        sys.path.pop(0)

Note the comment, which is part of the original code, not an addition of my own! Obviously, XXX (syt) iirk is an exclamation in this programmer's strange native language for the phrase, “put this module's parent directory on sys.path so that pylint will break mysteriously every time someone forces pylint to introspect a package with a threading sub-module.” It is, obviously, a very compact native language. :)

If you adjust the tracing module to watch sys.modules for the actual import of threading — an exercise I will leave to the reader — you will see that it happens when SocketServer, which is imported by some other Standard Library module during the analysis, in turn tries to innocently import threading.

So let us review what is happening:

1. pylint is dangerous magic.
2. As part of its magic, if it sees you import foo, then it runs off trying to find foo.py on disk, to parse it, and to predict whether you are loading valid or invalid names from its namespace.
3. [See my comment, below.] Because you call .split() on the return value of RSA.as_pem(), pylint tries to introspect the as_pem() method, which in turn uses the M2Crypto.BIO module, which in turn makes calls that induce pylint to import threading.
4. As part of loading any module foo.py, pylint throws the directory containing foo.py on sys.path, even if that directory is inside a package, and therefore gives modules in that directory the privilege of shadowing Standard Library modules of the same name during its analysis.
5. When Python exits, it is upset that the M2Crypto.threading library is sitting where threading belongs, because it wants to run the _shutdown() method of threading.

You should report this as a bug to the pylint / astng folks at logilab.org. Tell them I sent you.

If you decide to keep using pylint after it has done this to you, then there seem to be two solutions in this case: either don't inspect code that calls M2Crypto, or import threading during the pylint import process — by sticking import threading into the pylint/__init__.py, for example — so that the module gets the chance to grab the sys.modules['threading'] slot before pylint gets all excited and tries to let M2Crypto/threading.py grab the slot instead.

In conclusion, I think the author of astng says it best: XXX (syt) iirk. Indeed.

Answer 2

Many thanks to Brandon Craig Rhodes for having tracing this down and for such a detailed post.

I've removed the offending line from astng, code available from the hg repository until logilab-astng 0.23.0 is out. And I can confirm this fixes the OP's pb.

Answer 3

This looks more like a hack but I think it works. Copying the result of "as_pem()" and splitting it.

import M2Crypto
def f():
    M2Crypto.RSA.new_pub_key("").as_pem(cipher=None)[:].split("\n")

I'm using Python 2.6.7, M2Crypto 0.21.1, pylint 0.23