复杂Structlog配置下bound_contextvars失效问题及解决

极简示例（可正常输出上下文变量） #

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")

输出日志：

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

生产环境复杂配置示例（上下文变量丢失） #

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,
    ## 取消注释会输出null值
    # "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")

配套的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

输出日志：

{"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"}

问题与解决 #

问题 #

使用bound_contextvars绑定的frame_id和command_id未出现在日志中，即使将这两个字段添加到DEFAULT_EVENT_FIELDS，也只会输出null值，无法获取上下文变量。

解决方法 #

在STRUCTLOG_PROCESSORS列表的开头添加structlog.contextvars.merge_contextvars处理器即可解决该问题。

原因 #

structlog通过上下文变量存储bound_contextvars绑定的数据，但默认配置的处理器链中没有包含合并上下文变量的逻辑。merge_contextvars处理器的作用是将当前上下文环境中绑定的变量合并到日志事件字典，让后续处理器能读取并输出这些变量。

内容的提问来源于stack exchange，提问作者WurmD