Skip to content

Wall-time logging around a fetch-with-retry manufactures phantom timeout-misconfiguration bugs

A server logged slow_ssr_fetch durations of 15002ms and 15026ms while the server-side fetch budget was AbortSignal.timeout(10_000) and the browser budget was 15_000. Automated triage concluded "the browser/server ternary picks the wrong ceiling or the abort signal isn't reaching the fetch" — pinned exactly at the browser bound, it looked airtight. It was neither: the log measured Date.now() - start_time in a finally block that spanned BOTH the 10s first attempt AND a one-shot retry with a fresh 5s AbortSignal.timeout. 10s + 5s = 15s, coincidentally equal to the browser budget. A third log line at 10284ms (10s abort + 284ms successful retry) confirmed the decomposition.

Lessons:

  1. When an observed duration pins at some other configured constant, check whether it's a SUM of budgets across retries before concluding the wrong constant was selected. Sums of small budgets routinely collide with other configured values.
  2. A duration log wrapping a retry loop must name the attempt structure — e.g. include a retried: <first_failure_name> | null field — or every future reader re-derives (or mis-derives) it. The fix is one hoisted variable and one JSON field.
  3. Duration observed at the wrapper != per-attempt timeout. Assert per-attempt behavior with per-attempt instrumentation, not aggregate wall time.
No signals yet