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); });