bpo-41943: Fix bug where assertLogs doesn't correctly filter messages…

[iritkatriel]

… by level

@vsajip , @pitrou

https://bugs.python.org/issue41943

Automerge-Triggered-By: GH:vsajip

[iritkatriel]

Note that this test is similar to the one just above it, which doesn't set the level on the log_foo logger. In that case, log_foo has level WARNING, so the message is blocked by it. But in the new test log_foo lets the message through to the root logger, which has that _CapturingHandler attached to it. But since the _CapturingHandler's level was not set, it is NOTSET which is 0 so I guess it allows all messages through. So my change sets the level of the handler to the level specified by the user.

So with my change we set the log level both on the logger and on the handler attached to it. This seems to fix this particular bug but I'm not sure the interplay between the logger's and the handler's log level is always what we would expect it to be. Here is a small script demonstrating what's going on:

import logging

FORMAT = '%(levelname)-10s %(asctime)s: %(message)s'
handler = logging.StreamHandler()

# Uncomment the next line to fix it
# handler.setLevel(logging.WARNING) 
logging.basicConfig(format=FORMAT, level=logging.WARNING, handlers=[handler])

logger = logging.getLogger('blah')
logger.setLevel(logging.INFO)

logger.info('information')
logger.warning('warning')
logger.error('error')

As it is, all 3 log lines are emitted. If you uncomment the setLevel on the handler, only the warning and error are.

[iritkatriel]

I converted this to draft because I want to try and fix the issue in the logging library rather than patch over it as I did here.

[iritkatriel]

@vsajip I think the problem is in Logger.callHandlers(). In this loop:

        c = self
        found = 0
        while c:
            for hdlr in c.handlers:
                found = found + 1
                if record.levelno >= hdlr.level:
                    hdlr.handle(record)
            if not c.propagate:
                c = None    #break out
            else:
                c = c.parent

initially c is the current logger. It calls all handlers in c that have level at most that of the record. Then, as long as c.propagate is True it climbs up the logger tree and calls all handlers on ancestor loggers. But it never checks the levels of any of the ancestor loggers, only the levels of their handlers. So if the logger has a level set and the handler doesn't, we get into problems.

So I added this check:

        while c:
            if not c.isEnabledFor(record.levelno):
                c = None    #break out
            else:
                the code that was in the while loop before

Now the new test passes, but three pre-existing tests fail. I fixed one of them, by adding a handler to the child logger (following the fix, the root logger doesn't handle the record anymore).

test_config7_ok is a similar story - probably need to add a handler to the child logger (or change the expected results).

test_config8_ok I haven't investigated yet.

What do you think about the fix and it implications?

[vsajip]

But it never checks the levels of any of the ancestor loggers, only the levels of their handlers.

This is by design - it's always worked like this. So, the change you propose shouldn't be made, and tests need to fit in with the existing behaviour.

[iritkatriel]

But it never checks the levels of any of the ancestor loggers, only the levels of their handlers.

This is by design - it's always worked like this. So, the change you propose shouldn't be made, and tests need to fit in with the existing behaviour.

So the other option I see is in my first commit to this PR - to make assertLogs set the level on both the logger and the handler. Does that look right?

[vsajip]

to make assertLogs set the level on both the logger and the handler.

I think that's right. In general you set levels on loggers (as they are checked first), and then levels on handlers when the specific audience for those handlers want more filtering/less verbosity than the logger.

The tests just have to work with the expected/by design behaviour in this area. If necessary, the docs for assertLogs can be beefed up to make things clearer, with examples, if needed.

[iritkatriel]

@vsajip can you please request a review from @pitrou? I don't think I have that button.

[pitrou]

I'd rather let @vsajip decide on this, he's much more of an expert in logging than I am.

[iritkatriel]

Thanks.
@vsajip, @pitrou Do we want to backport this?