Search code examples
pytestpytest-fixturescaplog

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

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.

Solution

  • 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.