mesh-lab/src/log.ts

/**
 * 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) + "…";
}