Logurus threaded lock is unsafe in async code

[theunkn0wn1]

I have deadlock conditions in one of my production codebases that uses loguru extensively for logging.

This application is async, and enqueue=true is passed to the offending sink.

Whenever await logger.complete() gets called, the application deadlocks.
This is due in large part to loguru using a threading.Lock object for it's self._lock attribute, which results in the event loop being blocked indefinitely.
The sink itself makes no loguru logging calls, so it's not immediately clear why loguru is attempting to acquire it's own lock while in a locked state.

A threaded lock should not be used in an async context, because if it blocks, the entire thread (including the event loop) block which may result in deadlocks.

If it makes a difference, the sink is implemented as

async def loguru_to_redis(message: Message, *, tx: asyncio.Queue[Message]):
    # cannot call redis directly from here -- massive connection leaks
    # instead, write to a queue we control so our worker can bulk-write messages without leaking
    await tx.put(message)

I know the deadlock is loguru, since it is at the top of the stack trace:

Attaching to process 2711936
[New LWP 2711965]
[New LWP 2711966]
[New LWP 2711967]
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib/x86_64-linux-gnu/libthread_db.so.1".
futex_abstimed_wait_cancelable (private=0, abstime=0x0, clockid=0, expected=0, futex_word=0xb3f980) at ../sysdeps/nptl/futex-internal.h:320
320	../sysdeps/nptl/futex-internal.h: No such file or directory.
(gdb) py
py-bt               py-bt-full          py-down             py-list             py-locals           py-print            py-up               python              python-interactive  
(gdb) py-bt
Traceback (most recent call first):
  <built-in method __enter__ of _thread.lock object at remote 0x7fce64d10d20>
  File "REDACTED/venv/lib/python3.8/site-packages/loguru/_logger.py", line 1076, in __await__
    with self._core.lock:
  File "/usr/lib/python3.8/asyncio/tasks.py", line 695, in _wrap_awaitable
    return (yield from awaitable.__await__())

[Delgan]

Hi @theunkn0wn1. Thanks for the report and sorry you're experiencing deadlocks caused by Loguru.

I was able to reproduce the problem locally with the following program:

import asyncio

from loguru import logger

async def sink(message):
    print(message, end="")

async def some_task():
    i = 0
    while True:
        logger.info("{}", i)
        await asyncio.sleep(0)
        i += 1

async def another_task():
    while True:
        await asyncio.sleep(0.1)
        await logger.complete()

async def main():
    logger.remove()
    logger.add(sink)

    await asyncio.gather(some_task(), another_task())

if __name__ == "__main__":
    loop = asyncio.get_event_loop()
    loop.run_until_complete(main())

This is indeed a serious bug due to logger.complete() first acquiring a threading.Lock and then using await internally.

Would you be able to update Loguru to version 0.7.0? This bug isn't fixed, but the latest version contains a mechanism that detects possible deadlocks and generates a RuntimeError instead.