[issue24645] logging.handlers.QueueHandler should not lock when handling a record

[Justin Bronder]

Justin Bronder added the comment:

On 16/07/15 20:03 +0000, R. David Murray wrote:
> 
> R. David Murray added the comment:
> 
> Can you expand on the deadlock?  Are you saying that the "extra" locking is causing the deadlock?
> 
> ----------
> nosy: +r.david.murray, vinay.sajip
> versions:  -Python 3.2, Python 3.3
> 
> _______________________________________
> Python tracker <report at bugs.python.org>
> <http://bugs.python.org/issue24645>
> _______________________________________

Sure, here is the simplest example of the deadlock I could come up with.  Using
__repr__() in the way presented is pretty stupid in this case but it does make
sense if you have objects which are backed by a database where communication is
handled in a separate thread.

What happens is this:

1.  The main thread calls into the logger, handle() grabs the I/O lock.
2.  String expansion of the Blah instance begins, this makes a request to the
    second thread.
3.  The second thread wants to log prior to responding, it gets stuck waiting for
    the I/O lock in handle()

import logging
import logging.handlers
import queue
import types
import threading

fmt = logging.Formatter('LOG: %(message)s')

stream = logging.StreamHandler()
stream.setFormatter(fmt)

log_queue = queue.Queue(-1)
queue_handler = logging.handlers.QueueHandler(log_queue)
queue_listener = logging.handlers.QueueListener(log_queue, stream)
queue_listener.start()

def handle(self, record):
    rv = self.filter(record)
    if rv:
        self.emit(record)
    return rv
# Uncomment to remove deadlock
#queue_handler.handle = types.MethodType(handle, queue_handler)

logger = logging.getLogger()
logger.addHandler(queue_handler)
logger.setLevel(logging.DEBUG)

class Blah(object):
    def __init__(self):
        self._in = queue.Queue()
        self._out = queue.Queue()

        def pub():
            self._in.get(block=True)
            logging.info('Got a request')
            self._out.put('hi')

        self._pub_thread = threading.Thread(target=pub)
        self._pub_thread.start()

    def __repr__(self):
        self._in.put('gimme data')
        return self._out.get()

    def __del__(self):
        self._pub_thread.join()

b = Blah()
logger.info('About to log')
logger.info('blah = %s', b)
queue_listener.stop()

----------

_______________________________________
Python tracker <report at bugs.python.org>
<http://bugs.python.org/issue24645>
_______________________________________