Handling of loggers with propagate=False

[bluefish6]

Hi,

There is a 2-year old issue on the old repo and inspired by #3003 I thought it might be easier if I at least add some reference here:

eisensheng/pytest-catchlog#44

[bluefish6]

I suggest to remove the auto-added label os:mac, as this is an issue on Ubuntu 16.04 as well.

[dazza-codes]

When using the caplog.records or caplog.record_tuples there is nothing captured for a logger that does not propagate up to the root logger. When testing the log output, is there any work-around for this or does a solution require mocking of logging handlers?

[nicoddemus]

Not sure, we only capture what we get from the root logger... @Thisch might give some input here.

[dazza-codes]

So the simplest work around in a pytest test is to enable the propagation during the test, only for any test that must check the presence or content of a log message (other tests might confirm that propagation is disabled by default). If I had time, a PR on the docs might help, but here is what I have time for now, e.g.

def test_app_logger_content(caplog):
    logger = logging.getLogger('app')  # 'app' is already configured without propagation
    logger.propagate = True  # log capture only works for propagation to the root logger
    logger.info('foo')
    logger.error('err')
    assert caplog.record_tuples == [
        ('app', logging.INFO, 'foo'),
        ('app', logging.ERROR, 'err')
    ]

def test_app_logger_does_not_propagate(caplog):
    logger = logging.getLogger('app')
    assert not logger.propagate
    logger.info('foo')
    logger.error('err')
    assert not caplog.records

[nicoddemus]

If you have only a few loggers which don't propagate, probably you can use a session-scoped autouse fixture to enable propagation for those loggers.

[lig]

I think this is an issue. Enabling propagating for logger results in a possible false positive result of a test.

Say, I would like to ensure a message goes to exact logger I want it to go. There is no way at the moment to test that.

It would be helpful to be able to tell to caplog what logger I'm interested exactly. So, it will capture that logger and everything that goes there.

[twmr]

@lig If we add support for specifying a logger in _pytest.logging.catching_logs you can use the following code to tell caplog the logger you're interested in

import logging
from _pytest.logging import catching_logs


def test_app_logger_content_nocatchlog(caplog):
    logger = logging.getLogger('app')
    logger.propagate = False
    logger.info('foo')
    logger.error('err')
    assert ('app', logging.INFO, 'foo') not in caplog.record_tuples
    assert ('app', logging.ERROR, 'err') not in caplog.record_tuples


def test_app_logger_content_catchlog(caplog):
    logger = logging.getLogger('app')
    logger.propagate = False
    caplog.set_level(logging.INFO)

    with catching_logs(caplog.handler, logger=logger):
        logger.info('foo')
        logger.error('err')
        assert caplog.record_tuples == [
            ('app', logging.INFO, 'foo'),
            ('app', logging.ERROR, 'err')
        ]

[lig]

@Thisch looks really useful

one thing. I'd assume this would work either

def test_app_logger_content_catchlog(caplog):
    logger = logging.getLogger('app')
    logger.propagate = False
    caplog.set_level(logging.INFO)

    with catching_logs(caplog.handler, logger=logger):
        logger.info('foo')
        logger.error('err')
    assert caplog.record_tuples == [
        ('app', logging.INFO, 'foo'),
        ('app', logging.ERROR, 'err'),
    ]

notice that caplog keeps records after catching_logs context manager has exited

[chrisjsewell]

Yeh it would be ideal if there was a proper replacement in pytest for unittest.TestCase.assertLogs, i.e. with pytest.logs(...
Can you not just copy what that does, i.e. temporarily overriding the propagate and handler?

class _AssertLogsContext(_BaseTestCaseContext):
    """A context manager used to implement TestCase.assertLogs()."""

    LOGGING_FORMAT = "%(levelname)s:%(name)s:%(message)s"

    def __init__(self, test_case, logger_name, level):
        _BaseTestCaseContext.__init__(self, test_case)
        self.logger_name = logger_name
        if level:
            self.level = logging._nameToLevel.get(level, level)
        else:
            self.level = logging.INFO
        self.msg = None

    def __enter__(self):
        if isinstance(self.logger_name, logging.Logger):
            logger = self.logger = self.logger_name
        else:
            logger = self.logger = logging.getLogger(self.logger_name)
        formatter = logging.Formatter(self.LOGGING_FORMAT)
        handler = _CapturingHandler()
        handler.setFormatter(formatter)
        self.watcher = handler.watcher
        self.old_handlers = logger.handlers[:]
        self.old_level = logger.level
        self.old_propagate = logger.propagate
        logger.handlers = [handler]
        logger.setLevel(self.level)
        logger.propagate = False
        return handler.watcher

    def __exit__(self, exc_type, exc_value, tb):
        self.logger.handlers = self.old_handlers
        self.logger.propagate = self.old_propagate
        self.logger.setLevel(self.old_level)
        if exc_type is not None:
            # let unexpected exceptions pass through
            return False
        if len(self.watcher.records) == 0:
            self._raiseFailure(
                "no logs of level {} or higher triggered on {}"
                .format(logging.getLevelName(self.level), self.logger.name))