classification
Title: logging's QueueListener drops log messages
Type: Stage: resolved
Components: Library (Lib) Versions: Python 3.6, Python 3.5
process
Status: closed Resolution: fixed
Dependencies: Superseder:
Assigned To: Nosy List: petr.viktorin, python-dev, vinay.sajip
Priority: normal Keywords:

Created on 2016-09-01 15:15 by petr.viktorin, last changed 2016-09-08 00:25 by python-dev. This issue is now closed.

Files
File name Uploaded Description Edit
test.py petr.viktorin, 2016-09-01 15:15 Test script
Messages (3)
msg274139 - (view) Author: Petr Viktorin (petr.viktorin) * (Python committer) Date: 2016-09-01 15:15
There are two "barrier" like abstractions on Lib/logging/handlers.py in the _monitor method.

First _monitor has two loops, what is already kind of a hint something is not right.

Second, it has two ways to exit the loop, that also exit the thread:
1) The _stop threading.Event is "set"
2) The _sentinel object is added to the queue

The problem is, the documentation says that the correct way to not loose records, the stop method must be called, but, the stop method just sets the _stop object and then adds the _sentinel object to the queue.

The loop stops when noticing that _stop is set, and then enters a second version of the loop, trying again to see the _sentinel object, but this time with non blocking read.

The test case shows the problem, but it also hints about the race conditions by the fact that running the test case under "taskset 1" works, so, to reproduce the issue, run the test under a multiprocessor environment.

The proper solution would be to have a proper locking mechanism, otherwise, the _stop object should not be used, and rely only in seeing the _sentinel field; this is what the class DeterministicQueueListener does in the test case.


(Reported by Paulo Andrade at https://bugzilla.redhat.com/show_bug.cgi?id=1370484 )
msg274306 - (view) Author: Vinay Sajip (vinay.sajip) * (Python committer) Date: 2016-09-03 16:05
Removed 3.3 and 3.4 as they are not in scope for non-security issues.
msg274931 - (view) Author: Roundup Robot (python-dev) (Python triager) Date: 2016-09-08 00:25
New changeset 121b5b41c9e8 by Vinay Sajip in branch 'default':
Fixes #27930: improved QueueListener behaviour.
https://hg.python.org/cpython/rev/121b5b41c9e8

New changeset b2ea0ede3753 by Vinay Sajip in branch '3.5':
Fixes #27930: improved QueueListener behaviour.
https://hg.python.org/cpython/rev/b2ea0ede3753

New changeset 89b185372b2c by Vinay Sajip in branch 'default':
Closes #27930: Merged fix from 3.5.
https://hg.python.org/cpython/rev/89b185372b2c
History
Date User Action Args
2016-09-08 00:25:23python-devsetstatus: open -> closed

nosy: + python-dev
messages: + msg274931

resolution: fixed
stage: resolved
2016-09-03 16:05:42vinay.sajipsetmessages: + msg274306
versions: - Python 3.3, Python 3.4
2016-09-01 15:15:59petr.viktorincreate