# Separate the first symptom from the root cause in service logs

> Read an interleaved gateway, checkout and ledger log timeline. See how a tight caller timeout and a retry without an idempotency key cause duplicate writes.

- Canonical HTML: [https://unrust.dev/blog/trace-first-symptom-vs-root-cause-in-logs](https://unrust.dev/blog/trace-first-symptom-vs-root-cause-in-logs)
- Markdown representation: [https://unrust.dev/blog/trace-first-symptom-vs-root-cause-in-logs/index.md](https://unrust.dev/blog/trace-first-symptom-vs-root-cause-in-logs/index.md)

Published: 2026-10-22. By the Unrust team.

[Open the companion tool](https://unrust.dev/tools/async-log-timeline-explorer/index.md)

## Why the loudest log line is rarely the root cause

During an incident, the first line an engineer notices is usually the final HTTP error or a customer report of a duplicate charge. In an interleaved multi-service log stream, however, three distinct moments matter: the underlying condition that slowed or broke the work, the first observable symptom where the timeline diverges from normal, and the final outcome returned to the caller.

In the log timeline explorer, start with a 400ms gateway timeout, a 650ms ledger commit duration, and a retry without an idempotency key. The final line says 200 OK, yet the ledger committed two separate charges.

```text
L3 10:14:00.120 [LEDGER] WARN: waiting on row lock; commit will take 650ms (> gateway 400ms budget)
L4 10:14:00.400 [GATEWAY] WARN: upstream timeout after 400ms on attempt=1
L5 10:14:00.410 [GATEWAY] INFO: retrying POST /checkout attempt=2 idem=none
```

## A caller timeout does not cancel downstream database work

At 10:14:00.120 (Line 3), the ledger service logs that it is waiting on a row lock and will need 650ms to commit. At 10:14:00.400 (Line 4), the gateway hits its 400ms timeout budget. That timeout closes the gateway’s wait on attempt 1, which is the first caller-side symptom, but the ledger transaction for attempt 1 is still running.

Ten milliseconds later, the gateway fires attempt 2 without an idempotency key. Because attempt 1 commits at 665ms and attempt 2 commits shortly after, the customer is charged twice even though the HTTP response looks like a clean recovery.

## Compare idempotent retries against disabling retries

Switch the explorer’s retry policy to Retry once with idempotency key (idem=ord_42). The gateway still times out at 400ms and sends attempt 2, but both attempts carry the same idempotency token. When attempt 1 finishes committing tx_101, the ledger recognizes idem=ord_42 on attempt 2 and replays tx_101 instead of inserting a second charge.

Next, switch to No automatic retry. The duplicate charge disappears, but now the gateway returns 504 Gateway Timeout at 405ms while the ledger still commits tx_101 at 665ms. The caller believes the checkout failed even though the charge succeeded.

## Align timeout budgets and idempotency together

Finally, change the gateway timeout to 900ms or reduce the ledger commit duration to 250ms. When the caller’s timeout budget exceeds the downstream lock wait, attempt 1 finishes in a single pass and no retry is needed.

When reviewing service logs or retry configurations, always check two things together: whether the upstream timeout is shorter than a valid downstream commit, and whether every retryable write carries a deterministic idempotency key.

## References and next steps

[RFC 9110: HTTP semantics — idempotent methods](https://httpwg.org/specs/rfc9110.html#name-idempotent-methods)

[Practice reviewing retry and timeout logic](https://unrust.dev/guides/reviewing-retry-logic/index.md)

[Take the free diagnostic without tools or hints](https://unrust.dev/diagnostic/index.md)