Issue 265: a push outlived its caller, and the bus refused its answer
This commit is contained in:
@@ -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 <machine>` — 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.<laptop>.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.<laptop>.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.<laptop>.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.
|
||||
Reference in New Issue
Block a user