diff --git a/scripts/lib/timberborn-startup-diagnostics.ts b/scripts/lib/timberborn-startup-diagnostics.ts new file mode 100644 index 0000000..1b8571e --- /dev/null +++ b/scripts/lib/timberborn-startup-diagnostics.ts @@ -0,0 +1,229 @@ +import { copyFileSync, existsSync, mkdirSync, readdirSync, readFileSync, statSync, writeFileSync } from "fs"; +import { basename, join } from "path"; +import type { ShellRunner, TimberbornStartupFailureKind } from "./timberborn-startup.ts"; + +export type ErrorReportInventoryEntry = { + modifiedAt: string; + modifiedMs: number; + path: string; + sizeBytes: number; +}; + +export type StartupExitDiagnosticsOptions = { + afterErrorReports: ErrorReportInventoryEntry[]; + artifactDir: string; + beforeErrorReports: ErrorReportInventoryEntry[]; + errorReportDir: string; + failureKind: TimberbornStartupFailureKind; + frontmostBundleId: string; + launchIntentGuardDir: string; + message: string; + playerLogPath: string; + processName: string; + processRunning: boolean; + run: ShellRunner; +}; + +export type StartupExitDiagnosticsBundle = { + copiedErrorReports: string[]; + launchIntentCopyPath: string; + playerLogCopyPath: string; + playerLogScanPath: string; + processSnapshotPath: string; + summaryPath: string; +}; + +type PlayerLogScan = { + matchedLines: string[]; + tailLines: string[]; +}; + +const maxErrorReports = 12; +const playerLogTailLineCount = 80; +const playerLogScanLineCount = 80; +const processSnapshotCommand = "/bin/ps"; +const processSnapshotArgs = ["-axo", "pid=,comm=,args="]; + +const compactLogToken = (value: string): string => value.replaceAll(/\s+/gu, "_").replaceAll('"', "'"); + +export const errorReportInventory = (errorReportDir: string): ErrorReportInventoryEntry[] => { + if (!existsSync(errorReportDir)) { + return []; + } + + return readdirSync(errorReportDir, { withFileTypes: true }) + .filter((entry) => entry.isFile() && entry.name.startsWith("error-report-") && entry.name.endsWith(".zip")) + .map((entry) => { + const path = join(errorReportDir, entry.name); + const stat = statSync(path); + return { + modifiedAt: stat.mtime.toISOString(), + modifiedMs: stat.mtimeMs, + path, + sizeBytes: stat.size, + }; + }) + .sort((left, right) => right.modifiedMs - left.modifiedMs) + .slice(0, maxErrorReports); +}; + +export const diffErrorReportInventory = ( + before: ErrorReportInventoryEntry[], + after: ErrorReportInventoryEntry[], +): ErrorReportInventoryEntry[] => { + const beforeByPath = new Map(before.map((entry) => [entry.path, entry])); + return after.filter((entry) => { + const previous = beforeByPath.get(entry.path); + return previous === undefined || previous.modifiedMs !== entry.modifiedMs || previous.sizeBytes !== entry.sizeBytes; + }); +}; + +const readLaunchIntent = (launchIntentGuardDir: string): string => { + const intentPath = join(launchIntentGuardDir, "intent.json"); + if (!existsSync(intentPath)) { + return `launch intent metadata was missing: ${intentPath}\n`; + } + + return readFileSync(intentPath, "utf8"); +}; + +const captureProcessSnapshot = (run: ShellRunner, processName: string): string => { + const result = run(processSnapshotCommand, processSnapshotArgs); + const output = result.exitCode === 0 ? result.stdout : `${result.stdout}\n${result.stderr}`.trim(); + const lines = output + .split(/\r?\n/u) + .map((line) => line.trimEnd()) + .filter((line) => { + const parts = line.trimStart().split(/\s+/u); + return parts[1] === processName || parts[2]?.endsWith(`/${processName}`) === true; + }); + + return [ + `command=${processSnapshotCommand} ${processSnapshotArgs.join(" ")}`, + `exit_code=${result.exitCode}`, + `match_strategy=exact_comm_or_executable_basename`, + `process_name=${processName}`, + "", + ...(lines.length > 0 ? lines : ["no_exact_process_match"]), + "", + ].join("\n"); +}; + +const scanPlayerLog = (playerLogPath: string): PlayerLogScan => { + if (!existsSync(playerLogPath)) { + return { + matchedLines: [`Player.log was missing: ${playerLogPath}`], + tailLines: [], + }; + } + + const lines = readFileSync(playerLogPath, "utf8").split(/\r?\n/u); + const matchedLines = lines + .filter((line) => + [ + "Starting game version", + "ShutdownInProgress", + "Input System module state changed to: Shutdown", + "prematurely finalized", + "Exception", + "Fatal", + "Crash", + "wildfire_", + "command bridge", + ].some((token) => line.includes(token)), + ) + .slice(-playerLogScanLineCount); + + return { + matchedLines, + tailLines: lines.slice(-playerLogTailLineCount), + }; +}; + +const writeInventory = (label: string, entries: ErrorReportInventoryEntry[]): string[] => [ + `[${label}]`, + ...(entries.length > 0 + ? entries.map((entry) => `${entry.modifiedAt} size_bytes=${entry.sizeBytes} path=${entry.path}`) + : ["none"]), + "", +]; + +const copyErrorReports = (artifactDir: string, entries: ErrorReportInventoryEntry[]): string[] => { + const targetDir = join(artifactDir, "error-reports"); + mkdirSync(targetDir, { recursive: true }); + return entries + .filter((entry) => existsSync(entry.path)) + .map((entry) => { + const targetPath = join(targetDir, basename(entry.path)); + copyFileSync(entry.path, targetPath); + return targetPath; + }); +}; + +export const writeStartupExitDiagnosticsBundle = ( + options: StartupExitDiagnosticsOptions, +): StartupExitDiagnosticsBundle | null => { + if (options.failureKind !== "timberborn_process_exit") { + return null; + } + + const bundleDir = join(options.artifactDir, "startup-process-exit-diagnostics"); + mkdirSync(bundleDir, { recursive: true }); + + const changedErrorReports = diffErrorReportInventory(options.beforeErrorReports, options.afterErrorReports); + const copiedErrorReports = copyErrorReports(bundleDir, changedErrorReports); + const launchIntentCopyPath = join(bundleDir, "launch-intent.json"); + const processSnapshotPath = join(bundleDir, "process-snapshot.txt"); + const playerLogCopyPath = join(bundleDir, "Player.log"); + const playerLogScanPath = join(bundleDir, "Player-log-scan.txt"); + const summaryPath = join(bundleDir, "startup-process-exit-summary.txt"); + const playerLog = scanPlayerLog(options.playerLogPath); + + writeFileSync(launchIntentCopyPath, readLaunchIntent(options.launchIntentGuardDir)); + writeFileSync(processSnapshotPath, captureProcessSnapshot(options.run, options.processName)); + if (existsSync(options.playerLogPath)) { + copyFileSync(options.playerLogPath, playerLogCopyPath); + } else { + writeFileSync(playerLogCopyPath, `Player.log was missing: ${options.playerLogPath}\n`); + } + writeFileSync( + playerLogScanPath, + [ + "[matched lines]", + ...(playerLog.matchedLines.length > 0 ? playerLog.matchedLines : ["none"]), + "", + "[tail]", + ...(playerLog.tailLines.length > 0 ? playerLog.tailLines : ["none"]), + "", + ].join("\n"), + ); + + const summary = [ + "wildfire_startup_exit_diagnostics=present", + `failure_kind=${options.failureKind}`, + `process_running=${options.processRunning}`, + `frontmost_bundle_id=${options.frontmostBundleId}`, + `error=${compactLogToken(options.message)}`, + `artifacts_dir=${bundleDir}`, + `player_log=${playerLogCopyPath}`, + `player_log_scan=${playerLogScanPath}`, + `process_snapshot=${processSnapshotPath}`, + `launch_intent=${launchIntentCopyPath}`, + `error_report_dir=${options.errorReportDir}`, + `new_or_changed_error_reports=${changedErrorReports.length}`, + `copied_error_reports=${copiedErrorReports.length > 0 ? copiedErrorReports.join(",") : "none"}`, + "", + ...writeInventory("error reports before", options.beforeErrorReports), + ...writeInventory("error reports after", options.afterErrorReports), + ].join("\n"); + writeFileSync(summaryPath, `${summary}\n`); + + return { + copiedErrorReports, + launchIntentCopyPath, + playerLogCopyPath, + playerLogScanPath, + processSnapshotPath, + summaryPath, + }; +}; diff --git a/scripts/load-latest-save-and-unpause.ts b/scripts/load-latest-save-and-unpause.ts index 93eecb5..c391044 100644 --- a/scripts/load-latest-save-and-unpause.ts +++ b/scripts/load-latest-save-and-unpause.ts @@ -10,6 +10,11 @@ import { launchOrAttachTimberborn, recordLaunchIntentFailure, } from "./lib/timberborn-startup.ts"; +import { + errorReportInventory, + type ErrorReportInventoryEntry, + writeStartupExitDiagnosticsBundle, +} from "./lib/timberborn-startup-diagnostics.ts"; type Mode = "attach" | "launch"; type ScreenKind = "experimental-mode" | "loaded-save" | "main-menu" | "startup-mods" | "unknown"; @@ -109,6 +114,7 @@ const lockDir = join(home, "Library", "Application Support", "Timberborn", "Wild const lockInfoPath = join(lockDir, "lock.json"); const launchIntentGuardDir = join(dirname(lockDir), "timberborn-launch-intent"); const playerLogDefault = join(home, "Library", "Logs", "Mechanistry", "Timberborn", "Player.log"); +const errorReportDir = join(home, "Documents", "Timberborn", "Error reports"); const coordinateGuidePath = join(repoRoot, "docs", "timberborn-menu-coordinate-guide.md"); const inboxFileName = "command-inbox.txt"; const outboxFileName = "command-outbox.txt"; @@ -584,7 +590,12 @@ const launchIntentGuardFor = (options: Options) => ({ ttlMs: Math.max(60_000, options.waitSeconds * 1000), }); -const recordStartupFailure = (options: Options, error: unknown): void => { +const recordStartupFailure = ( + options: Options, + artifactDir: string, + beforeErrorReports: ErrorReportInventoryEntry[], + error: unknown, +): void => { const message = error instanceof Error ? error.message : String(error); const processRunning = isTimberbornRunning(run, processName); const frontmostBundleId = getFrontmostBundleId() ?? "unknown"; @@ -616,6 +627,26 @@ const recordStartupFailure = (options: Options, error: unknown): void => { message, ); } + + const diagnosticsBundle = writeStartupExitDiagnosticsBundle({ + afterErrorReports: errorReportInventory(errorReportDir), + artifactDir, + beforeErrorReports, + errorReportDir, + failureKind, + frontmostBundleId, + launchIntentGuardDir, + message, + playerLogPath: options.playerLogPath, + processName, + processRunning, + run, + }); + if (diagnosticsBundle !== null) { + log(`startup_exit_diagnostics_summary=${diagnosticsBundle.summaryPath}`); + log(`startup_exit_diagnostics_process_snapshot=${diagnosticsBundle.processSnapshotPath}`); + log(`startup_exit_diagnostics_player_log_scan=${diagnosticsBundle.playerLogScanPath}`); + } }; const assertTimberbornForeground = (label: string): void => { @@ -1643,6 +1674,7 @@ const main = async (): Promise => { const releaseLock = acquireLock(options); const artifactDir = createArtifactDir(options); const observedScreens: ScreenKind[] = []; + const beforeErrorReports = errorReportInventory(errorReportDir); try { const wasRunningBeforeLaunch = isTimberbornRunning(run, processName); @@ -1661,7 +1693,7 @@ const main = async (): Promise => { } log("latest_save_startup_complete"); } catch (error) { - recordStartupFailure(options, error); + recordStartupFailure(options, artifactDir, beforeErrorReports, error); throw error; } finally { releaseLock(); diff --git a/tests/timberborn-startup.test.ts b/tests/timberborn-startup.test.ts index 5f6116b..13459c2 100644 --- a/tests/timberborn-startup.test.ts +++ b/tests/timberborn-startup.test.ts @@ -1,7 +1,11 @@ import { describe, expect, test } from "bun:test"; -import { mkdirSync, mkdtempSync, rmSync, writeFileSync } from "fs"; +import { existsSync, mkdirSync, mkdtempSync, readFileSync, rmSync, utimesSync, writeFileSync } from "fs"; import { tmpdir } from "os"; import { join } from "path"; +import { + errorReportInventory, + writeStartupExitDiagnosticsBundle, +} from "../scripts/lib/timberborn-startup-diagnostics.ts"; import { launchOrAttachTimberborn, recordLaunchIntentFailure, @@ -456,3 +460,125 @@ describe("timberborn startup contract", () => { expect(commandCalls(runner.calls, "osascript")).toHaveLength(0); }); }); + +describe("timberborn startup process-exit diagnostics", () => { + test("writes a concise process-exit bundle with changed error reports and bounded Player.log evidence", async () => { + await withTempDir(async (dir) => { + const artifactDir = join(dir, "artifacts"); + const errorReportDir = join(dir, "Error reports"); + const guardDir = join(dir, "timberborn-launch-intent"); + const playerLogPath = join(dir, "Player.log"); + const beforeReport = join(errorReportDir, "error-report-2026-05-31-01h00m00s.zip"); + const afterReport = join(errorReportDir, "error-report-2026-05-31-01h05m00s.zip"); + const runner = createRunner((call) => { + if (call.command === "/bin/ps") { + return success( + [ + " 11 rg Timberborn", + " 12 zsh /bin/ps -axo pid=,comm=,args= | rg Timberborn", + " 123 Timberborn /Applications/Timberborn.app/Contents/MacOS/Timberborn", + ].join("\n"), + ); + } + + return success(); + }); + + mkdirSync(errorReportDir, { recursive: true }); + mkdirSync(guardDir, { recursive: true }); + writeFileSync(beforeReport, "old report"); + utimesSync(beforeReport, new Date("2026-05-31T01:00:00Z"), new Date("2026-05-31T01:00:00Z")); + const beforeErrorReports = errorReportInventory(errorReportDir); + writeFileSync(afterReport, "new report"); + utimesSync(afterReport, new Date("2026-05-31T01:05:00Z"), new Date("2026-05-31T01:05:00Z")); + writeFileSync( + join(guardDir, "intent.json"), + `${JSON.stringify({ + bundleId: "com.mechanistry.timberborn", + createdAt: "2026-05-31T01:04:00.000Z", + pid: 999, + processName: "Timberborn", + status: "open_bundle", + timestampMs: 1_000, + ttlMs: 240_000, + })}\n`, + ); + writeFileSync( + playerLogPath, + [ + "ordinary startup line", + "Starting game version 1.0.13.1-b769e88-xsm", + "Input System module state changed to: ShutdownInProgress", + "Thread 9 may have been prematurely finalized", + "Input System module state changed to: Shutdown", + ].join("\n"), + ); + + const bundle = writeStartupExitDiagnosticsBundle({ + afterErrorReports: errorReportInventory(errorReportDir), + artifactDir, + beforeErrorReports, + errorReportDir, + failureKind: "timberborn_process_exit", + frontmostBundleId: "com.valvesoftware.steam", + launchIntentGuardDir: guardDir, + message: "Expected Timberborn foreground, got frontmost_bundle_id=com.valvesoftware.steam.", + playerLogPath, + processName: "Timberborn", + processRunning: false, + run: runner.run, + }); + + expect(bundle).not.toBeNull(); + expect(bundle?.copiedErrorReports).toEqual([ + join(artifactDir, "startup-process-exit-diagnostics", "error-reports", "error-report-2026-05-31-01h05m00s.zip"), + ]); + expect(existsSync(bundle?.summaryPath ?? "")).toBe(true); + const summary = readFileSync(bundle?.summaryPath ?? "", "utf8"); + expect(summary).toContain("wildfire_startup_exit_diagnostics=present"); + expect(summary).toContain("failure_kind=timberborn_process_exit"); + expect(summary).toContain("frontmost_bundle_id=com.valvesoftware.steam"); + expect(summary).toContain("new_or_changed_error_reports=1"); + expect(summary).toContain(`player_log=${bundle?.playerLogCopyPath}`); + const launchIntent = JSON.parse(readFileSync(bundle?.launchIntentCopyPath ?? "", "utf8")) as { + failureKind?: string; + status?: string; + }; + expect(launchIntent.status).toBe("open_bundle"); + expect(launchIntent.failureKind).toBeUndefined(); + + const processSnapshot = readFileSync(bundle?.processSnapshotPath ?? "", "utf8"); + expect(processSnapshot).toContain("match_strategy=exact_comm_or_executable_basename"); + expect(processSnapshot).toContain("123 Timberborn /Applications/Timberborn.app/Contents/MacOS/Timberborn"); + expect(processSnapshot).not.toContain("rg Timberborn"); + expect(runner.calls).toEqual([{ args: ["-axo", "pid=,comm=,args="], command: "/bin/ps" }]); + + const playerLogScan = readFileSync(bundle?.playerLogScanPath ?? "", "utf8"); + expect(playerLogScan).toContain("Starting game version 1.0.13.1-b769e88-xsm"); + expect(playerLogScan).toContain("ShutdownInProgress"); + expect(playerLogScan).toContain("prematurely finalized"); + }); + }); + + test("skips the forensic bundle for non process-exit failures", async () => { + await withTempDir(async (dir) => { + const bundle = writeStartupExitDiagnosticsBundle({ + afterErrorReports: [], + artifactDir: join(dir, "artifacts"), + beforeErrorReports: [], + errorReportDir: join(dir, "Error reports"), + failureKind: "steam_frontmost", + frontmostBundleId: "com.valvesoftware.steam", + launchIntentGuardDir: join(dir, "timberborn-launch-intent"), + message: "frontmost_bundle_id=com.valvesoftware.steam", + playerLogPath: join(dir, "Player.log"), + processName: "Timberborn", + processRunning: true, + run: () => success(), + }); + + expect(bundle).toBeNull(); + expect(existsSync(join(dir, "artifacts"))).toBe(false); + }); + }); +});