From 3d2aafc8e99d2720bc146712ade4ec2764697fe0 Mon Sep 17 00:00:00 2001 From: Anthony Ettinger Date: Mon, 10 Aug 2026 13:04:57 +0000 Subject: [PATCH] fix(dns): prove the bridge is there before routing the machine at it MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit `startDaemon` spawned with `stdio: "ignore"`, wrote the pidfile from `child.pid`, and returned `started: true` in the same tick — before the child had done anything, including exist. On a machine where the daemon dies on startup that printed `ok bridge started (pid 22900)` for a process that was already gone, and `enable` went on to install catch-all routing (`Domains=~.`) pointing every lookup on the box at a dead port. The machine lost DNS entirely and the reason was unrecoverable: the daemon had written it to stderr, which was routed to /dev/null. Found on a Kubuntu desktop whose node comes from mise — under the privilege escalation `enable` performs, the interpreter was not where the daemon needed it. The specific cause matters less than the class: every startup failure arrived as the same confident success line. - stdout and stderr go to moshpit-dns.log next to the pidfile, truncated per run, so a startup failure has somewhere to have happened - an early exit (or a spawn that never ran) is a failed start carrying the daemon's own output; no pidfile is left behind for a dead process, which is what made the next run believe a bridge was already up - "started" now means it answered a real query on the port; alive but silent is reported as unproven rather than rounded up or killed, since a slow registry fetch looks exactly like that - `enable` refuses to write the drop-in at all when the bridge is down, and takes back the restore point it recorded Co-Authored-By: Claude Opus 5 (1M context) --- src/dns-system.mjs | 182 ++++++++++++++++++- src/dns.mjs | 34 +++- test/dns-daemon-verify.test.mjs | 307 ++++++++++++++++++++++++++++++++ 3 files changed, 516 insertions(+), 7 deletions(-) create mode 100644 test/dns-daemon-verify.test.mjs diff --git a/src/dns-system.mjs b/src/dns-system.mjs index 6e43984..8d5a541 100644 --- a/src/dns-system.mjs +++ b/src/dns-system.mjs @@ -274,7 +274,8 @@ export function requiredPort(platform, preferred = 5354) { /* ------------------------------------------------------- running the plan */ import { spawn } from "node:child_process"; -import { mkdir, readFile, rm, writeFile } from "node:fs/promises"; +import dgram from "node:dgram"; +import { mkdir, open, readFile, rm, writeFile } from "node:fs/promises"; import { existsSync } from "node:fs"; import { dirname, join } from "node:path"; import { homedir, tmpdir } from "node:os"; @@ -367,17 +368,132 @@ export async function daemonStatus(path = pidfilePath()) { } /** - * Start the bridge detached, so the shell that launched it can exit. + * Where a daemon that died on startup left its reason. * - * Not a systemd unit / launchd job / Windows service yet, which means it does + * Next to the pidfile, because the two answer halves of the same question and + * a person debugging one wants the other in the same directory. + */ +export function daemonLogPath(path = pidfilePath()) { + return join(dirname(path), "moshpit-dns.log"); +} + +/** + * How long to wait for the bridge to answer before reporting it unproven. + * + * Generous on purpose, and it costs nothing in the case that matters: a daemon + * that dies resolves the race on its `exit` event immediately, so this bounds + * only the "alive but has not answered yet" case. The bridge binds *after* it + * fetches the ending list, which against the live registry is ~3s on a fast + * link — a tighter deadline would print a warning about healthy bridges on + * every slow connection. + */ +export const READY_TIMEOUT_MS = 8000; +const POLL_MS = 150; +const LOG_TAIL_LINES = 20; + +const defaultSleep = (ms) => new Promise((resolve) => setTimeout(resolve, ms)); + +/** A minimal A query. Only the reply matters here, never what it says. */ +function encodeQuery(name, id) { + const labels = String(name).split(".").filter(Boolean); + const head = Buffer.alloc(12); + head.writeUInt16BE(id, 0); + head.writeUInt16BE(0x0100, 2); // standard query, recursion desired + head.writeUInt16BE(1, 4); // one question + const tail = Buffer.alloc(4); + tail.writeUInt16BE(1, 0); // A + tail.writeUInt16BE(1, 2); // IN + return Buffer.concat([ + head, + ...labels.map((label) => { + const bytes = Buffer.from(label, "ascii"); + return Buffer.concat([Buffer.from([bytes.length]), bytes]); + }), + Buffer.from([0]), + tail, + ]); +} + +/** + * Is something serving DNS on this port? + * + * Any well-formed reply counts, including NXDOMAIN and SERVFAIL. The question + * is whether the resolver is up, and a bridge whose upstreams are unreachable + * is still a bridge that started — conflating the two would turn a bad network + * into a failed start. + */ +export function probeResolver({ host = "127.0.0.1", port, name = "a.eggs", timeoutMs = 500 } = {}) { + return new Promise((resolve) => { + const socket = dgram.createSocket("udp4"); + const id = Math.floor(Math.random() * 65536); + let done = false; + const finish = (answered) => { + if (done) return; + done = true; + clearTimeout(timer); + try { + socket.close(); + } catch { + // Already closed by the error that brought us here. + } + resolve(answered); + }; + const timer = setTimeout(() => finish(false), timeoutMs); + socket.once("error", () => finish(false)); + socket.on("message", (msg) => finish(msg.length >= 2 && msg.readUInt16BE(0) === id)); + socket.send(encodeQuery(name, id), port, host, (err) => { + if (err) finish(false); + }); + }); +} + +async function readLogTail(path, lines = LOG_TAIL_LINES) { + const text = await readFile(path, "utf8").catch(() => ""); + const trimmed = text.trimEnd(); + return trimmed ? trimmed.split("\n").slice(-lines).join("\n") : ""; +} + +/** + * Start the bridge detached, so the shell that launched it can exit — and do + * not claim it started until it has proved it is there. + * + * The old version spawned with `stdio: "ignore"`, wrote the pidfile from + * `child.pid`, and returned `started: true` in the same tick. Both halves of + * that were wrong on any machine where the daemon dies on startup. `enable` + * printed `ok bridge started (pid N)` for a process that was already gone, then + * installed catch-all routing — `Domains=~.` — pointing every lookup on the box + * at a port with nothing behind it. The failure took the machine's whole + * resolver down and left no way to find out why, because the one stream the + * daemon wrote its reason to had been routed to /dev/null. A node that is not + * on root's PATH, a port it cannot bind, a half-written install: all of them + * arrived as the same confident success line. + * + * So: stdout and stderr go to a file, an early exit is a failed start that + * reports what the daemon said, and the pidfile is written only once the + * process is still there — never for one that is not, which is what made + * `daemonStatus` report a stale pid as a crash that had never happened. + * + * Still not a systemd unit / launchd job / Windows service, which means it does * not survive a reboot. `moshcode dns status` says so plainly rather than * letting someone discover it when their names stop resolving. */ -export async function startDaemon({ port, registryBase, path = pidfilePath(), entry, proxy = null }) { +export async function startDaemon({ + port, + registryBase, + path = pidfilePath(), + entry, + proxy = null, + host = "127.0.0.1", + logPath = null, + readyTimeoutMs = READY_TIMEOUT_MS, + probe = probeResolver, + sleep = defaultSleep, +}) { const existing = await daemonStatus(path); if (existing.running) return { started: false, pid: existing.pid, alreadyRunning: true }; await mkdir(dirname(path), { recursive: true }); + const log = logPath || daemonLogPath(path); const args = [entry, "dns", "start", "--port", String(port)]; if (registryBase) args.push("--registry", registryBase); // Passed at spawn time because it is what the resolver answers with, not @@ -385,10 +501,64 @@ export async function startDaemon({ port, registryBase, path = pidfilePath(), en // short of restarting it, which is why `enable` decides this before starting. if (proxy) args.push("--proxy", proxy); - const child = spawn(process.execPath, args, { detached: true, stdio: "ignore" }); + // Truncated rather than appended: the only question this file ever answers is + // "why did the run I just did fail", and a previous crash above this run's + // output is how that question gets answered wrong. + await writeFile(log, ""); + const handle = await open(log, "a"); + let child; + try { + child = spawn(process.execPath, args, { detached: true, stdio: ["ignore", handle.fd, handle.fd] }); + } finally { + // The child holds its own duplicate of the descriptor from spawn onward. + await handle.close(); + } + + // `error` covers the spawn itself failing — execPath gone, not executable — + // which never reaches `exit` at all. + const died = new Promise((resolve) => { + child.once("error", (error) => resolve({ reason: error.message })); + child.once("exit", (code, signal) => resolve({ + reason: signal ? `killed by ${signal}` : `exited ${code} before it could serve`, + code, + signal, + })); + }); + + let gone = null; + let verified = false; + const deadline = Date.now() + readyTimeoutMs; + while (Date.now() < deadline) { + gone = await Promise.race([died, sleep(POLL_MS).then(() => null)]); + if (gone) break; + if (await probe({ host, port })) { + verified = true; + break; + } + } + child.unref(); + + if (gone) { + // No pidfile for a process that is not there. Writing one anyway is what + // made the next `enable` believe a bridge was running and skip starting one. + await rm(path, { force: true }); + return { + started: false, + alreadyRunning: false, + pid: null, + error: gone.reason, + log: await readLogTail(log), + logPath: log, + }; + } + await writeFile(path, `${child.pid}\n`); - return { started: true, pid: child.pid, alreadyRunning: false }; + // `verified: false` is a process that is alive but had not answered by the + // deadline — a slow registry fetch on a slow link, most often. Reported as + // what it is rather than rounded up to success or down to failure: killing a + // bridge that was merely still waking up would be the worse mistake. + return { started: true, pid: child.pid, alreadyRunning: false, verified, logPath: log }; } export async function stopDaemon(path = pidfilePath()) { diff --git a/src/dns.mjs b/src/dns.mjs index 4bccea9..c2d6e91 100644 --- a/src/dns.mjs +++ b/src/dns.mjs @@ -2892,11 +2892,43 @@ export async function dnsCommand(args = [], out = console.log, deps = {}) { // too rather than pinning the answer to one family. proxy: proxyAddress ? (proxyAddress.v4 || proxyAddress.v6) : null, }); + // The routing this is about to install is catch-all — every lookup on the + // machine, not just Moshpit ones — so a bridge that did not come up is not + // a degraded feature, it is the machine's resolver pointed at nothing. + // Refused here, before the drop-in is written, because the alternative was + // discovering it from a box that could no longer resolve its own package + // mirror. Nothing has been changed at this point except the restore point, + // which is removed on the way out. + if (!started.reused && !started.alreadyRunning && !started.started) { + out(` FAIL bridge did not start on ${DEFAULT_HOST}:${wanted} — ${started.error}`); + if (started.log) { + out(""); + for (const line of started.log.split("\n")) out(` ${line}`); + } + out(""); + out("Refusing to route this machine's DNS at a bridge that is not running."); + out("Nothing has been changed."); + if (started.logPath) out(` the daemon's output is at ${started.logPath}`); + out(` to watch it start in the foreground: moshcode dns start --port ${wanted}`); + if (recorded2.ok) await applyPlan({ steps: [{ kind: "remove", path: manifestFile, why: "the switch never happened" }] }); + return 1; + } out(started.reused ? ` ok using the bridge already on ${DEFAULT_HOST}:${wanted} (pid ${reusing.pid || "?"}) — not starting a second one` : started.alreadyRunning ? ` ok bridge already running (pid ${started.pid})` - : ` ok bridge started on ${DEFAULT_HOST}:${wanted} (pid ${started.pid})`); + : started.verified === true + ? ` ok bridge started on ${DEFAULT_HOST}:${wanted} (pid ${started.pid}) — answering` + : ` ok bridge started on ${DEFAULT_HOST}:${wanted} (pid ${started.pid})`); + // Alive, but it had not answered a query by the deadline. Said out loud + // rather than swallowed: if the routing below fails to verify, this line is + // the reason, and it is cheaper to read it here than to derive it later. + // Strictly `false`, never merely absent: a starter that does not report on + // verification has not failed it, and rounding the two together would print + // a warning about every bridge that was started by something else. + if (started.started && started.verified === false) { + out(` -- it has not answered a query yet — still starting, or it will not serve`); + } const outcome = await applyWith(plan, { verify: () => verify({ moshpit: moshpitProbe }), diff --git a/test/dns-daemon-verify.test.mjs b/test/dns-daemon-verify.test.mjs new file mode 100644 index 0000000..755a6c0 --- /dev/null +++ b/test/dns-daemon-verify.test.mjs @@ -0,0 +1,307 @@ +// What `startDaemon` is allowed to call a started bridge. +// +// It used to spawn with `stdio: "ignore"`, write the pidfile from `child.pid`, +// and return `started: true` in the same tick — before the child had done +// anything at all, including exist. On a machine where the daemon dies on +// startup that produced `ok bridge started (pid 22900)` for a process that was +// already gone, and then `enable` installed catch-all routing (`Domains=~.`) +// pointing every lookup on the box at a dead port. The machine lost DNS +// entirely, and the reason was unrecoverable: the daemon wrote it to stderr, +// which had been routed to /dev/null. +// +// Observed on a Kubuntu desktop whose node comes from mise — under the sudo +// that `enable` escalates to, the interpreter was not where the daemon needed +// it. That specific cause matters less than the class: every startup failure +// arrived as the same confident success line. +// +// So the contract is: an early exit is a failed start that carries what the +// daemon said, no pidfile is left behind for a process that is not there, and +// "started" means it answered a query — or says plainly that it has not yet. +import test from "node:test"; +import assert from "node:assert/strict"; +import { mkdtemp, readFile, writeFile } from "node:fs/promises"; +import { existsSync } from "node:fs"; +import { tmpdir } from "node:os"; +import { join } from "node:path"; + +import { daemonStatus, isAlive, startDaemon } from "../src/dns-system.mjs"; +import { dnsCommand } from "../src/dns.mjs"; + +/** A fake `entry` — startDaemon runs `node dns start --port N`. */ +async function entryScript(dir, name, body) { + const path = join(dir, name); + await writeFile(path, body); + return path; +} + +const scratch = () => mkdtemp(join(tmpdir(), "moshcode-daemon-")); + +// Everything here binds an ephemeral port, so nothing collides with a real +// bridge on 5354 or with a parallel run of this file. +const somePort = () => 20000 + Math.floor(Math.random() * 20000); + +/** Dies on startup, the way a missing interpreter or a bad install does. */ +const DIES = ` +process.stderr.write("moshcode: node not on PATH — re-run installer\\n"); +process.exit(127); +`; + +/** Binds the port it was given and answers anything, i.e. a working bridge. */ +const SERVES = ` +import dgram from "node:dgram"; +const port = Number(process.argv[process.argv.indexOf("--port") + 1]); +const socket = dgram.createSocket("udp4"); +socket.on("message", (msg, from) => { + const reply = Buffer.from(msg); + reply.writeUInt16BE(0x8183, 2); // a response, NXDOMAIN — any reply proves it serves + socket.send(reply, from.port, from.address); +}); +socket.bind(port, "127.0.0.1"); +setTimeout(() => process.exit(0), 15000); // never outlive the test run +`; + +/** Alive, but never binds — the "still waking up" case. */ +const SILENT = ` +setTimeout(() => process.exit(0), 15000); +`; + +const reap = (pid) => { + try { + if (pid) process.kill(pid, "SIGKILL"); + } catch { + // Already gone, which is the outcome we wanted anyway. + } +}; + +/* --------------------------------------------- a daemon that does not survive */ + +test("a daemon that exits on startup is a failed start, not a started one", async () => { + const dir = await scratch(); + const path = join(dir, "moshpit-dns.pid"); + const result = await startDaemon({ + port: somePort(), + entry: await entryScript(dir, "dies.mjs", DIES), + path, + readyTimeoutMs: 3000, + }); + + assert.equal(result.started, false, "it did not start; saying otherwise is the bug"); + assert.equal(result.alreadyRunning, false); + assert.equal(result.pid, null, "there is no pid to report for a process that is gone"); + assert.match(result.error, /exited 127/); +}); + +test("a failed start hands back what the daemon wrote before it died", async () => { + const dir = await scratch(); + const result = await startDaemon({ + port: somePort(), + entry: await entryScript(dir, "dies.mjs", DIES), + path: join(dir, "moshpit-dns.pid"), + readyTimeoutMs: 3000, + }); + + // The whole point of the change. Under `stdio: "ignore"` this text existed + // for a few milliseconds and then nowhere, on any disk, ever. + assert.match(result.log, /node not on PATH/); + assert.equal( + await readFile(result.logPath, "utf8").then((t) => t.includes("node not on PATH")), + true, + "and it is still on disk afterwards, for whoever reads the failure later", + ); +}); + +test("a daemon that died leaves no pidfile claiming it is running", async () => { + const dir = await scratch(); + const path = join(dir, "moshpit-dns.pid"); + await startDaemon({ + port: somePort(), + entry: await entryScript(dir, "dies.mjs", DIES), + path, + readyTimeoutMs: 3000, + }); + + assert.equal(existsSync(path), false, "a pidfile for a dead process is what makes the next run skip starting one"); + const status = await daemonStatus(path); + assert.deepEqual(status, { running: false, pid: null, stale: false }); +}); + +test("a spawn that cannot run at all is reported, not thrown", async () => { + // No `exit` event ever fires for this one — the failure is on the spawn + // itself, which is why the error listener exists alongside it. + const dir = await scratch(); + const result = await startDaemon({ + port: somePort(), + entry: join(dir, "nothing.mjs"), + path: join(dir, "moshpit-dns.pid"), + readyTimeoutMs: 3000, + }); + assert.equal(result.started, false); + assert.equal(typeof result.error, "string"); +}); + +/* ------------------------------------------------- a daemon that does survive */ + +test("a bridge that answers is started, verified, and recorded", async () => { + const dir = await scratch(); + const path = join(dir, "moshpit-dns.pid"); + const result = await startDaemon({ + port: somePort(), + entry: await entryScript(dir, "serves.mjs", SERVES), + path, + readyTimeoutMs: 5000, + }); + + try { + assert.equal(result.started, true); + assert.equal(result.verified, true, "it answered a real query on the port — that is what verified means"); + assert.equal(isAlive(result.pid), true); + assert.equal((await readFile(path, "utf8")).trim(), String(result.pid)); + assert.equal((await daemonStatus(path)).running, true); + } finally { + reap(result.pid); + } +}); + +test("a bridge that is alive but silent is started and says it is unproven", async () => { + const dir = await scratch(); + const result = await startDaemon({ + port: somePort(), + entry: await entryScript(dir, "silent.mjs", SILENT), + path: join(dir, "moshpit-dns.pid"), + readyTimeoutMs: 600, + }); + + try { + // Deliberately not a failure: a slow registry fetch on a slow link looks + // exactly like this, and killing a bridge that was merely still waking up + // is the worse of the two mistakes. + assert.equal(result.started, true); + assert.equal(result.verified, false); + } finally { + reap(result.pid); + } +}); + +/* ------------------------------------------------------------------ controls */ + +/* ------------------------------- what `enable` does with a bridge that failed */ + +// Same shape as the harness in dns-enable-rollback.test.mjs: the decision is +// what is under test, and none of it should need root or a real resolver. +function noSystem() { + return { + tlds: async () => ["eggs", "hacker"], + safety: async () => ({ safe: true, upstreams: ["1.1.1.1"], why: "no bridge is running yet — this one will be ours" }), + preflight: async () => ({ ok: true, blockers: [], conflicts: [], holder: null }), + verify: async () => ({ ok: true, checks: [] }), + bridgeStatus: async () => ({ running: false, pid: null, stale: false }), + findLocalProxyImpl: async () => ({ found: false, why: null, address: { v4: null, v6: null } }), + startBridge: async () => ({ started: true, pid: 1, alreadyRunning: false }), + stopBridge: async () => ({ stopped: true, reason: null }), + dropins: async () => [], + readManifest: async () => null, + uid: 0, + }; +} + +test("enable refuses to route the machine at a bridge that did not start", async () => { + const dir = await scratch(); + const lines = []; + let applied = false; + const code = await dnsCommand(["enable"], (l) => lines.push(String(l)), { + ...noSystem(), + manifestFile: join(dir, "dns-restore.json"), + startBridge: async () => ({ + started: false, + alreadyRunning: false, + pid: null, + error: "exited 127 before it could serve", + log: "moshcode: node not on PATH — re-run installer", + logPath: join(dir, "moshpit-dns.log"), + }), + applyWith: async () => { + applied = true; + return { saved: { ok: true }, applied: { ok: true, results: [] }, verified: { ok: true, checks: [] }, rolledBack: null, backups: [] }; + }, + }); + const out = lines.join("\n"); + + assert.equal(code, 1); + // The routing is catch-all. Writing it against a dead bridge is not a + // degraded feature, it is the machine's resolver pointed at nothing — which + // is exactly how a desktop lost DNS entirely and could not look up the fix. + assert.equal(applied, false, "nothing may be written once the bridge is known to be down"); + assert.match(out, /FAIL bridge did not start on 127\.0\.0\.1:5354 — exited 127/); + assert.match(out, /node not on PATH/, "the daemon's own words, which used to go to /dev/null"); + assert.match(out, /Refusing to route this machine's DNS at a bridge that is not running/); + assert.match(out, /Nothing has been changed/); + // Somewhere to go next that does not require guessing. + assert.match(out, /moshcode dns start --port 5354/); +}); + +test("a refused enable does not leave the restore point it recorded", async () => { + const dir = await scratch(); + const manifestFile = join(dir, "dns-restore.json"); + await dnsCommand(["enable"], () => {}, { + ...noSystem(), + manifestFile, + startBridge: async () => ({ started: false, alreadyRunning: false, pid: null, error: "exited 1 before it could serve", log: "", logPath: null }), + }); + // It is recorded before the bridge is started, so a refusal has to take it + // back — a manifest describing a switch that never happened would be replayed + // by the next `disable` against a machine it does not describe. + assert.equal(existsSync(manifestFile), false); +}); + +test("a bridge that answered says so; one that has not is flagged, not refused", async () => { + const dir = await scratch(); + const answering = []; + await dnsCommand(["enable"], (l) => answering.push(String(l)), { + ...noSystem(), + manifestFile: join(dir, "a.json"), + startBridge: async () => ({ started: true, pid: 77, alreadyRunning: false, verified: true }), + applyWith: async () => ({ saved: { ok: true }, applied: { ok: true, results: [] }, verified: { ok: true, checks: [] }, rolledBack: null, backups: [] }), + }); + assert.match(answering.join("\n"), /bridge started on 127\.0\.0\.1:5354 \(pid 77\) — answering/); + + const silent = []; + const code = await dnsCommand(["enable"], (l) => silent.push(String(l)), { + ...noSystem(), + manifestFile: join(dir, "b.json"), + startBridge: async () => ({ started: true, pid: 78, alreadyRunning: false, verified: false }), + applyWith: async () => ({ saved: { ok: true }, applied: { ok: true, results: [] }, verified: { ok: true, checks: [] }, rolledBack: null, backups: [] }), + }); + // Alive but unproven is not a failure — a slow registry fetch looks like this. + assert.equal(code, 0); + assert.match(silent.join("\n"), /has not answered a query yet/); +}); + +test("a starter that does not report on verification is not accused of failing it", async () => { + // `verified` absent means "this starter does not check", which is every + // injected stub and every reused holder. Rounding that to false would print a + // warning about bridges that are working fine. + const dir = await scratch(); + const lines = []; + await dnsCommand(["enable"], (l) => lines.push(String(l)), { + ...noSystem(), + manifestFile: join(dir, "c.json"), + applyWith: async () => ({ saved: { ok: true }, applied: { ok: true, results: [] }, verified: { ok: true, checks: [] }, rolledBack: null, backups: [] }), + }); + assert.doesNotMatch(lines.join("\n"), /has not answered a query yet/); +}); + +/* ------------------------------------------------------------------ controls */ + +test("an already-running daemon still short-circuits without spawning", async () => { + const dir = await scratch(); + const path = join(dir, "moshpit-dns.pid"); + await writeFile(path, `${process.pid}\n`); // alive by definition + + const result = await startDaemon({ + port: somePort(), + entry: join(dir, "never-run.mjs"), + path, + readyTimeoutMs: 3000, + }); + assert.deepEqual(result, { started: false, pid: process.pid, alreadyRunning: true }); +});