logging's QueueListener drops log messages

[encukou]

BPO	27930
Nosy	@vsajip, @encukou
Files	test.py: Test script

^{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 2016-09-08.00:25:23.814>
created_at = <Date 2016-09-01.15:15:59.610>
labels = ['library']
title = "logging's QueueListener drops log messages"
updated_at = <Date 2016-09-08.00:25:23.766>
user = 'https://github.com/encukou'

bugs.python.org fields:

activity = <Date 2016-09-08.00:25:23.766>
actor = 'python-dev'
assignee = 'none'
closed = True
closed_date = <Date 2016-09-08.00:25:23.814>
closer = 'python-dev'
components = ['Library (Lib)']
creation = <Date 2016-09-01.15:15:59.610>
creator = 'petr.viktorin'
dependencies = []
files = ['44323']
hgrepos = []
issue_num = 27930
keywords = []
message_count = 3.0
messages = ['274139', '274306', '274931']
nosy_count = 3.0
nosy_names = ['vinay.sajip', 'petr.viktorin', 'python-dev']
pr_nums = []
priority = 'normal'
resolution = 'fixed'
stage = 'resolved'
status = 'closed'
superseder = None
type = None
url = 'https://bugs.python.org/issue27930'
versions = ['Python 3.5', 'Python 3.6']

[encukou]

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 )

[vsajip]

Removed 3.3 and 3.4 as they are not in scope for non-security issues.

[python-dev]

New changeset 121b5b41c9e8 by Vinay Sajip in branch 'default':
Fixes bpo-27930: improved QueueListener behaviour.
https://hg.python.org/cpython/rev/121b5b41c9e8

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

New changeset 89b185372b2c by Vinay Sajip in branch 'default':
Closes bpo-27930: Merged fix from 3.5.
https://hg.python.org/cpython/rev/89b185372b2c