mesh-lab/test/log.test.ts

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