Production: SPC outlook poll fails every cycle after 2.0.0 (unescaped LIKE in the SPC day match) #214

Closed
opened 2026-10-14 06:24:45 +00:00 by claude-bot · 2 comments
Collaborator

Found 2026-10-14 06:22Z during the post-deploy watch of v2.0.0 on production.

Impact

  • poll_spc_job has raised on every run since the upgrade (05:55, 06:00, 06:05, 06:10, 06:15, 06:21Z; 24 tracebacks).
  • The job aborts at the first failing location, so SPC convective outlook notifications are not being sent and the dashboard's SPC records stop refreshing for every location processed after it.
  • NWS warning alerts are unaffected: poll_alerts_job succeeded 31 of 31 runs in the same window.
  • Today's outlooks for the production locations are Marginal (level 1).

Error

asyncpg.exceptions.UniqueViolationError: duplicate key value violates unique constraint "uq_sent_alerts_dashboard_dedup"
DETAIL:  Key (nws_alert_id, location_id)=(SPC_OUTLOOK_D1_202610140100_1_MRGL, 8c65a685-…) already exists.
  File "/app/app/services/spc_processor.py", line 419, in _record_and_dispatch_outlook
  File "/app/app/services/spc_impacts.py", line 328, in upsert_spc_outlook_impact   (autoflush)

Seen for three keys: D1_202610140100_1_MRGL and D2_202610140521_2_MRGL on one location, D2_202610140521_2_MRGL on another.

Cause

_upgrade_check (app/services/spc_processor.py) finds a location's active SPC dashboard rows for one outlook day with:

day_suffix = f"_{outlook.day}_"
SentAlert.nws_alert_id.contains(day_suffix)      # -> LIKE '%' || '_2_' || '%'

In SQL LIKE, _ matches any single character. Product ids are timestamps, so the pattern matches almost every row. Checked against production's real ids:

id matches day 1 day 2 day 3
SPC_OUTLOOK_D1_202610140100_1_MRGL yes yes no
SPC_OUTLOOK_D2_202610140521_2_MRGL yes yes no
SPC_OUTLOOK_D3_202610131930_3_MRGL yes yes yes

The loop then treats the first same-risk row it gets as a "continuation" and renames it to the new product's dedup id. When that row belongs to a different day, and the correct day's row already holds that id, the partial unique index uq_sent_alerts_dashboard_dedup rejects it and the whole poll fails.

Why it surfaced with 2.0.0. The match itself predates 2.0.0, and production's data shows the scars: rows whose sent_at belongs to one day's record now carry another day's id. The query had no ORDER BY. The likely trigger is migration 0036's new ix_sent_alerts_location_sent_at index, which changed the plan, and so which row comes first, from "usually the right one" to "the wrong one every time". That is inference, not something I measured. Either way the root defect is the unescaped LIKE.

Why tests and dev missed it. Every test uses product ids like D1_P1, which never have a digit next to an underscore. Dev's locations carry only one or two outlook days at a time.

The same unescaped pattern is in app/api/alerts.py (the dashboard's per-day SPC history), where it only mixes other days' rows into a read-only list.

Fix

  • contains(day_suffix, autoescape=True) in both places.
  • In _upgrade_check, skip any row whose parsed day differs from the outlook's day (backstop), and order the rows by sent_at so the result is deterministic.
  • Regression test using production's real id shapes: three active rows for days 1–3 and a reissue on each day must not raise and must keep each row on its own day.
  • Hotfix release 2.0.1 and deploy.

Existing data

Rows already renamed across days are not repaired by the fix. Each still has a single active row per day-id, so the continuation logic recovers as new products arrive. Checking that on production after the hotfix is part of verifying it.

Found 2026-10-14 06:22Z during the post-deploy watch of v2.0.0 on production. ## Impact - `poll_spc_job` has raised on **every run since the upgrade** (05:55, 06:00, 06:05, 06:10, 06:15, 06:21Z; 24 tracebacks). - The job aborts at the first failing location, so **SPC convective outlook notifications are not being sent** and the dashboard's SPC records stop refreshing for every location processed after it. - **NWS warning alerts are unaffected**: `poll_alerts_job` succeeded 31 of 31 runs in the same window. - Today's outlooks for the production locations are Marginal (level 1). ## Error ``` asyncpg.exceptions.UniqueViolationError: duplicate key value violates unique constraint "uq_sent_alerts_dashboard_dedup" DETAIL: Key (nws_alert_id, location_id)=(SPC_OUTLOOK_D1_202610140100_1_MRGL, 8c65a685-…) already exists. File "/app/app/services/spc_processor.py", line 419, in _record_and_dispatch_outlook File "/app/app/services/spc_impacts.py", line 328, in upsert_spc_outlook_impact (autoflush) ``` Seen for three keys: `D1_202610140100_1_MRGL` and `D2_202610140521_2_MRGL` on one location, `D2_202610140521_2_MRGL` on another. ## Cause `_upgrade_check` (`app/services/spc_processor.py`) finds a location's active SPC dashboard rows for one outlook day with: ```python day_suffix = f"_{outlook.day}_" SentAlert.nws_alert_id.contains(day_suffix) # -> LIKE '%' || '_2_' || '%' ``` In SQL `LIKE`, `_` matches **any single character**. Product ids are timestamps, so the pattern matches almost every row. Checked against production's real ids: | id | matches day 1 | day 2 | day 3 | |---|---|---|---| | `SPC_OUTLOOK_D1_202610140100_1_MRGL` | yes | **yes** | no | | `SPC_OUTLOOK_D2_202610140521_2_MRGL` | **yes** | yes | no | | `SPC_OUTLOOK_D3_202610131930_3_MRGL` | **yes** | **yes** | yes | The loop then treats the first same-risk row it gets as a "continuation" and renames it to the new product's dedup id. When that row belongs to a different day, and the correct day's row already holds that id, the partial unique index `uq_sent_alerts_dashboard_dedup` rejects it and the whole poll fails. **Why it surfaced with 2.0.0.** The match itself predates 2.0.0, and production's data shows the scars: rows whose `sent_at` belongs to one day's record now carry another day's id. The query had no `ORDER BY`. The likely trigger is migration `0036`'s new `ix_sent_alerts_location_sent_at` index, which changed the plan, and so which row comes first, from "usually the right one" to "the wrong one every time". That is inference, not something I measured. Either way the root defect is the unescaped `LIKE`. **Why tests and dev missed it.** Every test uses product ids like `D1_P1`, which never have a digit next to an underscore. Dev's locations carry only one or two outlook days at a time. The same unescaped pattern is in `app/api/alerts.py` (the dashboard's per-day SPC history), where it only mixes other days' rows into a read-only list. ## Fix - [ ] `contains(day_suffix, autoescape=True)` in both places. - [ ] In `_upgrade_check`, skip any row whose parsed day differs from the outlook's day (backstop), and order the rows by `sent_at` so the result is deterministic. - [ ] Regression test using production's real id shapes: three active rows for days 1–3 and a reissue on each day must not raise and must keep each row on its own day. - [ ] Hotfix release 2.0.1 and deploy. ## Existing data Rows already renamed across days are not repaired by the fix. Each still has a single active row per day-id, so the continuation logic recovers as new products arrive. Checking that on production after the hotfix is part of verifying it.
Author
Collaborator

Fix merged via #215 (ad8184a). CI run 269 green in 6m3s, both test tiers.

The regression test seeds production's exact shape (one active MRGL row per outlook day, timestamp product ids). Without the fix it raises the same IntegrityError production logs; with the fix it passes, each row stays on its own day and nothing re-notifies.

v2.0.1 changelog is up as #216. Releasing and deploying to dev follows once that is green. Production deploy of 2.0.1 is waiting on @rbrooks's go-ahead: the 2.0.0 approval did not cover a second release. Until then SPC outlook notifications stay off on production; NWS warnings are unaffected.

Production status at 06:21Z, for the record: the first correlation pass completed (297 events, matching the rehearsal) with a memory peak of 711 MiB of 1 GiB, no OOM, no restarts.

Fix merged via #215 (`ad8184a`). CI run 269 green in 6m3s, both test tiers. The regression test seeds production's exact shape (one active MRGL row per outlook day, timestamp product ids). Without the fix it raises the same `IntegrityError` production logs; with the fix it passes, each row stays on its own day and nothing re-notifies. v2.0.1 changelog is up as #216. Releasing and deploying to dev follows once that is green. **Production deploy of 2.0.1 is waiting on @rbrooks's go-ahead**: the 2.0.0 approval did not cover a second release. Until then SPC outlook notifications stay off on production; NWS warnings are unaffected. Production status at 06:21Z, for the record: the first correlation pass completed (297 events, matching the rehearsal) with a memory peak of 711 MiB of 1 GiB, no OOM, no restarts.
Author
Collaborator

Fixed in v2.0.1, deployed to dev and production (2026-10-14)

Tag v2.0.1 on 12b59a3; release.yml run 273 pushed weatherbot:2.0.1 (digest sha256:2c1c6136…c9aa3). Pin Rhoving/iac-repo#643 (merged as 60b6266). Production deploy approved by @rbrooks, conditional on dev testing clean.

Dev (06:50Z): play ok=23 changed=3 failed=0; first SPC poll succeeded with each day's record continued on its own day; 0 errors.

Production (play 06:56–06:57Z, ok=24 changed=3 failed=0):

  • weatherbot:2.0.1 healthy, 0 restarts, reports v2.0.1.
  • First SPC poll at 07:02Z succeeded (poll_spc_job 1 ok, 0 raised). On 2.0.0 every run raised.
  • Same-risk reissues were recognised as continuations per day (for example Boleyn Place day 2 and day 3 separately), and dispatch was suppressed, so nothing re-notified.
  • Zero ERROR or traceback lines since start. Alert polling 7 of 7.
  • Active SPC rows: one per location per day-id, no duplicates.

Outage window for SPC outlook processing on production: 05:55Z to 07:02Z, about 67 minutes. NWS warning alerts were unaffected throughout.

Closing. The pre-existing drift (rows whose sent_at belongs to another day's record) is left to settle as SPC issues new outlooks; nothing in the current data violates the per-day uniqueness the fix now relies on.

## Fixed in v2.0.1, deployed to dev and production (2026-10-14) Tag `v2.0.1` on `12b59a3`; `release.yml` run 273 pushed `weatherbot:2.0.1` (digest `sha256:2c1c6136…c9aa3`). Pin Rhoving/iac-repo#643 (merged as `60b6266`). Production deploy approved by @rbrooks, conditional on dev testing clean. **Dev** (06:50Z): play `ok=23 changed=3 failed=0`; first SPC poll succeeded with each day's record continued on its own day; 0 errors. **Production** (play 06:56–06:57Z, `ok=24 changed=3 failed=0`): - `weatherbot:2.0.1` healthy, 0 restarts, reports `v2.0.1`. - **First SPC poll at 07:02Z succeeded** (`poll_spc_job` 1 ok, 0 raised). On 2.0.0 every run raised. - Same-risk reissues were recognised as continuations per day (for example Boleyn Place day 2 and day 3 separately), and dispatch was suppressed, so nothing re-notified. - Zero `ERROR` or traceback lines since start. Alert polling 7 of 7. - Active SPC rows: one per location per day-id, no duplicates. Outage window for SPC outlook processing on production: **05:55Z to 07:02Z**, about 67 minutes. NWS warning alerts were unaffected throughout. Closing. The pre-existing drift (rows whose `sent_at` belongs to another day's record) is left to settle as SPC issues new outlooks; nothing in the current data violates the per-day uniqueness the fix now relies on.
Sign in to join this conversation.
No milestone
No project
No assignees
1 participant
Notifications
Due date
The due date is invalid or out of range. Please use the format "yyyy-mm-dd".

No due date set.

Dependencies

No dependencies set

Reference
rbrooks/WeatherBot#214
No description provided.