Webex all-clear 400s in an endless retry loop; response body not logged

claude-bot commented

2026-07-28 00:37:05 +00:00

Contributor

Observed live in weatherbot-app-1 logs on 2026-07-27 (continuous through the whole retained log window, roughly once a minute):

INFO   app.services.alert_processor Processing 1 pending lifted alert records
ERROR  app.services.notifiers.webex Webex all-clear failed for channel
       e70842aa-8269-4858-b12e-f48d95a356ac: Client error '400 Bad Request'
       for url 'https://webexapis.com/v1/messages'
ERROR  app.services.alert_processor All-clear dispatch failed for channel
       e70842aa-8269-4858-b12e-f48d95a356ac (ChannelType.webex): Webex all-clear failed: HTTP 400

Two separate problems:

1. A 400 is being retried forever. HTTP 400 is a permanent client error — the request is malformed or references something that no longer exists (bad roomId, deleted room, revoked token). Retrying it cannot succeed. The delivery outbox has PermanentDeliveryError and a dead status precisely for this; either the Webex notifier is not raising PermanentDeliveryError for 4xx, or the all-clear path bypasses the outbox classification. A permanent failure should be marked dead after one attempt, not looped.

2. The response body is discarded. The log records only the status code. Webex returns a JSON body with a specific message and a trackingId, which is what would actually identify the cause. Without it the failure is undiagnosable from logs alone — the reason this needs a live reproduction rather than a log read.

Tasks

Classify Webex 4xx (except 429) as PermanentDeliveryError so it goes dead rather than retrying indefinitely.
Log the Webex response body and trackingId on failure, redacting the token.
Check the other notifiers for the same 4xx-retry-forever pattern — this is unlikely to be Webex-specific.
Work out why this particular channel 400s and either fix or disable it.

Note the retry loop also means the sent_alerts row keeps lifted_notified_at NULL indefinitely, so send_pending_lifted_notifications re-selects it every cycle.

Observed live in `weatherbot-app-1` logs on 2026-07-27 (continuous through the whole retained log window, roughly once a minute): ``` INFO app.services.alert_processor Processing 1 pending lifted alert records ERROR app.services.notifiers.webex Webex all-clear failed for channel e70842aa-8269-4858-b12e-f48d95a356ac: Client error '400 Bad Request' for url 'https://webexapis.com/v1/messages' ERROR app.services.alert_processor All-clear dispatch failed for channel e70842aa-8269-4858-b12e-f48d95a356ac (ChannelType.webex): Webex all-clear failed: HTTP 400 ``` Two separate problems: **1. A `400` is being retried forever.** HTTP 400 is a *permanent* client error — the request is malformed or references something that no longer exists (bad `roomId`, deleted room, revoked token). Retrying it cannot succeed. The delivery outbox has `PermanentDeliveryError` and a `dead` status precisely for this; either the Webex notifier is not raising `PermanentDeliveryError` for 4xx, or the all-clear path bypasses the outbox classification. A permanent failure should be marked dead after one attempt, not looped. **2. The response body is discarded.** The log records only the status code. Webex returns a JSON body with a specific `message` and a `trackingId`, which is what would actually identify the cause. Without it the failure is undiagnosable from logs alone — the reason this needs a live reproduction rather than a log read. ## Tasks - [ ] Classify Webex 4xx (except 429) as `PermanentDeliveryError` so it goes `dead` rather than retrying indefinitely. - [ ] Log the Webex response body and `trackingId` on failure, redacting the token. - [ ] Check the other notifiers for the same 4xx-retry-forever pattern — this is unlikely to be Webex-specific. - [ ] Work out why this particular channel 400s and either fix or disable it. Note the retry loop also means the `sent_alerts` row keeps `lifted_notified_at` NULL indefinitely, so `send_pending_lifted_notifications` re-selects it every cycle.

claude-bot added the

bug

area:notifications

labels

2026-07-28 00:37:05 +00:00

claude-bot referenced this issue

2026-07-28 00:38:19 +00:00

False all-clear when NWS replaces an alert (watch -> advisory/warning) #145

rbrooks referenced this issue from a commit

2026-07-28 00:48:06 +00:00

Suppress false all-clears when a hazard is superseded (#145)

claude-bot referenced this issue

2026-07-28 00:48:28 +00:00

Suppress false all-clears when a hazard is superseded (#145) #149

claude-bot referenced this issue

2026-07-28 00:59:08 +00:00

False all-clear when NWS replaces an alert (watch -> advisory/warning) #145

rbrooks referenced this issue from a commit

2026-07-28 01:57:58 +00:00

Stop all-clear delivery retrying forever (#148)

claude-bot referenced this issue from a pull request that will close it,

2026-07-28 01:58:20 +00:00

Stop all-clear delivery retrying forever (#148) #151

claude-bot referenced this issue from a commit

2026-07-28 02:08:00 +00:00

Merge pull request 'Stop all-clear delivery retrying forever (#148)' (#151) from fix/webex-permanent-failure into main

claude-bot closed this issue

2026-07-28 02:08:00 +00:00

claude-bot commented

2026-07-28 02:08:27 +00:00

Author

Contributor

Fixed in #151 (merged). CI green.

Root cause was one layer above where I expected. The classification was already right — classify_http_error maps a 4xx other than 408/429 to PermanentDeliveryError, and webex.send_alert_lifted raises it. But _dispatch_alert_lifted caught every exception and returned a bare False, discarding the distinction, and the caller only stamped lifted_notified_at on success. So the row stayed pending and was re-selected every cycle forever.

This was never Webex-specific. _dispatch_alert_lifted is the shared dispatch for every channel type, so the same unbounded loop applied to all of them — which resolves the "check the other notifiers" task: there was one pattern, in one place.

Now: _dispatch_alert_lifted returns (sent, permanent); record_delivery_result takes permanent=True and marks the ledger row dead immediately; the loop gives up once the row is dead, whether from a permanent rejection or from transient failures exhausting delivery_max_attempts / delivery_max_age_hours. Transient failures still retry — they just stop. No new config; this reuses bounds the outbox already had and the all-clear path was simply not consulting.

The Webex response body and trackingId are now logged on rejection (response only — the bot token is in the request headers and never echoed back). That is what will tell you why channel e70842aa is 400ing, which I could not determine from the code; a deleted room or revoked token are the usual causes, but the body will say.

On deploy: this does not retroactively clear the stuck row. It still has lifted_notified_at NULL, so it will make one final attempt, fail, log the body, and be marked dead — after which the log goes quiet and the delivery row carries the reason. Worth grabbing that one log line when it appears.

Fixed in #151 (merged). CI green. Root cause was one layer above where I expected. The classification was already right — `classify_http_error` maps a 4xx other than 408/429 to `PermanentDeliveryError`, and `webex.send_alert_lifted` raises it. But `_dispatch_alert_lifted` caught every exception and returned a bare `False`, discarding the distinction, and the caller only stamped `lifted_notified_at` on success. So the row stayed pending and was re-selected every cycle forever. **This was never Webex-specific.** `_dispatch_alert_lifted` is the shared dispatch for every channel type, so the same unbounded loop applied to all of them — which resolves the "check the other notifiers" task: there was one pattern, in one place. Now: `_dispatch_alert_lifted` returns `(sent, permanent)`; `record_delivery_result` takes `permanent=True` and marks the ledger row dead immediately; the loop gives up once the row is `dead`, whether from a permanent rejection or from transient failures exhausting `delivery_max_attempts` / `delivery_max_age_hours`. Transient failures still retry — they just stop. No new config; this reuses bounds the outbox already had and the all-clear path was simply not consulting. The Webex response body and `trackingId` are now logged on rejection (response only — the bot token is in the request headers and never echoed back). **That is what will tell you why channel `e70842aa` is 400ing**, which I could not determine from the code; a deleted room or revoked token are the usual causes, but the body will say. **On deploy:** this does not retroactively clear the stuck row. It still has `lifted_notified_at` NULL, so it will make one final attempt, fail, log the body, and be marked dead — after which the log goes quiet and the delivery row carries the reason. Worth grabbing that one log line when it appears.

claude-bot referenced this issue

2026-07-28 02:57:20 +00:00

All-clear image URL contains a literal space; Webex rejects it with HTTP 400 #152

rbrooks referenced this issue from a commit

2026-07-28 03:04:20 +00:00

Percent-encode the all-clear image URL (#152)

claude-bot referenced this issue

2026-07-28 03:04:37 +00:00

Percent-encode the all-clear image URL (#152) #153

claude-bot referenced this issue

2026-07-28 03:14:34 +00:00

All-clear image URL contains a literal space; Webex rejects it with HTTP 400 #152

claude-bot commented

2026-07-28 03:14:35 +00:00

Author

Contributor

Follow-up: the underlying cause is identified and fixed in #152 / #153.

The Webex 400 was not a bad room id or a revoked token. _iastate_allclear_image_url was emitting a URL containing a literal space — Iowa State's valid segment is 'YYYY-MM-DD HHMM' — and Webex validates files[] URLs, so it rejected the whole all-clear:

.../plot/208/valid:2026-07-24 1716::network:WFO::wfo:LSX::...png

Confirmed: curl cannot even form a request for the raw URL (http=000); percent-encoded it returns 200 image/png.

Found by code inspection rather than from the new log line, via the asymmetry this issue already noted — ordinary alerts sent fine, only all-clears failed. _iastate_alert_image_url has no valid: segment and therefore no space. The response-body logging added here would have shown it directly, and is still worth having.

So the two fixes are complementary and both wanted: #153 stops the rejection, this one stops a permanent rejection from looping forever if anything else ever produces one.

Deployment note (applies to #145, #146, #147, #148 and #152).

None of these fixes are live yet. The running stack (weatherbot-app-1, compose project dir /home/ryan/WeatherBot) is not what .forgejo/workflows/cd.yml deploys to — CD does cd ~/projects/WeatherBot on ${DEV_HOST:-claude@10.1.1.14}, a different checkout.

Evidence: CD run #5039 for the #148 merge succeeded at 02:13, and at 02:46–02:48 the app was still logging the pre-fix message format (Webex all-clear failed ... Client error '400 Bad Request', with no Webex API rejected the message line and no Giving up on all-clear). The loop had also grown from ~1/min to 2–3/min, so more than one all-clear row is now stuck.

Either the deploy step is being skipped (DEV_SSH_KEY unset — the workflow is written to pass silently in that case) or it is deploying to a different instance. Worth resolving, since a green CD run currently implies a deploy that may not be happening.

Follow-up: the underlying cause is identified and fixed in #152 / #153. The Webex 400 was **not** a bad room id or a revoked token. `_iastate_allclear_image_url` was emitting a URL containing a literal space — Iowa State's valid segment is `'YYYY-MM-DD HHMM'` — and Webex validates `files[]` URLs, so it rejected the whole all-clear: ``` .../plot/208/valid:2026-07-24 1716::network:WFO::wfo:LSX::...png ``` Confirmed: `curl` cannot even form a request for the raw URL (`http=000`); percent-encoded it returns `200 image/png`. Found by code inspection rather than from the new log line, via the asymmetry this issue already noted — ordinary alerts sent fine, only all-clears failed. `_iastate_alert_image_url` has no `valid:` segment and therefore no space. The response-body logging added here would have shown it directly, and is still worth having. So the two fixes are complementary and both wanted: #153 stops the rejection, this one stops a permanent rejection from looping forever if anything else ever produces one. --- **Deployment note (applies to #145, #146, #147, #148 and #152).** None of these fixes are live yet. The running stack (`weatherbot-app-1`, compose project dir `/home/ryan/WeatherBot`) is **not** what `.forgejo/workflows/cd.yml` deploys to — CD does `cd ~/projects/WeatherBot` on `${DEV_HOST:-claude@10.1.1.14}`, a different checkout. Evidence: CD run #5039 for the #148 merge succeeded at 02:13, and at 02:46–02:48 the app was still logging the pre-fix message format (`Webex all-clear failed ... Client error '400 Bad Request'`, with no `Webex API rejected the message` line and no `Giving up on all-clear`). The loop had also grown from ~1/min to 2–3/min, so more than one all-clear row is now stuck. Either the deploy step is being skipped (`DEV_SSH_KEY` unset — the workflow is written to pass silently in that case) or it is deploying to a different instance. Worth resolving, since a green CD run currently implies a deploy that may not be happening.

claude-bot referenced this issue

2026-07-28 03:40:47 +00:00

CD deploys only to the dev host; the live instance is 6 days behind and manually managed #154

Rows
Columns

Webex all-clear 400s in an endless retry loop; response body not logged #148

Tasks