diff --git a/04-ISSUES/200-the-controllers-answer-to-the-console-is-refused-by-the-bus/00-report.md b/04-ISSUES/200-the-controllers-answer-to-the-console-is-refused-by-the-bus/00-report.md index 67868eb4..d488597e 100644 --- a/04-ISSUES/200-the-controllers-answer-to-the-console-is-refused-by-the-bus/00-report.md +++ b/04-ISSUES/200-the-controllers-answer-to-the-console-is-refused-by-the-bus/00-report.md @@ -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..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. diff --git a/04-ISSUES/200-the-controllers-answer-to-the-console-is-refused-by-the-bus/01-diagnosis.md b/04-ISSUES/200-the-controllers-answer-to-the-console-is-refused-by-the-bus/01-diagnosis.md new file mode 100644 index 00000000..f7356ecc --- /dev/null +++ b/04-ISSUES/200-the-controllers-answer-to-the-console-is-refused-by-the-bus/01-diagnosis.md @@ -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 ". + 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. diff --git a/04-ISSUES/314-a-large-answer-was-lost-on-its-way-back/00-report.md b/04-ISSUES/314-a-large-answer-was-lost-on-its-way-back/00-report.md new file mode 100644 index 00000000..72fcb19e --- /dev/null +++ b/04-ISSUES/314-a-large-answer-was-lost-on-its-way-back/00-report.md @@ -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..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. diff --git a/04-ISSUES/314-a-large-answer-was-lost-on-its-way-back/01-diagnosis.md b/04-ISSUES/314-a-large-answer-was-lost-on-its-way-back/01-diagnosis.md new file mode 100644 index 00000000..6f4ac831 --- /dev/null +++ b/04-ISSUES/314-a-large-answer-was-lost-on-its-way-back/01-diagnosis.md @@ -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.`, 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 " 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: + `. Each part is answered raw with `Mesh-Part: /`. 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=`, 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=` 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.