The trace_id was the easy part — Rust, OTel, Loki

Companion to One port, three client crates. That post covered how one Rust service reads three blockchains through a single trait, and stopped at the boundary where the design was done. This one picks up after it: the same service, an issue estimated at an afternoon, and the four conditions that had to hold before the result meant anything — plus a fifth that arrived with the follow-up. Reading the first is not required; the traps below are about OpenTelemetry, tracing and Loki rather than about chains.

The seed post listed what the difficult middle of a data platform actually consists of, and one item on that list was "observability that points at the right wire when something breaks". This post is what that one item cost.

The system is a multi-chain ingestion pipeline: Rust services subscribing to Ethereum, Solana and Polkadot, publishing to Kafka, running on Kubernetes with Prometheus, Loki and Tempo behind it. An ordinary enough shape. What makes the observability requirement unusual is not the architecture but what the data does to it.

Blockchain sources are ephemeral in a way most sources are not. A database you are replicating from still has the row tomorrow. A chain's recent blocks are served by an RPC provider for a while and then they are not, and provider retention is a commercial decision rather than a promise to you. If the pipeline silently drops an event, the evidence it existed may be gone before anyone notices — and nothing upstream will complain, because nothing upstream knows you were listening.

So "did we see everything, and did we handle it correctly" is not a comfort question on this platform — it accounts for most of what the product is, which is why an issue that reads like a formatting nicety was not a cosmetic one.

The issue was one sentence: log lines should carry the active OpenTelemetry trace_id so a line in Loki links to its trace in Tempo. It was estimated at a field, a formatter and an afternoon.

The formatter did take about an afternoon. Making the field mean anything took the rest of the work, and three of the four conditions that had to hold failed silently — none of them raised an error, panicked or turned a test red, and each produced output that looked entirely correct.

That silence is the part worth generalising, because observability code has a property that makes it unusually prone to it: it is the instrument you use to check whether everything else works, so nothing else is watching it. A broken pipeline raises an error someone sees. A broken metric reads zero, and zero is a plausible number.

Four things, not one

Before a trace_id in a log line is useful, all of these have to hold:

1. A span exists around the work.
2. That span closes, so it gets exported.
3. The log event is emitted inside it, and inside the right one.
4. The formatter can see the span's OTel context and writes it out.

The issue named only the fourth, and the service had the first and nothing else.

The diagram, in words: two paths leave the opened span. The first closes it and exports it, producing the trace. The second carries the log event through the formatter into the JSON line, then through the log pipeline to the clickable link. Both have to finish before that link opens anything; the issue described only the last step of the second.

The formatter is the only step of that chain visible from a log line, which is why an afternoon was a fair estimate for it and a bad one for the feature.

Trap 1 — a span that never closes is never exported

The service's ingestion loop carried #[instrument] on its top-level run function, so a span did exist — exactly one, opened at startup and closed at shutdown.

tracing-opentelemetry ends and exports an OTel span in the subscriber's on_close callback. A span that never closes is never sent. The process could run for a week with tracing fully configured, the OTLP exporter connected and healthy, and Tempo would receive nothing at all.

Nothing in the system reports this, because from every component's point of view everything is working: the exporter is up, the sampler says AlwaysOn, and the configuration is correct. There is simply never anything for it to send.

The fix is a span whose lifetime matches a unit of work:

Some(Ok(event)) => {
    let span = info_span!("ingest_event", event_id = %event.event_id());
    span.in_scope(|| {
        // ... one event's worth of work
    });
    // the span drops here, and only here does it export
}

An #[instrument] on a long-running function is a logging construct, not a tracing one. It scopes your log lines correctly and it will never produce a trace.

Trap 2 — builder.trace_id is a root-span-only answer

To write the field, the formatter needs the trace id of the span it is inside. tracing-opentelemetry stores its per-span state in the registry's extensions, and the obvious implementation is three lines:

let extensions = span.extensions();
let otel = extensions.get::<OtelData>()?;
otel.builder.trace_id

OtelData is public, the field is right there, and this works. On root spans.

From tracing-opentelemetry-0.28.0/src/layer.rs:887:

// Record new trace id if there is no active parent span
if !parent_cx.has_active_span() {
    builder.trace_id = Some(self.tracer.new_trace_id());
}

On a child span it is None. The trace id lives in the parent context instead, reachable via parent_cx.span().span_context().trace_id().

This is a nasty shape of bug, because the naive version passes the naive test. Open one span, log inside it, assert the field is present — green. Every real log line in the service is inside a child span, so the field would have been silently absent in production and reliably present in CI.

The test that catches it logs from inside a child:

let root = tracing::info_span!("root");
let _root = root.enter();
let child = tracing::info_span!("child");
let _child = child.enter();
tracing::info!("block ingested");

It is worth proving that the test discriminates rather than assuming it. Replacing the parent-context fallback with return None fails that test and only that test — the other three stay green.

The obvious fixture is not a simpler version of the real case. It is a different case — and when the library branches on the difference, a green test is pinning the branch you do not ship.

Trap 3 — .instrument() on the wrong future compiles and does nothing

Each chain adapter runs its subscribe-and-reconnect loop in a spawned task. tokio::spawn does not inherit the caller's span, so every reconnect warning was emitted outside any span at all — invisible to the whole scheme.

The obvious fix, applied three times:

tokio::spawn(async move { run_subscription_loop(...).await; })
    .instrument(span);

It reads correctly, and it is completely inert.

tokio::spawn returns a JoinHandle, and JoinHandle is itself a Future. So .instrument() accepts it and produces an instrumented handle, which is dropped on the next line without ever being polled. The task — already handed to the executor — still has no span.

The type system has no objection, because nothing here is type-incorrect. The only signal is a lint:

warning: unused `tracing::instrument::Instrumented` that must be used
    = note: futures do nothing unless you `.await` or poll them
help: use `let _ = ...` to ignore the resulting value

Note that the suggested fix is precisely wrong — let _ = ... silences the one piece of evidence that the change did nothing. The message body is the actual information: you built a future and threw it away.

tokio::spawn(
    async move { run_subscription_loop(...).await; }.instrument(span)
);

.instrument() decorates a future you still own. Once a future is with the executor there is nothing left to decorate — same for .timeout(), .boxed(), and every other combinator. If you are calling one on a JoinHandle, ask what you actually meant.

Trap 4 — every span closed, and they all landed in one trace

This one survived implementation, review of the implementation, and a written retrospective. It was caught on a second review pass, by asking a question none of the tests asked: not does the span close, but what is it a child of.

ingest_event was created contextually, which makes it a child of run — the process-lifetime span from Trap 1. run is the root, so run generates the only trace id that ever exists, and every child inherits it.

Two sibling event spans under one root, printed from an actual test run:

trace_ids: [
    "f3da095a59a8db160b9f4605b879b2e0",
    "f3da095a59a8db160b9f4605b879b2e0",
]  same = true

So: spans close, spans export, logs carry a well-formed 32-hex-character trace id, every test passes — and clicking a log line opens a "trace" containing every event the process has handled inside the backend's retention window. On a blockchain ingester pulling three chains, that is several hundred thousand spans a day in one trace. That is not a trace in any useful sense; it is a haystack with a link pointing at it.

The fix is one keyword — make each unit of work its own root:

let span = info_span!(parent: None, "ingest_event", event_id = %event.event_id());

Same probe after the change:

trace_ids: [
    "508d439ce5a118553871703aea27d140",
    "29ec1a9e882c4970d778e47143d50833",
]  same = false

Parenting to run bought nothing anyway — run never closes, so it never exports. The child was inheriting an id from a span that does not exist downstream.

The general shape: "the span closed" and "the span is in a sensible trace" are separate claims, and only the first one is easy to test. A test that asserts a trace id is present passes identically whether you have one trace per event or one trace per process.

The formatter, and the advice I gave myself that was wrong

tracing-subscriber's fmt layer and the OTel layer are independent — the JSON formatter serialises fields and span names, and never looks at the OTel SpanContext. A Layer cannot add fields to an already-constructed Event either; the visitor is read-only. So the injection has to happen during serialisation, which means implementing FormatEvent.

There are two ways to do that, and I picked wrong first. My own note-to-self said: own the serialisation with serde_json, because splicing a field into another formatter's output is fragile string surgery.

Reading tracing-subscriber's fmt/format/json.rs changed my mind. The stock implementation uses WriteAdaptor and SerializableSpan, neither of which is public. Reimplementing means writing both by hand — including the part that pulls formatted fields out of span extensions and re-parses them as JSON, which carries a maintainer comment in that file calling it an ugly fix. Roughly 120 lines of replicated private internals, drifting from upstream as the crate evolves, to add one key.

The fragility argument was also only half right. Suffix surgery is fragile — inserting before the closing brace means reasoning about whether the object is empty. Prefix surgery has no such case: the record always opens with {, and inserting immediately after it preserves the stock key order exactly.

let mut record = String::new();
self.inner.format_event(ctx, Writer::new(&mut record), event)?;
 
match current_trace_id(ctx, event) {
    Some(trace_id) => write_with_trace_id(&mut writer, &record, trace_id),
    None => writer.write_str(&record),
}

The whole edit is one strip_prefix, one guard, and a fallback that emits the record untouched if the assumption ever breaks. A test pins that the delegated JSON shape survives.

"Don't do string surgery" is a good prior, not a rule. It was written for the case where you own the format — and here the entire point was not owning it.

Absent, not zero

An invalid span context yields the all-zero trace id. Writing "trace_id":"00000000000000000000000000000000" would satisfy a careless test — the key is present, it is 32 hex characters — and would then match the dashboard's derived-field regex, producing a clickable link to a trace that cannot exist.

The formatter omits the key entirely instead. Two of its four tests exist only to pin that: no OTel layer installed (a supported deployment — the exporter is optional), and no span entered.

For a correlation id, absent and wrong are not adjacent failure modes — they are opposites. An absent field tells the reader there is nothing to follow, whereas a wrong one sends someone down a dead end and costs them the time it takes to prove it is one.

And then the pipeline was wrong too

Verifying end to end found the part that no amount of Rust would have fixed: two breaks between the service and the dashboard link, neither in the application.

The derived-field matcher was written in logfmt. The Grafana datasource config had been carrying this since the stack was built:

derivedFields:
  - datasourceUid: tempo
    matcherRegex: "trace_id=(\\w+)"

The service emits JSON, so trace_id= never appears in a line that reads "trace_id":"...". It had matched nothing for weeks, and there was no way to notice, because nothing emitted a trace id either. Two halves of a feature, both missing, each hiding the other.

The log aggregator only parsed the outer envelope. Vector's aggregator ran one transform:

. = parse_json!(.message)

but its Kafka source had no decoding block, so the default byte codec made .message the agent's envelope rather than the service's log line. That single parse lifts the envelope and leaves the application's JSON as an escaped string still sitting inside .message. Querying the log store directly, the stored top-level keys were:

['file', 'kubernetes', 'message', 'source_type', 'stream']

None of the service's own fields made it into that list: level, target, span and the event id were all still inside the escaped string in .message. Every structured field the service works to emit was one parse_json short of being queryable — which also explained something I would otherwise have blamed on the log store, namely that the field list for those streams only ever showed labels.

There is a trap in fixing that too. The existing ! means abort on failure, and Vector drops the event and increments an error counter. Defensible for the envelope, which the agent always produces. Not defensible for the inner payload: every other container in the cluster logs plain text, and a ! there silently discards all of it.

With both ends repaired, the two halves finally describe the same string. The matcher, in JSON rather than logfmt:

derivedFields:
  - datasourceUid: tempo
    matcherRegex: '"trace_id":\s*"(\w+)"'

And a line off the ingest path, captured from a test that renders records through the same formatter production uses:

{"trace_id":"90a79d9c4db18e37d9f45c22338fa3e1","timestamp":"2026-08-25T14:37:59.805729Z","level":"INFO","fields":{"message":"chain event ingested","event_id":"01a0395b-4c7a-7112-b4ee-2c154b83f8c0","event_type":"block_ingested","lag_us":3259,"block_number":1},"target":"chain_ingestor::application::ingest_blocks","span":{"chain":"ethereum","event_id":"01a0395b-4c7a-7112-b4ee-2c154b83f8c0","name":"ingest_event"},"spans":[{"chain":"ethereum","event_id":"01a0395b-4c7a-7112-b4ee-2c154b83f8c0","name":"ingest_event"}]}

trace_id is the first key because the formatter splices it after the opening brace rather than appending it, which is what keeps the matcher a plain match instead of something that has to reason about position. Everything after it is queryable now that the inner payload is parsed, so level, event_type and lag_us are filters rather than text a human reads.

That is the entire feature: a line in the log store, a pattern that matches it, and a link that resolves to a trace holding that one event.

Trap 5 — a sampler that decides per span, not per trace

Trap 4's fix is one keyword, which is what it costs to read. What it costs to run is arithmetic.

A root span per event pins span count to event count, and the Kafka publisher already carries its own #[instrument], so each event produces two spans rather than one. Three chains at current block rates works out to roughly 222,000 events a day — call it 444,000 spans. The next issue adds transaction streaming to the Ethereum adapter, which takes Ethereum alone from 7,200 events a day to about 1.3 million. Two and a half million spans, from one chain, against a Tempo ingester with a 384Mi memory limit.

Storage is not where this breaks — retention is 24 hours and the volume stays in single-digit gigabytes. What does not scale is the ingester's memory and the OTLP exporter's batch queue, which drops spans when it fills and reports nothing when it does. Those drops cluster in exactly the busy periods worth looking at, so an accidental sample at an unknown rate is strictly worse than a deliberate one at a known rate.

That makes AlwaysOn — the sampler in place until now, which exports every trace and decides nothing — the wrong default at this volume. Replacing it is the obvious move, and the replacement carries a trap of precisely the same shape as the four above:

// re-decides at every span
Sampler::TraceIdRatioBased(ratio)
 
// decides once, at the root, and every descendant inherits it
Sampler::ParentBased(Box::new(Sampler::TraceIdRatioBased(ratio)))

should_sample is called per span. A bare ratio sampler therefore evaluates each span independently, so a parent can be sampled in while its child is sampled out. The trace arrives in Tempo with spans missing, and nothing in it indicates that anything is missing. That is worse than not sampling at all, for the same reason an all-zero trace_id is worse than an absent one: it is a dead end that costs someone the time it takes to prove it is one.

Writing the test for that was the interesting part. The obvious fixture — pick a ratio, check what the children do — passes against both samplers, because for most ratios they agree. They differ in exactly one case, and the test has to sit on it: a span whose parent arrived already sampled out, at ratio 1.0. At 1.0 the bare sampler keeps every trace id unconditionally, so it clears every other assertion in the module and fails only here, where the right answer is to drop a span the ratio would have kept. Get that fixture wrong and the suite passes against the broken sampler.

The fix then arrived carrying a version of its own trap. The ratio is a fraction, and 100 is what someone thinking in percentages writes — a valid f64, and TraceIdRatioBased reads anything >= 1.0 as always-on. A config edit meant to cut export by ninety-five percent silently produces the maximum instead. It is refused at load now; clamping it would have been one more thing that looks like it worked.

The real span rate is still unmeasured, so the deployed ratio is 1.0 and the number will follow the measurement. The wrapper was not the part to defer, though. A rate that is too high shows up on a dashboard; a half-sampled trace looks exactly like a whole one.

The take-home

Five traps, one property in common: each produced output that looked right.

• A span that never closes exports nothing, and nothing reports it.
• A trace id read from the wrong field is absent in production and present in CI.
• A combinator applied to the wrong future compiles, runs, and does nothing.
• Spans that close correctly can still all land in one trace, and every test still passes.
• A sampler that decides per span rather than per trace yields traces that are half there and look whole — and only one fixture in the space tells the broken one from the correct one.

The thread through them is that observability code has no independent observer. Everywhere else in a system, being wrong eventually surfaces as an error someone sees. Here, being wrong surfaces as telemetry that looks fine — and you find out during the incident it existed to help with.

Two habits would have caught all of them. Write the chain from work happens to human sees it before estimating any link in it. And for each link, ask what it would look like if it were broken — if the answer is "the same", that link needs a test that would fail.

If you have hit a different flavour of silently-fine telemetry — or think per-event root spans are the wrong call and run should have been the trace — I would genuinely like to hear which one bit you. The door is open at cordata.tech/contact. Related reading: One port, three client crates for the architecture of the service this post instruments.