Any level of logging lets assertLogs pass

Question

I am trying to test that a warning is logged in a unit test. It seems that the following test should fail:

import logging
import unittest

LOG_FORMAT = '%(levelname)-10s %(asctime)s: %(message)s'


def set_up_logger(app_name, level=logging.INFO, file="test.log"):
    formatter = logging.Formatter(LOG_FORMAT)
    log = logging.getLogger(app_name)
    # The next line lets the test pass
    log.setLevel(level)
    return log

logger = set_up_logger(__name__)

class TestLogging(unittest.TestCase):
    def test_logging(self):
        with self.assertLogs(level=logging.WARNING):
            logger.info('foo')

However, it passes with python 3.8.5.

If I remove the log.setLevel(level) line, the test fails, like expected. If I replace the logger.info line with pass, then the test also fails as expected.

Why does setting the level on the logger let the test incorrectly pass?

Shower

Answer 1

I'm not completely sure if this behavior is wanted, as it is a bit unexpected. To fix the test, you have to pass the logger:

class TestLogging(unittest.TestCase):
    def test_logging(self):
        with self.assertLogs(logger, level=logging.WARNING):
            logger.info('foo')

The reason why it does work that way is that in the assertLogs context manager, the log level of the passed logger is temporarily set to the passed level, and if no logging has happened on exit, the test will fail.

If you don't pass the logger, the root logger is used instead. If you don't set the level on your logger, it will use the level of the root logger, which during the call is set to WARNING by the context manager - so nothing will be logged, and the test fails as expected.

If you do set the log level, this log level will be used regardless of the root logger level, so logging will be done and the test passes (which is not what I would have expected, either).

Update:
There is now a Python issue that describes the problem, which is now fixed in master and Python 3.10.

Annabel

That seems like a bug. In my real code, the logger isn't declared 5 lines earlier, but inside another file, and would be private if python supported such a concept. Specifying the logger is also fragile: I care that the warning is logged, not exactly who logged it. If I change the logger from using __name__ to MyClass.__class__.__name__, I don't want to have to change the test. – Shower

I created a bug report: bugs.python.org/msg377719. We'll see if anything is changed. – Shower

Agreed - I also consider this a bug (and have seen it in Python 3.7 under Windows).. – Annabel

It certainly violates the principle of least astonishment. – Shower

As noted on the bug issue, this behavior is in line with the documentation. It also makes sense to me, and I wonder why you find it confusing. What should assertLogs do when you don't specify the logger? – Burmaburman

I now see that the question here, unlike the bug report, is focused on the issue of the log level. If you don't specify a logger, it is as if you specified the root logger. The root logger sees all messages that are propagated to it by descendent loggers. If you don't set the logging on your logger, it has the default logging level on INFO. So warnings on that logger are not propagated to the root logger. In other words, the INFO level of your logger (and not the INFO level on the root logger) is what blocked your message. – Burmaburman

The documentation states: "The test passes if at least one message emitted inside the with block matches the logger and level conditions, otherwise it fails.". In this case, no message was logged with a warning level or above, so I would have expected the test to fail, but it passes. I do understand why it passes given the implementation, but I think it does not match the documentation in this case. – Annabel

Yes, you're right. I understand now, sorry, the wording of the bug report threw me in the wrong direction. Can you reopen that ticket or create a new one? – Burmaburman

@IritKatriel - I added a new entry, please check if this is more clear (haven't written Python issues before). – Annabel

Thank you, I've created a PR with a unit test and fix. Let's see what the experts think of it. – Burmaburman

Probably most people use pytest + caplog anyway, so wouldn't hit this issue. – Tasia

The fix has been merged now. Thank you for reporting the issue! – Burmaburman