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

Merge pull request 'Issue 348: a resolver that stopped answering ran on unnoticed, and builds sent after it were blamed' (#249) from issues/348-the-resolver-stopped-answering-and-nothing-restarted-it into main

Browse Source
This commit was merged in pull request #249.
This commit is contained in:
mesh-admin
2026-10-09 13:25:22 +00:00
parent fce1bbb432 fbd00a16ca
commit 80b02dc9a0
3 changed files with 304 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
+187
View File
@@ -0,0 +1,187 @@
# 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 — only one that runs: a unit stopped or disabled on purpose, still starting
(waiting at boot for the private address) or failed is the service manager's or a person's, and is held
and said — without waiting for the start, at most once every two minutes and three times an hour (a
budget it reads back when it restarts itself), 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`
and, once the looks decide it, `restart-judged` (helped or not) on the bus beside the names it answers,
each remembered as said only once emitted. 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 whether it was there at the send.**
- A condition reopened within `ReopenWithin` keeps when the fault was first raised (`first`) and its
gaps, each from a clearing to the reopening after it, across a controller restart too (from the
history). The gate asks `OpenAt(send)`: the fault began at or before the send and the send fell in none
of its gaps. So a fault there at the send that flapped after it is not the send's, and a machine that
had recovered before the send and broke after it fails the gate, as it must (review of the controller's
pull request: a silent pass is worse than a false blame).
- An undecided part of a network statement — `unknown` or `starting`, as a node-engine just started says
— holds the open network conditions whose newest evidence names that part, and only those. A statement
undecided as a whole holds every part. 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 is unchanged: a resolver that answered nothing, refused or silent, is held for the next run, because
a few hundred milliseconds of refusals is a resolver restarting as well as one that stopped. D2 says it
five to ten minutes after; the node-engine's own network check is 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` reads the runtime's whole buffer of events: the window is complete when the buffer is
not full (it then holds every event since the runtime started) or reaches past the window's start, and
otherwise says where the history begins, 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 fault there at the send fails no gate; one recovered at the send and back after it does | controller `TestReplay348` (the day's statements: raised, an undecided restart, raised again; the gate on a send between), `TestAFaultThatFlappedAfterTheSendIsNotTheSendsAndOneThatRecoveredBeforeItIs`, conditions `TestAReopeningKeepsWhenTheFaultBegan`, `TestAFaultKeepsItsNewestGapsAndForgetsWhatWasBefore` |
| An undecided part holds only what names it | `TestReplay348`, `TestAnUndecidedPartHoldsOnlyWhatNamesIt` |
| A release's modules are rolling | `TestAReleaseRollsOutWhatItsTierNames` |
| The resolver is asked a real question, restarted, and said when it did not help | dnsmasq `TestALookFindsAResolverThatStoppedAnsweringOnOneAddress`, `TestTheWatchRestartsOnASecondFailingLookWithinItsBudget`, `TestTheWatchRestartsAResolverThatStoppedAnsweringAndHealthSaysWhetherItHelped`, `TestTheWatchRestartsOnlyAUnitThatRuns`, `TestTheWatchLoopKeepsItsBudgetAcrossItsOwnRestart`, `TestHealthSaysWhenTheWatchIsNotLookingOrTheUnitIsNotRunning`, `TestTheAnnouncerSaysWhatChangedAndRemembersOnlyWhatWasSaid` |
| Every changed condition is tested | the controller's and the modules' changes were mutated one at a time (28 in the controller, 31 in the modules); each failed a test |
| 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).
The controller's own test of the resolver's manifest (`TestTheResolverForwardsToFixedUpstreamsAndNeverReadsResolvConf`)
reads the catalogue beside it, so for now it takes either binding; once the catalogue's main binds once,
it should refuse `bind-dynamic` (a follow-up in the controller).
04-ISSUES/349-a-merge-acted-on-late-superseded-the-merge-after-it-and-built-the-older-commit/00-report.md
+64
View File
@@ -0,0 +1,64 @@
---
status: located
opened: 2026-10-09
located-in: [mesh-controller cmd/mesh-controller (release_plan.go supersededBy, upgrades.go), mesh-controller internal/inventory (release_plan)]
fixed-by:
amended-design:
---
# 349. A merge acted on late superseded the merge after it, and built the older commit
## Symptom
On 2026-10-09 the plans of the catalogue superseded each other out of the branch's order, twice
(`mesh-controller.plans`):
- the plan at 1833045c was "superseded at tier 0 by" the plan at a783ac94, a merge made before it;
- the plan at a082615b — the merge of a security fix to the forge's module — was "superseded at tier 0 by"
the plan at 8ff8197a, the merge before it, with "gitea planned there again". The forge's module was then
to be built from the commit without the fix. A third merge (9e4267bf) came a minute later and superseded
that plan in turn, so the fix was built from 9e4267bf. Had nothing come after, it would not have been.
## Why it is an issue
A newer plan of a branch supersedes the older open ones and builds what they had not
([ADR 0218](../../02-DECISIONS/0218-a-plan-sends-grants-before-code-rolls-out-one-machine-first-and-a-newer-merge-takes-over-an-older-plan.md),
issue 254). "Newer" was read from when each plan was made, never from the commits. The catch-up acts on a
merge the bus did not hand over (issue 266) after the merges that came after it, so its plan was made last
and won. The mesh built an older commit than the branch held, and said nothing wrong: each plan said
"superseded", as designed.
## Diagnosis
The order of merges into one branch is the forge's: each merge is made on the branch as the one before
left it, so a later merge's commit contains every earlier one's, and the forge's merge time
(`merged_at`, which every announcement carries) is the branch's order. A plan kept none of it.
`supersededBy` compared `Created`.
## Fix
In mesh-controller, in the same pull request as issue 348 (PR 179):
- A plan keeps when its merge was made, to the nanosecond (`merged_at`, migration 0086; null for a release
and for a plan kept before it).
- `supersededBy` orders two plans of a branch by their merge times where both are known, and by when they
were made only where one is not.
- A merge older than the newest planned merge of its branch — that plan in any state, open or already done
— is planned at that merge's commit, which contains it, with that merge's time. A module the newer merge
already looked at then reads as history and is not built again; what only the older merge moved, and its
dependents, are built from the newest commit. Comparing with open plans alone left a gap the review
found: a late merge arriving after the newer plan was done rebuilt its dependents at the older commit.
That gap is closed.
- Not covered: a newer merge that moved nothing the mesh builds made no plan, so it is not known here; a
late older merge after it is then planned at its own commit, as before. Its modules are those the newer
merge did not change, so what it builds from the older commit is what the newer one holds too, unless a
dependent's build reads shared code the newer merge changed.
## How it is checked
`TestTwoMergesActedOnInReverseOrderBuildTheNewerCommit` replays the day's case: the later merge acted on
first, the earlier one second; one plan is left open, at the later commit, building what both moved.
`TestALateMergeAfterTheNewerPlanEndedBuildsTheNewerCommit` acts on the late merge after the newer plan is
done. `TestTheBranchOrderIsTheMerges` holds the order and the lookup, to the nanosecond. The first and the
last fail on the commit before the fix, and every condition of the change was mutated and caught.
A replay in mesh-lab's register is still owed before this core issue resolves (ADR 0237).