Repository navigation
stacklevel handling in logging module is inconsistent #89334
Description
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
joukewitteveen commented on 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.
akulakov commented on 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 commented on 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 commented on Mar 27, 2022
New changeset 5ca6d74 by Jouke Witteveen in branch 'main':
bpo-45171: Fix stacklevel handling in logging. (GH-28287)
5ca6d74
tirkarthi commented on Mar 27, 2022
The commit seems to emit a deprecation warning in test_logging. Probably the warning needs to be handled while setting trigger = self.logger.warn
== Tests result: SUCCESS ==
1 test OK.
Total duration: 20.1 sec
Tests result: SUCCESS
vsajip commented on Mar 27, 2022
New changeset c12ba6b by Jouke Witteveen in branch 'main':
bpo-45171: Remove tests of deprecated logger.warn(). (GH-32139)
c12ba6b
joukewitteveen commented on Jun 13, 2022
This was fixed by #28287 and the issue can be closed.