diff --git a/04-ISSUES/348-a-resolver-that-stopped-answering-ran-on-unnoticed-and-builds-sent-after-it-were-blamed/00-report.md b/04-ISSUES/348-a-resolver-that-stopped-answering-ran-on-unnoticed-and-builds-sent-after-it-were-blamed/00-report.md new file mode 100644 index 00000000..407e8183 --- /dev/null +++ b/04-ISSUES/348-a-resolver-that-stopped-answering-ran-on-unnoticed-and-builds-sent-after-it-were-blamed/00-report.md @@ -0,0 +1,53 @@ +--- +status: located +opened: 2026-10-09 +located-in: [mesh-catalog modules/dnsmasq, mesh-controller cmd/mesh-controller (gate.go, machine_network.go, probes.go), mesh-controller internal/conditions, mesh-catalog modules/docker, mesh-catalog modules/netcheck] +fixed-by: +amended-design: +--- + +# 348. A resolver that stopped answering ran on unnoticed, and builds sent after it were blamed for it + +## Symptom + +On 2026-10-09, from 10:57:57 to 11:18:12 UTC, the mesh's resolver on the control node refused every +question asked on its private address. Its unit (`dnsmasq.service`, module `dnsmasq`, seat +`mesh-dns-resolver`) stayed active and running the whole time, and its journal said nothing. Every +question to that address got "connection refused". Loopback still answered. + +What it cost: + +- The certificate authority (`step-ca`, on the machine's own network stack) failed its health check from 10:59:37 UTC. +- The route proxy logged "lookup .internal on :53: … connection refused" for + every proxied request to a machine name, for twenty minutes. +- The control node's own network check failed (`machine..network`, raised 10:58:45 UTC). +- The controller (build 5438d7ff) and the node-engine (build 8f763ee9), sent to their first machines at + 10:59:34 UTC, failed their gate at 11:10:29 UTC with "raised since it was sent: + machine..network" and were put back. The fault began before they were sent. +- The second resolver of the mesh, on the home server, did not take over the route proxy's lookups. +- D2, the controller's probe that every resolver answers, raised the resolver only at 11:06:00 UTC, eight + minutes after it stopped answering. +- A person restarted the unit at 11:18:12 UTC by hand, and that fixed it. Nothing in the mesh would have. + +Five seconds before it stopped answering, at 10:57:52 UTC, a merge check on the control node removed its +throwaway containers, and the runtime tore down their bridge network and its virtual links. + +## Why it is an issue + +Three rules of the mesh did not hold. + +- **Failure must be loud** (ADR 0240). A module is judged healthy when its unit runs. Nothing asked the + resolver a question. A resolver that answers nothing on the address every machine and container uses + read as healthy for twenty minutes. +- **A send is judged on what it caused** (ADR 0236, issue 281). The gate failed two builds for a fault that + began before they were sent. +- **Nothing restarts on health; a healer that does is its own record** (ADR 0240 rule 6, ADR 0231). No + healer and no module repairs a resolver that stops answering, so the only repair was a person's. + +The operator's acceptance for the fix: if the mesh's name service stops answering on a node, the mesh +notices within a minute or two, restarts it by itself, and tells the operator only if that did not help. +A build is never put back for a problem that started before it was sent. + +The diagnosis is in [`01-diagnosis.md`](01-diagnosis.md). + +The fixes are in review: novox/mesh-controller pull request 179 and novox/mesh-catalog pull request 161. diff --git a/04-ISSUES/348-a-resolver-that-stopped-answering-ran-on-unnoticed-and-builds-sent-after-it-were-blamed/01-diagnosis.md b/04-ISSUES/348-a-resolver-that-stopped-answering-ran-on-unnoticed-and-builds-sent-after-it-were-blamed/01-diagnosis.md new file mode 100644 index 00000000..9ca4d796 --- /dev/null +++ b/04-ISSUES/348-a-resolver-that-stopped-answering-ran-on-unnoticed-and-builds-sent-after-it-were-blamed/01-diagnosis.md @@ -0,0 +1,175 @@ +# 348. Diagnosis + +## 2026-10-09 + +**The record.** A search of the records for "bind-dynamic", "raised since it was sent" and "dnsmasq" +found issue 110 (why the resolver is told an address and not an interface), issue 281 (a machine's +condition read as a module's), issue 277 (D2 asks again before it says anything) and research 032's +evidence that the runtime's event history is about a minute long. None of them is about a resolver that +stops answering while it runs. + +### Timeline (UTC) + +| time | what was seen | where | +|---|---|---| +| 10:57:52 | a merge check's throwaway containers removed, their bridge network and virtual links torn down | the runtime, on the control node | +| 10:57:57 | the route proxy's first "lookup … on :53: … connection refused" | the route proxy's log | +| 10:58:36 | `machine..network` raised: one of its two resolvers does not answer | conditions | +| 10:58:45 | `machine..network` raised; the home server's cleared, held under it | conditions | +| 10:59:34 | the controller 5438d7ff and the node-engine 8f763ee9 sent to their first machines | the walks | +| 10:59:37 | `module.step-ca..unhealthy` raised | conditions | +| 10:59:42 | `machine..network` **cleared**, its newest evidence (10:59:37) still "connection refused" | conditions | +| 11:00:23 | `machine..network` reopened, raised time 11:00:23 | conditions | +| 11:06:00 | `seat.mesh-dns-resolver..wrong` raised by D2 | conditions | +| 11:10:29 | both builds failed their gate: " as a whole: raised since it was sent: machine..network" — put back | conditions | +| 11:18:12 | `dnsmasq.service` restarted by hand; every question answered again | the operator | +| 11:21:46 | `machine..core-behind` raised: "… and no plan is rolling them out", while a release walked the node-engine | conditions | + +### What is measured, and what is guessed + +**Measured: the resolver ran and did not answer.** The unit stayed active; the journal said nothing; a +restart fixed it. Every question to the private address on port 53 got "connection refused" — the +kernel's answer when no socket is bound there. Loopback answered throughout. So dnsmasq had closed, or +lost, its socket on the private address and kept the one on loopback. + +**Guessed, then tested: the bridge teardown closed it.** The configuration says `bind-dynamic` and two +`listen-address` lines. With `bind-dynamic`, dnsmasq binds one socket per address and re-reads the +machine's addresses on every netlink change, closing what it finds gone. The teardown five seconds before +is a burst of exactly those changes. The reproduction is in the section below: the mechanism is measured, +the twenty-minute loss is not. + +**Measured: why the gate blamed the builds.** The gate counts a condition against a send when it was +raised after the send (`judgeHealth`, `aboutTheMachine` in the controller's `gate.go`). The comparison +was right; the raised time was not the fault's. The control node's network condition cleared at 10:59:42 +although its newest evidence still said "connection refused", and reopened at 11:00:23 with a new raised +time — after the send. The node-engine sent at 10:59:34 restarted, and a node-engine just started judges +each part of the network again from nothing: its first statement said the names part `unknown`, "one look +failed; a second decides" (`mesh-host` `internal/network`, `Look`). The controller clears every network +condition a statement no longer says unhealthy (`judgeNetworks`), so the restarted engine's first, +undecided statement cleared it, and its second look raised it anew. A reopening within ten minutes is the +same fault by the conditions' own rule (`ReopenWithin`), but a reopening took the new raised time. + +**Measured: why D2 took eight minutes.** The self-check runs every five minutes. D2 holds a resolver that +answered none of its questions for the next run (`Confirm`, issue 277), because on a loaded machine a +question can be lost. Its first run after 10:57:57 held it; the next, at 11:06:00, raised it. Every one +of those questions had been refused, which no load explains. + +**Measured: why the second walk of the node-engine waited on its own first machine.** A release keeps no +record per module — its modules are in its tier only — and D10 read only the records to know what a plan +is rolling out. So while a release walked the node-engine at 11:21, D10 raised `core-behind` on every +machine, "and no plan is rolling them out", and the gate on the home server, its first machine, waited +on it (issue 281's settle window) until D10's next run five minutes later found the new engine there. +The walk then passed. It did not fail, but it waited five minutes for a condition its own send caused. + +**Not explained: why the second resolver did not save the lookups.** Every machine's resolver file lists +both resolvers (`options timeout:1 attempts:2`), and the control node's own file lists its private address +first and the home server's second (read with `node-uplink.resolvers`). The control node's node-engine +reached the second resolver: its condition said one of two resolvers did not answer. The route proxy runs +on the machine's own network stack and resolves with Go's own resolver, which tries every listed server and, when all +fail, names the **last** one it tried (Go `net/dnsclient_unix.go`, `tryOneName`). Its error named the +private address of the control node, the first one. I think the route proxy's copy of the resolver file +lists only the control node's own resolver, because Go would otherwise have asked the second and named it. +That copy is the runtime's, made when the container was created (08:04 UTC that day), and no tool could +read it: it is root's, and the docker module had no way to show it. Next step: the new `docker_resolv_conf` +tool (below) reads it, on the next look after it is delivered. Whether the certificate authority's failure +has the same cause is not known. + +**Measured: why `docker_events` returned nothing for 180 minutes.** The runtime keeps about its last 256 +events in memory, and the containers' own health checks fill them within minutes (research 032). Asked at +11:24 UTC, the tool returned 254 events from the last ten minutes only. The teardown at 10:57:52 had already +been pushed out when the question was asked. The tool answered "0 events" as though nothing had happened. + +### The bind behaviour + +Reproduced on the laptop only, in a user and network namespace (never on a machine of the mesh): a dummy +link holding the private address, the module's configuration with `bind-dynamic` and both +`listen-address` lines, dnsmasq 2.93 in the foreground, a client asking the machine's name on both +addresses every 0.1 s, and a bridge with 4 to 80 virtual link pairs brought up and deleted, one by one or +all at once. + +**Measured.** Every few teardowns dnsmasq closed both listeners ("stopped listening on … port 53", at +debug level only, so never in a normal journal). A build with two lines of logging added showed each +closing follows a failed reading of the machine's addresses: "iface_allowed: index N gone (No such +device)", N a virtual link being deleted — 59 failed readings and 53 closings in 120 teardowns of 8 links +at once; 107 and 104 in 20 teardowns of 80. In every trial the next address change re-bound them within +the same burst: two seconds after a teardown the private address was unbound 0 times of 180, and the +client was never refused. + +**Read in the source** (dnsmasq 2.93, `src/`): `iface_allowed` returns 0 when a link's index no longer +resolves (`network.c:255-259`); that fails the whole enumeration (`netlink.c:225`, `256-258`, `297-301`); +a failed IPv6 pass skips the IPv4 pass, so no IPv4 address is marked found (`network.c:832-840`); under +`bind-dynamic` alone, every listener not found is closed (`network.c:849-875`); and one is bound again only +by a later netlink address event followed by a clean reading (`network.c:1177-1190`, `netlink.c:406-411`). + +**Guessed.** That on the control node the closing came with no later address event to re-bind it — the +netlink socket overflowing in the burst and dropping the events after it (it is read without blocking, +and what overflowed is lost), or no address changing on the machine for twenty minutes. Why loopback kept +its listener there is not known; a reading that failed at a link ordered after loopback and before the +private network's would close only the private address. + +**Tested alternatives.** `bind-interfaces` closed nothing under the same churn, kept answering after the +private address and its link were deleted and made again, and answered a query from another namespace +through a bridge (issue 110's case). It refuses to start when the address is not there yet. `interface=` +lines with `bind-dynamic` closed listeners as before (14 in one run). So the configuration now says +`bind-interfaces`, and a drop-in makes the unit wait up to 80 seconds for the private address before it +starts and retry every ten seconds, rather than leave it failed. The watch stays: it catches whatever else +stops the resolver answering. + +## The fixes + +One pull request per repository, each naming this issue. + +**mesh-catalog — the resolver binds once.** `bind-interfaces` in place of `bind-dynamic`, and the unit +waits for the private address (above). + +**mesh-catalog — the resolver asks itself, and restarts itself.** The `dnsmasq` module is now Go (its +TypeScript tools were never served on any machine). Its new long-running process, the watch, runs as root +and every 15 seconds asks the machine's own name — from the roster — on every address the configuration +listens on, over UDP and TCP, and checks the answer is that machine's address. After two failing looks in +a row it restarts the unit, at most once every two minutes and three times an hour, and the looks after it +say whether the restart helped. Its tool `dnsmasq_health` is the watch's declared check (ADR 0240): it asks +again and reads what the watch did, so a restart that helped leaves the module healthy and the operator +hears nothing, and one that did not becomes `module.dnsmasq..unhealthy`, saying "restarted at …, +which did not help". The unit itself is judged by its unit (`health: unit`). The bundle emits `restarted` +on the bus beside the names it answers. The repair is the module's own, as the identity provider repairs +its administrator (ADR 0224 §5), because a resolver that stops answering can cut its machine off from the +bus by name, and then nothing outside the machine reaches it. **This departs from ADR 0240 rule 6** +("nothing restarts on health"), which left a restart on health to a healer's own record under ADR 0231. +That record is not written; whether this module-local repair stands, or becomes a row of the healer +registry, is the operator's decision. + +**mesh-controller — a fault is judged by when it began.** + +- A condition keeps `first`, when the fault was first raised, across a reopening within `ReopenWithin` + (and across a controller restart, from the history); `Began()` reads it. The gate compares `Began()`, + not the raised time, with the send. +- An undecided network statement — a part `unknown` or `starting`, as a node-engine just started says — + clears no network condition about that machine. The next statement decides. +- D10 counts what a release's tier names as rolling out, so a walked node-engine is not `core-behind` on + its own first machine. +- D2 raises a resolver at once when every try of every question it asked was refused: a refusal is the + machine's answer that nothing listens there, not a loaded resolver. The detection is then at most one + self-check interval (five minutes). The node-engine's own network check stays the fast one (48 seconds + on the day). + +**mesh-catalog — the tools that were missing.** + +- `netcheck_dns` asks one named resolver directly (`server`, `tcp`), and `netcheck_listening` lists what + listens on the machine (`ss -lunt`). netcheck is assigned on the home server and the laptop only; + assigning it on the control node and the workstation is the operator's. +- `docker_events` says how far back the runtime's memory reaches, and says plainly when the window asked + reaches further back, instead of answering an empty list. +- `docker_resolv_conf` reads a container's resolver file as the container sees it. + +## How it is checked + +| Rule | Check | +|---|---| +| A reopened fault from before a send fails no gate | controller `TestReplay348` (the day's statements: raised, an undecided restart, raised again; the gate on a send between), `TestAReopenedFaultFromBeforeTheSendIsNotRaisedSinceIt`, conditions `TestAReopeningKeepsWhenTheFaultBegan` — the first two fail on the commit before the fix | +| An undecided statement clears nothing | `TestReplay348`, `TestAnUndecidedStatementKeepsTheMachinesNetworkConditions` | +| A release's modules are rolling | `TestAReleaseRollsOutWhatItsTierNames` | +| A refusing resolver is raised at once | `TestAResolverThatRefusesEveryTryIsSaidAtOnce` — fails on the commit before the fix | +| The resolver is asked a real question, restarted, and said when it did not help | dnsmasq `TestALookFindsAResolverThatStoppedAnsweringOnOneAddress`, `TestTheWatchRestartsOnASecondFailingLookWithinItsBudget`, `TestTheWatchRestartsAResolverThatStoppedAnsweringAndHealthSaysWhetherItHelped` | +| live | after delivery: `dnsmasq_health` on both resolvers healthy; a restart by the watch said as `restarted` on the bus | + +A replay in mesh-lab's register is still owed before this core issue resolves (ADR 0237).