Failing to use bound_contextvars with complex logger configuration because of missing structlog.contextvars.merge_contextvars processor

Question

This

import structlog
from structlog.contextvars import bound_contextvars
if __name__=="__main__":
    log = structlog.getLogger(__name__)
    with bound_contextvars(frame_id="ADA", command_id="123"):
        log.info("rabo")

logs 2023-11-04 21:17:15 [info ] rabo command_id=123 frame_id=ADA

This minimal example of what we actually use in production:

import os
from pathlib import Path
import logging
import logging.config

import structlog
from structlog.contextvars import bound_contextvars

LOG_DIR: Path = Path(".")
LOG_CONFIG_FILE: Path = Path("logging.conf")

STRUCTLOG_PROCESSORS = [
    structlog.stdlib.filter_by_level,
    structlog.stdlib.add_logger_name,
    structlog.stdlib.add_log_level,
    structlog.processors.CallsiteParameterAdder(
        [
            structlog.processors.CallsiteParameter.THREAD_NAME,
            structlog.processors.CallsiteParameter.PROCESS_NAME,
            structlog.processors.CallsiteParameter.PATHNAME,
        ]
    ),
    structlog.stdlib.PositionalArgumentsFormatter(),
    structlog.processors.TimeStamper(fmt="ISO", key="@timestamp"),
    structlog.processors.UnicodeDecoder(),
    structlog.processors.ExceptionRenderer(),
    structlog.processors.StackInfoRenderer(),
    structlog.processors.EventRenamer("message"),
    structlog.processors.JSONRenderer(),
]

DEFAULT_EVENT_FIELDS = {
    "appVersion": "unset",
    "supervisor_process_name": "not_set",
    "hostname": None,
    ## This causes log line    "frame_id": null, "command_id": null, "message": "rabo"
    # "frame_id": None,
    # "command_id": None,
}


def _configure_logging(processors) -> None:
    LOG_DIR.mkdir(parents=True, exist_ok=True)
    os.environ["LOG_DIR"] = str(LOG_DIR)
    logging.config.fileConfig(LOG_CONFIG_FILE, disable_existing_loggers=False)

    structlog.configure(
        processors=processors,
        wrapper_class=structlog.stdlib.BoundLogger,
        logger_factory=structlog.stdlib.LoggerFactory(),
        cache_logger_on_first_use=True,
    )


def add_custom_fields(logger, method_name, event_dict):  # pylint: disable=unused-argument
    return {**event_dict, **DEFAULT_EVENT_FIELDS}


_configure_logging([add_custom_fields] + STRUCTLOG_PROCESSORS)


if __name__=="__main__":
    log = structlog.getLogger(__name__)
    with bound_contextvars(frame_id="ADA", command_id="123"):
        log.info("rabo")

with logging.conf

[loggers]
keys=root

[handlers]
keys=consoleHandler,consoleHandlerErr

[formatters]
keys=Formatter

[logger_root]
level=DEBUG
handlers=consoleHandler

[handler_consoleHandler]
class=StreamHandler
level=DEBUG
formatter=Formatter
args=(sys.stdout,)

[handler_consoleHandlerErr]
class=StreamHandler
level=DEBUG
formatter=Formatter
args=(sys.stderr,)

[formatter_Formatter]
format=%(message)s

logs {"appVersion": "unset", "supervisor_process_name": "not_set", "hostname": null, "logger": "__main__", "level": "info", "thread_name": "MainThread", "process_name": "n/a", "pathname": "/Users/dario.figueira/Library/Application Support/JetBrains/PyCharm2023.1/scratches/bound_contextvars.py", "@timestamp": "2023-11-04T21:19:17.083187Z", "message": "rabo"}

What's missing so that the bound context vars show up in the log lines? Adding frame_id and command_id to DEFAULT_EVENT_FIELDS was not enough

EDIT: Adding structlog.contextvars.merge_contextvars, after STRUCTLOG_PROCESSORS = [ fixes it

Answer 1

Your configuration is missing the structlog.contextvars.merge_contextvars processor that is part of the default configuration.