Yelp/zygote — Issue #16: zygote can deadlock in logging
Author: Roguelazer
Created: 2011-11-16 03:53:10+00:00
State: open
Labels: bug

I've seen a few times where a zygote will get "stuck" waiting on the logging semaphore. I thing it might be a signal issue, but I'm not positive. The top of the stack trace looks like:

```
#0 sem_wait () at ../nptl/sysdeps/unix/sysv/linux/x86_64/sem_wait.S:86
#1 0x00000000004d4498 in PyThread_acquire_lock (lock=0xf20480, waitflag=128) at ../Python/thread_pthread.h:349
#2 0x00000000004d7932 in lock_PyThread_acquire_lock (self=0x7f21f4850168, args=) at ../Modules/threadmodule.c:46
#3 0x00000000004a7c5e in call_function (f=
Frame 0xf3c370, for file /usr/lib/python2.6/threading.py, line 123, in acquire (self=<_RLock(_Verbose__verbose=False, _RLock__owner=None, _RLock__block=, _RLock__count=0) at remote 0x7f21f478b590>, blocking=1, me=139783813953280), throwflag=) at ../Python/ceval.c:3750
#4 PyEval_EvalFrameEx (f=
Frame 0xf3c370, for file /usr/lib/python2.6/threading.py, line 123, in acquire (self=<_RLock(_Verbose__verbose=False, _RLock__owner=None, _RLock__block=, _RLock__count=0) at remote 0x7f21f478b590>, blocking=1, me=139783813953280), throwflag=) at ../Python/ceval.c:2412
#5 0x00000000004a9671 in PyEval_EvalCodeEx (co=0x7f21f47b2eb8, globals=, locals=, args=0x2, argcount=, kws=, kwcount=0, defs=0x7f21f30b95a8, defcount=1, closure=0x0)
at ../Python/ceval.c:3000
#6 0x00000000004a7809 in fast_function (f=
Frame 0xf3c1b0, for file /usr/lib/python2.6/logging/__init__.py, line 622, in acquire (self=, _RLock__count=0) at remote 0x7f21f478b590>, formatter=, stream=, filters=[], level=20) at remote 0xd1ba70>), throwflag=)
at ../Python/ceval.c:3846
```

and the next interesting part is at

```
#20 PyEval_EvalFrameEx (f=
Frame 0xf3b2a0, for file /usr/lib/python2.6/logging/__init__.py, line 1165, in _log (self=, _RLock__count=0) at remote 0x7f21f478b8d0>, formatter=None, filters=[], level=0) at remote 0xdc4128>, , _RLock__count=0) at remote 0xdc3710>, formatter=None, stream=, filters=[], level=10) at remote 0xdc7050>], level=10, disabled=0, propagate=1, filters=[]) at remote 0x7f21f47b35a8>, handlers=[, _RLock__count=0) at remote 0x7f21f478b590>, formatter=, _RLock__count=0) at remote 0x7f21f478b8d0>, formatter=None, filters=[], level=0) at remote 0xdc4128>, , _RLock__count=0) at remote 0xdc3710>, formatter=None, stream=, filters=[], level=10) at remote 0xdc7050>], level=10, disabled=0, propagate=1, filters=[]) at remote 0x7f21f47b35a8>, handlers=[, _RLock__count=0) at remote 0x7f21f478b590>, formatter=, stream=, arg=, kw=0x0) at ../Objects/abstract.c:2492
#24 0x00000000004a6351 in ext_do_call (f=
Frame 0xf3b0b0, for file /usr/lib/python2.6/logging/__init__.py, line 1048, in info (self=, _RLock__count=0) at remote 0x7f21f478b8d0>, formatter=None, filters=[], level=0) at remote 0xdc4128>, , _RLock__count=0) at remote 0xdc3710>, formatter=None, stream=, filters=[], level=10) at remote 0xdc7050>], level=10, disabled=0, propagate=1, filters=[]) at remote 0x7f21f47b35a8>, handlers=[, _RLock__count=0) at remote 0x7f21f478b590>, formatter=, _RLock__count=0) at remote 0x7f21f478b8d0>, formatter=None, filters=[], level=0) at remote 0xdc4128>, , _RLock__count=0) at remote 0xdc3710>, formatter=None, stream=, filters=[], level=10) at remote 0xdc7050>], level=10, disabled=0, propagate=1, filters=[]) at remote 0x7f21f47b35a8>, handlers=[, _RLock__count=0) at remote 0x7f21f478b590>, formatter=