Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

logging.handlers.QueueHandler should not lock when handling a record #68833

Closed
jsbronder mannequin opened this issue Jul 16, 2015 · 7 comments
Closed

logging.handlers.QueueHandler should not lock when handling a record #68833

jsbronder mannequin opened this issue Jul 16, 2015 · 7 comments
Labels
stdlib Python modules in the Lib dir

Comments

@jsbronder
Copy link
Mannequin

jsbronder mannequin commented Jul 16, 2015

BPO 24645
Nosy @vsajip, @bitdancer, @jsbronder
Files
  • queue-handler-no-lock.patch
  • Note: these values reflect the state of the issue at the time it was migrated and might not reflect the current state.

    Show more details

    GitHub fields:

    assignee = None
    closed_at = <Date 2015-07-25.21:04:13.354>
    created_at = <Date 2015-07-16.19:03:19.727>
    labels = ['invalid', 'library']
    title = 'logging.handlers.QueueHandler should not lock when handling a record'
    updated_at = <Date 2015-07-25.21:04:13.353>
    user = 'https://github.com/jsbronder'

    bugs.python.org fields:

    activity = <Date 2015-07-25.21:04:13.353>
    actor = 'vinay.sajip'
    assignee = 'none'
    closed = True
    closed_date = <Date 2015-07-25.21:04:13.354>
    closer = 'vinay.sajip'
    components = ['Library (Lib)']
    creation = <Date 2015-07-16.19:03:19.727>
    creator = 'jsbronder'
    dependencies = []
    files = ['39935']
    hgrepos = []
    issue_num = 24645
    keywords = ['patch']
    message_count = 7.0
    messages = ['246812', '246816', '246827', '246830', '246837', '246838', '246839']
    nosy_count = 3.0
    nosy_names = ['vinay.sajip', 'r.david.murray', 'jsbronder']
    pr_nums = []
    priority = 'normal'
    resolution = 'not a bug'
    stage = None
    status = 'closed'
    superseder = None
    type = None
    url = 'https://bugs.python.org/issue24645'
    versions = ['Python 3.4', 'Python 3.5', 'Python 3.6']

    @jsbronder
    Copy link
    Mannequin Author

    jsbronder mannequin commented Jul 16, 2015

    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__().

    @jsbronder jsbronder mannequin added the stdlib Python modules in the Lib dir label Jul 16, 2015
    @bitdancer
    Copy link
    Member

    Can you expand on the deadlock? Are you saying that the "extra" locking is causing the deadlock?

    @jsbronder
    Copy link
    Mannequin Author

    jsbronder mannequin commented Jul 16, 2015

    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()

    @bitdancer
    Copy link
    Member

    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.

    @vsajip
    Copy link
    Member

    vsajip commented Jul 16, 2015

    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?

    @jsbronder
    Copy link
    Mannequin Author

    jsbronder mannequin commented Jul 16, 2015

    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.

    @vsajip
    Copy link
    Member

    vsajip commented Jul 17, 2015

    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.

    @vsajip vsajip closed this as completed Jul 25, 2015
    @vsajip vsajip added the invalid label Jul 25, 2015
    @ezio-melotti ezio-melotti transferred this issue from another repository Apr 10, 2022
    Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
    Labels
    stdlib Python modules in the Lib dir
    Projects
    None yet
    Development

    No branches or pull requests

    2 participants