No alerting on prod 5xx: 87 errors in 24h (incl. 5x /healthz, 5x homepage) went entirely undetected #54

New issue

Closed

opened 2026-07-24 19:54:19 +00:00 by admin_emi · 0 comments

admin_emi commented

2026-07-24 19:54:19 +00:00

Owner

Summary

Prod served 87 HTTP 5xx in the last 24h against 11,079 requests (0.79% error rate). None of it triggered any alert. It was found only by manually querying Caddy access logs in Loki. Five of the failures were /healthz itself - the endpoint whose entire job is to be noticed when it fails - and five were the homepage.

Evidence (re-derived 2026-07-24 ~19:45 UTC, prod Caddy logs via Loki)

Total requests, 24h:

sum(count_over_time({job="caddy", host="prod"} [24h]))
=> 11079

5xx by status:

sum by (status) (count_over_time({job="caddy", host="prod"} | json | status>=500 [24h]))
  status=500  ->   2
  status=502  ->  16
  status=503  ->  69
                 ----
                  87    = 0.79% of 11079

By route (sum by (request_uri, status) (count_over_time(... [24h]))):

/logo.png                        503 x15
/                                503 x5     <- homepage
/healthz                         503 x5     <- health endpoint
/sw.js                           503 x3
/api/version                     503 x1
/robots.txt                      503 x1
/wp-admin/install.php            503 x1     (scanner noise)
/climate/* (34 distinct pages)   503 x37
/api/v2/geocode                  502 x16
/climate/odesa-ua/records        500 x1
/climate/windhoek-...-na/august  500 x1

Composition - three distinct causes, only one of them new

1. 69x 503 - the thermograph-lb reboot race. 67 of the 69 fall inside a single one-hour bucket:

sum(count_over_time({job="caddy",host="prod"} | json | status=503 [1h])), 7d range, 1h step
  1784847600 ->  1
  1784876400 -> 67     <- ~2026-07-24 07:00-08:00 UTC
  1784923200 ->  1

This is already root-caused in the note notes/2026-07-24-ci-runner-had-no-persistent-systemd-unit-fixed-rca-for-the-j.md (finding #2): thermograph-lb is a plain container, not a Swarm service, so its startup is not ordered against or health-gated on the Swarm services it proxies to. On reboot there is a window where every thermograph_* service reports 1/1 while the LB is not yet serving. That note explicitly left it "flagged for the operator to decide priority on; not acted on unilaterally." This issue is the tracking item for that deferred decision.

2. 16x 502 on /api/v2/geocode - all of these are the _REVGEO_LOCK NameError, which was fixed during this investigation (PR #51; prod and beta both serve 200 now). Not a separate defect - listed only so the 87 reconciles.

3. 2x 500 - content-route timeouts. Both served to Googlebot, both ~10s wall time, 35-byte JSON error body from uvicorn:

/climate/windhoek-khomas-region-na/august  duration=10.111s  status=500  client=66.249.66.65
/climate/odesa-ua/records                  duration=10.802s  status=500  client=66.249.66.64

The ~10s duration points at an upstream timeout on the content path rather than a logic error. PRs #47 / #48 / #49 (content cache token, derived-store-first, off-request pre-warm) all target this path and may already have addressed it - worth confirming these stop recurring rather than fixing twice.

Impact

Real users, and Googlebot, hit 5xx and nobody found out. The 503 window took the homepage down. The /healthz 503s mean an external health check would have caught it - if one existed. Today the only detection mechanism is a human deciding to run a LogQL query, which is how this was found.

Suggested action

Alert on prod 5xx rate, and on /healthz non-200. Grafana dashboards/alerts are provisioned from repo JSON, so this goes in as a PR - UI edits get overwritten on the next provision.
Settle the thermograph-lb startup-ordering question the RCA note deferred (health-gate the LB, or accept the gap as bounded and document it as accepted).
Confirm #47/#48/#49 closed out the content-route 500s.

Filed from a verified reproduction; all figures above re-derived from logs at filing time rather than carried over from an earlier report.

## Summary Prod served **87 HTTP 5xx in the last 24h against 11,079 requests (0.79% error rate)**. None of it triggered any alert. It was found only by manually querying Caddy access logs in Loki. Five of the failures were `/healthz` itself - the endpoint whose entire job is to be noticed when it fails - and five were the homepage. ## Evidence (re-derived 2026-07-24 ~19:45 UTC, prod Caddy logs via Loki) Total requests, 24h: ``` sum(count_over_time({job="caddy", host="prod"} [24h])) => 11079 ``` 5xx by status: ``` sum by (status) (count_over_time({job="caddy", host="prod"} | json | status>=500 [24h])) status=500 -> 2 status=502 -> 16 status=503 -> 69 ---- 87 = 0.79% of 11079 ``` By route (`sum by (request_uri, status) (count_over_time(... [24h]))`): ``` /logo.png 503 x15 / 503 x5 <- homepage /healthz 503 x5 <- health endpoint /sw.js 503 x3 /api/version 503 x1 /robots.txt 503 x1 /wp-admin/install.php 503 x1 (scanner noise) /climate/* (34 distinct pages) 503 x37 /api/v2/geocode 502 x16 /climate/odesa-ua/records 500 x1 /climate/windhoek-...-na/august 500 x1 ``` ## Composition - three distinct causes, only one of them new **1. 69x 503 - the `thermograph-lb` reboot race.** 67 of the 69 fall inside a single one-hour bucket: ``` sum(count_over_time({job="caddy",host="prod"} | json | status=503 [1h])), 7d range, 1h step 1784847600 -> 1 1784876400 -> 67 <- ~2026-07-24 07:00-08:00 UTC 1784923200 -> 1 ``` This is already root-caused in the note `notes/2026-07-24-ci-runner-had-no-persistent-systemd-unit-fixed-rca-for-the-j.md` (finding #2): `thermograph-lb` is a plain container, not a Swarm service, so its startup is not ordered against or health-gated on the Swarm services it proxies to. On reboot there is a window where every `thermograph_*` service reports `1/1` while the LB is not yet serving. That note explicitly left it *"flagged for the operator to decide priority on; not acted on unilaterally."* **This issue is the tracking item for that deferred decision.** **2. 16x 502 on `/api/v2/geocode`** - all of these are the `_REVGEO_LOCK` NameError, which was fixed during this investigation (PR #51; prod and beta both serve 200 now). Not a separate defect - listed only so the 87 reconciles. **3. 2x 500 - content-route timeouts.** Both served to Googlebot, both ~10s wall time, 35-byte JSON error body from uvicorn: ``` /climate/windhoek-khomas-region-na/august duration=10.111s status=500 client=66.249.66.65 /climate/odesa-ua/records duration=10.802s status=500 client=66.249.66.64 ``` The ~10s duration points at an upstream timeout on the content path rather than a logic error. PRs #47 / #48 / #49 (content cache token, derived-store-first, off-request pre-warm) all target this path and may already have addressed it - worth confirming these stop recurring rather than fixing twice. ## Impact Real users, and Googlebot, hit 5xx and nobody found out. The 503 window took the homepage down. The `/healthz` 503s mean an external health check *would* have caught it - if one existed. Today the only detection mechanism is a human deciding to run a LogQL query, which is how this was found. ## Suggested action - Alert on prod 5xx rate, and on `/healthz` non-200. Grafana dashboards/alerts are provisioned from repo JSON, so this goes in as a PR - UI edits get overwritten on the next provision. - Settle the `thermograph-lb` startup-ordering question the RCA note deferred (health-gate the LB, or accept the gap as bounded and document it as accepted). - Confirm #47/#48/#49 closed out the content-route 500s. *Filed from a verified reproduction; all figures above re-derived from logs at filing time rather than carried over from an earlier report.*