Dead on Import

The Zope profile in slc.ipythonprofiles provides a convenient way to access a Zope/Plone instance from an IPython shell with all the bells and whistles like readline support.

The ipython_config.py is very small:

c = get_config()
c.InteractiveShellApp.ignore_old_config=True
c.TerminalIPythonApp.exec_lines = [ "import zdebug" ]

The zdebug module does the heavy lifting.

class ZopeDebug(object):
    [...]


def main():
    [...]
    zope_debug = ZopeDebug()
    [...]


main()

Recently it failed me in some installations. It just froze at some point during startup. Investigating revealed that the ZEO client thread was created but never reported back as having started. Multithreaded code is of course somewhat trickier to debug. In this case not even attaching a PDB’s stdin and stdout to a different terminal (see a future blog post, maybe) worked. The PDB call just froze up as well. But with a couple of print statements I figured out where exactly execution stopped. It was at an import statement.

In trollius.events:

def _init_event_loop_policy():
    global _event_loop_policy
    with _lock:
        if _event_loop_policy is None:  # pragma: no branch
            from . import DefaultEventLoopPolicy
            _event_loop_policy = DefaultEventLoopPolicy()

This seemed odd to me. What could go wrong at an import? Well, a lot, as a little more thought made me realize. This import however seemed pretty straightforward. There was a bit of code that decided what exactly DefaultEventLoopPolicy would be at import time, but it didn’t seem like something that would fail this badly.

Searching the web for deadlocks at import time led me to a stackoverflow post about imports inside threads. It said that there is an import lock that makes imports thread safe, and that prior to Python 3.3 this lock was not per-module, so it was possible to get deadlocks.

This matched my situation - the issue only occurred on Python 2. To be exact, it only occurred when using Plone 5.2.x with Python 2. On Python 3 the asyncio module from the standard library is used instead of trollius. Prior to Plone 5.2 ZServer was used instead of WSGI.

Looking back at ipython_config.py and zdebug.py I realized that the whole initialization code was running inside the import zdebug statement, because the main() call happened at module level in zdebug. This meant the import lock was already taken, and the newly spawned thread was unable to do an import before the first import was finished. However, it needed to do that import to finish starting up and to allow the first import to terminate. A classic deadlock.

The solution is minimal: move the main() call out of the zdebug module and into ipython_config.py:

c = get_config()
c.InteractiveShellApp.ignore_old_config=True
c.TerminalIPythonApp.exec_lines = [ "import zdebug", "zdebug.main()" ]

and

class ZopeDebug(object):
    [...]


def main():
    [...]
    zope_debug = ZopeDebug()
    [...]