Issue #751 resolved

logging: Python file objects are not thread-safe

Robert Brewer
created an issue

This bit me while running the autoreload test in test_states; the test runs CP in a new process, and that process execv's to a third process. That third process consistently crashes with the call stack:

{{{ ntdll!RtlEnterCriticalSection+0x12 MSVCR71!_crtGetLocaleInfoW+0x29e python24!PyFile_GetLine+0x43f python24!PyCFunction_Call+0x47 python24!PyEval_CallObject+0x2af python24!PyEval_EvalFrame+0x77c python24!PyEval_EvalFrame+0x1b44 python24!PyEval_GetFuncDesc+0x11b }}}

The other thread stacks: {{{ ntdll.dll!KiFastSystemCallRet kernel32.dll!WaitForSingleObject+0x12 python24.dll!PySys_WriteStderr+0x14d python24.dll!PyTuple_Type }}}

{{{ ntdll.dll!KiFastSystemCallRet kernel32.dll!BaseThreadInitThunk+0x12 ntdll.dll!LdrInitializeThunk+0x4d }}}

See for a similar issue.

Oddly, test_states_demo has a reference to state.log, which is the pyconquer log from the parent. Not sure why, or if this is the resource in conflict.

Comments (5)

  1. Robert Brewer reporter

    It seems that the access.log is the culprit. When the process autoreloads, the child process has two handles to the same file, since atexit is not run on execv, and file handles are inherited:

    [ Windows docs]: "Files that are open when an _exec call is made remain open in the new process."

    [ Unix docs]: "File descriptors open in the calling process image remain open in the new process image, except for those whose close-on-exec flag FD_CLOEXEC is set; (see fcntl(2)). For those file descriptors that remain open, all attributes of the open file description, including file locks, remain unchanged."

  2. Robert Brewer reporter

    There's also the issue of atexit handlers running when the main thread exits, regardless of whether other threads are running or not. Proof:

    import atexit
    import threading
    import time
    def exit():
        print "atexit handler called"
    def wait():
        while True:

    This is a problem for test_states because it calls engine.stop() in a request method; the main thread is released from engine.block() and exits, logging.shutdown is called by atexit, but then the request thread tries to write "Bus STOPPED" to the error log and a line for itself to the access log.

  3. Log in to comment