novox/hq
6
0
Fork 0
Code Issues Pull Requests 5 Releases Wiki Activity

Issue 348: a resolver that stopped answering ran on unnoticed, and builds sent after it were blamed

Browse Source 
Records the 2026-10-09 outage on the control node: what was measured
(the unit ran, the private address refused; a restarted node-engine's
undecided statement cleared the network condition and its reopening
dated the fault after the send), what the reproduction showed of
bind-dynamic, what is still guessed, and the fixes in review.
This commit is contained in:
jschoubben
2026-10-09 14:12:42 +02:00
committed by jochen
parent fce1bbb432
commit 582be67f05
2 changed files with 228 additions and 0 deletions
Download Patch File Download Diff File Expand all files Collapse all files
04-ISSUES/348-a-resolver-that-stopped-answering-ran-on-unnoticed-and-builds-sent-after-it-were-blamed/00-report.md
+53
View File
@@ -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 <machine>.internal on <private address>:53: … connection refused" for
every proxied request to a machine name, for twenty minutes.
- The control node's own network check failed (`machine.<control node>.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.<control node>.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.
04-ISSUES/348-a-resolver-that-stopped-answering-ran-on-unnoticed-and-builds-sent-after-it-were-blamed/01-diagnosis.md
+175
View File
@@ -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 <private address>:53: … connection refused" | the route proxy's log |
| 10:58:36 | `machine.<home server>.network` raised: one of its two resolvers does not answer | conditions |
| 10:58:45 | `machine.<control node>.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.<control node>.unhealthy` raised | conditions |
| 10:59:42 | `machine.<control node>.network` **cleared**, its newest evidence (10:59:37) still "connection refused" | conditions |
| 11:00:23 | `machine.<control node>.network` reopened, raised time 11:00:23 | conditions |
| 11:06:00 | `seat.mesh-dns-resolver.<control node>.wrong` raised by D2 | conditions |
| 11:10:29 | both builds failed their gate: "<control node> as a whole: raised since it was sent: machine.<control node>.network" — put back | conditions |
| 11:18:12 | `dnsmasq.service` restarted by hand; every question answered again | the operator |
| 11:21:46 | `machine.<each>.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.<machine>.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).