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.
2026-10-06 18:15:58 +02:00
parent 3e32db519f
commit fef40505ae
2 changed files with 110 additions and 0 deletions
@@ -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.
@@ -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/<key>/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.