ci: timestamp the browser lane's test server lines

scripts/ci-browser-parallel.test.ts

@@ -0,0 +1,56 @@
+import { describe, expect, it } from "bun:test";
+import { mkdirSync, mkdtempSync, readFileSync, rmSync, writeFileSync } from "node:fs";
+import { tmpdir } from "node:os";
+import { join } from "node:path";
+import { failureSite } from "./ci-browser-parallel.ts";
+
+describe("parallel browser output timestamps", () => {
+  it("timestamps script log lines without changing status output or summary JSON", async () => {
+    const dir = mkdtempSync(join(tmpdir(), "browser-parallel-test-"));
+    const bin = join(dir, "bin");
+    const logs = join(dir, "browser-logs");
+    mkdirSync(bin);
+    writeFileSync(join(bin, "bash"), '#!/bin/sh\nprintf "/stub/chrome\\\\n"\n', { mode: 0o755 });
+    writeFileSync(join(bin, "bun"), '#!/bin/sh\nif [ "$1" = scripts/demo-build.ts ]; then exit 0; fi\nprintf "PASS stubbed browser step\\\\nFAIL stubbed failure marker\\\\nSERVER listening on 127.0.0.1:4321"\n', { mode: 0o755 });
+    try {
+      const child = Bun.spawn([process.execPath, "scripts/ci-browser-parallel.ts"], {
+        cwd: join(import.meta.dir, ".."),
+        env: {
+          ...process.env,
+          PATH: `${bin}:${process.env.PATH}`,
+          BROWSER_SCRIPTS: "scripts/ui-regression.ts",
+          BROWSER_RETRY: "0",
+          CHECK_DIR: dir,
+        },
+        stdin: "ignore", stdout: "pipe", stderr: "pipe", timeout: 10_000,
+      });
+      const [text, error, code] = await Promise.all([
+        new Response(child.stdout).text(),
+        new Response(child.stderr).text(),
+        child.exited,
+      ]);
+      expect(error).toBe("");
+      expect(code).toBe(0);
+      expect(text).toContain("[worker-0] PASS scripts/ui-regression.ts");
+      const log = readFileSync(join(logs, "ui-regression.log"), "utf8");
+      expect(log).toMatch(/^\[\d{4}-\d\d-\d\dT[^\]]+\] PASS stubbed browser step$/m);
+      expect(log).toMatch(/^\[\d{4}-\d\d-\d\dT[^\]]+\] FAIL stubbed failure marker$/m);
+      expect(log).toMatch(/^\[\d{4}-\d\d-\d\dT[^\]]+\] SERVER listening on 127\.0\.0\.1:4321$/m);
+      expect(failureSite(`${log}[2026-10-23T00:00:00.000Z] AssertionError: stub failure\n[2026-10-23T00:00:00.000Z]     at run (/repo/scripts/ui-regression.ts:1:1)`)).toEqual({
+        site: "scripts/ui-regression.ts:1",
+        message: "AssertionError: stub failure",
+      });
+      expect(text).toContain("Total: 1/1 passed");
+      const summary = readFileSync(join(logs, "summary.json"), "utf8");
+      expect(summary).toContain('"workers": 1');
+      expect(summary).toContain('"passed": 1');
+      expect(summary).toContain('"total": 1');
+      expect(summary).toContain('"flaky": []');
+      expect(summary).toContain('"script": "scripts/ui-regression.ts"');
+      expect(summary).toContain('"code": 0');
+      expect(summary).not.toContain("timestamp");
+    } finally {
+      rmSync(dir, { recursive: true, force: true });
+    }
+  });
+});

scripts/ci-browser-parallel.ts

@@ -15,7 +15,7 @@
  */
 import { availableParallelism } from "node:os";
 import { basename, join } from "node:path";
-import { appendFileSync, closeSync, mkdirSync, mkdtempSync, openSync, readFileSync, renameSync, rmSync, writeFileSync } from "node:fs";
+import { appendFileSync, mkdirSync, mkdtempSync, readFileSync, renameSync, rmSync, writeFileSync } from "node:fs";
 import { tmpdir } from "node:os";
 
 const repo = join(import.meta.dir, "..");
@@ -55,7 +55,7 @@ interface ScriptResult {
  * Either is null when the log does not hold it.
  */
 export function failureSite(log: string): { site: string | null; message: string | null } {
-  const lines = log.split(/\r?\n/);
+  const lines = log.split(/\r?\n/).map((line) => line.replace(/^\[[^\]]+\] /, ""));
   const index = lines.findIndex((line) => /^\s*[A-Za-z_$][\w.$]*Error:/.test(line));
   if (index < 0) return { site: null, message: null };
   const message = lines[index]?.trim() ?? null;
@@ -107,26 +107,38 @@ async function buildDemo(dir: string): Promise<void> {
   console.log(`[setup] Demo build completed in ${((Date.now() - started) / 1000).toFixed(1)}s`);
 }
 
+async function timestampLog(stream: ReadableStream<Uint8Array>, log: string): Promise<void> {
+  let partial = "";
+  const decoder = new TextDecoder();
+  for await (const chunk of stream) {
+    const lines = (partial + decoder.decode(chunk, { stream: true })).split("\n");
+    partial = lines.pop() ?? "";
+    for (const line of lines) appendFileSync(log, `[${new Date().toISOString()}] ${line}\n`);
+  }
+  partial += decoder.decode();
+  if (partial) appendFileSync(log, `[${new Date().toISOString()}] ${partial}\n`);
+}
+
 async function runScript(script: string, env: Record<string, string>, log: string): Promise<ScriptResult> {
   const started = Date.now();
-  const fd = openSync(log, "w");
-  try {
-    const child = Bun.spawn(["bun", script], {
-      cwd: repo,
-      env: { ...process.env, ...env },
-      stdin: "ignore",
-      stdout: fd,
-      stderr: fd,
-    });
-    // A hung script shows up as a repeated line instead of silence.
-    const heartbeat = setInterval(() => {
-      console.log(`[running] ${script} (${Math.round((Date.now() - started) / 1000)}s, log ${log})`);
-    }, HEARTBEAT_MS);
-    const code = await child.exited.finally(() => clearInterval(heartbeat));
-    return { script, seconds: (Date.now() - started) / 1000, code, log };
-  } finally {
-    closeSync(fd);
-  }
+  writeFileSync(log, "");
+  const child = Bun.spawn(["bun", script], {
+    cwd: repo,
+    env: { ...process.env, ...env },
+    stdin: "ignore",
+    stdout: "pipe",
+    stderr: "pipe",
+  });
+  // A hung script shows up as a repeated line instead of silence.
+  const heartbeat = setInterval(() => {
+    console.log(`[running] ${script} (${Math.round((Date.now() - started) / 1000)}s, log ${log})`);
+  }, HEARTBEAT_MS);
+  const [code] = await Promise.all([
+    child.exited.finally(() => clearInterval(heartbeat)),
+    timestampLog(child.stdout, log),
+    timestampLog(child.stderr, log),
+  ]);
+  return { script, seconds: (Date.now() - started) / 1000, code, log };
 }
 
 async function main(): Promise<void> {

scripts/ci-browser.sh

@@ -22,14 +22,19 @@ finish() {
 trap finish EXIT
 
 run_script() {
-  local started=$SECONDS code=0 evidence="${UI_EVIDENCE_DIR:-}"
+  local started=$SECONDS code=0 evidence="${UI_EVIDENCE_DIR:-}" line
   if [ -n "${CI:-}${CHECK_DIR:-}" ]; then
     # These evidence branches add viewport changes, assertions or font waits, not just captures.
     case "$1" in
       scripts/ui-regression.ts|scripts/ui-contexts-regression.ts|scripts/key-bar-customization-demo-regression.ts) evidence="";;
     esac
   fi
-  UI_EVIDENCE_DIR="$evidence" bun "$@" || code=$?
+  UI_EVIDENCE_DIR="$evidence" bun "$@" 2>&1 | while IFS= read -r line || [ -n "$line" ]; do
+    case "$line" in
+      PASS\ *|FAIL\ *) printf '%s\n' "$line";;
+      *) printf '[%s] %s\n' "$(date -Is)" "$line";;
+    esac
+  done || code=$?
   local seconds=$((SECONDS - started))
   printf 'TIMING %s seconds=%s exit=%s\n' "$1" "$seconds" "$code"
   timings="${timings}$(printf '%-60s %7s %5s' "$1" "$seconds" "$code")"$'\n'

scripts/ci-browser.test.ts

@@ -10,7 +10,7 @@ bun() {
     scripts/demo-build.ts) printf 'DEMO_DIR=%s\\n' "$HERDR_DEMO_BUILD";;
     scripts/*)
       [ "\${CHROME_PATH:-}" = /stub/chrome ] || return 91
-      printf 'STEP=%s EVIDENCE=%s\\n' "$1" "\${UI_EVIDENCE_DIR:-}";;
+      printf 'PASS stubbed browser step\\nFAIL stubbed browser marker\\nSERVER listening on http://127.0.0.1:3000\\nSTEP=%s EVIDENCE=%s\\n' "$1" "\${UI_EVIDENCE_DIR:-}";;
   esac
   if [ "$1" = "\${FAIL_SCRIPT:-}" ]; then return 7; fi
 }
@@ -35,7 +35,7 @@ async function lane(fail = "", kept = false, ci = "") {
     });
     const [text, error, code] = await Promise.all([new Response(child.stdout).text(), new Response(child.stderr).text(), child.exited]);
     expect(error).toBe("");
-    const demo = text.match(/^DEMO_DIR=(.+)$/m)?.[1];
+    const demo = text.match(/^\[[^\]]+\] DEMO_DIR=(.+)$/m)?.[1];
     expect(demo).toBeDefined();
     expect(existsSync(demo ?? "")).toBe(false);
     return { text, code, evidence: existsSync(join(dir, kept ? "" : ".ci", "browser-evidence")) };
@@ -63,8 +63,13 @@ describe("browser lane", () => {
       { script: "scripts/herdr-restart-regression.ts", seconds: expect.any(Number), code: 0 },
       { script: "scripts/sticky-modifiers-regression.ts", seconds: expect.any(Number), code: 7 },
     ]);
-    expect(text).not.toContain("STEP=scripts/key-bar-customization-demo-regression.ts");
-    expect(text).toMatch(/scripts\/sticky-modifiers-regression\.ts.*seconds=\d+.*exit=7/);
+    expect(text).not.toMatch(/STEP=scripts\/key-bar-customization-demo-regression\.ts/);
+    expect(text).toMatch(/^TIMING scripts\/sticky-modifiers-regression\.ts seconds=\d+ exit=7$/m);
+    expect(text).toMatch(/^scripts\/sticky-modifiers-regression\.ts\s+\d+\s+7$/m);
+    expect(text).toMatch(/^\[\d{4}-\d\d-\d\dT[^\]]+\] SERVER listening on http:\/\/127\.0\.0\.1:3000$/m);
+    expect(text).toMatch(/^PASS stubbed browser step$/m);
+    expect(text).toMatch(/^FAIL stubbed browser marker$/m);
+    expect(text).toMatch(/^Browser lane total: seconds=\d+ exit=7$/m);
   });
 
   it("summarizes every script and exits zero on success without enabling local evidence", async () => {
@@ -116,24 +121,28 @@ describe("browser lane", () => {
     expect(rows(text).at(-1)?.script).toBe("scripts/herdr-profiles-browser-qa.ts");
     expect(evidence).toBe(false);
     expect(text).not.toMatch(/EVIDENCE=.+/);
+    expect(text).toMatch(/^\[\d{4}-\d\d-\d\dT[^\]]+\] SERVER listening on http:\/\/127\.0\.0\.1:3000$/m);
+    expect(text).toMatch(/^PASS stubbed browser step$/m);
+    expect(text).toMatch(/^FAIL stubbed browser marker$/m);
   });
 
   it("keeps only cheap existing screenshots when CHECK_DIR is set", async () => {
     const { text, code, evidence } = await lane("", true);
     expect(code).toBe(0);
     expect(evidence).toBe(true);
     for (const script of ["sticky-modifiers-regression.ts", "file-viewer-regression.ts"]) {
-      expect(text).toMatch(new RegExp(`STEP=scripts/${script} EVIDENCE=.+/browser-evidence`));
+      expect(text).toMatch(new RegExp(`^\\[[^\\]]+\\] STEP=scripts/${script} EVIDENCE=.+/browser-evidence$`, "m"));
     }
     for (const script of ["ui-regression.ts", "ui-contexts-regression.ts", "key-bar-customization-demo-regression.ts"]) {
-      expect(text).toContain(`STEP=scripts/${script} EVIDENCE=\n`);
+      expect(text).toMatch(new RegExp(`^\\[[^\\]]+\\] STEP=scripts/${script} EVIDENCE=$`, "m"));
     }
   });
 
   it("creates evidence under .ci when CI has no CHECK_DIR", async () => {
     const { text, code, evidence } = await lane("", false, "1");
     expect(code).toBe(0);
     expect(evidence).toBe(true);
-    expect(text).toContain("STEP=scripts/file-viewer-regression.ts EVIDENCE=.ci/browser-evidence\n");
+    expect(text).toMatch(/^\[[^\]]+\] STEP=scripts\/file-viewer-regression\.ts EVIDENCE=.ci\/browser-evidence$/m);
+    expect(text).toMatch(/^Browser lane total: seconds=\d+ exit=0$/m);
   });
 });