Can I log with thread names/IDs in `__del__` methods?

Question

In the Python stdlib's logging library, using the %(thread) or %(threadName) macro (documented here) calls threading.current_thread (code), which takes out a threading-internal lock.

This, as per the warnings in the __del__ documentation, causes a problem if you want to log inside __del__. We've run into a single-threaded deadlocking issue caused by this.

So, my question: is there an always-safe way to log from inside __del__ methods? It'd be nice to log information about, in our case, connections being closed as the result of their owners being GC'd, but this can cause problems in the (perhaps unlikely) case that a user turns on debug logging and adds threading information to their debug configuration. I have found some posts about more explicit resource-sharing in __del__, but none about the stdlib logging behavior.

Answer 1

The CPython stdlib version of threading.current_thread() doesn't actually take a lock. The issue you ran into is particular to eventlet, which does a bunch of monkey-patching to mess with the threading system. While one approach could be to stop using eventlet, that'd probably require you to rewrite your whole application, and it doesn't fix any of the other ways you might end up trying to take a lock while logging - for example, if a __str__ method turns out to need a lock.

The closest thing to a safe way to log within __del__, or to do any complex work in __del__, is probably to instead have __del__ send a message telling some other code to do the logging instead. This would introduce a delay between __del__ and the actual logging, but such a delay is essentially unavoidable, because we must delay the logging until the resources it needs are available. It would also not guarantee that the logging call and the __del__ happen on the same thread; in a non-eventlet context, it's probably safe to call current_thread() to figure out which thread is handling __del__, but with eventlet, there probably isn't a good way.

Most ways of sending the message would have similar thread-safety or reentrancy issues, but Python 3.7 adds the queue.SimpleQueue class with a put method designed to be reentrant. Using it to manage your __del__-logging messages might look something like

import queue
del_log_queue = queue.SimpleQueue()

def stop_del_logging():
    del_log_queue.put(None)

...

def __del__(self):
    del_log_queue.put((tuple, of, relevant, information))

...

# in some other thread

while True:
    info = del_log_queue.get()
    if info is None:
        break
    relevant_logger.log(do_something_with(info))

In a non-eventlet context, it might be safe to have a logging.QueueHandler and logging.QueueListener handle the SimpleQueue, but with eventlet, that won't work, because we need to delay creation of the LogRecord until we're out of __del__.