This issue tracker has been migrated to GitHub, and is currently read-only.
For more information, see the GitHub FAQs in the Python's Developer Guide.

classification
Title: logging reopens file with same mode, possibly truncating
Type: behavior Stage: patch review
Components: Library (Lib) Versions: Python 3.8
process
Status: open Resolution:
Dependencies: Superseder:
Assigned To: Nosy List: Dustin.Oprea, andrei.avk, ecatmur2, miss-islington, vinay.sajip
Priority: normal Keywords: patch

Created on 2020-11-16 19:48 by ecatmur2, last changed 2022-04-11 14:59 by admin.

Pull Requests
URL Status Linked Edit
PR 27310 merged andrei.avk, 2021-07-23 16:37
PR 30468 merged miss-islington, 2022-01-07 21:52
Messages (7)
msg381146 - (view) Author: Ed Catmur (ecatmur2) Date: 2020-11-16 19:48
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 issue 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
msg398078 - (view) Author: Andrei Kulakov (andrei.avk) * (Python triager) Date: 2021-07-23 16:38
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.
msg398195 - (view) Author: miss-islington (miss-islington) Date: 2021-07-25 20:17
New changeset 96cf5a63d2dbadaebf236362b4c7c09c51fda55c by andrei kulakov in branch 'main':
bpo-42378: fixed log truncation on logging shutdown (GH-27310)
https://github.com/python/cpython/commit/96cf5a63d2dbadaebf236362b4c7c09c51fda55c
msg410030 - (view) Author: Dustin Oprea (Dustin.Oprea) Date: 2022-01-07 20:43
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.
msg410031 - (view) Author: Dustin Oprea (Dustin.Oprea) Date: 2022-01-07 20:45
<- 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.
msg410043 - (view) Author: Vinay Sajip (vinay.sajip) * (Python committer) Date: 2022-01-07 21:50
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.
msg410045 - (view) Author: Vinay Sajip (vinay.sajip) * (Python committer) Date: 2022-01-07 22:15
New changeset e35430bec528dfb1a653cd457ea58b5a08543632 by Miss Islington (bot) in branch '3.10':
[3.10] bpo-42378: fixed log truncation on logging shutdown (GH-27310) (GH-30468)
https://github.com/python/cpython/commit/e35430bec528dfb1a653cd457ea58b5a08543632
History
Date User Action Args
2022-04-11 14:59:38adminsetgithub: 86544
2022-01-07 22:15:34vinay.sajipsetmessages: + msg410045
2022-01-07 21:52:33miss-islingtonsetpull_requests: + pull_request28671
2022-01-07 21:50:44vinay.sajipsetmessages: + msg410043
2022-01-07 21:18:45ned.deilysetnosy: + vinay.sajip
2022-01-07 20:45:28Dustin.Opreasetmessages: + msg410031
2022-01-07 20:43:52Dustin.Opreasetnosy: + Dustin.Oprea
messages: + msg410030
2021-07-25 20:17:50miss-islingtonsetnosy: + miss-islington
messages: + msg398195
2021-07-23 16:38:46andrei.avksetmessages: + msg398078
2021-07-23 16:37:40andrei.avksetkeywords: + patch
nosy: + andrei.avk

pull_requests: + pull_request25855
stage: patch review
2020-11-16 19:48:22ecatmur2create