Issue 314: a large answer was lost on its way back; issue 200 resolved by 265's fix

An answer over the bus's max_payload was refused inside the controller and every caller timed out, while calls said answered. Diagnosed and proved (R314), and told apart from issue 200, whose permission refusal issue 265 already fixed.
2026-10-08 11:30:10 +02:00
parent b11219e3de
commit f78e21c5f9
4 changed files with 223 additions and 4 deletions
@@ -1,8 +1,8 @@
 ---
-status: open
+status: resolved
 opened: 2026-10-02
-located-in: []
-fixed-by:
+located-in: [mesh-controller internal/link, mesh-controller cmd/mesh-controller, mesh-tools node-tools/internal/console]
+fixed-by: novox/mesh-controller PR #72 (eda457f), novox/mesh-tools PR #15 (730b404) — issue 265's fix
 amended-design:
 ---

@@ -16,7 +16,7 @@ The push had run; the machine applied. The bus's log on the control node, at the

 ```
 [ERR] 10.10.0.1:56030 - cid:4015 - Publish Violation - User "controller",
-      Subject "_INBOX.shanks.mesh-console.WRNO5V9IJ1FX35AU5NRBEB.WRNO5V9IJ1FX35AU5PN1UW"
+      Subject "_INBOX.<workstation>.mesh-console.WRNO5V9IJ1FX35AU5NRBEB.WRNO5V9IJ1FX35AU5PN1UW"
 ```

 The controller's reply to the console's request was refused: the controller's bus account may not
@@ -34,3 +34,12 @@ the request outlives the inbox subscription, is what a diagnosis has to tell apa

 - Which reply inboxes may the controller's account publish to, and which does the console request on?
 - Does a reply after the requester's timeout count as a violation, or is the prefix itself refused?
+
+## Resolved (2026-10-08)
+
+The same fault as [issue 265](../265-a-push-outlived-its-caller-and-its-answer-was-refused/00-report.md),
+which found the mechanism and fixed it: a push makes the broker reload its user list, the reload forgets the
+controller's permission to answer the request it already holds, and the answer is refused when the push
+ends. The diagnosis is in [`01-diagnosis.md`](01-diagnosis.md). It is not
+[issue 314](../314-a-large-answer-was-lost-on-its-way-back/00-report.md), which loses an answer too large
+for one message inside the controller, before the bus sees it.
@@ -0,0 +1,26 @@
+# 200 — diagnosis
+
+**2026-10-08.** Read from the controller's journal on the control node, and from issues 265 and 314.
+
+1. **The two open questions are answered by issue 265.** The prefix is not refused: the console asks on
+   its own inbox, and the controller's account may answer any request it receives (`allow_responses`).
+   The reply is refused because the broker reloaded its user list while the push ran. A reload gives
+   every connected user a new, empty table of the replies it may send. So the permission to answer the
+   request already held is gone. A reply after the requester's timeout is not itself a violation. The
+   violations came 35 to 50 s after the console gave up, and each followed a reload. None came at the
+   bus's 60 s window.
+2. **Issue 265's fix removes the cause.** A push answers its caller before it sends the broker's machine
+   (`Acknowledge`), and every call is answered within 10 s, in full or as "still running as call <id>".
+   What came of the call is kept for `calls`. A refused answer is recorded against its call, no longer
+   only printed by the client library.
+3. **Since then.** In the five days to 2026-10-08, the controller's journal holds one `Permissions
+   Violation for Publish to "_INBOX…"`, on 2026-10-06 at 13:12, around the time 265's fix was rolled
+   out, and none in the two days after.
+4. **Issue 314 is a different fault.** On 2026-10-08 the console again read "did not answer" from the
+   controller, for `conditions` and `status`. That answer was lost because it was larger than
+   `max_payload`. The client library refused it inside the controller (`nats: maximum payload
+   exceeded`, 577 times), so the bus never saw it and logged no violation. Same symptom at the console,
+   different cause and different place.
+
+**Resolved** by issue 265's fix. Opened before 2026-10-07, so no replay is required. Issue 265 says why
+none was registered for it.
@@ -0,0 +1,67 @@
+---
+status: located
+opened: 2026-10-08
+located-in: [mesh-controller internal/link (seattools.go, calls.go, the reply to a seat's verb), mesh-controller cmd/mesh-controller (conditions.go, readable.go, doctor.go, seatverbs.go: the overviews), mesh-tools node-tools/internal/bus (bus.go: the asker and a module's reply)]
+fixed-by: novox/mesh-controller PR #138, novox/mesh-tools PR #22, novox/mesh-lab PR #66
+replay: R314
+amended-design:
+---
+
+# 314. A large answer was lost on its way back
+
+## Symptom
+
+On 2026-10-08, from about 01:18 local time, every call of `mesh-controller.conditions` without a
+filter, and some calls of `mesh-controller.status`, ended for its caller in:
+
+> mesh-controller.conditions did not answer within 30s. That is not a failure: something is serving
+> it … The controller answers every call within seconds, so its answer was lost on the way;
+> mesh-controller.calls lists its recent calls and what came of each.
+
+At about 11:06, asked from the laptop through the mesh MCP server, both verbs timed out twice. `calls` said
+the same calls were answered in about 130 ms. Earlier that day `conditions` had answered 136 to 188 KB
+without trouble, and `calls` itself answered 422 KB.
+
+The operator's channel reads `conditions` once a minute to know what is open. It had read nothing
+since 01:18.
+
+Filtered calls still answered. `conditions` with `severity=urgent` answered at once that no urgent
+condition was open, out of **691 open**. `conditions` with `scope=delivery` timed out like the
+unfiltered one.
+
+## Evidence
+
+The controller's journal on the control node, one line per lost answer:
+
+```
+mesh-controller.conditions: could not answer call-…-209: nats: maximum payload exceeded
+mesh-controller.status: could not answer call-…-219: nats: maximum payload exceeded
+```
+
+There were 577 such lines between 01:18 and 11:13: 575 for `conditions` and 2 for `status`. There
+were none before 01:18. The bus reports `max_payload` 1 048 576 bytes, the server's default. The
+catalogue's bus module does not set it.
+
+691 conditions were open. 689 of them were `delivery.<id>.stalled`, raised by the self-check's probe
+D14, one for each delivery held past its bound. Each condition keeps its last ten observations as
+evidence. The verb's answer carried the list twice: once as data (`answer`) and once as the text the
+command printed (`output`), indented. A test with 689 such conditions measures 1.16 MB for the printed
+text alone, before the copy as data.
+
+## Why it matters beyond this instance
+
+An answer the bus could not carry was dropped inside the process that wrote it. Three records then
+disagreed with what happened, and nothing said so:
+
+- the caller read a timeout and was told the answer was lost on the way;
+- `calls` recorded the call as answered, and kept "sent to its caller in full" in place of the answer;
+- the only true line was the client library's error in the controller's journal.
+
+The mesh's overviews grow with the mesh. They will cross the limit again however they are trimmed. A
+reply path that fails silently past one size will fail in the same way for any verb that grows: the
+operator's channel went blind exactly when the mesh had most to say.
+
+## Open questions
+
+- Is issue 200, the controller's answer refused by the bus, the same fault? See the diagnosis: it is
+  not.
@@ -0,0 +1,117 @@
+# 314 — diagnosis
+
+**2026-10-08.** Read through the mesh's tools and the code, then proved on a test bus.
+
+## How a verb's answer travels
+
+1. The mesh MCP server on the laptop, the tool runner's loopback mode (mesh-tools
+   `node-tools/internal/bus`, `Ask`), publishes the call on the seat's subject, `mesh.seat.mesh-controller.tool.<verb>`, as a core request. It waits
+   `RequestTimeout`, 30 s, for one reply on its own inbox.
+2. The controller (mesh-controller `internal/link/seattools.go`) takes the request in its queue group.
+   It runs the verb in `serveCall` (`calls.go`) and answers once with `msg.Respond`: in full when the
+   verb finishes within `AnswerWithin` (10 s), or "still running as call <id>" otherwise
+   (issue 265). For `conditions` and `status` the verb is the controller's own command, run again
+   with `--json`. The answer is `{output, ok, answer}`: what the command printed, and the same JSON
+   parsed as data.
+3. The bus lets the controller answer once (`allow_responses: { max: 1 }`). The tool runner
+   reads the reply and hands it to the MCP client.
+
+## What happens above `max_payload`
+
+The client library compares a message with the server's `max_payload` before it sends it. A larger
+one is refused in the sender with `nats: maximum payload exceeded`, and nothing reaches the bus. So
+the server logs nothing and the requester receives nothing. In `serveCall` the verb's answer was
+recorded first, as answered, with a large answer replaced by "sent to its caller in full". Only then
+was it sent. The error from `Respond` went to the controller's journal and nowhere else. The tool runner
+waited out its 30 s.
+
+The runtime's own replies for a module's tools (`answerOn` in the tool runner) ignored the same error
+entirely. A module answering more than a mebibyte would leave its caller to time out with nothing
+logged anywhere.
+
+**Proved** on a bus of the release the mesh runs, by `TestReplay314` (mesh-controller
+`internal/link/replay314_test.go`). A seat verb answers about 3 MB, three times the limit. On the
+commit before the fix, a caller through `AskMeshSeatTool` reads "did not answer within 5s", and a plain
+request times out. On the fix, the first reads the whole answer, and the second is told in one
+message that fits. The lab's prover: `R314 (issue 314): PROVED — before its fix fails, on its fix
+passes`.
+
+## Why it began at 01:18
+
+`conditions` without a filter lists every open condition with its whole evidence, ten observations
+each, twice. When D14 had raised enough stalled deliveries, the answer crossed 1 MiB. The measure in
+`cmd/mesh-controller/conditions_brief_test.go` for 689 of them: 1.16 MB printed, plus the same again as
+data. `status` leads with the same list, so it crossed at about the same time. `calls` lists calls
+without their answers, so it stayed under the limit at 422 KB.
+
+Why 689 deliveries are held past their bound is a question for the delivery's owner and healer H2. It
+is not this issue's. This issue is that a mesh with that much to say said nothing.
+
+## Ruled out
+
+- **The bus refusing the answer** (permissions, issue 200's symptom): the bus logged no violation for
+  these calls, and the controller's journal names `maximum payload exceeded` for each.
+- **The verb being slow**: `calls` and the journal agree that each answered in about 130 ms.
+- **The tool runner's own limit**: the tool runner received nothing at all, so no reply ever reached it.
+
+## Issue 200 is a different fault
+
+Issue 200 (2026-10-02) is a `Publish Violation` logged by the bus server for the controller's reply
+to an inbox of the mesh MCP server, after a long `push`. A payload over the limit never reaches the server, so it
+cannot cause a violation there. Issue 265 diagnosed 200's mechanism: a push makes the broker reload
+its user list, the reload forgets the reply permission, and the push's answer is then refused. Issue
+265's fix answers a push before it sends the broker's machine, and answers every call within 10 s.
+Since that fix, the controller's journal holds one inbox violation, 2026-10-06 13:12, and none in the
+two days after. In the same time it holds 577 `maximum payload exceeded`. So issue 200 is resolved by
+265's fix, and this issue is new.
+
+## Located
+
+- mesh-controller `internal/link`: a seat's reply was sent whatever its size, and a refusal of the send
+  was logged and recorded as answered.
+- mesh-controller `cmd/mesh-controller`: the overviews (`conditions`, `status`, `doctor`) carried every
+  observation of every condition, and every finding of every probe, and sent their JSON twice.
+- mesh-tools `node-tools/internal/bus`: a module's reply had the same silent failure, and the asker
+  could not read anything larger than one message.
+
+## Fix
+
+**The reply path** (mesh-controller `internal/link/pages.go`, mesh-tools
+`node-tools/internal/bus/pages.go`):
+
+- A seat's answer larger than the connection's `max_payload` is never sent as one message. The holder
+  keeps it for five minutes under the call's id. It answers with an error that says how large the
+  answer is, the limit, and how to ask for it, and with `paged` giving the call, the size and the
+  number of parts.
+- A caller that pages asks **the same subject** again, once per part, with the header `Mesh-Page:
+  <call> <part>`. Each part is answered raw with `Mesh-Part: <n>/<parts>`. The same subject means no
+  new grant, and each part is a request of its own, within `allow_responses: max 1`. A part goes only
+  to the caller the answer was paged to, judged from its inbox. The tool runner's asker and the
+  controller's own askers (`AskSeatTool`, `AskMeshSeatTool`) join the parts. A part that cannot be had
+  fails the whole answer and names the part. A shorter answer is never returned.
+- A caller that does not page reads the error and is told what to do. It is never left waiting.
+- `calls` records `answer paged`. If the bus refuses a send anyway, that is recorded as the answer
+  refused, and the caller is told in a message that fits. A call's record on the bus no longer
+  carries an answer over 512 KiB, which the bus would refuse just as it refused the reply.
+- A module's answer too large for one message is answered by the runtime as an error that says so.
+  It is not paged: a module's tool may have several instances in one queue group, so a part asked
+  again could reach another instance.
+
+**The overviews** (mesh-controller `cmd/mesh-controller`):
+
+- `conditions` and `status` list each condition with its newest observation, how many it keeps, and
+  `more: mesh-controller.conditions key=<key>`, which gives the condition whole. `conditions` also
+  answers `counted`, the number of open conditions per source and kind, for example `D14 stalled:
+  689`. A list is never shortened. The operator's channel reads every open condition from it, and a
+  condition missing from the list would read as cleared.
+- `doctor` shows at most twenty findings of a probe, with their count and `doctor probe=<id>` for one
+  probe whole. That is a new optional argument.
+- `conditions`, `status` and `doctor` send their JSON once, as `answer`. `output` keeps only what the
+  command wrote to standard error. Every reader of these three reads `answer` first.
+
+Measured: 689 stalled deliveries now make a `conditions` answer of 458 KB on the wire, where before it
+was about 1.9 MB. The overviews will grow past the limit again. When they do, paging carries them.
+
+**Resolved when** the three pull requests have merged, and `mesh-controller.conditions` without a
+filter answers through the mesh MCP server while 689 conditions are open, and the operator's channel reads it
+again.