Propagation trace-контекста в логах

Инженер находит log-строку с 5xx ошибкой от checkout-сервиса. Ищет контекст. У log-строки нет trace_id. Она не может открыть трейс, не видит, какой downstream-вызов упал, и не может восстановить request flow. У неё симптом — и больше ничего. Без trace_id структурные логи — остров.

Почему trace_id — самое ценное поле

Log-строка с trace_id кликабельна в соответствующий distributed trace. Этот трейс показывает каждый span каждого сервиса, тронувшего запрос: per-span timing, dependency-вызовы, error-span’ы, upstream/downstream-контекст. Log-строка больше не остров — это узел в полном observability-графе.

Без trace_id та же log-строка несёт симптом, но не путь к причине. Единственный вариант — коррелировать по timestamp в надежде, что никакие другие запросы не перекрывались — что ломается в тот момент, как сервис обрабатывает более одного concurrent-запроса.

OTel Logs Data Model кодирует это отношение напрямую: каждая log-запись несёт TraceId, SpanId и TraceFlags как first-class поля, унаследованные от активного span’а на emit-time. Это не опциональные метаданные — это структурный join-ключ.

Как trace-контекст попадает в log-строку

Trace-контекст — immutable struct, хранящий текущий trace_id, span_id и trace flags — живёт в language-scoped execution context запроса. Logger читает из него на emit-time, автоматически.

• Node.js: OTel SDK хранит контекст в AsyncLocalStorage. Callback mixin pino (или механизм context.with() из @opentelemetry/api) читает активный span из store на emit-time. Каждый лог, эмитированный в request handler’е, наследует trace_id без per-call-site boilerplate.
• Go: context.Context несёт активный span. Slog-handler или zap-logger читает из context, переданного в handler-функцию. В отличие от Node, контекст явный — ctx должен пробрасываться по цепочке вызовов.
• Python: contextvars.ContextVar хранит активный span (Python 3.7+). Processor merge_contextvars structlog читает активный span на render-time.
• JVM: OTel Java agent auto-инструментирует thread-local context. ThreadContext log4j2 или MDC Logback несут trace_id автоматически, когда agent подключён.

В каждом случае паттерн один: у logger’а есть hook (mixin, processor, handler), консультирующий активный execution context и инжектирующий trace_id и span_id в log-запись без необходимости передавать их явно в вызывающем коде.

Pitfalls async-context propagation

Logger читает контекст из активного execution context. Всё, что ломает propagation execution context, ломает trace_id в log-строке. Это самый частый источник записей trace_id = "00000000000000000000000000000000".

Node.js pitfalls: setTimeout, setImmediate, fire-and-forget Promise’ы и worker-thread’ы могут уронить AsyncLocalStorage, если не обёрнуты в context.bind() или context.with(). Callback, запланированный через setTimeout(() => { logger.warn(...) }, 0), срабатывает вне исходного request-контекста, если span не пропагирован явно в callback.

Python pitfalls: asyncio.create_task пропагирует contextvars корректно с Python 3.7. Но thread’ы через threading.Thread и subprocess’ы ProcessPoolExecutor не наследуют контекст автоматически — контекст должен быть захвачен и восстановлен вручную.

Go pitfalls: в Go нет ambient context propagation. context.Context должен пробрасываться явно через каждую функцию в цепочке вызовов, включая goroutine’ы. Goroutine, запущенная без parent-контекста (go func() { logger.Warn(...) }()), не несёт trace_id, если контекст не передан явно.

Обнаружение: запрашивай log-backend на долю trace_id IS NULL или trace_id = "000000000000..." от общего объёма. Если доля выше 1%, что-то роняет контекст на hot-path. Дополни CI-тестом, упражняющим async-пути (делает запрос, ждёт завершения async-callback, assert’ует, что его log-строка несёт inbound trace_id).