用 OpenTelemetry LoggingInstrumentor 把 trace_id 注入 Python 日志

问题场景

在微服务或异步任务中，一次请求可能跨越多个函数、多个服务。分布式追踪能记录调用链，日志能记录细节。但两者常常割裂：在 Jaeger 看到一个慢 trace，想查当时的日志，只能靠时间戳和请求参数去日志平台大海捞针；反过来，看到一条报错日志，也无法直接跳到对应 trace。若每条日志都带上当前 span 的 trace_id 和 span_id，就可以在日志平台按 trace_id 过滤，也能从日志行跳转到 Jaeger 的 trace 详情。

方案概述

OpenTelemetry Python 提供了 opentelemetry-instrumentation-logging，其中的 LoggingInstrumentor 会包装标准库 logging 的 LogRecord 工厂，在每条日志记录上注入 otelTraceID、otelSpanID、otelTraceSampled、otelServiceName 等属性。这样只要在 Formatter 中引用这些字段，就能让日志自动携带当前追踪上下文。

最小可运行示例

依赖安装：

pip install opentelemetry-api opentelemetry-sdk opentelemetry-exporter-otlp-proto-grpc opentelemetry-instrumentation-logging

示例脚本 log_trace_demo.py：

import logging

from opentelemetry import trace
from opentelemetry.exporter.otlp.proto.grpc.trace_exporter import OTLPSpanExporter
from opentelemetry.instrumentation.logging import LoggingInstrumentor
from opentelemetry.sdk.resources import Resource, SERVICE_NAME
from opentelemetry.sdk.trace import TracerProvider
from opentelemetry.sdk.trace.export import BatchSpanProcessor

# 1. 初始化 TracerProvider，并导出到 Jaeger 的 OTLP 端口
resource = Resource.create({SERVICE_NAME: 'log-trace-demo'})
provider = TracerProvider(resource=resource)
provider.add_span_processor(
    BatchSpanProcessor(
        OTLPSpanExporter(endpoint='http://localhost:4317', insecure=True)
    )
)
trace.set_tracer_provider(provider)

# 2. 启用日志埋点：只注入字段，不自动改格式
LoggingInstrumentor().instrument(set_logging_format=False)

# 3. 自定义日志格式，引用注入的字段
logging.basicConfig(
    level=logging.INFO,
    format=(
        '%(asctime)s %(levelname)s '
        '[trace_id=%(otelTraceID)s span_id=%(otelSpanID)s '
        'sampled=%(otelTraceSampled)s service=%(otelServiceName)s] '
        '%(name)s %(message)s'
    ),
)

logger = logging.getLogger(__name__)
tracer = trace.get_tracer(__name__)


def do_work():
    with tracer.start_as_current_span('do_work'):
        logger.info('开始处理任务')
        with tracer.start_as_current_span('sub_task'):
            logger.info('子任务执行中')
        logger.info('任务完成')


if __name__ == '__main__':
    do_work()
    provider.shutdown()

运行方法：

1. 启动一个本地 Jaeger 实例（示例）：

docker run --rm --name jaeger \
  -p 16686:16686 \
  -p 4317:4317 \
  -p 4318:4318 \
  jaegertracing/all-in-one:latest

1. 运行脚本：

python log_trace_demo.py

控制台会输出类似：

2025-01-01 00:00:00,000 INFO [trace_id=4bf92f3577b34da6a3ce929d0e0e4736 span_id=00f067aa0ba902b7 sampled=True service=log-trace-demo] __main__ 开始处理任务
2025-01-01 00:00:00,001 INFO [trace_id=4bf92f3577b34da6a3ce929d0e0e4736 span_id=a1b2c3d4e5f60718 sampled=True service=log-trace-demo] __main__ 子任务执行中
2025-01-01 00:00:00,002 INFO [trace_id=4bf92f3577b34da6a3ce929d0e0e4736 span_id=00f067aa0ba902b7 sampled=True service=log-trace-demo] __main__ 任务完成

注意 trace_id 在同一个 trace 中相同，而 span_id 在不同 span 中不同。

1. 打开 Jaeger UI：http://localhost:16686，在 Search 中选择服务 log-trace-demo，找到对应 trace；也可以直接访问 http://localhost:16686/trace/<trace_id>，其中 <trace_id> 替换为日志中的值。

如果希望让 LoggingInstrumentor 自动修改 root logger 的格式，可以把 set_logging_format=False 改为 True，它会在现有格式前加上 %(otelTraceID)s %(otelSpanID)s %(otelTraceSampled)s %(otelServiceName)s。但自动修改会影响所有日志 handler，团队中需评估。

边界与限制

• 没有处于任何 span 上下文时，otelTraceID 和 otelSpanID 会是全 0 字符串，otelTraceSampled 为 False。此时日志无法关联到具体 trace，属于正常现象。
• 如果 trace 未被采样，日志中可能仍有 trace_id，但 Jaeger 中查不到该 trace，跳转链接会失效。需要结合采样策略判断。
• 上下文传播：同步代码中通常没问题；使用线程池、ThreadPoolExecutor 或手动创建线程时，OpenTelemetry 上下文不会自动跨线程传递，需要显式 context.attach 或使用支持传播的封装。asyncio 默认基于 contextvars，通常能正确工作，但也要注意任务创建方式。
• 只对标准库 logging 生效。loguru、structlog 等第三方日志库需要额外的处理器或适配器；结构化日志场景下，建议在日志事件字段中显式加入 trace_id。
• 直接引用 %(otelTraceID)s 等字段前，必须确保 LoggingInstrumentor 已经 instrument，否则格式化时会因缺少属性而抛异常。
• 日志格式引入 trace_id 后，日志平台可以按 trace_id 建立跳转链接，但 trace_id 本身不是敏感信息，日志正文仍要做好脱敏。
• 不同版本的 OpenTelemetry Python 包字段名、exporter 参数可能不同。本文示例基于常见的 1.x SDK 与 instrumentation 包，落地时请以实际安装版本的文档和源码为准。

小结

通过 LoggingInstrumentor 把 trace_id、span_id 注入 Python 日志，可以在不改变业务日志调用方式的前提下，让日志与追踪系统建立关联。排查时先用 trace_id 在日志平台缩小范围，再从日志行跳回 Jaeger 查看完整调用链；反过来也能从 Jaeger 的慢 trace 找到对应日志。实现成本低，但要注意上下文传播、采样和第三方日志库的适配。