Correlating Logs, Metrics, and Traces

A latency dashboard turns red at 02:14. The p99 for the checkout route has jumped from 180 ms to 2.3 seconds. You have the metric, and the metric tells you that something is slow — but it cannot tell you which request was slow, what it was doing, or why it failed. So you open your logs, filter by the checkout service, and drown in ten thousand lines from the same two-minute window, none of which are obviously the ones behind the spike. This is the correlation gap: three signal types collected by three subsystems, each internally consistent and mutually disconnected. The fix is not a fourth tool. It is a shared join key — the trace_id — threaded through all three so that a metric bucket points at a representative trace, and that trace points at the exact log lines emitted while it ran.

Prerequisites

Before wiring correlation, confirm the following are in place:

  • An OpenTelemetry SDK setup for backend services is initialized and already producing spans (opentelemetry-sdk >= 1.24 for Python, @opentelemetry/sdk-node >= 0.52 for Node.js).
  • A structured (JSON) logging pipeline — Python logging with a JSON formatter, or Node.js pino >= 8 / winston >= 3 — shipping to a queryable store (Loki, Elasticsearch, or a cloud log backend).
  • A Prometheus server built with exemplar storage enabled (--enable-feature=exemplar-storage) and scraping targets over the OpenMetrics content type.
  • A trace backend such as Jaeger or Tempo reachable from the same UI that renders your metrics, so exemplar links can deep-link into a trace.
  • Familiarity with how the span lifecycle exposes the active span context, since every correlation step reads trace_id and span_id from it.

The Correlation Triangle: One Key, Three Signals

The mental model that makes this tractable is a triangle. Each vertex is a signal store optimized for a different question. Metrics answer “is the system healthy, and by how much” cheaply and at scale, because they are pre-aggregated. Traces answer “what did this one request do across services” with per-request structure. Logs answer “what did the code actually say happened” with unbounded free-form detail. None of the three can be cheaply converted into another — that is why you keep all three — but all three can carry the same trace_id, and that identifier is the edge that connects the vertices.

The direction of travel matters. You almost always start at the metrics vertex, because that is where alerts fire and where a spike is visible. From a metric you need a bridge into a specific trace: that bridge is the exemplar, a small annotation attached to a histogram bucket that records the trace_id of one representative observation that fell in that bucket. From the trace you need a bridge into logs: that bridge is the trace_id field embedded in every structured log line the request produced. The workflow is therefore a directed walk — metric → exemplar → trace → logs — and each arrow is only possible if you instrumented the join key at that layer.

The Correlation Triangle Keyed by trace_id Three vertices — Metrics, Traces, and Logs — form a triangle. An exemplar edge links a metric histogram bucket to a trace. A trace_id field edge links the trace to its structured log lines. The shared trace_id sits at the center. shared trace_id Metrics histogram + exemplar Traces spans by trace_id Logs JSON lines + trace_id exemplar filter logs on trace_id aggregate back

The dashed edge from logs back to metrics closes the triangle conceptually — you can aggregate log-derived counts back into metrics — but it is not part of the debugging walk and you rarely traverse it live. Focus your instrumentation budget on the two solid amber edges.

Step-by-Step Implementation

Step 1: Inject trace_id and span_id Into Structured Logs

The foundation of the whole triangle is getting the active span’s identifiers onto every log line. Without this, the trace-to-log arrow does not exist. In Python, the OpenTelemetry LoggingInstrumentor patches the standard logging module so that every LogRecord gains otelTraceID and otelSpanID attributes, which a JSON formatter can then emit.

import json
import logging
from opentelemetry.instrumentation.logging import LoggingInstrumentor

# Patch the logging module so records carry trace context.
# set_logging_format=False keeps control of the formatter in our hands.
LoggingInstrumentor().instrument(set_logging_format=False)


class TraceJsonFormatter(logging.Formatter):
    def format(self, record: logging.LogRecord) -> str:
        payload = {
            "ts": self.formatTime(record, "%Y-%m-%dT%H:%M:%S%z"),
            "level": record.levelname,
            "msg": record.getMessage(),
            # Injected by LoggingInstrumentor; "0" when no active span.
            "trace_id": getattr(record, "otelTraceID", "0"),
            "span_id": getattr(record, "otelSpanID", "0"),
            "service": getattr(record, "otelServiceName", "checkout"),
        }
        return json.dumps(payload)


handler = logging.StreamHandler()
handler.setFormatter(TraceJsonFormatter())
logging.basicConfig(level=logging.INFO, handlers=[handler])

For a deeper, framework-agnostic treatment of the record-factory approach and the Node.js pino mixin, see adding trace IDs to application logs. In Node.js the idiomatic equivalent is a pino mixin that reads the active context on every log call:

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

const logger = pino({
  // mixin runs per log call and merges its return into the line
  mixin() {
    const span = trace.getSpan(context.active());
    if (!span) return {};
    const { traceId, spanId } = span.spanContext();
    return { trace_id: traceId, span_id: spanId };
  },
});

// Anything logged inside an active span now carries both ids.
logger.info({ order_id: 'A-1471' }, 'charging payment method');

Step 2: Wire Metric Exemplars Carrying trace_id

An exemplar is a (value, trace_id, timestamp) tuple attached to a histogram observation. When your metrics client records a request-duration observation, it reads the current span context and staples the trace_id to that sample. Prometheus stores it alongside the bucket, and the dashboard renders it as a clickable point.

With the Prometheus Python client, exemplars are passed on observe:

from prometheus_client import Histogram
from opentelemetry import trace

REQUEST_DURATION = Histogram(
    "http_request_duration_seconds",
    "Request latency",
    ["route"],
    buckets=(0.05, 0.1, 0.25, 0.5, 1.0, 2.5, 5.0),
)


def record_latency(route: str, seconds: float) -> None:
    span = trace.get_current_span()
    ctx = span.get_span_context()
    exemplar = None
    # Only attach when we have a real, sampled span context.
    if ctx.is_valid and ctx.trace_flags.sampled:
        exemplar = {"trace_id": format(ctx.trace_id, "032x")}
    REQUEST_DURATION.labels(route=route).observe(seconds, exemplar=exemplar)

Two rules keep this correct. Attach the exemplar only when ctx.trace_flags.sampled is set — an exemplar pointing at a dropped trace is a dead link (see the FAQ on missing exemplars). And expose the metrics endpoint with the OpenMetrics content type, because exemplars do not exist in the legacy Prometheus text format. Serve Content-Type: application/openmetrics-text and start Prometheus with --enable-feature=exemplar-storage.

Step 3: Run the Unified Metric → Exemplar → Trace → Log Query

With both edges instrumented, the debugging walk becomes mechanical. Start from the histogram spike. In Grafana or a compatible UI, a histogram-quantile panel over your instrumented metric surfaces exemplars as diamonds above the line:

histogram_quantile(
  0.99,
  sum by (le, route) (rate(http_request_duration_seconds_bucket[5m]))
)

Click the exemplar diamond sitting in the 2.5 s bucket. The UI reads its trace_id and deep-links to the trace in Jaeger or Tempo, where you see the full span tree and identify which downstream call ate the two seconds. Copy that trace_id and pivot to logs with a filter that keys on it exactly — this is where clock skew stops mattering, because you are joining on the identifier, not the timestamp:

# Loki (LogQL): pull every line the request emitted, in order
logcli query '{service="checkout"} | json | trace_id="4bf92f3577b34da6a3ce929d0e0e4736"'

The result is the complete, ordered log narrative for exactly one request: the SQL it issued, the retry it attempted, the timeout it hit. You traversed metric → trace → log without ever guessing at a time window.

Step 4: Propagate the Key Across Service Boundaries

Correlation is only as complete as your context propagation. If the slow span lives in a downstream service, its logs carry the same trace_id only because the W3C TraceContext traceparent header was propagated across the call. When the trace crosses async boundaries — a thread pool, an event loop callback, a queue consumer — the active context can be lost, and downstream log lines silently fall back to trace_id="0". Ensure async boundaries restore context before any logging happens, so the join key survives the whole request path rather than just the entry service.

Verification

Confirm all three edges resolve before you trust the setup in an incident:

  1. Emit a synthetic slow request. Add a deliberate sleep(2.5) behind a debug route, call it, and confirm the observation lands in the 2.5 s histogram bucket.

  2. Confirm the exemplar exists. Scrape the metrics endpoint directly and grep for the exemplar syntax — a # suffix on the bucket sample:

curl -s -H "Accept: application/openmetrics-text" http://localhost:8000/metrics \
  | grep 'http_request_duration_seconds_bucket' | grep '# {trace_id='
# Expect a line ending: } 1.0 # {trace_id="..."} 2.51 <ts>

  1. Open the linked trace. Follow the trace_id into Jaeger or Tempo and confirm the span tree renders with the expected 2.5 s root duration.

  2. Run the log join. Query your log store filtered on that exact trace_id and confirm it returns the lines your synthetic route logged — and only those lines. A zero-result query means Step 1 is not attaching the id on that code path.

Edge Cases & Gotchas

  1. Logs outside an active span show trace_id="0". Startup, config loading, and scheduled jobs run with no span in context. This is correct behavior, not a bug — filter these lines out of correlation views rather than trying to force an id onto them.

  2. Sampled-out exemplars create dead links. If a request was dropped by head-based sampling, its exemplar points at a trace_id that was never stored. Gate exemplar attachment on the sampled flag, and prefer tail-based retention for latency outliers so the interesting traces always survive.

  3. Timestamp skew across hosts. A trace spanning several machines with unsynchronized clocks can show a span that appears to start before its parent. This never breaks trace_id-keyed log joins, but it does corrupt time-window log queries — so always filter by id first.

  4. trace_id leaking into metric labels. A tempting mistake is adding trace_id as a Prometheus label. Each request would mint a unique series, and cardinality would explode within hours. The id belongs in the exemplar attachment and the log body, never in a label set.

  5. Format mismatch between layers. OpenTelemetry represents trace_id as 32 lowercase hex characters. If one layer logs it as bytes, another as an integer, and a third as uppercase hex, your joins silently return nothing. Normalize to 32-char lowercase hex everywhere.

Performance & Scale Notes

Log injection cost. Reading the span context and merging two fields per log line is a few hundred nanoseconds — negligible next to the serialization and I/O the log call already pays. The real cost is volume: injecting trace_id does not increase line count, but teams often raise log verbosity once correlation makes logs useful again. Keep log levels disciplined; the point of correlation is to read fewer lines, precisely, not more.

Exemplar storage. Prometheus stores a bounded ring of exemplars per series (configurable, default a small fixed count per series). Exemplars are cheap because only one representative per bucket per scrape is retained — you are not storing a trace_id for every request, only for the sampled representative. This keeps exemplar overhead flat regardless of request rate.

Cardinality discipline. Because the join key lives outside the metric label set, correlation adds zero series cardinality to your metrics backend. This is the property that makes the triangle scale: metrics stay cheap and aggregate, traces stay per-request, and the trace_id bridges them without contaminating either store. When you also carry business context, keep it in baggage or span attributes rather than metric labels for the same reason.

Query-time cost. The log join is bounded by filtering on a single high-selectivity field. On indexed stores the trace_id filter is near-instant; on Loki it benefits from a coarse time-range pre-filter to limit the scanned chunk set — use the exemplar’s timestamp to set a tight ±1-minute window before the trace_id filter runs.

Troubleshooting FAQ

Why is trace_id empty in some of my log lines?

The log call executed outside an active span, so there was no span context to read. This happens in startup code, background schedulers, and callbacks that lost the context across an async or thread boundary. Either start a span around that work or accept that those lines are legitimately unlinked and filter them out of correlation dashboards.

The metric spike has no exemplar to click. Why?

Exemplars are only recorded for sampled spans, so if the representative request was dropped by head-based sampling the bucket has no exemplar attached. Raise the sampling rate for the affected route, or switch to tail-based sampling so error and latency outliers are always retained and can back an exemplar.

The trace and the logs disagree on timestamps by a few seconds. Is correlation broken?

No. Correlation keys on trace_id, not on time, so a clock skew between hosts does not break the join. Skew only matters when you widen a log query by time window instead of filtering by trace_id. Always filter by trace_id first and use the time window only as a coarse pre-filter to limit the scan.

Do exemplars work with a Prometheus counter?

Exemplars are supported on histogram and counter sample types in the OpenMetrics exposition format, but tooling overwhelmingly surfaces them on histogram buckets, which is where latency debugging lives. Attach exemplars to your request-duration histogram rather than to raw counters for the most useful metric-to-trace pivot.

How much cardinality does injecting trace_id into logs add?

None to your metrics, because trace_id lives in log fields and exemplar metadata, not in metric label sets. Keep trace_id out of Prometheus labels — a 32-hex-character identifier per request would explode series cardinality. It belongs in the log body and in the exemplar attachment only.

↑ Back to Trace-Based Debugging & Signal Correlation