From 1d8745b54d3509366993df024c90ef13aa287415 Mon Sep 17 00:00:00 2001 From: jochen Date: Tue, 6 Oct 2026 01:14:56 +0200 Subject: [PATCH] Issue 265: a push outlived its caller, and the bus refused its answer --- .../00-report.md | 145 ++++++++++++++++++ 1 file changed, 145 insertions(+) create mode 100644 04-ISSUES/265-a-push-outlived-its-caller-and-its-answer-was-refused/00-report.md diff --git a/04-ISSUES/265-a-push-outlived-its-caller-and-its-answer-was-refused/00-report.md b/04-ISSUES/265-a-push-outlived-its-caller-and-its-answer-was-refused/00-report.md new file mode 100644 index 0000000..4105c8d --- /dev/null +++ b/04-ISSUES/265-a-push-outlived-its-caller-and-its-answer-was-refused/00-report.md @@ -0,0 +1,145 @@ +--- +status: located +opened: 2026-10-06 +located-in: [mesh-controller internal/link, mesh-controller cmd/mesh-controller, mesh-tools node-tools/internal/console] +fixed-by: +amended-design: +--- + +# 265. A push outlived its caller, and its answer was refused + +## Symptom + +Through the console, a call to the controller's seat — `mesh-controller.push` with a machine, or +`mesh-controller.command` with `push ` — ended in: + +> mesh-controller.push did not answer in time. Something is serving it, so this is the tool being slow +> rather than absent. + +and the push had happened: the machine applied what it was sent. Over 2026-10-04 and 2026-10-05, 54 +of 103 pushes asked through the console ended that way. Each one left the operator not knowing whether +to push again. + +Some of them also left a line in the controller's journal, written by the bus client library and by +nothing of the mesh's own: + +> nats: permissions violation: Permissions Violation for Publish to "_INBOX..node-tools.….…" +> on connection [838] + +Thirty such lines in three days. No caller, no `status` and no record said that a call had lost its +answer. + +## Evidence + +Three waits govern one call, and they disagreed: + +| Who waits | How long | Where | +|---|---|---| +| The console, for an answer | 30 s | mesh-tools `node-tools/internal/bus`, `RequestTimeout` | +| The bus, for the one answer it lets the controller send | 1 min, one message | the user list the controller composes (`allow_responses`, ADR 0043) | +| The controller, for the verb's command | 5 min | mesh-controller `internal/link`, `HandlerTimeout` | + +**A push takes about as long as the console waits.** The calls the console made were paired with +their answers from the session transcripts. Of the pushes that were answered, the median took 26.6 s. +The longest took up to two minutes, because the console queues calls made side by side. A named push +composes the named machine, then the machine holding the bus when its user list changed (issue 249). +It then composes every other machine to flush what fell behind (ADR 0083). Composing one machine +alone took 9 s for the anchor, measured with a `plan` call. Anything slower than 30 s was reported as +"did not answer in time", and its answer went to an inbox nobody read any more. The bus says nothing +about that. + +**Every journal line was a timed-out push whose answer the bus refused.** Each violation was set +against the console calls before it. Every one of the 30 came 35 to 50 seconds after a push or a +`command push …` that had timed out at 30 s. None came after a call that was answered. None came at +the 60 s the bus's window would explain. The two from the night of 2026-10-05, in the broker's own +log: + +``` +22:25:00 console asks push of the anchor +22:25:15 broker: "the mesh's user list changed; reloading in place" — Reloaded server configuration +22:25:30 console gives up (30 s) +22:25:44 broker: Publish Violation - User "controller", Subject "_INBOX..node-tools.….LNRyztuX" + +22:41:17 console asks push of the anchor +22:41:30 broker: user list changed; reloaded +22:41:47 console gives up +22:42:00 broker: Publish Violation - User "controller", Subject "_INBOX..node-tools.….BzO7Ep8s" +``` + +The bus server's source names the cause (`client.go`, `setPermissions`). A reload of the +authorization re-registers every connected user and gives each a new, empty table of the replies it +may send. The permission to answer a request already received is forgotten. A push sends the machine +holding the bus first when its user list changed (issue 249). The broker reloads. When the push +finishes, the answer it waited to send is refused. + +## Cause + +**A verb answered only when it finished, however long that took.** The control plane runs each verb's +command and answers with what it printed (ADR 0154, design 33). Nothing bounded that by the caller's +wait or by the bus's window for an answer. Nothing ruled out the verb destroying that window itself. +Three silences followed: + +1. A verb slower than its caller's wait answered nobody. The caller was told it was slow, and read + that as failed. +2. A verb that reloaded the bus had its answer refused, every time the user list had changed. +3. The refusal reached only the client library's default error handler, which prints a line. No + record of the mesh's own said which call lost its answer, or what the answer was. + +The two-minute default for `allow_responses` (the hypothesis this was opened under) is not the cause: +the mesh sets the window to one minute, and every refusal came well inside it. + +## Fix + +**The controller answers every call within ten seconds and keeps what came of it.** In mesh-controller: + +- `internal/link`: a seat's call is answered once, as before. It gets its whole answer when the + command finishes within `AnswerWithin` (10 s). Otherwise it is told the call is running, with the + call's id. The command runs on. Its answer is kept in a log of the last hundred calls, and the + journal says when it ended. +- **A push is answered before it sends anything**, by its verb or through `command`: its own first + act can reload the bus. The answer says it is running, with the id. +- The connection's error handler is chained, not replaced. A refused answer is matched to its call + by the reply subject the bus names. It is recorded on the call and said in the mesh's words, naming + the call. +- A new verb, `calls`, lists the recent calls: running, answered, finished after its caller was + answered, and answer refused by the bus. Given an id, it returns that call's whole answer. + Arguments are kept by name, and settings and secrets are never kept. +- The bus's window for an answer is now a named constant (`ResponseTTL`). A test holds + `AnswerWithin` inside it and inside the console's wait. + +In mesh-tools, the console's timeout no longer reads as a failure. It says the call may still be +running and may already have done what was asked, and to check before repeating a call that changes +the mesh. For the controller it adds that the answer was lost on the way, and that +`mesh-controller.calls` has it. + +Why this shape rather than the others weighed: + +- **Widening the bus's window does nothing for the refusal.** A reload empties the reply table + whatever its expiry is. +- **Making push faster** narrows the race and keeps it. The flush of every other machine is ADR + 0083's and stays. +- **Answering early with an id** is how `build` already works ("asked, not waited for"). It is the + only shape where the answer cannot depend on what the verb does to the bus. + +## How it is checked + +- `internal/link` tests: + - a call that finishes in time is answered once, in full; + - a call that outlasts the window is answered once, that it is running, with its id, and its final + answer is kept under that id; + - an acknowledged call is answered before its handler goes on; + - the bus's refusal text, with the call's reply subject, is recorded on that call, and other + errors are not; + - settings and secrets are not kept. +- `cmd/mesh-controller` tests: + - `push`, and `command push …`, answer first, and `status` and `assign` do not; + - `calls` is served, refuses an argument it does not declare, and says plainly when it holds no + such call; + - `AnswerWithin` is under half the console's wait and under `ResponseTTL`. +- mesh-tools console test: a timeout says "not a failure", and for the controller names + `mesh-controller.calls`. +- Once rolled out: + - a push through the console answers at once with an id, and `mesh-controller.calls` with that id + shows what it sent; + - the controller's journal shows no bare `Permissions Violation for Publish to "_INBOX.…"` without + the mesh's own line naming the call beside it.