Navigation Menu

Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

logging reopens file with same mode, possibly truncating #86544

Closed
ecatmur mannequin opened this issue Nov 16, 2020 · 9 comments
Closed

logging reopens file with same mode, possibly truncating #86544

ecatmur mannequin opened this issue Nov 16, 2020 · 9 comments
Labels
3.8 only security fixes stdlib Python modules in the Lib dir type-bug An unexpected behavior, bug, or error

Comments

@ecatmur
Copy link
Mannequin

ecatmur mannequin commented Nov 16, 2020

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
    Copy link
    Mannequin Author

    ecatmur mannequin commented Nov 16, 2020

    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

    @ecatmur ecatmur mannequin added 3.8 only security fixes stdlib Python modules in the Lib dir type-bug An unexpected behavior, bug, or error labels Nov 16, 2020
    @akulakov
    Copy link
    Contributor

    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
    Copy link
    Contributor

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

    @DustinOprea
    Copy link
    Mannequin

    DustinOprea mannequin commented Jan 7, 2022

    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
    Copy link
    Mannequin

    DustinOprea mannequin commented Jan 7, 2022

    <- 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
    Copy link
    Member

    vsajip commented Jan 7, 2022

    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
    Copy link
    Member

    vsajip commented Jan 7, 2022

    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

    @ezio-melotti ezio-melotti transferred this issue from another repository Apr 10, 2022
    @erlend-aasland
    Copy link
    Contributor

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

    @vsajip
    Copy link
    Member

    vsajip commented May 19, 2022

    I think we can close it.

    @vsajip vsajip closed this as completed May 19, 2022
    Javagedes pushed a commit to tianocore/edk2-pytool-extensions that referenced this issue Jun 9, 2023
    Python logging to a file with mode='w' can cause log loss when logging happens after the logger has already been cleaned up.
    See issue: python/cpython#86544
    
    The fix for Python was to have special cases for files opened in mode='w'. Currently we use mode='w+', so the checked in fix does not solve our problem.
    
    I've implemented moving the file_logger to mode='a' and an explicit deletion of the logging file before opening the FileHandler.
    Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
    Labels
    3.8 only security fixes stdlib Python modules in the Lib dir type-bug An unexpected behavior, bug, or error
    Projects
    None yet
    Development

    No branches or pull requests

    4 participants