Skip to content

stacklevel handling in logging module is inconsistent #89334

Closed
Closed
stacklevel handling in logging module is inconsistent#89334
Labels
3.10 (EOL)end of life3.11only security fixes3.8 (EOL)end of life3.9 (EOL)end of lifestdlibStandard Library Python modules in the Lib/ directory

Description

@joukewitteveen
joukewitteveen
mannequin
opened on 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']

    Activity

    1. joukewitteveen commented on Sep 11, 2021

      @joukewitteveen
      joukewitteveenmannequin
      on Sep 11, 2021
      MannequinAuthor

      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.

    2. joukewitteveen
      added
      3.8 (EOL)end of life
      3.9 (EOL)end of life
      3.10 (EOL)end of life
      3.11only security fixes
      stdlibStandard Library Python modules in the Lib/ directory
      on Sep 11, 2021

    3. akulakov commented on Nov 9, 2021

      @akulakov
      akulakov
      on Nov 9, 2021
      Contributor

      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?

    4. joukewitteveen commented on Nov 9, 2021

      @joukewitteveen
      joukewitteveenmannequin
      on Nov 9, 2021
      MannequinAuthor

      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.

    5. vsajip commented on Mar 27, 2022

      @vsajip
      vsajip
      on Mar 27, 2022
      Member

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

    6. tirkarthi commented on Mar 27, 2022

      @tirkarthi
      tirkarthi
      on Mar 27, 2022
      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

    7. vsajip commented on Mar 27, 2022

      @vsajip
      vsajip
      on Mar 27, 2022
      Member

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

    8. ezio-melotti
      transferred this issue fromon Apr 10, 2022
    9. serhiy-storchaka
      added this to Logging issues 🪵on May 20, 2022

    10. joukewitteveen commented on Jun 13, 2022

      @joukewitteveen
      joukewitteveen
      on Jun 13, 2022
      ContributorAuthor

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

    11. vsajip
      closed this as completedon Jun 13, 2022
    12. vsajip
      moved this to Done in Logging issues 🪵on Jun 13, 2022
    Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

    Metadata

    Metadata

    Assignees

    No one assigned

      Labels

      3.10 (EOL)end of life3.11only security fixes3.8 (EOL)end of life3.9 (EOL)end of lifestdlibStandard Library Python modules in the Lib/ directory

      Projects

      Milestone

      No milestone

      Relationships

      None yet

      Development

      No branches or pull requests

      Issue actions