microsoft / microsoft/picologging
Picologging is deadlocking when multiple threads are logging
Nobody has claimed this yet.
- Dominant language
- Python
- Stars
- 779
- Forks
- 29
- Avg merge
- 23h 3m
- Merged PRs (30d)
- 1
Description
We have an issue with picologging in our application that uses multiple threads. After some time it deadlocks.
I managed to reproduce this behavior with a very simple script:
import threading
import picologging as logging
if __name__ == '__main__':
logging.basicConfig(level=logging.INFO, format='[%(name)s] [%(thread)d]: %(message)s')
def log_in_a_loop(name: str):
logger = logging.getLogger(name)
while True:
logger.info('log message')
threading.Thread(name="worker-1", target=log_in_a_loop, args=["worker-1"]).start()
log_in_a_loop("main-thread")
When I replace picologging with the standard logging package the code does not deadlock
This script deadlocks almost instantaneously after being run, producing only a handful of log messages.
The analysis with pystack (attached at the bottom) shows that one thread is holding a GIL and trying to acquire a lock in Handler_handle while the other thread that does not have the GIL is blocked in StreamHandler_emit on pthread_cond_timedwait.
I looked at the picologging source code and I don't see any call to a timedwait on condition.
Traceback for thread 37490 (python) [] (most recent call last):
(C) File "../sysdeps/unix/sysv/linux/x86_64/clone.S", line 95, in __clone (/usr/lib/x86_64-linux-gnu/libc-2.31.so)
(C) File "/build/glibc-wuryBv/glibc-2.31/nptl/pthread_create.c", line 477, in start_thread (/usr/lib/x86_64-linux-gnu/libpthread-2.31.so)
(Python) File "/usr/lib/python3.10/threading.py", line 973, in _bootstrap
self._bootstrap_inner()
Arguments:
self: <Thread at 0x7fa5dc6b3fd0>
(Python) File "/usr/lib/python3.10/threading.py", line 1016, in _bootstrap_inner
self.run()
Arguments:
self: <Thread at 0x7fa5dc6b3fd0>
(Python) File "/usr/lib/python3.10/threading.py", line 953, in run
self._target(*self._args, **self._kwargs)
Arguments:
self: <Thread at 0x7fa5dc6b3fd0>
(Python) File "/home/piotrjanisz/work/logging_test/main.py", line 12, in log_in_a_loop
logger.info('log message')
Arguments:
name: "worker-1"
Locals:
logger: <picologging.Logger at 0x7fa5dbb08030>
(C) File "???", line 0, in Logger_logAndHandle(LoggerT*, _object*, _object*, unsigned short) (/home/piotrjanisz/.virtualenvs/logging_test/lib/python3.10/site-packages/picologging/_picologging.cpython-310-x86_64-linux-gnu.so)
(C) File "???", line 0, in Handler_handle(Handler*, _object*) (/home/piotrjanisz/.virtualenvs/logging_test/lib/python3.10/site-packages/picologging/_picologging.cpython-310-x86_64-linux-gnu.so)
(C) File "???", line 0, in StreamHandler_emit(StreamHandler*, _object* const*, long) (/home/piotrjanisz/.virtualenvs/logging_test/lib/python3.10/site-packages/picologging/_picologging.cpython-310-x86_64-linux-gnu.so)
(C) File "/build/glibc-wuryBv/glibc-2.31/nptl/pthread_cond_wait.c", line 665, in pthread_cond_timedwait@@GLIBC_2.3.2 (/usr/lib/x86_64-linux-gnu/libpthread-2.31.so)
(C) File "/build/glibc-wuryBv/glibc-2.31/nptl/pthread_cond_wait.c", line 520, in __pthread_cond_wait_common (inlined) (/usr/lib/x86_64-linux-gnu/libpthread-2.31.so)
(C) File "../sysdeps/nptl/futex-internal.h", line 320, in futex_abstimed_wait_cancelable (inlined) (/usr/lib/x86_64-linux-gnu/libpthread-2.31.so)
Traceback for thread 37489 (python) [Has the GIL] (most recent call last):
(C) File "???", line 0, in _start (/usr/bin/python3.10)
(C) File "../csu/libc-start.c", line 308, in __libc_start_main (/usr/lib/x86_64-linux-gnu/libc-2.31.so)
(C) File "???", line 0, in Py_BytesMain (/usr/bin/python3.10)
(C) File "???", line 0, in Py_RunMain (/usr/bin/python3.10)
(Python) File "/home/piotrjanisz/work/logging_test/main.py", line 17, in <module>
log_in_a_loop("main-thread")
(Python) File "/home/piotrjanisz/work/logging_test/main.py", line 12, in log_in_a_loop
logger.info('log message')
Arguments:
name: "main-thread"
Locals:
logger: <picologging.Logger at 0x7fa5dbb080f0>
(C) File "???", line 0, in Logger_logAndHandle(LoggerT*, _object*, _object*, unsigned short) (/home/piotrjanisz/.virtualenvs/logging_test/lib/python3.10/site-packages/picologging/_picologging.cpython-310-x86_64-linux-gnu.so)
(C) File "???", line 0, in Handler_handle(Handler*, _object*) (/home/piotrjanisz/.virtualenvs/logging_test/lib/python3.10/site-packages/picologging/_picologging.cpython-310-x86_64-linux-gnu.so)
(C) File "../nptl/pthread_mutex_lock.c", line 115, in __pthread_mutex_lock (/usr/lib/x86_64-linux-gnu/libpthread-2.31.so)
(C) File "/build/glibc-wuryBv/glibc-2.31/nptl/lowlevellock.c", line 52, in __lll_lock_wait (/usr/lib/x86_64-linux-gnu/libpthread-2.31.so)
Contributor guide
No contributing guide indexed for this repository
First steps
- Read the whole issue, then the project's contributing guide.
- Comment on the issue to say you are picking it up — it saves two people doing the same work.
- Fork the repository and make your change on a branch.
- Open a pull request that references the issue number.
Research direction
Run the reported two-thread reproducer first, then inspect the Logger_logAndHandle, Handler_handle, and StreamHandler_emit entry points shown in the stack traces. Trace the lock and GIL interaction and add a regression test for concurrent logging. Done means the reproducer no longer deadlocks while preserving log output.
Written by the indexing model from the issue text.
Assessment
- Tech stack
- python
- Domain
- developer-experience
- Issue type
- Bug
- Difficulty
- 4/5
- Estimated time
- 3-5 days
- Activity status
- Stale
- Clarity
- Mostly clear
- Newbie friendliness
- 35/100