classification
Title: logging.StreamHandler performs two syscalls when one would do
Type: behavior Stage: resolved
Components: Versions: Python 3.7
process
Status: closed Resolution: fixed
Dependencies: Superseder:
Assigned To: Nosy List: josnyder, ulope, vinay.sajip, xtreak
Priority: normal Keywords: patch

Created on 2018-10-22 18:51 by josnyder, last changed 2019-02-06 14:24 by ulope. This issue is now closed.

Pull Requests
URL Status Linked Edit
PR 10042 merged josnyder, 2018-10-22 20:52
PR 10043 closed vinay.sajip, 2018-10-22 20:54
PR 10050 merged miss-islington, 2018-10-23 06:48
Messages (4)
msg328269 - (view) Author: Josh Snyder (josnyder) * Date: 2018-10-22 18:51
logging.StreamHandler contains the following code:

    stream.write(msg)
    stream.write(self.terminator)
    stream.flush()

When sys.stderr (or whatever other stream) is unbuffered, this results in two system calls and allows log records from different processes to concatenate on the same line in the output stream (followed by multiple newlines). This issue is new in Python 3.7, as stdout and stderr became "truly unbuffered" (cf. #30404).

As a simple solution, I believe the following would fix the issue and also be backward compatible:

    stream.write(msg + self.terminator)
    stream.flush()
msg328286 - (view) Author: Vinay Sajip (vinay.sajip) * (Python committer) Date: 2018-10-23 06:48
New changeset b7d62050e7d5fc208ae7673613da4f1f2bc565c4 by Vinay Sajip (Josh Snyder) in branch 'master':
bpo-35046: do only one system call per line (logging.StreamHandler) (GH-10042)
https://github.com/python/cpython/commit/b7d62050e7d5fc208ae7673613da4f1f2bc565c4
msg328295 - (view) Author: Vinay Sajip (vinay.sajip) * (Python committer) Date: 2018-10-23 10:07
New changeset d730719b094cb006711b1cd546927b863c173b31 by Vinay Sajip (Miss Islington (bot)) in branch '3.7':
bpo-35046: do only one system call per line (logging.StreamHandler) (GH-10042) (GH-10050)
https://github.com/python/cpython/commit/d730719b094cb006711b1cd546927b863c173b31
msg334938 - (view) Author: Ulrich Petri (ulope) * Date: 2019-02-06 14:24
This change breaks (probably unsupported) uses of the logging module (esp. in combination with structlog) where non-string objects are passed through the .format() and .emit() calls.

Previously it was possible to set the terminator attribute to None (and then handling that case in a custom 'stream' implementation), which now breaks with a TypeError due to the concatenation.

In case anyone else runs into this (however unlikely that is). A workaround is to set the .terminator to something like this:

    class ConcatenableNothing:
        def __radd__(self, other):
            return other
History
Date User Action Args
2019-02-06 14:24:59ulopesetnosy: + ulope
messages: + msg334938
2018-10-23 10:07:47vinay.sajipsetstatus: open -> closed
resolution: fixed
stage: patch review -> resolved
2018-10-23 10:07:13vinay.sajipsetmessages: + msg328295
2018-10-23 06:48:50miss-islingtonsetpull_requests: + pull_request9388
2018-10-23 06:48:42vinay.sajipsetmessages: + msg328286
2018-10-22 20:54:13vinay.sajipsetpull_requests: + pull_request9382
2018-10-22 20:52:09josnydersetkeywords: + patch
stage: patch review
pull_requests: + pull_request9381
2018-10-22 18:57:00xtreaksetnosy: + vinay.sajip, xtreak
2018-10-22 18:51:21josnydercreate