py311: incorrect logging.LogRecord.module value (and related attrs) when using a custom log-level method

[bastimeyer]

Bug report

#28287 has introduced changes to the logging.LogRecord's module, pathname and filename attributes when a custom log-level method gets used due to how the logging.Logger.findCaller() and logging.currentframe() methods were changed and how "internal" call stack frames are handled now. This change doesn't seem intentional to me, so I decided to open this bug report.

Related: streamlink/streamlink#4862

Your environment

• CPython versions tested on: CPython 3.10.7 and CPython 3.11-rc2
• Operating system and architecture: Arch Linux (x86_64) (irrelevant to the issue)

Reproduction

Consider the following example which defines a custom trace() logging method on a custom Logger subclass that gets set as the default logger class.

myproject/__init__.py

myproject/__main__.py

import myproject.logger
from myproject.content import content

content()

myproject/logger.py

import logging

TRACE = 5

logging.addLevelName(TRACE, "trace")

class MyLoggingClass(logging.getLoggerClass()):
    def trace(self, message, *args, **kwargs):
        if self.isEnabledFor(TRACE):
            self._log(TRACE, message, args, **kwargs)

logging.setLoggerClass(MyLoggingClass)

handler = logging.StreamHandler()
handler.setFormatter(logging.Formatter("[{module}][{name}][{levelname}] {message}", style="{"))

root = logging.getLogger("myproject")
root.addHandler(handler)
root.setLevel(TRACE)

myproject/content.py

import logging
from myproject.logger import TRACE

log = logging.getLogger(__name__)

def content():
    log.trace("foo")
    log.log(TRACE, "bar")

Result

$ python3.10 -m myproject
[content][myproject.content][trace] foo
[content][myproject.content][trace] bar

$ python3.11 -m myproject
[logger][myproject.content][trace] foo
[content][myproject.content][trace] bar

As you can see, on py311 the custom logger.trace() method causes the log record to have a different module (and pathname + filename), but not any of the default log-level methods like the generic log() method.

From what it looks like, the call stack that's being read and iterated now stops at the first "non internal frame". Since the default log-level methods are considered "internal", everything's working fine. The custom trace() method however is not "internal" and is thus used as the source of the log call instead of the example's content() function.

This "internal frame" implementation is not quite right, because the trace() method is calling the private _log() method, and not any of the public log-level methods where it would make sense to stop on those "internal" call stack frames. It should also ignore call stack frames which are calling the private _log() method, so users can define custom log-level methods like in the example shown above.

The solution for now is defining two trace() methods, one for py<3.11 and one for py>=3.11, where the py311 one sets the stacklevel keyword on the _log() call to 2 (instead of the default value of 1), so the loop skips one additional call stack frame when checking for "internal" call stack frames, which would be the custom trace() method. This is a bad and very unintuitive workaround though.

Thanks for taking a look at this.

[vsajip]

You can use the stacklevel parameter to adjust the stack level for this: if I change the trace method as follows:

    def trace(self, message, *args, **kwargs):
        if self.isEnabledFor(TRACE):
            kwargs.setdefault('stacklevel', 2)
            self._log(TRACE, message, args, **kwargs)

then when I run python -m myproject, I get

[content][myproject.content][trace] foo
[content][myproject.content][trace] bar

[bastimeyer]

You can use the stacklevel parameter to adjust the stack level for this: if I change the trace method as follows:

No, you can not, because as I already said at the bottom of my post, that breaks on Python <= 3.10

    def trace(self, message, *args, **kwargs):
        if self.isEnabledFor(TRACE):
            kwargs.setdefault('stacklevel', 2)
            self._log(TRACE, message, args, **kwargs)

$ python3.10 -m myproject
[__main__][myproject.content][trace] foo
[content][myproject.content][trace] bar

$ python3.11 -m myproject
[content][myproject.content][trace] foo
[content][myproject.content][trace] bar

this requires having two separate methods for py<3.11 and for py>=3.11, which is bad and a sign that this is a regression in 3.11

class MyLoggingClass(logging.getLoggerClass()):
    if sys.version_info >= (3, 11):
        def trace(self, message, *args, **kws):
            if self.isEnabledFor(TRACE):
                kws["stacklevel"] = 2
                self._log(TRACE, message, args, **kws)
    else:
        def trace(self, message, *args, **kws):
            if self.isEnabledFor(TRACE):
                self._log(TRACE, message, args, **kws)

$ python3.10 -m myproject
[content][myproject.content][trace] foo
[content][myproject.content][trace] bar

$ python3.11 -m myproject
[content][myproject.content][trace] foo
[content][myproject.content][trace] bar

[vsajip]

Yes, but gh-89334 (for which the change in #28287 was made) is a valid issue, isn't it? Do you have an alternative fix for it? Not sure why you need two methods, anyway - you could just have if sys.version_info >= (3, 11): kws['stacklevel'] = 2 in a single method - it's just one extra line, not as many as in your snippet.

[bastimeyer]

Not sure why you need two methods

The intention is to optimize log calls. There could of course be a simple if-block inside the method, but that doesn't change the fact that you have to make a distinction between py311 and below.

Do you have an alternative fix for it?

I made a suggestion in my OP in regards to also checking for the _log() call, so custom log-level methods like the trace() example get ignored.

[vsajip]

Do you have an alternative fix for it?

I made a suggestion in my OP in regards to also checking for the _log() call

Not sure if that suggestion's specific enough to constitute a fix; perhaps I'm not understanding exactly what you're getting at. Would you like to propose an alternative PR with tests that resolves both this issue and gh-89334 in a different way to #28287? If so, please make sure to add the users who worked on #28287 so they can comment on it.

[bastimeyer]

perhaps I'm not understanding exactly what you're getting at.

I'm talking about ignoring the call stack frame in which _log() gets called.

_log() is a private method, which means that every method that's declared a public interface which calls this function is either an "internal" method (log(), info(), etc.) or an "external" method (trace()). Since Logger.findCaller() apparently does only get called by _log(), this solution should work, for both the logging stdlib as well as custom subclasses of Logger that are calling _log(). If any application logic is calling _log() directly, this obviously won't work, but that wouldn't matter, since it's a private method.

Would you like to propose an alternative PR with tests

Well, I could have a look at least, but I'm not sure if I will manage to get a PR ready with working tests as I am very much unfamiliar with the internals of the stdlib as well as the test setup.

[bastimeyer]

I had a closer look at this, and I believe it's not worth fixing. That would require making a distinction between "internal" and "external" calls to Logger._log() and subtracting the stacklevel based on that (deferred by one frame if external), and I'm not sure if this can be done in a proper way if findCaller() is declared as a public method and could thus be called by other methods in application code, and not just by _log() in the logging module.

The workaround with the stacklevel keyword value depending on the python version may be ugly, but it's working and makes sense for skipping wrapper functions/methods like the custom trace() log-level method.