Author vstinner
Recipients vstinner
Date 2020-03-25.23:02:19
SpamBayes Score -1.0
Marked as misclassified Yes
Message-id <1585177339.63.0.649345561784.issue40068@roundup.psfhosted.org>
In-reply-to
Content
Example of crash in master in a child process after os.fork().

The crash occurred in logging._releaseLock() called by logging._after_at_fork_child_reinit_locks().

Old issues about logging + fork

* bpo-36533 (closed): logging regression with threading + fork are mixed in 3.7.1rc2 (deadlock potential)
* bpo-37429 (open): Python hangs on fork when a logger is in use in a background thread
* bpo-6721 (open): Locks in the standard library should be sanitized on fork

--

(gdb) where
#0  0xd0563e00 in _internal_error () from /usr/lib/libpthreads.a(shr_xpg5.o)
#1  0xd0573270 in _event_notify_locked@AF34_24 () from /usr/lib/libpthreads.a(shr_xpg5.o)
#2  0xd057247c in _event_notify () from /usr/lib/libpthreads.a(shr_xpg5.o)
#3  0xd0582b2c in _cond_broadcast () from /usr/lib/libpthreads.a(shr_xpg5.o)
#4  0xd0584b0c in pthread_cond_signal@AF29_12 () from /usr/lib/libpthreads.a(shr_xpg5.o)
#5  0xd058320c in pthread_cond_signal () from /usr/lib/libpthreads.a(shr_xpg5.o)
#6  0x100a7568 in PyThread_release_lock (lock=0x200848f0) at Python/thread_pthread.h:687
#7  0x10249d38 in rlock_release (self=0x30295758, _unused_ignored=0xffffffff) at ./Modules/_threadmodule.c:357
#8  0x102109dc in method_vectorcall_NOARGS (func=0x0, args=0x302cdd80, nargsf=4294967295, kwnames=0x0) at Objects/descrobject.c:20
#9  0x10109d84 in call_function (tstate=0x200d5ca0, pp_stack=0x20e82aec, oparg=24, kwnames=0x0) at ./Include/cpython/abstract.h:118
#10 0x101164f4 in _PyEval_EvalFrameDefault (tstate=0x200d5ca0, f=0x302cdc48, throwflag=537746592) at Python/ceval.c:2586
#11 0x1011bd10 in function_code_fastcall (tstate=0x3027c972, co=0x3027d820, args=0x3052cef0, nargs=808246660, globals=0x302cdc48) at ./Include/internal/pycore_ceval.h:40
#12 0x1011c9a0 in _PyFunction_Vectorcall (func=0x302bd030, stack=0x3027c968, nargsf=0, kwnames=0x0) at Objects/call.c:366
#13 0x10109d84 in call_function (tstate=0x200d5ca0, pp_stack=0x20e82d08, oparg=56, kwnames=0x0) at ./Include/cpython/abstract.h:118
#14 0x1011662c in _PyEval_EvalFrameDefault (tstate=0x200d5ca0, f=0x3052cdb0, throwflag=537746592) at Python/ceval.c:2600
#15 0x1011bd10 in function_code_fastcall (tstate=0x3027d9ec, co=0x3027da00, args=0x0, nargs=810733296, globals=0x3052cdb0) at ./Include/internal/pycore_ceval.h:40
#16 0x1011c9a0 in _PyFunction_Vectorcall (func=0x302bd120, stack=0x3027d998, nargsf=0, kwnames=0x0) at Objects/call.c:366
#17 0x1015c848 in run_at_forkers (lst=0x302bd120, reverse=-1) at ./Include/cpython/abstract.h:118
#18 0x101682e8 in PyOS_AfterFork_Child () at ./Modules/posixmodule.c:479
#19 0x10168384 in os_fork (module=0x0, _unused_ignored=0xffffffff) at ./Modules/posixmodule.c:6264
#20 0x101e7644 in cfunction_vectorcall_NOARGS (func=0x38, args=0xffffffff, nargsf=806606368, kwnames=0x1) at Objects/methodobject.c:20
#21 0x10109d84 in call_function (tstate=0x200d5ca0, pp_stack=0x20e8304c, oparg=24, kwnames=0x0) at ./Include/cpython/abstract.h:118
#22 0x101165a8 in _PyEval_EvalFrameDefault (tstate=0x200d5ca0, f=0x306b39d0, throwflag=537746592) at Python/ceval.c:2569
#23 0x10119f80 in _PyEval_EvalCode (tstate=0x306b3b04, _co=0x306b65c8, globals=0x306a47b8, locals=0x306b3b10, args=0x306b3b08, argcount=-1, kwnames=0x30280030, kwargs=0xffffffff, kwcount=805326908, kwstep=0, defs=0x0, defcount=0, 
    kwdefs=0x0, closure=0x0, name=0x20e831f0, qualname=0x28000282) at ./Include/internal/pycore_ceval.h:40
#24 0x1011cb84 in _PyFunction_Vectorcall (func=0x0, stack=0x306a47b8, nargsf=0, kwnames=0x8) at Objects/call.c:395
#25 0x1011c270 in PyVectorcall_Call (callable=0x30625440, tuple=0x30005030, kwargs=0x306b5180) at Objects/call.c:230
#26 0x1011c510 in _PyObject_Call (tstate=0x30005030, callable=0x2003a67c <_ccCGOhKO.rw_+21820>, args=0x306b5180, kwargs=0x30625440) at Objects/call.c:265
#27 0x1011c71c in PyObject_Call (callable=0x0, args=0xffffffff, kwargs=0xffffffff) at Objects/call.c:292
#28 0x10116ad4 in _PyEval_EvalFrameDefault (tstate=0x200d5ca0, f=0x306d5760, throwflag=0) at Python/ceval.c:4198
#29 0x1011bd10 in function_code_fastcall (tstate=0x3029a7d2, co=0x302c07a8, args=0x3066edac, nargs=812472476, globals=0x306d5760) at ./Include/internal/pycore_ceval.h:40
#30 0x1011c9a0 in _PyFunction_Vectorcall (func=0x302c93a0, stack=0x3029a7b8, nargsf=1, kwnames=0x0) at Objects/call.c:366
#31 0x10109d84 in call_function (tstate=0x200d5ca0, pp_stack=0x20e8357c, oparg=56, kwnames=0x0) at ./Include/cpython/abstract.h:118
#32 0x101164f4 in _PyEval_EvalFrameDefault (tstate=0x200d5ca0, f=0x3066ec70, throwflag=537746592) at Python/ceval.c:2586
#33 0x1011bd10 in function_code_fastcall (tstate=0x302ac200, co=0x302c0a00, args=0x306cb16c, nargs=812051888, globals=0x3066ec70) at ./Include/internal/pycore_ceval.h:40
#34 0x1011c9a0 in _PyFunction_Vectorcall (func=0x302c9530, stack=0x302ac180, nargsf=1, kwnames=0x0) at Objects/call.c:366
#35 0x10109d84 in call_function (tstate=0x200d5ca0, pp_stack=0x20e8379c, oparg=56, kwnames=0x0) at ./Include/cpython/abstract.h:118
#36 0x101164f4 in _PyEval_EvalFrameDefault (tstate=0x200d5ca0, f=0x306cb030, throwflag=537746592) at Python/ceval.c:2586
#37 0x1011bd10 in function_code_fastcall (tstate=0x302a4930, co=0x302c0820, args=0x20e83928, nargs=812429680, globals=0x306cb030) at ./Include/internal/pycore_ceval.h:40
#38 0x1011c9a0 in _PyFunction_Vectorcall (func=0x302c93f0, stack=0x302a4928, nargsf=1, kwnames=0x0) at Objects/call.c:366
#39 0x10220394 in method_vectorcall (method=0x302c93f0, args=0x3000503c, nargsf=56, kwnames=0x0) at ./Include/cpython/abstract.h:118
#40 0x1011c270 in PyVectorcall_Call (callable=0x301e3ed0, tuple=0x30005030, kwargs=0x0) at Objects/call.c:230
#41 0x1011c510 in _PyObject_Call (tstate=0x30005030, callable=0x2003878c <_ccCGOhKO.rw_+13900>, args=0x0, kwargs=0x301e3ed0) at Objects/call.c:265
#42 0x1011c71c in PyObject_Call (callable=0x0, args=0xffffffff, kwargs=0xffffffff) at Objects/call.c:292
#43 0x1024a158 in t_bootstrap (boot_raw=0x301df820) at ./Modules/_threadmodule.c:1011
#44 0x100a683c in pythread_wrapper (arg=0xffffffff) at Python/thread_pthread.h:235
#45 0xd055df68 in _pthread_body () from /usr/lib/libpthreads.a(shr_xpg5.o)
#46 0x00000000 in ?? ()

(gdb) frame 10
#10 0x101164f4 in _PyEval_EvalFrameDefault (tstate=0x200d5ca0, f=0x302cdc48, throwflag=537746592) at Python/ceval.c:2586
2586                PyObject *v = GETLOCAL(oparg);
(gdb) p (char*)( ((PyASCIIObject*)f->f_code->co_name) + 1)
$16 = 0x3027ad28 "_releaseLock"
(gdb) p (char*)( ((PyASCIIObject*)f->f_code->co_filename) + 1)
$17 = 0x3026d4c0 "/home/vstinner/python/master/Lib/logging/__init__.py"

(gdb) frame 14
#14 0x1011662c in _PyEval_EvalFrameDefault (tstate=0x200d5ca0, f=0x3052cdb0, throwflag=537746592) at Python/ceval.c:2600
2600                PyObject *cell = freevars[oparg];
(gdb)  p (char*)( ((PyASCIIObject*)f->f_code->co_name) + 1)
$18 = 0x30278af0 "_after_at_fork_child_reinit_locks"
(gdb) p (char*)( ((PyASCIIObject*)f->f_code->co_filename) + 1)
$19 = 0x3026d4c0 "/home/vstinner/python/master/Lib/logging/__init__.py"


(gdb) info threads
  Id   Target Id         Frame 
  2    Thread 1745 (tid 70975785, running) aix-thread: ptrace (52, 70975785) returned -1 (errno = 3 The process does not exist.)
History
Date User Action Args
2020-03-25 23:02:19vstinnersetrecipients: + vstinner
2020-03-25 23:02:19vstinnersetmessageid: <1585177339.63.0.649345561784.issue40068@roundup.psfhosted.org>
2020-03-25 23:02:19vstinnerlinkissue40068 messages
2020-03-25 23:02:19vstinnercreate