Adding Trace IDs to Application Logs

To make logs joinable to traces, read the active span’s context at log time and write its trace_id and span_id as first-class fields on every structured log line — using a Python logging record factory or a Node.js pino mixin so the fields appear automatically without touching a single call site.

Context & When It Matters

A log line that says payment declined is nearly useless during an incident if you cannot tie it to the request that produced it. The moment you attach a trace_id, that line stops being an isolated string and becomes a node in a request’s story — one you can pull up next to its span tree and its siblings from every other service the request touched. This is the single highest-leverage instrumentation change for debuggability, and it is almost entirely mechanical: you are copying two identifiers out of the ambient context and into the log record. The trick is doing it in one place, so that adding a field never means editing thousands of log.info(...) calls, and doing it at the right moment, so the identifiers you capture actually belong to the request that is logging.

Minimal Working Code First

The cleanest Python approach hooks the logging module’s record factory. Every LogRecord is built through this factory, so wrapping it injects the identifiers globally — one hook, universal coverage.

import logging
from opentelemetry import trace

_base_factory = logging.getLogRecordFactory()

def _trace_record_factory(*args, **kwargs):
    record = _base_factory(*args, **kwargs)
    ctx = trace.get_current_span().get_span_context()
    if ctx.is_valid:
        record.trace_id = format(ctx.trace_id, "032x")  # 32-hex, lowercase
        record.span_id = format(ctx.span_id, "016x")     # 16-hex, lowercase
    else:
        record.trace_id = record.span_id = "0"
    return record

logging.setLogRecordFactory(_trace_record_factory)

Now any formatter that references %(trace_id)s — or a JSON formatter that reads record.trace_id — emits the id with no change to application code. The factory runs synchronously on the calling thread, which is exactly why it captures the correct context: it executes before the log record is ever queued or handed to an async handler.

Implementation

The Node.js counterpart uses a pino mixin. The mixin function runs on every log call and returns an object merged into the emitted line, giving the same “one hook, universal coverage” property. Reading the context inside the mixin — rather than binding it once at logger creation — is what keeps it correct across concurrent requests sharing one logger instance.

const pino = require('pino');
const { trace, context } = require('@opentelemetry/api');

const logger = pino({
  base: { service: 'checkout' },
  mixin() {
    // Runs per log call, on the request's active context.
    const span = trace.getSpan(context.active());
    if (!span) return {};                 // outside a span: emit nothing extra
    const sc = span.spanContext();
    if (!sc.traceId) return {};           // guard invalid contexts
    return {
      trace_id: sc.traceId,               // already 32-hex lowercase
      span_id: sc.spanId,                 // already 16-hex lowercase
    };
  },
});

// Inside a request handler that runs within an active span:
logger.info({ order_id: 'A-1471' }, 'authorizing card');
// -> {"level":30,...,"service":"checkout",
//     "trace_id":"4bf92f...4736","span_id":"00f0...b7","msg":"authorizing card"}

Two details make or break this. First, the mixin reads context.active() each call, so a single shared logger serves thousands of concurrent requests correctly — the active context is per-async-execution, not per-logger. Second, both runtimes already normalize the ids to lowercase hex (32 characters for trace_id, 16 for span_id), which is the exact format your trace backend indexes on; do not reformat them, or the correlation join will silently return nothing. Getting the ids onto the line is only useful if the underlying W3C TraceContext was propagated into this service in the first place — otherwise you will faithfully log a brand-new root id that matches nothing upstream.

Verification

Confirm the injection works before relying on it:

Common Pitfalls

  • Logging outside an active span. Startup, migrations, and cron entry points run with no span in context, so their lines legitimately show trace_id="0". Do not force a synthetic id to make them “look linked” — instead, wrap genuinely trace-worthy background work in an explicit span so it earns a real id.
  • Async context loss silently zeroes the id. When work is handed to a raw thread pool or a detached promise, the async boundary can drop the OpenTelemetry context, and every downstream log line falls back to "0". Capture the context on the caller and re-attach it inside the worker before it logs.
  • Over-logging once logs become useful. Correlation tempts teams to raise verbosity because logs are finally navigable. Resist it — the payoff of a trace_id is reading fewer lines precisely, not flooding storage. Keep levels disciplined and let the trace, not a wall of DEBUG lines, carry the structural story.

FAQ

Should I inject trace_id at the formatter or the record factory?

Read the span context at the record factory, not the formatter. The factory runs on the thread that made the log call, where the active context is still correct. A formatter can run later on a different worker in async handlers, by which point the context has moved on and you would capture the wrong id.

Why do my worker-thread logs show a zeroed trace_id?

Context does not cross a raw thread or a detached task automatically. When you hand work to a ThreadPoolExecutor or an untracked callback, the OpenTelemetry context is not carried along, so the active span is empty on the worker. Capture the context on the caller and re-attach it inside the worker before logging.

Do I need to log span_id as well as trace_id?

Yes, log both. trace_id joins every line for a request together, but a single request can span dozens of operations; span_id tells you which specific operation emitted a line. Without span_id you can find the request but not pinpoint the failing step within it.

Related

↑ Back to Correlating Logs, Metrics, and Traces