logging reopens file with same mode, possibly truncating

[ecatmur]

BPO	42378
Nosy	@vsajip, @miss-islington, @ecatmur, @akulakov
PRs	bpo-42378: fixed log truncation on logging shutdown #27310 [3.10] bpo-42378: fixed log truncation on logging shutdown (GH-27310) (GH-30468) #30468

^{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 = None
created_at = <Date 2020-11-16.19:48:22.970>
labels = ['3.8', 'type-bug', 'library']
title = 'logging reopens file with same mode, possibly truncating'
updated_at = <Date 2022-01-07.22:15:34.327>
user = 'https://github.com/ecatmur'

bugs.python.org fields:

activity = <Date 2022-01-07.22:15:34.327>
actor = 'vinay.sajip'
assignee = 'none'
closed = False
closed_date = None
closer = None
components = ['Library (Lib)']
creation = <Date 2020-11-16.19:48:22.970>
creator = 'ecatmur2'
dependencies = []
files = []
hgrepos = []
issue_num = 42378
keywords = ['patch']
message_count = 7.0
messages = ['381146', '398078', '398195', '410030', '410031', '410043', '410045']
nosy_count = 5.0
nosy_names = ['vinay.sajip', 'Dustin.Oprea', 'miss-islington', 'ecatmur2', 'andrei.avk']
pr_nums = ['27310', '30468']
priority = 'normal'
resolution = None
stage = 'patch review'
status = 'open'
superseder = None
type = 'behavior'
url = 'https://bugs.python.org/issue42378'
versions = ['Python 3.8']

[ecatmur]

If a logging.FileHandler is configured with mode='w', or if logging.basicConfig is called with filemode='w' (as suggested by the Basic Logging Tutorial https://docs.python.org/3/howto/logging.html#logging-basic-tutorial)
and if some code logs during shutdown, after logging has closed its handlers (asyncio is prone to do this, e.g.),
then logging.FileHandler._open will reopen the log file with the same mode as it was originally opened with, potentially truncating it and losing valuable information:

import atexit
atexit.register(lambda: logging.info("so long"))
import logging
logging.basicConfig(filename='test.log', filemode='w', level=logging.INFO)
logging.info("super important stuff")

$ python truncate.py
$ cat test.log
INFO:root:so long

I have a hunch that the fix to bpo-26789 will potentially make things worse, as previously at least there was a chance that logging had been fully unloaded so that the call to open would fail.

https://stackoverflow.com/questions/39838616/why-is-python-logging-framework-losing-messages

[akulakov]

I've put up a PR here: https://github.com/python/cpython/pull/27310/files

If this looks good, I will update the docs and add news entry.

[miss-islington]

New changeset 96cf5a6 by andrei kulakov in branch 'main':
bpo-42378: fixed log truncation on logging shutdown (GH-27310)
96cf5a6

[DustinOprea]

I believe I'm seeing this, still, in an async situation. It seems like the obvious culprit.

When will this go out in a release? I'm on 3.10.1 from December (under Arch). The PR got merged to master in July but I went through all changelogs back to March and don't see it listed.

[DustinOprea]

<- I'm intentionally using mode 'w' (to support development) and it's never been an issue until I recently refactored the project to be asynchronous. Now, every time I fail, I suddenly lose the logs. Not awesome.

[vsajip]

I guess it got missed during the 3.10 beta cycle by not being backported - it might have needed to be cherry-picked. I'll see about getting it backported to 3.10.

[vsajip]

New changeset e35430b by Miss Islington (bot) in branch '3.10':
[3.10] bpo-42378: fixed log truncation on logging shutdown (GH-27310) (GH-30468)
e35430b

[erlend-aasland]

Can we close this, or is there more work left?

[vsajip]

I think we can close it.