diff --git a/README.md b/README.md index 67eba59..39a6014 100644 --- a/README.md +++ b/README.md @@ -165,6 +165,27 @@ If it says the daemon is not reachable, the group grant postdates the shell. `ne but a heredoc into `newgrp` runs the suite as a child of a shell that then exits — start it with `setsid nohup … &` inside the heredoc, or the run dies with the shell that launched it. +## When something takes too long + +```sh +export MESH_LAB_LOG=info # or debug, or trace +export MESH_LAB_LOG_FILE=/tmp/lab.log # unset writes to stderr +``` + +| level | what it adds | +|---|---| +| `info` | each step of a raise, with how long the previous one took; anything that failed; **and a line every 15s naming whatever is still running** | +| `debug` | every command the lab runs — incus, docker, and anything local — with its duration, and the stderr of anything that failed | +| `trace` | what those commands printed | + +**The heartbeat is the point.** A stall is a command that started and has not finished, and the +only thing separating it from ordinary work is how long it has been going — which nothing can tell +you unless something is still counting. At `info` a run says `… docker load -i /tmp/image.tar — +still running after 45s` while it happens, rather than nothing until it gives up. + +Written with `appendFileSync`, so unlike a redirected stdout it cannot lag behind the run. It is +off unless asked for. + **A redirected log lags, so do not diagnose a stall from it.** Node block-buffers stdout when it is a file rather than a terminal, so `> run.log` can sit unchanged for minutes while the run is working normally. On 2026-09-01 that was read as a stall twice, once after a real stall had just diff --git a/src/incus/client.ts b/src/incus/client.ts index 070fc96..31d9e66 100644 --- a/src/incus/client.ts +++ b/src/incus/client.ts @@ -13,6 +13,8 @@ import { spawn } from "node:child_process"; +import { around, log, shorten } from "../log.ts"; + /** * How to invoke incus. Overridable because the socket is group-owned and a session that * predates the group grant cannot reach it — which is a real thing that happens on the @@ -52,6 +54,27 @@ export class IncusError extends Error { * that worked perfectly when typed. */ export async function incus(args: string[], timeoutMs = 60_000): Promise { + // **Every command through here is recorded** (novox/hq 04-ISSUES/024). This is one of three + // places the lab runs an external program, and ninety-odd call sites reach a hypervisor through + // it — so logging here covers all of them and none of them has to remember to. + return invoke(args, timeoutMs, false); +} + +/** + * `expectedToFail` is not about this command; it is about the caller. + * + * `incus` rejects and the caller is expected to care. `incusOk` and `succeeds` turn a failure into + * an answer — *does this network exist*, *is the agent up yet* — and those are asked constantly + * while a scenario comes up. Recording them as faults fills a healthy run with ✗. + */ +function invoke(args: string[], timeoutMs: number, expectedToFail: boolean): Promise { + return around(`incus ${shorten(args)}`, () => run(args, timeoutMs), { + heartbeatMs: 15_000, + expectedToFail, + }); +} + +function run(args: string[], timeoutMs: number): Promise { const [command, ...prefix] = INCUS; if (!command) throw new Error("MESH_LAB_INCUS is empty"); @@ -80,10 +103,15 @@ export async function incus(args: string[], timeoutMs = 60_000): Promise { clearTimeout(timer); if (timedOut) { + // Said explicitly. A SIGKILL leaves an empty stderr, so without this the failure arrives + // with no explanation at all — which is how the first raise reported "(no output)". + log.info(`incus ${shorten(args)} was killed after ${timeoutMs}ms`); reject(new IncusError(args, `timed out after ${timeoutMs}ms`, null)); } else if (code === 0) { + if (stdout.trim()) log.trace(` stdout: ${shorten([stdout.trim()], 400)}`); resolve({ stdout, stderr }); } else { + log.debug(` exit ${code}: ${shorten([stderr.trim() || "(nothing on stderr)"], 400)}`); reject(new IncusError(args, stderr, code)); } }); @@ -105,7 +133,7 @@ export async function incus(args: string[], timeoutMs = 60_000): Promise { try { - return (await incus(args, timeoutMs)).stdout; + return (await invoke(args, timeoutMs, true)).stdout; } catch { return null; } diff --git a/src/lifecycle/place.ts b/src/lifecycle/place.ts index 6763e61..eb245a6 100644 --- a/src/lifecycle/place.ts +++ b/src/lifecycle/place.ts @@ -18,6 +18,7 @@ import { tmpdir } from "node:os"; import { join } from "node:path"; import { incus, incusOk, succeeds } from "../incus/client.ts"; +import { around, log, shorten } from "../log.ts"; /** * What this stage can put inside a machine. @@ -322,6 +323,18 @@ function local( command: string, args: string[], timeoutMs: number, +): Promise<{ ok: boolean; stdout: string; stderr: string }> { + // The third and last place the lab runs an external program (novox/hq 04-ISSUES/024). + // `docker save` of a large image is the slowest single thing a raise does. + return around(`${command} ${shorten(args)}`, () => runLocal(command, args, timeoutMs), { + heartbeatMs: 15_000, + }); +} + +function runLocal( + command: string, + args: string[], + timeoutMs: number, ): Promise<{ ok: boolean; stdout: string; stderr: string }> { return new Promise((resolve) => { const child = spawn(command, args, { stdio: ["ignore", "pipe", "pipe"] }); @@ -336,6 +349,9 @@ function local( }); child.on("close", (code) => { clearTimeout(timer); + if (code !== 0) { + log.debug(` exit ${code}: ${shorten([stderr.trim() || "(nothing on stderr)"], 400)}`); + } resolve({ ok: code === 0, stdout, stderr }); }); }); diff --git a/src/lifecycle/raise.ts b/src/lifecycle/raise.ts index 34dcd86..3cb4374 100644 --- a/src/lifecycle/raise.ts +++ b/src/lifecycle/raise.ts @@ -25,6 +25,7 @@ import { applyHostFirewalls } from "./firewall.ts"; import { IMAGE_PREFIX, BASE_IMAGE_ALIAS, BASE_IMAGE_HOWTO, planPlacements, applyPlacements } from "./place.ts"; import { baseImageExists, UPSTREAM_IMAGE } from "./base.ts"; import { discardStock, raiseRegistry, stockRegistry } from "./registry.ts"; +import { log as record } from "../log.ts"; /** Drivers whose snapshots are copy-on-write. On `dir` a snapshot is a full copy. */ const COW_DRIVERS = ["btrfs", "zfs"]; @@ -174,7 +175,19 @@ export async function raise( scenario: Scenario, options: RaiseOptions = {}, ): Promise { - const log = options.onProgress ?? (() => {}); + // **Progress always reaches the file, whether or not anyone asked to see it.** + // + // This used to be the caller's callback or nothing, and every function below takes its `log` + // from here — so a caller that passed none silenced the whole lifecycle. That is exactly what + // happened: the end-to-end test called `raise` with no callback, so the one run that mattered + // reported not a single step (novox/hq 04-ISSUES/024). + // + // Teeing rather than replacing: the caller still gets what it asked for, and the record is kept + // regardless. A record nobody switched on is the one you want after the thing goes wrong. + const log = (message: string): void => { + record.info(message); + options.onProgress?.(message); + }; // A scenario that places a runtime or an image needs machines built from the base image, // because a sealed machine cannot install one (novox/hq ADR 0006). Chosen here rather than @@ -198,19 +211,33 @@ export async function raise( // has been created, and there is no wreckage to leave standing. assertSupported(scenario); - let step = "choosing a storage pool"; + // **The step is the log.** Setting it and recording it are one act, so a step added later + // cannot be a step that goes unrecorded — which is the drift that made a thirty-five minute + // stall untraceable (novox/hq 04-ISSUES/024). Each entry closes the previous one with its + // duration, so the log says where a raise spends its time as well as where it stopped. + let step = ""; + let stepFrom = Date.now(); + const enter = (next: string): string => { + if (step) record.info(` ${step} — ${((Date.now() - stepFrom) / 1000).toFixed(1)}s`); + record.info(`▶ ${next}`); + stepFrom = Date.now(); + step = next; + return next; + }; + + enter("choosing a storage pool"); try { const pool = await choosePool(log); log(`instance ${instanceId} pool ${pool}`); - step = "creating segments"; + enter("creating segments"); const networks: string[] = []; for (const [segment, spec] of Object.entries(scenario.segments)) { networks.push(await createNetwork(instanceId, segment, spec)); log(` segment ${segment}`); } - step = "creating machines"; + enter("creating machines"); const created: string[] = []; const byMachine = new Map(); for (const [machine, spec] of Object.entries(scenario.machines)) { @@ -221,32 +248,32 @@ export async function raise( log(` machine ${machine}${spec.at === "detached" ? " (detached)" : ""}`); } - step = "starting machines"; + enter("starting machines"); for (const name of created) { await succeeds(["start", name], 60_000); } - step = "waiting for machines to become usable"; + enter("waiting for machines to become usable"); await waitUntilAllUsable(created, readyTimeout, log); - step = "applying declared addresses"; + enter("applying declared addresses"); await applyAddresses(scenario, instanceId, byMachine, log); // Transit first: a gateway's default route points at it, so it has to exist. - step = "wiring the public networks together"; + enter("wiring the public networks together"); const transit = await raiseTransit(scenario, instanceId, log); - step = "raising routers"; + enter("raising routers"); const routers = await raiseRouters(scenario, instanceId, planRouters(scenario, instanceId), log); if (transit) routers.push(transit); // Stocked on this workstation, where there is a network, and served from inside the // scenario, where there is not (novox/hq 04-ISSUES/009). - step = "stocking the registry"; + enter("stocking the registry"); const stock = await stockRegistry(scenario.images ?? [], log); let registry: Awaited> = null; try { - step = "raising the registry"; + enter("raising the registry"); registry = await raiseRegistry(scenario, instanceId, stock, log); } finally { // Cleaning up scratch must not fail a raise that succeeded. The scenario is standing @@ -258,17 +285,17 @@ export async function raise( } } - step = "routing machines through their gateways"; + enter("routing machines through their gateways"); await applyDefaultRoutes(scenario, byMachine, log); // Last: a machine that refuses inbound must still have been reachable while the lab // was configuring it. - step = "applying host firewalls"; + enter("applying host firewalls"); await applyHostFirewalls(scenario, byMachine, log); // Last, and only once the underlay is real. Placing before the machines can reach each // other would test the host against a network the scenario does not describe. - step = "placing"; + enter("placing"); await applyPlacements(scenario, byMachine, log); return { diff --git a/src/lifecycle/registry.ts b/src/lifecycle/registry.ts index 287120b..4daefd8 100644 --- a/src/lifecycle/registry.ts +++ b/src/lifecycle/registry.ts @@ -23,6 +23,7 @@ import { spawn } from "node:child_process"; import { incus, incusOk, succeeds } from "../incus/client.ts"; import { macFor, networkName } from "./names.ts"; import { addressLink } from "./address.ts"; +import { around, log, shorten } from "../log.ts"; import { BASE_IMAGE_ALIAS, placeImage } from "./place.ts"; import { mkdtemp, rm } from "node:fs/promises"; import { tmpdir } from "node:os"; @@ -171,6 +172,16 @@ async function waitForRegistry(port: number): Promise { function docker( args: string[], timeoutMs: number, +): Promise<{ ok: boolean; stdout: string; stderr: string }> { + // The second of the three places the lab runs an external program (novox/hq 04-ISSUES/024). + // `docker push` of a large image is minutes of legitimate silence, which is exactly when a + // heartbeat earns its keep. + return around(`docker ${shorten(args)}`, () => runDocker(args, timeoutMs), { heartbeatMs: 15_000 }); +} + +function runDocker( + args: string[], + timeoutMs: number, ): Promise<{ ok: boolean; stdout: string; stderr: string }> { return new Promise((resolve) => { const child = spawn("docker", args, { stdio: ["ignore", "pipe", "pipe"] }); @@ -185,6 +196,11 @@ function docker( }); child.on("close", (code) => { clearTimeout(timer); + // A docker failure is an answer here rather than an exception, so it would otherwise pass + // through the log looking exactly like a success. + if (code !== 0) { + log.debug(` exit ${code}: ${shorten([stderr.trim() || "(nothing on stderr)"], 400)}`); + } resolve({ ok: code === 0, stdout, stderr }); }); }); @@ -321,7 +337,9 @@ export async function raiseRegistry( // The registry's own image, placed by tag — an archive keeps a tag and cannot keep a digest, // which is the whole reason this machine exists. - await placeImage(name, "registry", REGISTRY_IMAGE, () => {}); + // Logged, not silenced. This is the step a stall sat in for thirty-five minutes while the + // caller had passed it a callback that threw everything away (novox/hq 04-ISSUES/024). + await placeImage(name, "registry", REGISTRY_IMAGE, log); // The destination must EXIST before a recursive push, or incus copies the source's contents // rather than the source — the data lands one directory too shallow, the registry finds diff --git a/src/lifecycle/router.ts b/src/lifecycle/router.ts index 4d619d4..7fc62a4 100644 --- a/src/lifecycle/router.ts +++ b/src/lifecycle/router.ts @@ -62,7 +62,7 @@ export async function ensureRouterImage(log: (message: string) => void = () => { // Default profile on purpose: this is the one container that needs to reach a repository. await incus(["launch", ROUTER_BASE, builder], 300_000); - await waitUntilUsable(builder, 120, () => {}); + await waitUntilUsable(builder, 120, log); // `exec` works before the container has an address. Usable means a command runs; it does // not mean the network is up, and the first attempt failed on DNS because those were @@ -279,7 +279,7 @@ export async function raiseTransit( } } await succeeds(["start", name], 60_000); - await waitUntilUsable(name, 120, () => {}); + await waitUntilUsable(name, 120, log); for (const [index, segment] of publicSegments.entries()) { const device = `eth${index}`; @@ -343,7 +343,7 @@ export async function raiseRouters( } for (const name of created) { - await waitUntilUsable(name, 120, () => {}); + await waitUntilUsable(name, 120, log); } for (const plan of plans) { diff --git a/src/log.ts b/src/log.ts new file mode 100644 index 0000000..179ae71 --- /dev/null +++ b/src/log.ts @@ -0,0 +1,163 @@ +/** + * What the lab was doing, written down while it does it. + * + * **The lab's own recurring fault, and the one it exists to catch elsewhere.** On 2026-09-01 a run + * stalled for thirty-five minutes and said nothing at all. The cause was a link that systemd was + * still configuring, three layers down inside a `docker load` that was blocked on a socket — and + * every one of those layers knew what it was waiting for. None of them said so + * (novox/hq 04-ISSUES/024). + * + * Three decisions follow from that, and each is doing work: + * + * **Every external command is logged, at the three places that run one.** Ninety-seven call sites + * reach a hypervisor or a container runtime through three wrappers, so instrumenting the wrappers + * covers all of them and nothing has to remember to log. + * + * **A command that is still running says so while it runs.** A line before and a line after tells + * you nothing until the after arrives, which is exactly the case that matters. So a command + * outstanding past a few seconds reports itself periodically, with how long it has been going. + * *"I cannot see progress" is not evidence of no progress* — but it should not be the only thing + * available either. + * + * **It goes to a file, written synchronously.** Node block-buffers stdout when it is redirected, + * and a test runner buffers it again, so a console log can sit minutes behind the run. That was + * read as a stall twice in one day — the second time straight after the real fix, where a + * buffering artifact argues the fix did not work. `appendFileSync` cannot lag. + */ + +import { appendFileSync, mkdirSync } from "node:fs"; +import { dirname } from "node:path"; + +/** How much to say. `off` writes nothing at all, for a caller that wants none of this. */ +export type Level = "off" | "info" | "debug" | "trace"; + +const ORDER: Record = { off: 0, info: 1, debug: 2, trace: 3 }; + +/** + * Where the log goes, and how much of it. + * + * Off unless asked for, because a suite that writes a debug log nobody reads is a suite that + * writes a debug log nobody reads. `MESH_LAB_LOG` turns it on; `MESH_LAB_LOG_FILE` says where. + */ +function configured(): { level: Level; file: string | null } { + const asked = (process.env["MESH_LAB_LOG"] ?? "").trim().toLowerCase(); + const level: Level = asked === "info" || asked === "debug" || asked === "trace" ? asked : "off"; + const file = process.env["MESH_LAB_LOG_FILE"]?.trim() || null; + return { level, file }; +} + +let level: Level = configured().level; +let file: string | null = configured().file; +const started = Date.now(); +let opened = false; + +/** Re-read the environment. For a test, and for a caller that sets it after import. */ +export function reconfigure(): void { + const now = configured(); + level = now.level; + file = now.file; + opened = false; +} + +/** Point the log somewhere explicitly, whatever the environment says. */ +export function logTo(path: string | null, at: Level = "debug"): void { + file = path; + level = path === null ? "off" : at; + opened = false; +} + +function elapsed(): string { + return ((Date.now() - started) / 1000).toFixed(1).padStart(7) + "s"; +} + +/** + * Write one line, synchronously. + * + * A failure to write is swallowed. A log that cannot be written is a nuisance; a run that dies + * because its log could not be written is a fault the log invented. + */ +function write(at: Level, message: string): void { + if (level === "off" || ORDER[at] > ORDER[level]) return; + const line = `${new Date().toISOString()} ${elapsed()} ${at.padEnd(5)} ${message}\n`; + if (!file) { + process.stderr.write(line); + return; + } + try { + if (!opened) { + mkdirSync(dirname(file), { recursive: true }); + opened = true; + } + appendFileSync(file, line); + } catch { + // Nothing sensible to do, and saying so on every line would be worse than silence. + } +} + +export const log = { + info: (message: string) => write("info", message), + debug: (message: string) => write("debug", message), + trace: (message: string) => write("trace", message), + /** Whether anything is being recorded, for a caller deciding whether to compose an expensive message. */ + on: () => level !== "off", +}; + +/** + * Run something, saying what it is and how long it took — and saying so *while* it runs. + * + * The heartbeat is the point. A stall is a command that started and has not finished, and the only + * thing that distinguishes it from ordinary work is how long it has been going — which nothing can + * tell you unless something is still counting. + */ +export async function around( + what: string, + run: () => Promise, + options: { heartbeatMs?: number; at?: Level; expectedToFail?: boolean } = {}, +): Promise { + const at = options.at ?? "debug"; + // Only when nothing at all is being recorded. **Skipping the wrapper whenever the step's own + // level is too low was wrong twice over**: it dropped the failure line, which is logged louder + // than the step precisely so it survives a turned-down log, and it dropped the heartbeat, which + // is the whole reason this function exists. Both went missing at exactly the level somebody + // would actually run — `info`. The gate belongs in `write`, which already has one. + if (level === "off") return run(); + + const beat = options.heartbeatMs ?? 15_000; + const from = Date.now(); + write(at, `→ ${what}`); + + const timer = setInterval(() => { + // **Reported as still running, not as stuck.** Which it is is not knowable from here, and a + // log that calls a slow step a hang teaches people to ignore it. + write("info", `… ${what} — still running after ${((Date.now() - from) / 1000).toFixed(0)}s`); + }, beat); + // Never hold the process open for a heartbeat. + timer.unref?.(); + + try { + const result = await run(); + write(at, `← ${what} (${((Date.now() - from) / 1000).toFixed(1)}s)`); + return result; + } catch (err) { + // Failures are logged at info even when the step was debug: whoever turned logging down still + // wants the thing that went wrong. + // + // **Unless failing is one of the answers.** Plenty of commands here are questions — does this + // network exist, is the agent up yet — and a failure is a no. Logging those as faults fills a + // normal run with ✗ and teaches whoever reads it that ✗ means nothing, which is the state to + // be in when one of them is real. + write(options.expectedToFail ? "debug" : "info", + `${options.expectedToFail ? "·" : "✗"} ${what} ` + + `(${((Date.now() - from) / 1000).toFixed(1)}s): ${(err as Error).message}`); + throw err; + } finally { + clearInterval(timer); + } +} + +/** A command line, shortened for a log without losing which command it was. */ +export function shorten(argv: string[], limit = 200): string { + const whole = argv.join(" "); + if (whole.length <= limit) return whole; + return whole.slice(0, limit - 1) + "…"; +} diff --git a/test/log.test.ts b/test/log.test.ts new file mode 100644 index 0000000..5e68dbf --- /dev/null +++ b/test/log.test.ts @@ -0,0 +1,172 @@ +import { test } from "node:test"; +import assert from "node:assert/strict"; +import { readFileSync, mkdtempSync } from "node:fs"; +import { tmpdir } from "node:os"; +import { join } from "node:path"; + +import { around, log, logTo, shorten } from "../src/log.ts"; + +function intoAFile(): string { + const path = join(mkdtempSync(join(tmpdir(), "mesh-lab-log-")), "run.log"); + logTo(path, "debug"); + return path; +} + +function read(path: string): string { + try { + return readFileSync(path, "utf8"); + } catch { + return ""; + } +} + +// Nothing at all unless asked. A suite that writes a debug log nobody reads is a suite that +// writes a debug log nobody reads. +test("it is off until it is turned on", () => { + const path = join(mkdtempSync(join(tmpdir(), "mesh-lab-log-")), "run.log"); + logTo(null); + log.info("this should go nowhere"); + assert.equal(read(path), ""); + assert.equal(log.on(), false); +}); + +test("what it records says when, and how far into the run", () => { + const path = intoAFile(); + log.info("a thing happened"); + const written = read(path); + assert.match(written, /a thing happened/); + assert.match(written, /^\d{4}-\d{2}-\d{2}T/, `no timestamp:\n${written}`); + assert.match(written, /\d+\.\ds/, `no elapsed time:\n${written}`); + logTo(null); +}); + +test("a level below the one asked for is not written", () => { + const path = join(mkdtempSync(join(tmpdir(), "mesh-lab-log-")), "run.log"); + logTo(path, "info"); + log.info("kept"); + log.debug("dropped"); + log.trace("dropped"); + const written = read(path); + assert.match(written, /kept/); + assert.doesNotMatch(written, /dropped/); + logTo(null); +}); + +// **The assertion this file exists for** (novox/hq 04-ISSUES/024). A line before and a line after +// tells you nothing until the after arrives, which is precisely the case that matters. +test("something still running says so while it runs", async () => { + const path = intoAFile(); + await around("a slow thing", async () => { + await new Promise((r) => setTimeout(r, 250)); + }, { heartbeatMs: 60 }); + const written = read(path); + assert.match(written, /still running after/, + `nothing was said while it ran:\n${written}`); + assert.match(written, /→ a slow thing/); + assert.match(written, /← a slow thing \(0\.\ds\)/, `it did not say how long it took:\n${written}`); + logTo(null); +}); + +// A quick command should not litter the log with heartbeats it never needed. +test("something quick says only that it happened", async () => { + const path = intoAFile(); + await around("a quick thing", async () => "done", { heartbeatMs: 10_000 }); + const written = read(path); + assert.doesNotMatch(written, /still running/); + assert.match(written, /← a quick thing/); + logTo(null); +}); + +// A failure is worth more than a success, so it survives a level that would have dropped it. +test("a failure is recorded even when the step was not", async () => { + const path = join(mkdtempSync(join(tmpdir(), "mesh-lab-log-")), "run.log"); + logTo(path, "info"); + await assert.rejects( + around("a failing thing", async () => { + throw new Error("it did not work"); + }, { at: "info" }), + ); + const written = read(path); + assert.match(written, /✗ a failing thing/, `the failure was not recorded:\n${written}`); + assert.match(written, /it did not work/); + logTo(null); +}); + +test("what it returns is what the step returned", async () => { + logTo(null); + assert.equal(await around("a thing", async () => 42), 42); +}); + +// A command line is identifiable in the log even when it is very long. +test("a long command keeps its beginning", () => { + const long = shorten(["incus", "exec", "machine", "--", "sh", "-c", "x".repeat(500)]); + assert.ok(long.length <= 200, `it is ${long.length} characters`); + assert.match(long, /^incus exec machine/); + assert.match(long, /…$/); +}); + +// A question that answers "no" is not a fault, and must not be logged as one. +// +// Plenty of the lab's commands are questions — does this network exist, is the agent up yet — and +// they fail constantly while a scenario comes up. Recording those as faults fills a healthy run +// with ✗ and teaches whoever reads it that ✗ means nothing. +test("a failure the caller expects is recorded quietly", async () => { + const path = join(mkdtempSync(join(tmpdir(), "mesh-lab-log-")), "run.log"); + logTo(path, "info"); + await assert.rejects( + around("asking whether a thing exists", async () => { + throw new Error("not found"); + }, { expectedToFail: true }), + ); + assert.equal(read(path), "", `an expected answer was reported as a fault:\n${read(path)}`); + + // And it is still there for anyone who turns the log up. + logTo(path, "debug"); + await assert.rejects( + around("asking again", async () => { + throw new Error("not found"); + }, { expectedToFail: true }), + ); + assert.match(read(path), /· asking again/, `it was dropped entirely:\n${read(path)}`); + logTo(null); +}); + +// And a failure nobody expected is still loud at the same level. +test("a failure the caller does not expect is recorded loudly", async () => { + const path = join(mkdtempSync(join(tmpdir(), "mesh-lab-log-")), "run.log"); + logTo(path, "info"); + await assert.rejects( + around("doing a thing", async () => { + throw new Error("it broke"); + }), + ); + assert.match(read(path), /✗ doing a thing/, `a real failure was quiet:\n${read(path)}`); + logTo(null); +}); + +// A turned-down log still shows a failure and still beats while something runs. +// +// **Both were lost, briefly, to an optimisation.** `around` skipped its own wrapper whenever the +// step's level was below the configured one — which is the ordinary case at `info` — taking the +// failure line and the heartbeat with it. The two things worth having at a low level were the two +// that disappeared. +test("at info, a debug step still reports failing and still beats", async () => { + const path = join(mkdtempSync(join(tmpdir(), "mesh-lab-log-")), "run.log"); + logTo(path, "info"); + + await around("a slow debug step", async () => { + await new Promise((r) => setTimeout(r, 200)); + }, { heartbeatMs: 50, at: "debug" }); + assert.match(read(path), /still running after/, `no heartbeat at info:\n${read(path)}`); + + await assert.rejects( + around("a failing debug step", async () => { + throw new Error("it broke"); + }, { at: "debug" }), + ); + assert.match(read(path), /✗ a failing debug step/, `no failure at info:\n${read(path)}`); + + // And the ordinary begin/end pair is still held back, which is what the level asked for. + assert.doesNotMatch(read(path), /→ a slow debug step/); + logTo(null); +});