Ticket #751 (defect)
Opened 10 months ago
Last modified 10 months ago
logging: Python file objects are not thread-safe
Status: closed (fixed)
| Reported by: | fumanchu | Assigned to: | fumanchu |
|---|---|---|---|
| Priority: | normal | Milestone: | 3.1 |
| Component: | CherryPy code | Keywords: | |
| Cc: |
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 http://aegisknight.livejournal.com/128191.html 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.
Change History
11/12/07 16:09:30: Modified by fumanchu
- owner changed from rdelon to fumanchu.
- status changed from new to assigned.
11/12/07 18:18:53: Modified by fumanchu
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" atexit.register(exit) def wait(): while True: time.sleep(1) threading.Thread(target=wait).start()
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.
11/13/07 20:09:21: Modified by fumanchu
- status changed from assigned to closed.
- resolution set to fixed.
Fixed in [1830] by delaying main thread exit until a new EXITING state is reached.
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."