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

stacklevel handling in logging module is inconsistent #89334

Closed
joukewitteveen mannequin opened this issue Sep 11, 2021 · 7 comments
Closed

stacklevel handling in logging module is inconsistent #89334

joukewitteveen mannequin opened this issue Sep 11, 2021 · 7 comments
Labels
3.8 only security fixes 3.9 only security fixes 3.10 only security fixes 3.11 bug and security fixes stdlib Python modules in the Lib dir

Comments

@joukewitteveen
Copy link
Mannequin

joukewitteveen mannequin commented Sep 11, 2021

BPO 45171
Nosy @vsajip, @tirkarthi, @akulakov, @joukewitteveen
PRs
  • bpo-45171: Fix stacklevel handling in logging. (GH-28287) #28287
  • bpo-45171: Remove tests of deprecated logger.warn(). (GH-32139) #32139
  • 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 2021-09-11.13:17:18.763>
    labels = ['3.8', 'library', '3.9', '3.10', '3.11']
    title = 'stacklevel handling in logging module is inconsistent'
    updated_at = <Date 2022-03-27.18:22:12.434>
    user = 'https://github.com/joukewitteveen'

    bugs.python.org fields:

    activity = <Date 2022-03-27.18:22:12.434>
    actor = 'vinay.sajip'
    assignee = 'none'
    closed = False
    closed_date = None
    closer = None
    components = ['Library (Lib)']
    creation = <Date 2021-09-11.13:17:18.763>
    creator = 'joukewitteveen'
    dependencies = []
    files = []
    hgrepos = []
    issue_num = 45171
    keywords = ['patch']
    message_count = 6.0
    messages = ['401638', '405995', '406001', '416125', '416129', '416132']
    nosy_count = 4.0
    nosy_names = ['vinay.sajip', 'xtreak', 'andrei.avk', 'joukewitteveen']
    pr_nums = ['28287', '32139']
    priority = 'normal'
    resolution = None
    stage = 'patch review'
    status = 'open'
    superseder = None
    type = None
    url = 'https://bugs.python.org/issue45171'
    versions = ['Python 3.8', 'Python 3.9', 'Python 3.10', 'Python 3.11']

    @joukewitteveen
    Copy link
    Mannequin Author

    joukewitteveen mannequin commented Sep 11, 2021

    Handling of stacklevel in the logging module makes a few unwarranted assumptions, for instance on the depth of the stack due to internal logging module calls. This can be seen for instance when using the shortcut call logging.warning to the root logger, instead of using root_logger.warning. Consider the following stacklevel.py file:

    import logging
    import warnings
    
    root_logger = logging.getLogger()
    root_logger.handle = print
    
    def test(**kwargs):
        warnings.warn("warning-module", **kwargs)
        logging.warning("on-module", **kwargs)
        root_logger.warning("on-logger", **kwargs)
    
    for stacklevel in range(5):
        print(f"{stacklevel=}")
        test(stacklevel=stacklevel)
    

    The output of running PYTHONWARNINGS=always python stacklevel.py is:

    stacklevel=0
    stacklevel.py:8: UserWarning: warning-module
      warnings.warn("warning-module", **kwargs)
    <LogRecord: root, 30, stacklevel.py, 9, "on-module">
    <LogRecord: root, 30, stacklevel.py, 10, "on-logger">
    stacklevel=1
    stacklevel.py:8: UserWarning: warning-module
      warnings.warn("warning-module", **kwargs)
    <LogRecord: root, 30, stacklevel.py, 9, "on-module">
    <LogRecord: root, 30, stacklevel.py, 10, "on-logger">
    stacklevel=2
    stacklevel.py:14: UserWarning: warning-module
      test(stacklevel=stacklevel)
    <LogRecord: root, 30, stacklevel.py, 9, "on-module">
    <LogRecord: root, 30, stacklevel.py, 14, "on-logger">
    stacklevel=3
    sys:1: UserWarning: warning-module
    <LogRecord: root, 30, stacklevel.py, 14, "on-module">
    <LogRecord: root, 30, stacklevel.py, 10, "on-logger">
    stacklevel=4
    sys:1: UserWarning: warning-module
    <LogRecord: root, 30, stacklevel.py, 9, "on-module">
    <LogRecord: root, 30, stacklevel.py, 10, "on-logger">
    

    Looking at the line numbers, we get:
    stacklevel 0: lines 8, 9, 10.
    stacklevel 1: lines 8, 9, 10.
    stacklevel 2: lines 14, 9, 14.
    stacklevel 3: lines sys:1, 14, 10.
    stacklevel 4: lines sys:1, 9, 10.

    As can be seen, the stacklevel for the on-module (shortcut) calls lags one level of unwinding behind.

    @joukewitteveen joukewitteveen mannequin added 3.8 only security fixes 3.9 only security fixes 3.10 only security fixes 3.11 bug and security fixes stdlib Python modules in the Lib dir labels Sep 11, 2021
    @akulakov
    Copy link
    Contributor

    akulakov commented Nov 9, 2021

    The stacklevel arg was added 3+ years ago, wouldn't fixing this break a lot of code in a way that's hard to detect? That is to say, logs will look just fine, but when you try to debug an issue, you will realise it's pointing to an unhelpful location?

    @joukewitteveen
    Copy link
    Mannequin Author

    joukewitteveen mannequin commented Nov 9, 2021

    I would expect the opposite. Since the issue is visible only in certain cases (shortcut calls such as logging.info over logger.info, or redirected calls such as logger.warn which adds a stack frame for redirecting to logger.warning), any code that uses the stacklevel argument is probably broken in subtle ways. It will work fine for the anticipated case, but for instance behave weirdly in interactive sessions such as in a debugger.

    Added to this, if we want to fix the documentation instead of the logging module code, we have to come up with an understandable description of a behavior that is really inconsistent and odd. We would probably spend most of the documentation explaining edge cases.

    @vsajip
    Copy link
    Member

    vsajip commented Mar 27, 2022

    New changeset 5ca6d74 by Jouke Witteveen in branch 'main':
    bpo-45171: Fix stacklevel handling in logging. (GH-28287)
    5ca6d74

    @tirkarthi
    Copy link
    Member

    The commit seems to emit a deprecation warning in test_logging. Probably the warning needs to be handled while setting trigger = self.logger.warn

    PYTHONWARNINGS=always ./python -Wall -m test test_logging                       
    0:00:00 load avg: 1.63 Run tests sequentially
    0:00:00 load avg: 1.63 [1/1] test_logging
    /home/karthikeyan/stuff/python/cpython/Lib/test/test_logging.py:5056: DeprecationWarning: The 'warn' method is deprecated, use 'warning' instead
      trigger('test', stacklevel=the_level)

    == Tests result: SUCCESS ==

    1 test OK.

    Total duration: 20.1 sec
    Tests result: SUCCESS

    @vsajip
    Copy link
    Member

    vsajip commented Mar 27, 2022

    New changeset c12ba6b by Jouke Witteveen in branch 'main':
    bpo-45171: Remove tests of deprecated logger.warn(). (GH-32139)
    c12ba6b

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

    This was fixed by #28287 and the issue can be closed.

    Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
    Labels
    3.8 only security fixes 3.9 only security fixes 3.10 only security fixes 3.11 bug and security fixes stdlib Python modules in the Lib dir
    Projects
    Development

    No branches or pull requests

    4 participants