This issue tracker has been migrated to GitHub, and is currently read-only.
For more information, see the GitHub FAQs in the Python's Developer Guide.

classification
Title: stacklevel handling in logging module is inconsistent
Type: Stage: patch review
Components: Library (Lib) Versions: Python 3.11, Python 3.10, Python 3.9, Python 3.8
process
Status: open Resolution:
Dependencies: Superseder:
Assigned To: Nosy List: andrei.avk, joukewitteveen, vinay.sajip, xtreak
Priority: normal Keywords: patch

Created on 2021-09-11 13:17 by joukewitteveen, last changed 2022-04-11 14:59 by admin.

Pull Requests
URL Status Linked Edit
PR 28287 merged joukewitteveen, 2021-09-11 13:25
PR 32139 merged joukewitteveen, 2022-03-27 17:20
Messages (6)
msg401638 - (view) Author: Jouke Witteveen (joukewitteveen) * Date: 2021-09-11 13:17
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.
msg405995 - (view) Author: Andrei Kulakov (andrei.avk) * (Python triager) Date: 2021-11-09 02:20
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?
msg406001 - (view) Author: Jouke Witteveen (joukewitteveen) * Date: 2021-11-09 07:52
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.
msg416125 - (view) Author: Vinay Sajip (vinay.sajip) * (Python committer) Date: 2022-03-27 13:49
New changeset 5ca6d7469be53960843df39bb900e9c3359f127f by Jouke Witteveen in branch 'main':
bpo-45171: Fix stacklevel handling in logging. (GH-28287)
https://github.com/python/cpython/commit/5ca6d7469be53960843df39bb900e9c3359f127f
msg416129 - (view) Author: Karthikeyan Singaravelan (xtreak) * (Python committer) Date: 2022-03-27 16:40
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
msg416132 - (view) Author: Vinay Sajip (vinay.sajip) * (Python committer) Date: 2022-03-27 18:22
New changeset c12ba6b2ff7908c8970b978f149d51ecd3fb195c by Jouke Witteveen in branch 'main':
bpo-45171: Remove tests of deprecated logger.warn(). (GH-32139)
https://github.com/python/cpython/commit/c12ba6b2ff7908c8970b978f149d51ecd3fb195c
History
Date User Action Args
2022-04-11 14:59:49adminsetgithub: 89334
2022-03-27 18:22:12vinay.sajipsetmessages: + msg416132
2022-03-27 17:20:11joukewitteveensetpull_requests: + pull_request30220
2022-03-27 16:40:13xtreaksetnosy: + xtreak
messages: + msg416129
2022-03-27 13:49:36vinay.sajipsetnosy: + vinay.sajip
messages: + msg416125
2021-11-09 07:52:47joukewitteveensetmessages: + msg406001
2021-11-09 02:20:47andrei.avksetnosy: + andrei.avk
messages: + msg405995
2021-09-11 13:25:58joukewitteveensetkeywords: + patch
stage: patch review
pull_requests: + pull_request26703
2021-09-11 13:17:18joukewitteveencreate