From c9e1b0521ca6426818acc045221dd45db7050cd7 Mon Sep 17 00:00:00 2001 From: Hako Date: Sat, 24 Oct 2026 08:19:16 +0900 Subject: [PATCH] ci: timestamp the browser lane's test server lines Timestamp browser script output in serial and parallel lanes while preserving lane summaries and failure-site parsing. Add regression coverage for timestamped output and unchanged summary formats. Part of #897 --- scripts/ci-browser-parallel.test.ts | 56 +++++++++++++++++++++++++++++ scripts/ci-browser-parallel.ts | 52 ++++++++++++++++----------- scripts/ci-browser.sh | 9 +++-- scripts/ci-browser.test.ts | 23 ++++++++---- 4 files changed, 111 insertions(+), 29 deletions(-) create mode 100644 scripts/ci-browser-parallel.test.ts diff --git a/scripts/ci-browser-parallel.test.ts b/scripts/ci-browser-parallel.test.ts new file mode 100644 index 0000000000..257ee7d051 --- /dev/null +++ b/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 }); + } + }); +}); diff --git a/scripts/ci-browser-parallel.ts b/scripts/ci-browser-parallel.ts index 6876246e86..9a7a4f1857 100644 --- a/scripts/ci-browser-parallel.ts +++ b/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 { console.log(`[setup] Demo build completed in ${((Date.now() - started) / 1000).toFixed(1)}s`); } +async function timestampLog(stream: ReadableStream, log: string): Promise { + 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, log: string): Promise { 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 { diff --git a/scripts/ci-browser.sh b/scripts/ci-browser.sh index 1c4e398cc4..0a9a32147a 100644 --- a/scripts/ci-browser.sh +++ b/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' diff --git a/scripts/ci-browser.test.ts b/scripts/ci-browser.test.ts index 8b4072365c..97e81134de 100644 --- a/scripts/ci-browser.test.ts +++ b/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,6 +121,9 @@ 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 () => { @@ -123,10 +131,10 @@ describe("browser lane", () => { 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")); } }); @@ -134,6 +142,7 @@ describe("browser lane", () => { 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); }); });