stacklevel handling in logging module is inconsistent

[joukewitteveen]

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]

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.

[akulakov]

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]

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]

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

[tirkarthi]

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]

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