microsoft / microsoft/picologging

Picologging is deadlocking when multiple threads are logging

Open
#207 2 comments 0 reactions 0 assignees View on GitHub

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

  1. Read the whole issue, then the project's contributing guide.
  2. Comment on the issue to say you are picking it up — it saves two people doing the same work.
  3. Fork the repository and make your change on a branch.
  4. 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

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.