Say what the lab is doing, while it is doing it
novox/hq 04-ISSUES/024. A run stalled for thirty-five minutes and said nothing. The cause was a link systemd was still configuring, three layers down inside a `docker load` blocked on a socket — and every one of those layers knew what it was waiting for. None of them said so. Three decisions, each 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 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. Anything outstanding past fifteen seconds reports itself with how long it has been going. It is reported as still running, not as stuck — which it is is not knowable from there, and a log that calls a slow step a hang teaches people to ignore it. **It goes to a file, written synchronously.** Node block-buffers stdout when redirected and a test runner buffers it again, so a console log can sit minutes behind. `appendFileSync` cannot lag. Two things this found in itself while being written, both the same shape as what it exists to catch: A question that answers no is not a fault. Half the lab's commands are questions — does this network exist, is the agent up yet — and they fail constantly while a scenario comes up. Logging those as faults filled a healthy run with ✗, which is how you end up ignoring ✗ when one is real. They are recorded quietly now, and still recorded. And `around` skipped its own wrapper when a step's level was below the configured one — taking the failure line and the heartbeat with it. The two things worth having at a low level were the two that vanished at exactly the level somebody would use. The gate belongs in `write`. Also unsilences the four call sites that passed a callback throwing everything away, including the one the stall sat in, and tees `raise`'s progress into the file whether or not a caller asked to see it — the end-to-end test passed no callback, so the one run that mattered reported not a single step.
This commit is contained in:
@@ -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
|
||||
|
||||
+29
-1
@@ -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<IncusResult> {
|
||||
// **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<IncusResult> {
|
||||
return around(`incus ${shorten(args)}`, () => run(args, timeoutMs), {
|
||||
heartbeatMs: 15_000,
|
||||
expectedToFail,
|
||||
});
|
||||
}
|
||||
|
||||
function run(args: string[], timeoutMs: number): Promise<IncusResult> {
|
||||
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<IncusRe
|
||||
child.on("close", (code) => {
|
||||
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<IncusRe
|
||||
*/
|
||||
export async function incusOk(args: string[], timeoutMs = 60_000): Promise<string | null> {
|
||||
try {
|
||||
return (await incus(args, timeoutMs)).stdout;
|
||||
return (await invoke(args, timeoutMs, true)).stdout;
|
||||
} catch {
|
||||
return null;
|
||||
}
|
||||
|
||||
@@ -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 });
|
||||
});
|
||||
});
|
||||
|
||||
+41
-14
@@ -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<RaisedScenario> {
|
||||
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<string, string>();
|
||||
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<ReturnType<typeof raiseRegistry>> = 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 {
|
||||
|
||||
@@ -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<void> {
|
||||
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
|
||||
|
||||
@@ -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) {
|
||||
|
||||
+163
@@ -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<Level, number> = { 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<T>(
|
||||
what: string,
|
||||
run: () => Promise<T>,
|
||||
options: { heartbeatMs?: number; at?: Level; expectedToFail?: boolean } = {},
|
||||
): Promise<T> {
|
||||
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) + "…";
|
||||
}
|
||||
@@ -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);
|
||||
});
|
||||
Reference in New Issue
Block a user