Merge pull request 'Issue 314: a large answer was lost on its way back; issue 200 resolved by 265's fix' (#198) from issues/314-a-large-answer-was-lost-on-its-way-back into main

2026-10-08 11:06:34 +00:00
parent c3022d5e14 f78e21c5f9
commit df0097245d
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.