12.3 Golden Signals & Upstream Forensics

Advanced

What you will learn

1. The latency trio: $request_time, $upstream_response_time, $upstream_connect_time — which trip each measures.

2. Upstream forensics: retry chains, status chains, and the connect-time signal for "server's alive but slow."

3. Cache and compression verdicts as trendable data.

4. The jq receipts: error rate, p95, upstream mix — dashboards before the dashboard.

5. The second war story: a corrupted max-age that silently disabled caching — caught by exactly these fields.

1. The latency trio

Three timers, three different trips:

The gaps are the diagnosis. $request_time − $upstream_response_time ≈ nginx's own time (client body receipt, buffering, compression, slow clients). Big gap with small upstream time → the client is slow or the body was huge. $upstream_response_time − $upstream_connect_time ≈ the app's processing time. connect itself large → the handshake problem: SYN drops, TLS negotiation, connection-pool exhaustion (Module 5's keepalive receipts).

The slow probe (real line, ?delay=1 backend):

{"uri":"/slow/?delay=1","status":200,"latency":1.002}

and the fast baseline ( "latency":0.000, "connect":"0.000", "response":"0.000") — the spread between them is what percentiles are made of.

2. Upstream forensics — chains are evidence

On retry, the upstream variables become comma-chains — one value per attempt, in order:

"upstream": { "addr": "10.0.0.1:9001, 10.0.0.2:9001", ⏎               "status": "502, 200", ⏎               "connect": "0.010, 0.001", "response": "0.010, 0.050" }

Read that as: first peer took 10 ms to connect and immediately 502'd; the retry connected in 1 ms and served in 50 ms. That's not noise — that's Module 5's proxy_next_upstream behavior as data: which peer failed, how fast, whether the retry saved the request. Alerts key off chains ( .upstream.status | contains(",") = "a retry happened at all"); dashboards split on the first address; postmortems use the timing gaps.

The failure line from a real run:

{"uri":"/boom/","status":503,"upstream":{"addr":"127.0.0.1:9001","status":"503",...},"latency":0.000}

Note what the log proves: the 503 came from the upstream ( upstream.status:"503"), not from nginx — the first question in every "who returned my 500" argument, answered by a field you already emit.

3. Cache and compression verdicts

$upstream_cache_status (Module 8's vocabulary — MISS, HIT, EXPIRED, STALE, BYPASS, REVALIDATED) becomes a ratio problem the moment you log it: HIT/(total) is your offload; STALE-rate climbing means your origin is degrading before it's down; BYPASS-rate is your cookie/auth carve-outs (and their cost).

The MISS→HIT pair (real lines):

{"uri":"/api/data?run=10531","cache":"MISS","gzip_ratio":"0.85","upstream":"127.0.0.1:9001"}
{"uri":"/api/data?run=10531","cache":"HIT","gzip_ratio":"0.85","upstream":""}

$gzip_ratio (Module 9) next to bytes gives compressed-size economics per route; a ratio trending toward 1.0 on JSON routes usually means the payload became repetitive blobs — or compression stopped applying.

4. Dashboards are jq one-liners (the receipts)

Until you need a time series database, your log IS the database. The capture run, on four probes (1 slow, 2 cached, 1 error):

error rate:
    "25% (1/4)"

p95 latency:
    1.001s

upstream distribution:
    [{"upstream":"","requests":1},{"upstream":"127.0.0.1:9001","requests":2},{"upstream":"127.0.0.1:9004","requests":1}]

status code histogram:
    [{"status":200,"n":3},{"status":503,"n":1}]

The generating one-liners (they fit in any terminal — and any sidecar):

jq -s 'length as $t | map(select(.status >= 500)) | "\(100*length/$t)%"' golden.log
jq -r '.latency' golden.log | sort -n | awk '{a[NR]=$1} END{print a[int(NR*0.95)+1]}'
jq -c -s 'group_by(.upstream.addr) | map({upstream: .[0].upstream.addr, n: length})' golden.log

Translation to production: error rate → alert threshold; p95 → your SLO; upstream mix → weight sanity; histograms → release regression checks. The golden diff from Module 9 is exactly this, run twice — before/after a config change, diff the histograms and ratios. Any change that "should be invisible" becomes provably invisible or visibly not.

5. The corrupted max-age (a misconfiguration story)

A common misconfiguration: both /api probes logged MISS. The cause chain, visible in the response headers: proxy_pass http://obs_app/cache/30 (no trailing slash) glued the remainder onto the URI — the origin saw /cache/30data, parsed the TTL as 30data, and emitted Cache-Control: max-age=30data. Unparseable → nothing cached → MISS forever, silently, with green health checks everywhere.

The observability lesson: the MISS-ratio dashboard catches what health checks can't — everything was "working," nothing was cached. A ratio alert ("cache offload below X%") would have paged on a real deployment; here the never-moving MISS field was the only witness. Same class of bug as "failures that log 200s": the system was healthy by every liveness measure and wrong by every correctness one.

Try it yourself

• jq -s 'length as $t | map(select(.status >= 500)) | "\(100*length/$t)%"' golden.log — the first of the section-4 one-liners; run them against your own golden.log, and every field from this lesson and Lesson 12.2 gets an end-to-end check.

• Generate your own forensics: kill one backend of a two-peer pool (the Module 5 upstream shape), hit it, and read the comma-chains in golden.log.

• Run the golden diff: capture the status histogram, reload with gzip off, capture again — the gzip_ratio column flattens.

Q&A

Q: Why is my p95 a string sort sometimes? A: You sorted text. sort -n (or jq's tonumber) — "1.002" < "0.85" lexically. Percentile bugs are 90% sorting bugs.

Q: percentiles from logs at scale? A: Logs give exact percentiles on a window; for streaming percentiles you move to a metrics system (this format feeds it). But for incident forensics — "what was p99 during 14:00–14:10" — the log beats the histogram bucket every time.

Q: $upstream_response_time has multiple values for ONE upstream? A: That's retries (or an internal redirect re-proxying), not streaming — nginx records one timer per upstream attempt, never per chunk, so a slowly-streamed response is ONE large value. The same address twice usually means a retry re-selected it; a colon-separated pair means the request went upstream twice (X-Accel-Redirect, error_page hop). Count values vs addrs either way.

Takeaways

• Three timers, three trips: whole-request, upstream turn-around, handshake. The gaps between them are the diagnosis.

• Retry chains in upstream fields are Module 5's behavior as data — alert on "contains a comma," split on first address.

• Cache status and gzip ratio turn Modules 8–9 into trendable ratios; a falling HIT-rate catches silent breakage that health checks never see (the max-age=30data receipt).

• Error rate, p95, upstream mix, histograms: four jq one-liners that ARE your dashboards until you outgrow files.