classification
Title: logging.handlers.QueueHandler should not lock when handling a record
Type: Stage:
Components: Library (Lib) Versions: Python 3.6, Python 3.4, Python 3.5
process
Status: closed Resolution: not a bug
Dependencies: Superseder:
Assigned To: Nosy List: jsbronder, r.david.murray, vinay.sajip
Priority: normal Keywords: patch

Created on 2015-07-16 19:03 by jsbronder, last changed 2015-07-25 21:04 by vinay.sajip. This issue is now closed.

Files
File name Uploaded Description Edit
queue-handler-no-lock.patch jsbronder, 2015-07-16 19:03 review
Messages (7)
msg246812 - (view) Author: Justin Bronder (jsbronder) * Date: 2015-07-16 19:03
The Queue backing the QueueHandler is already sufficiently locking for thread-safety.

This isn't a huge issue, but the QueueHandler is a very nice built-in which could be used to work around a deadlock I've encountered several times.  In brief, functions which can cause other threads to log being called from either __repr__() or __str__().
msg246816 - (view) Author: R. David Murray (r.david.murray) * (Python committer) Date: 2015-07-16 20:03
Can you expand on the deadlock?  Are you saying that the "extra" locking is causing the deadlock?
msg246827 - (view) Author: Justin Bronder (jsbronder) * Date: 2015-07-16 20:54
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@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()
msg246830 - (view) Author: R. David Murray (r.david.murray) * (Python committer) Date: 2015-07-16 21:02
I can't see doing io in __repr__ ever making sense, so I'm not sure this is a use case we care about.  But Vinay might not have any objection to removing locking if it is redundant, so we'll see what he has to say.
msg246837 - (view) Author: Vinay Sajip (vinay.sajip) * (Python committer) Date: 2015-07-16 23:21
I'm not sure I want to make a special case just to support what seems like a somewhat pathological use case (no offence intended).

If you need this, there's no reason you couldn't subclass QueueHandler and override handle(), is there?
msg246838 - (view) Author: Justin Bronder (jsbronder) * Date: 2015-07-16 23:46
On 16/07/15 23:21 +0000, Vinay Sajip wrote:
> 
> Vinay Sajip added the comment:
> 
> I'm not sure I want to make a special case just to support what seems like a somewhat pathological use case (no offence intended).
> 
> If you need this, there's no reason you couldn't subclass QueueHandler and override handle(), is there?

Hey, no offense taken, it wasn't even my code that tripped on this, I
just got the pleasure of debugging it!

Anyways, it's up to you all if you want to include this, as you
mentioned, it's easy enough to work around and I've already done so.

However, the reason I submitted the patch is because I believe using the
I/O lock is redundant as the Queue is handling the necessary
synchronization already.
msg246839 - (view) Author: Vinay Sajip (vinay.sajip) * (Python committer) Date: 2015-07-17 00:32
I agree the lock could be seen as redundant as there are no shared data structures used by the current implementation of the enqueue and prepare methods (which are called after the lock is acquired), but users could potentially override those methods in subclasses in ways that require locking to be thread-safe. Currently, people overriding emit() [or code called from there] know that any state they manipulate there is protected by the handler lock - and this would not be the case if I implemented your suggestion. It could certainly break subclasses of QueueHandler which are out there in the wild.

Note that the reference to locking is there in the Handler.handle docstring - https://docs.python.org/library/logging.html#logging.Handler.handle - so changing it would change the contract which is documented.
History
Date User Action Args
2015-07-25 21:04:13vinay.sajipsetstatus: open -> closed
resolution: not a bug
2015-07-17 00:32:42vinay.sajipsetmessages: + msg246839
2015-07-16 23:46:19jsbrondersetmessages: + msg246838
2015-07-16 23:21:02vinay.sajipsetmessages: + msg246837
2015-07-16 21:02:20r.david.murraysetmessages: + msg246830
2015-07-16 20:54:17jsbrondersetmessages: + msg246827
2015-07-16 20:03:22r.david.murraysetnosy: + vinay.sajip, r.david.murray

messages: + msg246816
versions: - Python 3.2, Python 3.3
2015-07-16 19:03:19jsbrondercreate