I'm using structlog with keyword arguments to generate stdlib log events with the extra dict storing keyword arguments necessary to understand the context around the log message being printed.

When my program is run under pytest, the log messages written directly to stdout honor the application's log settings, but when pytest prints captured log messages they go through a default-to-pytest formatter that doesn't include this information.

As far as I know, a format string can't be used to format a dictionary into a string with key=value pairs (rather, when extra= is in use, the expectation is that a format string will pull in specific keywords from that dictionary), so it isn't obvious to me that log_cli_format (as recommended by numerous preexisting Q&A entries) is sufficient for the task at hand.

Consider the following reproducer:

import pytest
import logging

logger = logging.getLogger()

def test_logging():
    # in the real use case "extra" is generated by structlog
    # ...the names may change for each log message and cannot be hardcoded
    logger.info('message here', extra={"foo": "bar", "baz": "qux"})
    assert False, 'Trigger failure'

When running:

pytest --log-cli-level INFO

this outputs:

----------------------------------------- Captured log call -----------------------------------------
INFO     root:test_me.py:8 message here
====================================== short test summary info ======================================
FAILED test_me.py::test_logging - AssertionError: Trigger failure
assert False
========================================= 1 failed in 0.08s =========================================

I want message here (within the Captured log call section, not captured stdout or stderr) to contain content equivalent to foo='bar' baz='qux'. How can this be accomplished?

I'm using structlog with keyword arguments to generate stdlib log events with the extra dict storing keyword arguments necessary to understand the context around the log message being printed.

When my program is run under pytest, the log messages written directly to stdout honor the application's log settings, but when pytest prints captured log messages they go through a default-to-pytest formatter that doesn't include this information.

As far as I know, a format string can't be used to format a dictionary into a string with key=value pairs (rather, when extra= is in use, the expectation is that a format string will pull in specific keywords from that dictionary), so it isn't obvious to me that log_cli_format (as recommended by numerous preexisting Q&A entries) is sufficient for the task at hand.

Consider the following reproducer:

import pytest
import logging

logger = logging.getLogger()

def test_logging():
    # in the real use case "extra" is generated by structlog
    # ...the names may change for each log message and cannot be hardcoded
    logger.info('message here', extra={"foo": "bar", "baz": "qux"})
    assert False, 'Trigger failure'

When running:

pytest --log-cli-level INFO

this outputs:

----------------------------------------- Captured log call -----------------------------------------
INFO     root:test_me.py:8 message here
====================================== short test summary info ======================================
FAILED test_me.py::test_logging - AssertionError: Trigger failure
assert False
========================================= 1 failed in 0.08s =========================================

I want message here (within the Captured log call section, not captured stdout or stderr) to contain content equivalent to foo='bar' baz='qux'. How can this be accomplished?

• python
• logging
• pytest

1 Answer 1

While this makes use of implementation details and thus is subject to breaking at notice with pytest updates, one can address this by creating a subclass of _pytest.logging.LoggingPlugin.

Below, I'm using structlog.dev.ConsoleRenderer, since this formats extras into the log string out-of-the-box, but an alternate replacement would do as well.

Put the following in conftest.py:

import _pytest.logging
import logging
import structlog.dev
import structlog.stdlib
import structlog.processors
import structlog.typing

def drop_structlog_fields(
    logger: logging.Logger | structlog.typing.FilteringBoundLogger,
    method_name: str,
    event_dict: structlog.types.EventDict,
):
    _ = logger, method_name
    _ = event_dict.pop('_from_structlog', None)
    _ = event_dict.pop('_record', None)
    _ = event_dict.pop('message', None)
    return event_dict


class MyLoggingPlugin(_pytest.logging.LoggingPlugin):
    def _create_formatter(self, log_format, log_date_format, auto_indent):
        return structlog.stdlib.ProcessorFormatter(processors=[
            structlog.stdlib.add_logger_name,
            structlog.stdlib.add_log_level,
            structlog.stdlib.PositionalArgumentsFormatter(),
            structlog.processors.StackInfoRenderer(),
            structlog.processors.format_exc_info,
            structlog.processors.UnicodeDecoder(),
            structlog.stdlib.ExtraAdder(),
            drop_structlog_fields,
            structlog.dev.ConsoleRenderer(),
        ])

def pytest_configure(config):
    log_plugin = config.pluginmanager.get_plugin('logging')
    log_plugin.LoggingPlugin = MyLoggingPlugin

...and the output of the sample tool given in the question becomes:

[info     ] message here                   [root] baz=qux foo=bar