Skip to content

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

Closed as not planned
Closed as not planned
py311: incorrect logging.LogRecord.module value (and related attrs) when using a custom log-level method#97941
Assignees
vsajip
Labels
invalidstdlibStandard Library Python modules in the Lib/ directory

Description

@bastimeyer
bastimeyer
opened on Oct 5, 2022

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.
Activity
  1. bastimeyer
    added 
    type-bugAn unexpected behavior, bug, or error
     on Oct 5, 2022
  2. AlexWaygood
    added 
    stdlibStandard Library Python modules in the Lib/ directory
     on Oct 5, 2022
  3. AlexWaygood
    assigned 
    vsajip
    on Oct 5, 2022
  4. AlexWaygood
    added this to  Logging issues 🪵on Oct 5, 2022
  5. vsajip
    added 
    invalid
     and removed 
    type-bugAn unexpected behavior, bug, or error
     on Oct 6, 2022
  6. vsajip commented on Oct 6, 2022 
    @vsajip
    vsajip
    on Oct 6, 2022
    Member
    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

  7. vsajip
    closed this as not plannedon Oct 6, 2022
  8. vsajip
    moved this to Done in  Logging issues 🪵on Oct 6, 2022
  9. bastimeyer commented on Oct 6, 2022 
    @bastimeyer
    bastimeyer
    on Oct 6, 2022
    Author
    

    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
  10. vsajip commented on Oct 6, 2022 
    @vsajip
    vsajip
    on Oct 6, 2022
    Member
    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.
  11. bastimeyer commented on Oct 6, 2022 
    @bastimeyer
    bastimeyer
    on Oct 6, 2022
    Author
    

    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.
  12. vsajip commented on Oct 6, 2022 
    @vsajip
    vsajip
    on Oct 6, 2022
    Member
    

    

    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.
  13. bastimeyer commented on Oct 6, 2022 
    @bastimeyer
    bastimeyer
    on Oct 6, 2022
    Author
    

    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.
  14. bastimeyer commented on Oct 7, 2022 
    @bastimeyer
    bastimeyer
    on Oct 7, 2022
    Author
    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.
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Metadata
Metadata
Assignees
Labels
invalidstdlibStandard Library Python modules in the Lib/ directory
Projects
Milestone
No milestone
Relationships
None yet
Development
No branches or pull requests
Issue actions