From fef40505ae9dbaeb27849461492d5a88c24da401 Mon Sep 17 00:00:00 2001 From: jochen Date: Tue, 6 Oct 2026 18:15:58 +0200 Subject: [PATCH] Issue 276: a handler that did its work was offered it five times A refresh answered with an empty body was read as JSON, so the media server module's handler threw after scanning; each finished download was offered five times and raised a false max-deliveries. Records the one rule for taking an event, and where the fixes are. --- .../00-report.md | 74 +++++++++++++++++++ .../01-diagnosis.md | 36 +++++++++ 2 files changed, 110 insertions(+) create mode 100644 04-ISSUES/276-a-handler-that-did-its-work-was-offered-it-five-times/00-report.md create mode 100644 04-ISSUES/276-a-handler-that-did-its-work-was-offered-it-five-times/01-diagnosis.md diff --git a/04-ISSUES/276-a-handler-that-did-its-work-was-offered-it-five-times/00-report.md b/04-ISSUES/276-a-handler-that-did-its-work-was-offered-it-five-times/00-report.md new file mode 100644 index 0000000..9334f76 --- /dev/null +++ b/04-ISSUES/276-a-handler-that-did-its-work-was-offered-it-five-times/00-report.md @@ -0,0 +1,74 @@ +--- +status: located +opened: 2026-10-06 +located-in: [mesh-media-catalog modules/plex, mesh-tools node-tools/internal/launch, mesh-sdk src/stdio, mesh-sdk go] +fixed-by: +amended-design: +--- + +# 276. A handler that did its work was offered it five times + +## Symptom + +Observed on 2026-10-06 on the home-server. Each time a downloader finished (`*.download.completed` +from the movie and series managers and the usenet downloader), the media server module's handler +asked the media server to rescan — the media server's own log shows the scans at the right times — and +yet the runtime said, every five seconds, five times: + +> `[mesh-tools] plex did not take radarr.download.completed: Unexpected end of JSON input; offered again` + +after which the controller's bus watchdog (S9 of +[to-be 45](../../03-DESIGN/01-to-be/45-a-core-that-cannot-fail-silently.md)) raised `max-deliveries` +for the module's consumer, *handed message N over 5 times and gave up*. One finished download cost up to +five rescans and a warning the operator could do nothing about. + +## Why it matters + +Two things the mesh promises failed at once. The event was handled and reported as not handled, so a +condition about a fault nobody had reached the operator — the alarm that teaches people to ignore +alarms. And the line that should have said where the fault was read like the **runtime** failing to +parse something, when the words were the **handler's** own: nothing in the line said whose they were. + +Behind both: the contract between the runtime and a handler was nowhere written as one rule. ADR 0198 +says an event is acknowledged "only after the child answered"; the SDKs said an error answer is not +taken; nobody said what a handler must and must not throw for. + +## Located + +See [01-diagnosis.md](01-diagnosis.md). In short: + +- **The module.** The media server answers a library refresh with 200 and an **empty body**. The + module's client read every answer as JSON, so the refresh threw *Unexpected end of JSON input* after + the first library's scan had begun. The handler threw, the SDK answered `mesh/event` with that error, + and the runtime correctly did not acknowledge. Each offer rescanned the first library again and never + reached the others. +- **The runtime's line.** It printed the bundle's error message bare, with no event id and no sign that + the text was the handler's. +- **The SDKs**, found on the way: both added a handler before asking the runtime to subscribe and kept + it when the runtime refused, so a module that asks again until it is taken — every Go consumer does — + could have its handler run once per attempt for every event. + +## The rule + +**A handler takes an event by returning, and asks for it again by throwing.** On the wire: any answer +to `mesh/event` that is not a JSON-RPC error takes it — `{}`, `null`, or no result at all; an error, no +answer within the runtime's event timeout, or the bundle exiting leaves it to be offered again, up to the +consumer's maximum deliveries. So a handler throws only when its work was not done, and does work that +is safe to do twice (delivery is at-least-once). An empty answer counts as taken: the alternative — a +reply must carry a particular result — would add a second way to fail that says nothing a handler means. + +Written down in the SDK's README ("Taking an event"), where event handling is documented, and checked +by the SDKs' stdio tests and the runtime's launch test. + +## Fix direction + +- The module sends a refresh without reading its body, and rescans once per download — known by event + id and by emitter and body — for ten minutes, so an event offered again is taken without another scan; + a failed rescan is still thrown. A test against a fake server that answers as the real one does. +- The runtime's line says the handler answered an error, quotes it, and names the event id and the + delay before the next offer. +- Both SDKs remove a handler whose subscribe the runtime refused; the rule is in the README. + +No other event consumer in the catalogues had a success path that throws. Two consumers do the +opposite — catch a failed write and take the event anyway — which the rule now names as wrong; they are +listed in the diagnosis and left for their own change. diff --git a/04-ISSUES/276-a-handler-that-did-its-work-was-offered-it-five-times/01-diagnosis.md b/04-ISSUES/276-a-handler-that-did-its-work-was-offered-it-five-times/01-diagnosis.md new file mode 100644 index 0000000..2f1db91 --- /dev/null +++ b/04-ISSUES/276-a-handler-that-did-its-work-was-offered-it-five-times/01-diagnosis.md @@ -0,0 +1,36 @@ +# 276. Diagnosis + +**2026-10-06.** + +1. **Where the words come from.** *Unexpected end of JSON input*, capitalised, is the JavaScript + engine's message for `JSON.parse("")`; Go's encoder says it in lower case. The runtime is Go and its + event delivery parses nothing the bundle answers: `launch.Start`'s `deliver` sends `mesh/event` and + returns only whether the answer was an error, whose message it passes on. So the text was the + bundle's, relayed — not the runtime failing to read a reply. The record held no entry for it. +2. **Which bundle code threw.** The module's handler was `await plex.refreshAll()`: list the libraries + (JSON), then `GET /library/sections//refresh` for each through the same JSON-reading helper. The + media server answers that refresh `200` with an empty body. Reproduced with a fake server answering + the same way: the handler throws exactly this error, after the first refresh was sent. That is why the + server's log showed scans — of the first library, once per offer — and why the rest were never asked. +3. **What the runtime did with it** was right: an error answer is not acknowledged, the event is + negatively acknowledged with a five-second delay, and after the consumer's maximum deliveries the bus + gives it up and the controller's advisory watch raises `max-deliveries`. +4. **The contract.** The SDKs (TypeScript and Go) answer `mesh/event` with `{}` once every matching + handler returned, and with an error when one threw; the runtime takes any answer that is not an error. + That is one rule in the code, but it was written nowhere a module author reads, and nothing told a + handler author what to throw for. +5. **The SDKs' subscribe** registered the handler before the runtime answered, and kept it on a + refusal. A Go consumer asks again in a loop until it is taken, so each refused attempt left one more + copy of its handler. Ruled out as the cause here (the module is TypeScript and subscribes once), but the + same family: work done more than once per event. +6. **Every other consumer**, in both catalogues and the photo service (which consumes none). The + lifecycle audits of the cache, the SQL server, the document store, the message broker and the secret + vault only log; the build-graph consumer throws only when its store fails and is idempotent on replay; + the four Go consumers (the database provider's audit, the records reader, the messenger, the watcher) + return `nil` on success and on an unreadable body. None throws on a success. Two do the reverse — the + audit logger and the usage store catch a failed write and take the event — which under the rule loses + it; left for their own change, since making them throw changes what the operator is told. +7. **A port of the module to Go is open on a branch.** It already ignores an empty body and remembers + event ids; it marks an id as done before the work, and forgets it only when a refresh fails, not when + listing the libraries does — an offer after that failure would be taken without a rescan. Noted to its + author rather than changed here.