From 9b0fae5280ee720a1e6c53b6d2633b866a1ae167 Mon Sep 17 00:00:00 2001 From: emi Date: Sat, 25 Jul 2026 17:51:42 +0000 Subject: [PATCH] alerting: base web/worker liveness on the app heartbeat, not container stdout (#94) --- .../provisioning/alerting/rules-prod.yml | 166 ++++++++++++------ 1 file changed, 113 insertions(+), 53 deletions(-) diff --git a/observability/grafana/provisioning/alerting/rules-prod.yml b/observability/grafana/provisioning/alerting/rules-prod.yml index ec2b3bb..f3f2a3b 100644 --- a/observability/grafana/provisioning/alerting/rules-prod.yml +++ b/observability/grafana/provisioning/alerting/rules-prod.yml @@ -400,6 +400,24 @@ groups: # dev is deliberately excluded: the LAN box had zero heartbeats for the # first 10.5h of the backtest window because it was simply off. Alerting # on dev would mean an alert that is firing more often than not. + # + # MUST stay filtered to daemon="subscription-notifier". The selector was + # originally bare `tag="heartbeat"`, which was unambiguous while the + # notifier thread was the only thing that ever beat. It stopped being + # unambiguous on 2026-07-25T17:24Z, when web/app.py's _start_heartbeat + # shipped: every uvicorn process in every replica now beats every 300s + # under the same tag, tagged daemon=web / daemon=worker. Measured + # immediately after that deploy, a 20m window held 16 web beats and 4 + # worker beats against 2 notifier beats — so the bare selector clears the + # `< 1` threshold on web traffic alone and can no longer observe the + # notifier at all. + # + # That matters because this rule had just caught a real 17.5h outage + # (notifier silent 2026-07-24T23:49Z -> 2026-07-25T17:25Z, zero + # subscription notifications delivered). Left bare, it would have gone + # quiet on the next occurrence instead of paging. `daemon` is a JSON field + # and not a stream label, hence the `| json |` parse rather than a label + # matcher. - uid: tg_notifier_heartbeat_prod title: NotifierHeartbeatMissingProd condition: C @@ -427,7 +445,7 @@ groups: model: refId: A datasource: { type: loki, uid: loki } - expr: 'sum(count_over_time({job="app-json", tag="heartbeat", host="prod"} [20m])) or vector(0)' + expr: 'sum(count_over_time({job="app-json", tag="heartbeat", host="prod"} | json | daemon="subscription-notifier" [20m])) or vector(0)' queryType: instant editorMode: code intervalMs: 1000 @@ -480,7 +498,7 @@ groups: model: refId: A datasource: { type: loki, uid: loki } - expr: 'sum(count_over_time({job="app-json", tag="heartbeat", host="beta"} [20m])) or vector(0)' + expr: 'sum(count_over_time({job="app-json", tag="heartbeat", host="beta"} | json | daemon="subscription-notifier" [20m])) or vector(0)' queryType: instant editorMode: code intervalMs: 1000 @@ -506,16 +524,31 @@ groups: - evaluator: { type: lt, params: [1] } # =========================================================================== - # Per-container liveness, inferred from log volume. The fleet collects no - # container metrics, so "did this service stop producing any output at all" is - # the only death certificate available — and it turns out to be a good one, - # because every service below logs on a floor that never approaches zero. + # Per-service liveness. The fleet collects no container metrics, so liveness + # has to be inferred from "is this thing still producing output at all". Two + # different sources are used here, and picking the wrong one is how this group + # generated a day of false pages: # - # Caveat worth knowing before you trust these: a container can be running and - # logging while its lines never reach Loki, if the node's Alloy agent stops - # tailing it. That is a real observed failure on prod (see README). These - # rules cannot tell the two apart — they say "no logs", which is the honest - # claim. Either way something needs looking at. + # * db and frontend infer it from CONTAINER LOG VOLUME. Valid for these two: + # both log to stdout on a floor that never approaches zero (db a metronomic + # 54-69 lines/2h, frontend ~66/30m), and prod's Alloy ships both. + # + # * web and worker infer it from the APP'S OWN HEARTBEAT (tag=heartbeat in + # the app-json file source, filtered by the daemon field). Container log + # volume is NOT a valid liveness signal for either: web's request logging + # moved off stdout onto app-json, and worker's stdout is dropped outright + # by a rule in prod's alloy config. Both containers can be perfectly + # healthy while their docker streams sit at exactly zero forever. + # + # Before adding a container-log-silence rule for a new service, confirm the + # service actually logs to stdout AND that prod's discovery.relabel "containers" + # block does not drop it. A rule against a dropped stream is unsatisfiable and + # will page forever. + # + # Caveat that still applies to the db/frontend rules: a container can be + # running and logging while its lines never reach Loki, if the node's Alloy + # agent stops tailing it. Those rules cannot tell the two apart — they say + # "no logs", which is the honest claim. Either way something needs looking at. # =========================================================================== - orgId: 1 name: prod-services @@ -524,24 +557,43 @@ groups: rules: # -- 8 ----------------------------------------------------------------- - # DATA: 15-minute windows over 24h ranged 54 -> 954 lines. The minimum, 54, - # occurred during the outage; the quietest healthy window was ~150. A - # 30-minute window has never been below ~110. Zero means the container is - # gone. This is the app itself, so it pages. + # Web-tier liveness, from the app's own heartbeat rather than container + # stdout. + # + # This rule used to count `{job="docker", container=~"thermograph_web.+"}` + # over 30m against a measured floor of ~110 lines. That floor was real when + # it was written (the backtest saw 3.8k-10.5k lines per 6h), but the app + # moved its request logging off stdout onto the app-json file source, and + # from 2026-07-25T00:02Z a web container emits ~15 uvicorn banner lines for + # its entire lifetime and nothing after. The old rule then sat firing + # permanently on a perfectly healthy tier, clearing only for the few + # minutes after each deploy or autoscale event produced fresh banners — + # 20+ pages in a day, every one of them false. See web/app.py's + # _start_heartbeat docstring, which states outright that stdout silence + # cannot distinguish a live web process from a dead one and that this + # heartbeat is the signal to alert on instead. + # + # DATA: _start_heartbeat beats every 300s from every uvicorn process in + # every replica, unguarded by the leader election, so a 4-process replica + # yields ~16 beats per 20m (measured: exactly 16). Zero over 20m means no + # web process is alive anywhere. This is the app itself, so it pages. - uid: tg_prod_web_silent - title: ProdWebContainerSilent + title: ProdWebHeartbeatMissing condition: C for: 5m noDataState: OK execErrState: OK annotations: - summary: 'prod: thermograph_web has logged nothing for 30 minutes' + summary: 'prod: no web heartbeat for 20 minutes' description: >- - The main app container has produced zero log lines in 30 minutes. - Healthy floor is ~110 lines per 30m and it never dipped below 54 even - mid-outage, so this is a container that is gone, wedged, or no longer - being tailed by prod's Alloy agent. Run `docker service ps - thermograph_web` on prod. + No thermograph_web process on prod has emitted a liveness heartbeat + in 20 minutes. Every uvicorn process beats every 5 minutes + independently of the notifier leader election, so a healthy 4-process + replica produces ~16 beats per window — zero means no web process is + alive anywhere, not merely quiet. Run `docker service ps + thermograph_web` on prod. Note this is the app's own heartbeat, not + container stdout: web's stdout is silent by design and is not a + liveness signal. labels: severity: critical host: prod @@ -549,12 +601,12 @@ groups: isPaused: false data: - refId: A - relativeTimeRange: { from: 1800, to: 0 } + relativeTimeRange: { from: 1200, to: 0 } datasourceUid: loki model: refId: A datasource: { type: loki, uid: loki } - expr: 'sum(count_over_time({job="docker", host="prod", container=~"thermograph_web.+"} [30m])) or vector(0)' + expr: 'sum(count_over_time({job="app-json", host="prod", tag="heartbeat"} | json | daemon="web" [20m])) or vector(0)' queryType: instant editorMode: code intervalMs: 1000 @@ -689,42 +741,50 @@ groups: - evaluator: { type: lt, params: [1] } # -- 11 ---------------------------------------------------------------- - # DATA: a dead-steady 121 lines/hour (its own healthcheck polling) for the - # first 14h of the backtest, then nothing at all. + # Worker liveness, from the app's own heartbeat rather than container + # stdout. # - # HEADS UP: THIS RULE WILL BE FIRING THE MOMENT YOU DEPLOY IT, and it is - # right to. As of 2026-07-24 19:45Z the prod worker container is running - # and healthy and is writing ~19 lines per 10 minutes to its own docker - # log — but not one of those lines has reached Loki since 04:43Z. Prod's - # Alloy agent stopped tailing the container when Swarm replaced the task. - # Nobody knew, because nothing was watching. See README "Known gaps". + # The previous rule counted `{job="docker", container=~"thermograph_worker.+"}` + # and was UNSATISFIABLE BY CONSTRUCTION — it could never return anything but + # zero, no matter how healthy the worker was. prod's Alloy config drops that + # container on purpose, in discovery.relabel "containers": # - # WHY THIS IS A WARNING AND NotifierHeartbeatMissingProd IS CRITICAL: the - # two draw on *different* Alloy sources — this one on loki.source.docker - # (the container's stdout), the heartbeat on loki.source.file tailing - # /applogs. That independence is the diagnostic. Right now prod's - # heartbeats are arriving in every single 20-minute window while its - # worker docker stream has been empty for 14 hours, which localises the - # fault to Alloy's docker tail rather than to the worker: the process is - # doing its job, we just cannot see it breathe. Both rules firing together - # means the worker really is down. + # regex = "(alloy|autoscaler|thermograph-test_.*|thermograph-lb|thermograph_worker).*" + # action = "drop" + # + # with the stated reasoning that worker stdout was 100% /healthz poll noise + # and the app's own access/*.jsonl is a strict superset of it. So the stream + # this rule queried is discarded at the agent and never reaches Loki. + # + # The old comment here read the resulting permanent zero as "Alloy stopped + # tailing the container after Swarm replaced the task" and pointed the + # runbook at restarting alloy-alloy-1. That diagnosis was wrong, and the + # fix it recommended could not have worked: a restarted Alloy re-reads the + # same config and drops the same container again. The rule fired + # continuously from 2026-07-24T21:05Z with no underlying fault. + # + # DATA: _start_heartbeat beats every 300s from the worker process + # (measured: exactly 4 per 20m). Unlike the notifier below it is not gated + # on the leader election, so it reports the process being alive even when + # this worker is not the elected notifier — which is the distinction the + # old rule was trying and failing to draw. - uid: tg_prod_worker_silent - title: ProdWorkerContainerSilent + title: ProdWorkerHeartbeatMissing condition: C for: 10m noDataState: OK execErrState: OK annotations: - summary: 'prod: thermograph_worker has logged nothing for 2 hours' + summary: 'prod: no worker heartbeat for 20 minutes' description: >- - The worker container has produced zero log lines in 2 hours against - a healthy floor of ~242 per 2h. Two different faults look identical - here: the worker is actually dead, or prod's Alloy agent has stopped - tailing it (a real, observed failure — Alloy can miss a container - after Swarm replaces the task). Check both: `docker service ps - thermograph_worker` on prod, and whether `docker logs` on the live - container is producing lines that Loki does not have. Restarting - alloy-alloy-1 on prod fixes the second case. + The thermograph_worker process on prod has not emitted a liveness + heartbeat in 20 minutes (healthy is ~4 per window, one every 5 + minutes). This beat is independent of the notifier leader election, + so it means the worker process itself is gone or wedged, not merely + that it lost the election. Run `docker service ps thermograph_worker` + on prod. Do not look at the worker's container logs — prod's Alloy + config drops that stream deliberately, so it is always empty and is + not evidence of anything. labels: severity: warning host: prod @@ -732,12 +792,12 @@ groups: isPaused: false data: - refId: A - relativeTimeRange: { from: 7200, to: 0 } + relativeTimeRange: { from: 1200, to: 0 } datasourceUid: loki model: refId: A datasource: { type: loki, uid: loki } - expr: 'sum(count_over_time({job="docker", host="prod", container=~"thermograph_worker.+"} [2h])) or vector(0)' + expr: 'sum(count_over_time({job="app-json", host="prod", tag="heartbeat"} | json | daemon="worker" [20m])) or vector(0)' queryType: instant editorMode: code intervalMs: 1000