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. |