pytest caplog LogCaptureFixture is broken when using logging.config.dictConfig()

Question

I have been going around in circles on this problem for several days now and I am no closer to a solution than when I started.

I have reviewed all of the other stackoverflow entries dealing with the pytest caplog fixture and I have narrowed my problem down to the use of logging.config.dictConfig()

I have tried multiple configurations, with and without propagate=True, and they all result in the same problem ... logging is not captured when using dictConfig().

Pytest logging when used in conjunction with config.dictConfig() is broken.

---

Here's my test code which demonstrates the problem:

# =====================
# File: test_caplog.py
# =====================

class TestCapLog:

    def _test_logger(self, tf_caplog):
        """Display caplog capture text"""
        # display capture log
        print("\nCAPLOG:")
        output = tf_caplog.text.rstrip('\n').split(sep='\n')
        if output == ['']:
            print("Nothing captured")
        else:
            for i in range(len(output)):
                print(f'{i}: {output[i]}')

    def test_caplog0_root(self, caplog):
        """Test caplog 'root' logger w/o dictConfig()"""
        import logging
        # use logging configuration "as-is"
        logger = logging.getLogger()
        # log at all logging levels
        logger.debug('DEBUG: log entry captured')
        logger.info('INFO: log entry captured')
        logger.error('ERROR: log entry captured')
        logger.warning('WARNING: log entry captured')
        self._test_logger(caplog)

    def test_caplog1_main1(self, caplog):
        """Test caplog 'main' logger w/ dictConfig(), propagate=False"""
        import logging.config
        import logging
        import log_config
        # configure logging, propagate False
        log_config.LOGGING['loggers']['main']['propagate'] = False
        logging.config.dictConfig(log_config.LOGGING)
        logger = logging.getLogger(name='main')
        # log at all logging levels
        logger.debug('DEBUG: log entry captured')
        logger.info('INFO: log entry captured')
        logger.error('ERROR: log entry captured')
        logger.warning('WARNING: log entry captured')
        self._test_logger(caplog)

    def test_caplog1_main2(self, caplog):
        """Test caplog 'main' logger w/ dictConfig(), propagate=True"""
        import logging.config
        import logging
        import log_config
        # configure logging, propagate True
        log_config.LOGGING['loggers']['main']['propagate'] = True
        logging.config.dictConfig(log_config.LOGGING)
        logger = logging.getLogger(name='main')
        # log at all logging levels
        logger.debug('DEBUG: log entry captured')
        logger.info('INFO: log entry captured')
        logger.error('ERROR: log entry captured')
        logger.warning('WARNING: log entry captured')
        self._test_logger(caplog)

---

Here's the logging configuration file

# =====================
# File: log_config.py
# =====================

"""logging configuration support"""

# System imports
import logging.handlers
import sys


#: logging formatters
_formatters = {
    'msgonly': {
        'format': '%(message)s'
    },
    'minimal': {
        'format': '(%(name)s) %(message)s'
    },
    'normal': {
        'format': '%(asctime)s (%(name)s) %(levelname)s %(message)s'
    },
    'debug': {
        'format': '%(asctime)s (%(name)s) %(levelname)s %(module)s %(funcName)s %(message)s'
    }
}

#: logging stream handler string
LOGGING_STREAM_HANDLER = 'logging.StreamHandler'
#: logging timed file handler string
LOGGING_TIMED_FILE_HANDLER = 'logging.handlers.TimedRotatingFileHandler'

#: logging handlers
_handlers = {
    'debugHandler': {
        'class': LOGGING_STREAM_HANDLER,
        'level': logging.DEBUG,
        'formatter': 'debug',
        'stream': sys.stdout,
    },
    'consoleHandler': {
        'class': LOGGING_STREAM_HANDLER,
        'level': logging.DEBUG,
        'formatter': 'normal',
        'stream': sys.stdout,
    },
    'fileHandler': {
        'class': LOGGING_TIMED_FILE_HANDLER,
        'level': logging.DEBUG,
        'formatter': 'normal',
        'filename': 'logging.log',
        'when': 'D',
        'interval': 1,
        'backupCount': 7,
        'delay': True,
    },
}

#: Loggers
_loggers = {
    '': {
        'level': logging.INFO,
        'handlers': ['consoleHandler', 'fileHandler'],
        'qualname': 'root',
        'propagate': False,
    },
    'root': {
        'level': logging.DEBUG,
        'handlers': ['debugHandler', 'fileHandler'],
        'qualname': 'root',
        'propagate': False,
    },
    '__main__': {
        'level': logging.DEBUG,
        'handlers': ['debugHandler', 'fileHandler'],
        'qualname': '__main__',
        'propagate': False,
    },
    'main': {
        'level': logging.DEBUG,
        'handlers': ['debugHandler', 'fileHandler'],
        'qualname': 'main',
        'propagate': False,
    },
}

#: Configuration dictionary
LOGGING = {
    "version": 1,
    "loggers": _loggers,
    "handlers": _handlers,
    "formatters": _formatters,
}

The 3 tests that I run are:

1. logging using the root logger with no call to dictConfig()
2. logging using named logger (main) with call to dictConfig() and propagate=False
3. logging using named logger (main) with call to dictConfig() and propagate=True

---

What follows is the output of executing my test code:

/home/mark/PycharmProjects/pytest_caplog/venv/bin/python /home/mark/.local/share/JetBrains/pycharm-2022.2.2/plugins/python/helpers/pycharm/_jb_pytest_runner.py --path /home/mark/PycharmProjects/pytest_caplog/test_caplog.py 
Testing started at 1:09 AM ...
Launching pytest with arguments /home/mark/PycharmProjects/pytest_caplog/test_caplog.py --no-header --no-summary -q in /home/mark/PycharmProjects/pytest_caplog

============================= test session starts ==============================
collecting ... collected 3 items

test_caplog.py::TestCapLog::test_caplog0_root PASSED                     [ 33%]
CAPLOG:
0: ERROR    root:test_caplog.py:23 ERROR: log entry captured
1: WARNING  root:test_caplog.py:24 WARNING: log entry captured

test_caplog.py::TestCapLog::test_caplog1_main1 PASSED                    [ 66%]2022-12-22 01:09:28,810 (main) DEBUG test_caplog test_caplog1_main1 DEBUG: log entry captured
2022-12-22 01:09:28,810 (main) INFO test_caplog test_caplog1_main1 INFO: log entry captured
2022-12-22 01:09:28,810 (main) ERROR test_caplog test_caplog1_main1 ERROR: log entry captured
2022-12-22 01:09:28,811 (main) WARNING test_caplog test_caplog1_main1 WARNING: log entry captured

CAPLOG:
Nothing captured

test_caplog.py::TestCapLog::test_caplog1_main2 PASSED                    [100%]2022-12-22 01:09:28,815 (main) DEBUG test_caplog test_caplog1_main2 DEBUG: log entry captured
2022-12-22 01:09:28,815 (main) DEBUG DEBUG: log entry captured
2022-12-22 01:09:28,815 (main) INFO test_caplog test_caplog1_main2 INFO: log entry captured
2022-12-22 01:09:28,815 (main) INFO INFO: log entry captured
2022-12-22 01:09:28,815 (main) ERROR test_caplog test_caplog1_main2 ERROR: log entry captured
2022-12-22 01:09:28,815 (main) ERROR ERROR: log entry captured
2022-12-22 01:09:28,816 (main) WARNING test_caplog test_caplog1_main2 WARNING: log entry captured
2022-12-22 01:09:28,816 (main) WARNING WARNING: log entry captured

CAPLOG:
Nothing captured


============================== 3 passed in 0.03s ===============================

Process finished with exit code 0

---

The only way that I have been able to get caplog to behave as I would expect it to behave is to not use dictConfig() and write my own get_logger() function.

That seems like a waste and would not be necessary if the pytest caplog fixture would respect the dictConfig() settings.

---

I have read through the pytest documentation and none of the caplog examples that I have found address using anything other than the root logger.

At this point I am reconsidering my decision to switch from the standard Python unittest capability to pytest

This is a major blocker for me.

Any help that anyone can give me will be greatly appreciated.

Answer 1

I am not sure if this solution acceptable for you but you can have a look. Seems like you need to overwrite logging-plugin caplog_handler property that is used by caplog fixture after dictConfig call.

You can write your own fixture that sets config and overwrites caplog_handler property of logging-plugin instance with your LogCaptureHandler that is described in config. Also this handler must be specified with loggers that needs it.

# log_config.py

...
CAPLOG_HANDLER = '_pytest.logging.LogCaptureHandler'

#: logging handlers
_handlers = {
    'logCaptureHandler': {
        'class': CAPLOG_HANDLER,
        'level': logging.DEBUG,
        'formatter': 'debug'
    },
    'debugHandler': {

...

    'main': {
        'level': logging.DEBUG,
        'handlers': ['debugHandler', 'fileHandler', 'logCaptureHandler'],
        'qualname': 'main',
        'propagate': False,
    },
...

# conftest.py

import logging.config
import log_config
import pytest


@pytest.fixture(scope="function")
def logging_config(request):
    logging_plugin = request.config.pluginmanager.get_plugin("logging-plugin")
    config = getattr(request, "param", log_config.LOGGING)
    logging.config.dictConfig(config)
    logging_plugin.caplog_handler = logging._handlers["logCaptureHandler"]

Also keep in mind that your logging config must not be reconfigured during tests with logging.config.dictConfig(log_config.LOGGING) because it will cause recreation of handlers.

So logging configuration will be done only with your logging_config fixture.

To change config before test you can use indirect parametrization. Example of changing propagate in main logger in 3rd test:

import log_config
import logging

import pytest


class TestCapLog:

    def _test_logger(self, tf_caplog):
        """Display caplog capture text"""
        # display capture log
        print("\nCAPLOG:")
        output = tf_caplog.text.rstrip('\n').split(sep='\n')
        if output == ['']:
            print("Nothing captured")
        else:
            for i in range(len(output)):
                print(f'{i}: {output[i]}')

    def test_caplog0_root(self, caplog):
        """Test caplog 'root' logger w/o dictConfig()"""
        import logging
        # use logging configuration "as-is"
        logger = logging.getLogger()
        # log at all logging levels
        logger.debug('DEBUG: log entry captured')
        logger.info('INFO: log entry captured')
        logger.error('ERROR: log entry captured')
        logger.warning('WARNING: log entry captured')
        self._test_logger(caplog)

    def test_caplog1_main1(self, logging_config, caplog):
        """Test caplog 'main' logger w/ dictConfig(), propagate=False"""
        import logging
        # configure logging, propagate False
        logger = logging.getLogger(name='main')

        # log at all logging levels
        logger.debug('DEBUG: log entry captured')
        logger.info('INFO: log entry captured')
        logger.error('ERROR: log entry captured')
        logger.warning('WARNING: log entry captured')
        self._test_logger(caplog)

    MAIN_PROPAGATE_TRUE = log_config.LOGGING.copy()
    MAIN_PROPAGATE_TRUE['loggers']['main']['propagate'] = True

    @pytest.mark.parametrize("logging_config", [MAIN_PROPAGATE_TRUE], indirect=True)
    def test_caplog1_main2(self, logging_config, caplog):
        """Test caplog 'main' logger w/ dictConfig(), propagate=True"""

        # configure logging, propagate True
        # logging.config.dictConfig(log_config.LOGGING)
        logger = logging.getLogger(name='main')
        # log at all logging levels
        logger.debug('DEBUG: log entry captured')
        logger.info('INFO: log entry captured')
        logger.error('ERROR: log entry captured')
        logger.warning('WARNING: log entry captured')
        self._test_logger(caplog)

Also you can rewrite fixture to use mergedeep to merge your initial config (LOGGING) with request.param just to avoid defining and passing whole config before @pytest.mark.parametrize.