DEV Community

Aryan
Aryan

Posted on

The Job Finished. The Trace Didn’t.

How I repaired broken causality across FastAPI, Redis Streams, retries, and a background worker with OpenTelemetry and SigNoz

The API returned 202 Accepted. The worker finished the job. Redis had nothing left to process. Then I searched for job-before-001 in SigNoz and found two unrelated trace IDs.

Nothing in the application had visibly failed. The FastAPI service accepted the synthetic job, the Redis Stream delivered it, and the worker ran its steps. But the trace could not explain how the worker got there. The API span ended after publishing to Redis; the worker appeared in a new root trace.

That was the point of this local experiment: a system can look healthy while its causal story is broken.

One app.job_id returned API and worker spans, but the trace IDs differed. The Redis boundary split one logical operation into separate traces.

The small system I used to reproduce it

I kept the setup deliberately small: a client calls POST /agent-jobs, FastAPI publishes a message to the agent-jobs Redis Stream, and a background worker consumes it. Inside the worker, I created agent.plan, tool.retrieve, agent.evaluate, and result.persist spans. The services are named async-agent-api and async-agent-worker.

All job IDs, payloads, and failures were synthetic. I did not need a large workload to see the problem; one queue boundary and a few child spans were enough. The project also includes casting.yaml and casting.yaml.lock so the local SigNoz setup is reproducible.

Conceptual diagram, not telemetry evidence: the same workflow before and after W3C trace context crosses the Redis message boundary.

The broken version

The broken experiment was intentional. I started the API and worker with PROPAGATE_TRACE=false and sent job-before-001 using the tested command below.

PROPAGATE_TRACE=false APP_EXPERIMENT=before docker compose up -d --force-recreate async-agent-api async-agent-worker
python scripts/send_jobs.py --job-id job-before-001
Enter fullscreen mode Exit fullscreen mode

The producer still created a redis.publish span and wrote a normal Redis Stream message. The key difference was that its trace_context field stayed empty:

carrier: dict[str, str] = {}
if propagate_context:
    propagate.inject(carrier)

payload = {
    "job_id": job_id,
    "experiment": experiment,
    "attempt": "1",
    "trace_context": json.dumps(carrier),
}
client.xadd("agent-jobs", payload)
Enter fullscreen mode Exit fullscreen mode

On the consumer side, an empty carrier meant parent_context was None. Starting redis.consume with that context made it a new root. The useful app.job_id attribute still linked the records semantically, which is why the SigNoz filter app.job_id = 'job-before-001' found both sides. It did not connect them causally.

The part that was missing

Redis is a manual propagation boundary in this setup. FastAPI instrumentation can create the server-side HTTP span, but a custom message body does not automatically know which field should carry the W3C context. OpenTelemetry’s propagation model calls that message field a carrier: a mutable string map that is written on the sending side and read on the receiving side.

“Telemetry can be complete and still be causally wrong.”

The repair was simple in concept: inject the current context, transport the carrier inside the Redis message, then extract it before the worker creates its consumer span. The exact placement mattered more than the number of lines.

The three-part fix: inject, transport, extract

For the repaired run, I recreated the services with PROPAGATE_TRACE=true and sent job-after-001. The API injects while the producer span is current, then serializes the carrier because Redis Stream fields must be strings or bytes in this client setup.

with tracer.start_as_current_span("redis.publish", context=workflow_context,
                                  kind=SpanKind.PRODUCER) as span:
    carrier: dict[str, str] = {}
    if propagate_context:
        propagate.inject(carrier)
    payload = {
        "job_id": job_id,
        "experiment": experiment,
        "trace_context": json.dumps(carrier),
    }
    client.xadd("agent-jobs", payload)
Enter fullscreen mode Exit fullscreen mode

The worker does the inverse before it creates redis.consume. It also records whether a carrier existed and keeps the same app.job_id on every span.

carrier = json.loads(job.get("trace_context", "{}"))
context_present = bool(carrier)
parent_context = propagate.extract(carrier) if context_present else None

with tracer.start_as_current_span("redis.consume", context=parent_context,
                                  kind=SpanKind.CONSUMER) as consume:
    consume.set_attributes({
        **attrs(job, context_present),
        "messaging.system": "redis",
        "messaging.destination.name": "agent-jobs",
    })
Enter fullscreen mode Exit fullscreen mode

This follows the OpenTelemetry Python propagation guidance: deserialize the carrier, extract a context, and start the next span with it. After that change, POST /agent-jobs, redis.publish, redis.consume, agent.plan, tool.retrieve, agent.evaluate, and result.persist appeared in one connected trace for the repaired job.

After injection in the API and extraction in the worker, the repaired job appears as one connected API-to-worker trace.

Retries were a second propagation boundary

Fixing the first publish was not enough. A retry can accidentally create a fresh carrier and quietly split the workflow again. I tested this with job-after-retry-001 and the tested script flag --fail-first-attempt. Attempt one raises the controlled RuntimeError("controlled retrieval failure") inside tool.retrieve.

The worker records a retry.schedule span, preserves the existing carrier, changes only attempt from "1" to "2", and sends the retry back to agent-jobs:

retry_job = {**job, "attempt": "2", "trace_context": json.dumps(carrier)}
client.xadd("agent-jobs", retry_job)
retries_total.add(1, {"app.experiment": job["experiment"]})
Enter fullscreen mode Exit fullscreen mode

The second attempt completed in the local test. There is no artificial backoff in this code, so I do not claim one. The useful result is narrower: the retry reused the original propagated context instead of losing it at the second queue publish.

A controlled retrieval failure triggers retry.schedule; the retry preserves the carried context and completes on attempt two.

Logs finally told the same story

I also wanted logs to be navigable with the trace, not merely searchable by job ID. emit_log() creates an OTLP log record using get_current() while the active span is still in scope. The API emits Agent job accepted; the worker emits Worker job started, Agent job scheduled for retry when applicable, and Agent job completed.

The Logs Explorer screenshot shows API and worker messages for the same synthetic job. The code intentionally sends no full message payloads, passwords, or API keys to the log attributes. SigNoz documents the same general correlation model: log records with trace context can be opened from Logs Explorer and navigated back to their corresponding trace (trace-log correlation).

API and worker log messages for the repaired workflow, filtered by the shared job attribute.

Turning trace integrity into a signal

Finding one split job was satisfying, but I wanted a way to notice the pattern again. The worker emits three counters: async_jobs_total, async_jobs_context_missing_total, and async_jobs_retried_total. I made the Async Agent Trace Integrity dashboard in SigNoz from those real metrics.

In the captured 30-minute dashboard view, the panels show Total Jobs: 2, Missing Context: 0, and Retry Count: 0. Those values are only a snapshot of the selected local time range, not a throughput claim. The panel construction used SigNoz Query Builder’s metric aggregation options; SigNoz documents that the same visual builder is available in dashboards and supports filtering and aggregation (Query Builder).

I did not configure or test a trace-integrity alert in this experiment, so I am not presenting an alert as evidence. The next useful step would be an alert on nonzero missing-context jobs after deciding what volume and sampling policy make sense.

The local dashboard snapshot tracks total jobs, jobs missing propagated context, and retries for the selected 30-minute window.

What I learned

The main lesson was not that adding telemetry is enough. Telemetry presence and telemetry correctness are different things. A stable job ID helped me locate the split, but it could not repair causality. The repair came from treating both the async handoff and the retry handoff as boundaries that needed deliberate context handling.

I also learned to emit correlation-sensitive logs while a span is active, and to start with one workflow I could understand end to end. This remains a local synthetic experiment with limited traffic; it does not establish production-scale behavior, sampling policy, or baggage governance. Next time, I would add an automated integration check that asserts the API and worker share a trace for a known job.

Before this experiment, I treated a completed worker job as proof that the workflow was healthy. Now I also check whether the trace can explain how that job got there.

Top comments (0)