Break/Fix: Tempo Receives No Traces · Break/Fix · Observability

Reported symptoms

A settlement run fails at 03:40. The on-call engineer has the run’s log, which contains a trace ID, and opens Tempo. Tempo has no trace from settlement-worker.

That is the report. The detail underneath it is stranger:

It is not zero. Searching the last 24 hours by service name returns 11 traces. The CronJob completed 288 times in that window. So the service is instrumented, and something works about four percent of the time.
The trace IDs are real. Paste one into Tempo and a trace comes back - containing only the downstream ledger API spans. The worker generated a trace ID, propagated it correctly across the service boundary, and is itself absent from its own trace.
The traces that exist are cut short. All 11 stop before the end of the run. The span ID in each run’s last log line is not in the trace Tempo returns.
Two tickets already exist and were closed as unrelated. The SDK self-observability scrape job for this service has been down for weeks, and somebody raised the collector queue size two days ago on the theory that spans were being dropped under load. The fraction did not move.
It works locally. The same binary, run by hand as a long-lived process against the same collector, produces complete traces every time.

Four people have looked at this. The hypotheses on the board are: the collector is dropping spans, Tempo is rejecting them, the sampler is discarding them, and the service is only partly instrumented. Each of those explains some of the evidence and none of them explains all of it.

Evidence provided

Read-only / Safe11 traces for a job that completed 288 times

$ curl -s -G 'http://tempo.obs.example.com:3200/api/search' --data-urlencode 'q={resource.service.name="settlement-worker"}' --data-urlencode 'start=1755000000' --data-urlencode 'end=1755086400' --data-urlencode 'limit=500' | jq '.traces | length'

Illustrative output

Read-only / Safethe denominator

$ kubectl get jobs -n batch -l app=settlement-worker -o json | jq '[.items[] | select(.status.succeeded == 1)] | length'

Illustrative output

Take a trace ID from the worker’s own log line and ask Tempo what is in it:

Read-only / Safethe downstream service is there; the worker that started the trace is not

$ curl -s 'http://tempo.obs.example.com:3200/api/traces/4d2b18c7f0a95e63' | jq -r '.. | .spans? // empty | .[] | .name' | sort | uniq -c

      3 GET /v1/accounts
    1 POST /v1/postings

Illustrative output

The eleven that did arrive, against the run durations:

# How long do these runs actually take? Compare against the five-second mark.
kubectl get jobs -n batch -l app=settlement-worker \
  -o jsonpath='{range .items[*]}{.status.startTime}{"\t"}{.status.completionTime}{"\n"}{end}' \
  | head -20

Ninety-six percent of runs complete in under five seconds. All 11 traces that reached Tempo came from runs that did not.

The pipeline downstream of the application is unremarkable:

Read-only / Safeaccepted equals sent, failures are zero

$ curl -s http://otel-collector.obs.example.com:8888/metrics | grep -E '^otelcol_(receiver_accepted_spans|exporter_sent_spans|exporter_send_failed_spans)'

otelcol_receiver_accepted_spans{receiver="otlp",transport="grpc"} 4.187442e+07
otelcol_exporter_sent_spans{exporter="otlp/tempo"} 4.187441e+07
otelcol_exporter_send_failed_spans{exporter="otlp/tempo"} 0

Illustrative output

And the change that started it:

Read-only / Safea refactor, described as a refactor

$ git -C /srv/settlement-worker log --oneline --since=4.weeks -- .

e73c0d9 settlement-worker: replace opentelemetry-instrument launcher with explicit SDK setup
b118af4 settlement-worker: bump base image

Illustrative output

Work the evidence before reading on

The five links between an application and a queryable trace are: the SDK running, propagation intact, the collector reachable, the exporter healthy, and the sampler keeping the trace. Four of them can be cleared from the evidence above.

The worker logged a trace ID and the downstream service’s spans carry it. Which two links does that clear, and how completely?
The collector’s accepted count equals its sent count and its failure count is zero. Which link does that clear - and be precise about what “accepted” means and where the counter lives.
Eleven traces exist, all from long runs, all missing their endings. A sampler that dropped 96 percent of traces would produce a different distribution. What kind of mechanism keeps the beginning of a run and discards the end of it?
The same binary works perfectly on a workstation. What is different about that execution, and is it something about the machine or something about the run?

Before continuing: the collector queue was raised two days ago and nothing changed. Why was that a reasonable hypothesis, and what one piece of evidence should have ruled it out before anybody touched the collector?

Root cause

1. The spans never left the process

A tracing SDK does not send a span when the span ends. It hands the span to a span processor, and the production default is a batch processor: spans go into an in-memory queue and are exported on a schedule. The specification’s defaults are a scheduled delay of five seconds, a maximum queue of 2,048 spans, a maximum export batch of 512, and an export timeout of thirty seconds.

A process that exits discards that queue. There is no flush unless something asks for one.

settlement-worker runs for two to four seconds in 96 percent of its executions. Its spans are created, recorded, and buffered, and then the process returns from main and the buffer goes with it. Nothing is dropped, refused, rejected or sampled away, because nothing was ever sent. That is why every downstream diagnostic is clean, and why the collector queue change made no difference: the constraint was never on the network.

2. That is exactly the distribution you would see

The four percent is not random, and it is the most useful number in the incident.

A run that lasts longer than the scheduled delay gets at least one export before it exits. Those runs appear. Runs shorter than the delay never do. The histogram of run durations and the fraction of traces that arrive are the same distribution seen twice.

It also explains the truncation. The runs that do appear were exported at their five-second mark, which captured the spans that had already ended. Every span that ended after that export - including the run’s last span, the one whose ID is in the last log line - was still in the queue when the process exited. The traces are not “incomplete because Tempo lost something”. They are complete records of everything that happened before the only export that ever fired.

Any hypothesis about dropping, sampling or rejection has to explain why the loss is aligned to the end of a run rather than distributed across it. None of them do.

3. The launcher had been doing this all along

The change three weeks ago replaced opentelemetry-instrument with a hand-written SDK setup. The diff adds a tracer provider, a resource, and an OTLP exporter. Every line in it is correct.

What the diff does not contain is the thing that was removed, because it was never written down in this repository: the launcher installed the SDK and its lifecycle handling, including flushing at exit. Moving to explicit setup moved that responsibility to the application, and nobody knew there was a responsibility to move.

This is why the commit message says “refactor” honestly. From inside the change it is one. The behaviour that disappeared was never in the file being edited.

4. The local run tests a different program

The binary that works perfectly on a workstation is started by hand, watched, and stopped with Ctrl-C after several minutes. That execution crosses the scheduled delay dozens of times, so every span is exported long before the process ends, and the missing flush is unreachable.

It is not a weaker test of the same program. It is a correct test of a different one, and it is the reason four people spent three weeks looking downstream of an application that was working.

Under the hood

The batch span processor is worth understanding as a queue with three exits, because which exit a span takes determines which metric can see it.

A span that ends is enqueued. It leaves the queue in one of three ways. It is exported when the scheduled delay elapses or when the queue reaches the maximum export batch size, whichever comes first. It is dropped, and counted as dropped, when the queue is full. Or it is exported during shutdown, when something calls the provider’s shutdown or force-flush and the processor drains what it holds.

There is no fourth exit that involves the process terminating. Termination is not an event the processor observes; the memory is simply gone. That is what makes this failure so quiet: a dropped span increments a counter inside the SDK, and a span discarded at exit increments nothing, because the thing that would have counted it has also stopped existing.

It compounds with where the SDK’s own metrics live. A short-lived process cannot be scraped: a job that runs for three seconds is not there when the next scrape interval comes round, which is why the self-observability job for this service has been permanently down and why everyone learned to ignore it. Link A of the chain - is the SDK running and emitting - is the one link with no usable evidence for this workload, and it was also the link everyone assumed was fine because trace IDs were appearing in the logs. Trace IDs prove context was generated. They prove nothing about span data leaving the process.

The fix can turn missing traces into killed jobs

Shutting down the tracer provider blocks until the final export completes or the export timeout expires, and the specification default for that timeout is thirty seconds.

For a job that normally runs for two seconds, that is a meaningful change in shape. If the collector is slow or briefly unreachable, the worker now waits. If the CronJob has an active deadline, or the container has a termination grace period shorter than the export timeout, the run is killed part way through its flush - and you are back to missing spans, with the added confusion of a job that now sometimes fails.

Set the export timeout to something the job can afford, make the grace period larger than it, and check the job’s deadline against both. The point is not that the fix is risky; it is that “flush before exit” adds a dependency on the collector to a process that previously had none, and the timeouts are where that dependency becomes visible.

The same reasoning applies to the tempting alternative of exporting every span synchronously as it ends. It closes the gap completely and it makes the collector a latency dependency of every span in the job. On a three-second batch process that may be an entirely reasonable trade. As a pattern copied into a request-serving service, it is a serious one.

Resolution

Confirm the diagnosis cheaply before changing anything. Run the job once with an artificially extended duration - a sleep at the end, longer than the scheduled delay - and check whether the complete trace appears. If it does, the spans are being discarded at exit and every downstream hypothesis is closed.
Add the flush. Shut the tracer provider down on the way out of the process, and register it so that it runs on the error path as well as the success path. A settlement run that fails is the run whose trace is worth the most.
Choose the export timeout deliberately rather than inheriting thirty seconds. Pick a value the job can afford to wait, and write down why that number.
Make the container termination grace period larger than the export timeout, and check the job deadline against both. This is the step that stops the fix from producing killed runs during flush.
Do not reach for a simple span processor as the default. It exports each span synchronously and does close the gap, but it makes the collector a latency dependency of the job. Defensible here, wrong as a pattern to copy.
Do not shorten the scheduled delay to a few hundred milliseconds and call it fixed. It narrows the window without closing it, and it multiplies export volume across every service that copies the setting.
Revert the collector queue-size change. It was a reasonable hypothesis, it was tested, and it was wrong. Leaving it in place bequeaths an unexplained setting that the next engineer will assume is load-bearing.
Decide whether this is worth an out-of-hours fix at all. Nothing is customer-facing and no data is being lost outside telemetry. A hold with an owner and a date is a legitimate answer - provided you record loudly that this job currently has no traces, so the next responder does not spend twenty minutes rediscovering it.

Verification

Verify the end of a trace, not the existence of one. Take the span ID from the run final log line and require it to be present in the trace Tempo returns. A check that only asks whether a trace exists would have passed 11 times while the job was 96 percent unobserved.
Prove the check can fail. Run the pre-fix build once and confirm that same final span is absent. You have a ready-made negative control and no reason to trust a green result without one.
Verify the population, not the sample. Over 24 hours, the number of traces carrying the service name must equal the number of completed runs. Any gap is the fraction still being discarded, and it will point at a code path that exits without the flush.
Confirm the job runtime has not grown past its deadline and that no run was terminated during its flush. This is the failure the fix itself can introduce, and it looks like an unrelated flake.
Confirm otelcol_receiver_accepted_spans rose by roughly the volume you now expect. That counter is the independent statement that spans crossed the network rather than merely being created.
Check the error path specifically. Force a failing run and require its trace to be complete. The success path is the easy half and it is not the half that matters at 03:40.
Close the two inherited tickets honestly. The self-observability scrape job will stay down because the process is too short-lived to scrape, so either push those metrics or record that link A is unverifiable for this workload by design.

Prevention

Treat a short-lived process as a different instrumentation problem from a server. Every default in a tracing SDK assumes a process that outlives its own buffers. A job that runs for two seconds breaks that assumption before it starts, and it breaks it silently, because the evidence dies with the process.
Make flush-on-exit a reviewed requirement for any workload that can terminate, on the error path as well as the success path, and pair it with timeouts that the workload can actually afford.
Review a change that replaces an auto-instrumentation launcher with manual setup as a behaviour change, not a refactor. The launcher was providing lifecycle handling nobody had enumerated, and a diff shows what was added, never what stopped happening.
Alert on the ratio of completed runs to traces rather than on the presence of traces. Presence is exactly what this failure preserves, which is why it survived three weeks and two closed tickets.
Do not let a permanently-down detector become furniture. The dead self-observability scrape job was a true statement about a real gap, and the team had agreed to ignore it long before the gap mattered.
Test instrumentation with a run whose duration is representative of production. A long-lived debug session exercises a different program, and every hour spent trusting it is an hour spent downstream of a healthy pipeline.

What if the runs had all been shorter than five seconds?

Then the number would have been zero rather than eleven, and the incident would have been easier.

Zero is an unambiguous statement. It rules out sampling immediately, because a probabilistic sampler that produces exactly zero over 288 runs is not a sampler. It rules out load-related dropping, because dropping under load is proportional. Zero says something categorical happened, and the search starts at link A.

Four percent invited every partial explanation on the whiteboard. Sampling explains a fraction. Queue pressure explains a fraction. Partial instrumentation explains a fraction. All three are wrong here and all three survive first contact with the evidence, which is why the investigation went sideways for three weeks.

The lesson is to be suspicious of a partial failure that nobody can explain the shape of. “Some of them work” is not a milder version of “none of them work”; it is a different question, and the productive form of it is: what distinguishes the ones that work from the ones that do not? Here that question resolves the whole incident in one query, because the answer is run duration and the boundary is exactly the scheduled delay.

Why this matters

The trace ID in the log was true. The propagation was correct. The collector was healthy, the exporter had no failures, Tempo accepted everything it was sent, and the sampler kept every trace it saw. Every component reported success, and every report was accurate.

The span data was destroyed inside the application, by a queue doing precisely what it was designed to do, in a process that ended before the queue’s turn came round. No metric anywhere in the estate could see it, because the only thing that could have counted it died in the same instant.

That is the general shape worth carrying out of this incident. Telemetry pipelines are observable from the collector onwards, and almost blind before it. Everything upstream of the first network hop - the SDK, the sampler, the processor queue, the process lifetime - is a place where data can vanish without leaving a counter behind, and the further upstream the loss, the cleaner every downstream dashboard looks.

So when a signal is missing and the pipeline is healthy, the pipeline’s health is evidence about the pipeline and nothing else. The question that actually moves the investigation is not “where was it lost”, it is “how far did it get before nobody could see it any more” - and the answer, more often than the dashboards suggest, is that it never got anywhere at all.

Reported symptoms

Evidence

Root cause

Remediation

Verification

Prevention

Reported symptoms

Evidence provided

Work the evidence before reading on

Root cause

1. The spans never left the process

2. That is exactly the distribution you would see

3. The launcher had been doing this all along

4. The local run tests a different program

Resolution

Verification

Prevention