[New-bugs-announce] [issue45171] stacklevel handling in logging module is inconsistent

[Jouke Witteveen]

New submission from Jouke Witteveen <j.witteveen at gmail.com>:

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.

----------
components: Library (Lib)
messages: 401638
nosy: joukewitteveen
priority: normal
severity: normal
status: open
title: stacklevel handling in logging module is inconsistent
versions: Python 3.10, Python 3.11, Python 3.8, Python 3.9

_______________________________________
Python tracker <report at bugs.python.org>
<https://bugs.python.org/issue45171>
_______________________________________