From 9049dbaf0c3df32357419f9899965df2b611f493 Mon Sep 17 00:00:00 2001 From: morluto <76467478+morluto@users.noreply.github.com> Date: Tue, 13 Oct 2026 15:12:08 +0800 Subject: [PATCH] fix(process): preserve monotonic capture timing and observed wall dates --- .../PlaywrightBrowserScenarioProvider.test.ts | 56 ++++++------ .../process/processCaptureValidation.ts | 4 - src/process/capture/ProcessCaptureClock.ts | 3 + src/process/capture/ProcessCaptureJournal.ts | 6 +- .../capture/ProcessCaptureLifecycle.test.ts | 5 +- .../capture/ProcessCaptureLifecycle.ts | 74 ++++++++++----- src/process/capture/ProcessCaptureProgress.ts | 3 +- src/process/capture/ProcessHarness.ts | 7 +- src/process/capture/ProcessSampling.ts | 3 +- .../filesystem/ghidraPspExtension.test.ts | 65 +++++++------- .../process/processCaptureLifecycle.test.ts | 89 ++++++++++++++++++- 11 files changed, 224 insertions(+), 91 deletions(-) create mode 100644 src/process/capture/ProcessCaptureClock.ts diff --git a/src/browser/PlaywrightBrowserScenarioProvider.test.ts b/src/browser/PlaywrightBrowserScenarioProvider.test.ts index 883b0c3b4..734e32426 100644 --- a/src/browser/PlaywrightBrowserScenarioProvider.test.ts +++ b/src/browser/PlaywrightBrowserScenarioProvider.test.ts @@ -304,33 +304,6 @@ describe("PlaywrightBrowserScenarioProvider", () => { expect(result.value.limitations).toContain(session.eventGaps[0]); }); - it("keeps capture elapsed values valid across a backward wall-clock jump", async () => { - let wallClock = 10_000; - vi.spyOn(Date, "now").mockImplementation(() => wallClock); - const session = new FakeSession("launch"); - session.onPerform = () => { - wallClock = 1; - }; - const provider = new PlaywrightBrowserScenarioProvider(() => - Promise.resolve(session), - ); - - try { - const result = await provider.captureScenario(scenario()); - if (!result.ok) throw result.error; - expect(wallClock).toBe(1); - expect(Number.isInteger(result.value.duration_ms)).toBe(true); - expect(result.value.duration_ms).toBeGreaterThanOrEqual(0); - expect( - result.value.steps.every( - ({ elapsed_ms }) => Number.isInteger(elapsed_ms) && elapsed_ms >= 0, - ), - ).toBe(true); - } finally { - vi.restoreAllMocks(); - } - }); - it("returns an initial state and every step beyond the former action ceiling", async () => { const session = new FakeSession("launch"); const provider = new PlaywrightBrowserScenarioProvider(() => @@ -404,6 +377,35 @@ describe("PlaywrightBrowserScenarioProvider", () => { }); }); +describe("PlaywrightBrowserScenarioProvider timing", () => { + it("keeps capture elapsed values valid across a backward wall-clock jump", async () => { + let wallClock = 10_000; + vi.spyOn(Date, "now").mockImplementation(() => wallClock); + const session = new FakeSession("launch"); + session.onPerform = () => { + wallClock = 1; + }; + const provider = new PlaywrightBrowserScenarioProvider(() => + Promise.resolve(session), + ); + + try { + const result = await provider.captureScenario(scenario()); + if (!result.ok) throw result.error; + expect(wallClock).toBe(1); + expect(Number.isInteger(result.value.duration_ms)).toBe(true); + expect(result.value.duration_ms).toBeGreaterThanOrEqual(0); + expect( + result.value.steps.every( + ({ elapsed_ms }) => Number.isInteger(elapsed_ms) && elapsed_ms >= 0, + ), + ).toBe(true); + } finally { + vi.restoreAllMocks(); + } + }); +}); + describe("PlaywrightBrowserScenarioProvider comparison coverage", () => { it("keeps quiet captures with different event families from comparing unchanged", async () => { const capture = async (events: readonly BrowserScenarioEventFamily[]) => { diff --git a/src/domain/process/processCaptureValidation.ts b/src/domain/process/processCaptureValidation.ts index 10d6b831b..33c6d5483 100644 --- a/src/domain/process/processCaptureValidation.ts +++ b/src/domain/process/processCaptureValidation.ts @@ -47,10 +47,6 @@ const validateCommitments = ( digestProcessCommitment( value, ), `manifest.${field}`, "commitment does not match its canonical value"); - require(Date.parse(manifest.started_at) <= - Date.parse( - manifest.completed_at, - ), "manifest.completed_at", "completion precedes start"); }; const validateOrdering = ( diff --git a/src/process/capture/ProcessCaptureClock.ts b/src/process/capture/ProcessCaptureClock.ts new file mode 100644 index 000000000..1fe9fda0a --- /dev/null +++ b/src/process/capture/ProcessCaptureClock.ts @@ -0,0 +1,3 @@ +/** Keep wall-clock timestamps separate from capture-relative elapsed time. */ +export const monotonicProcessCaptureClock = (): number => + Math.floor(performance.now()); diff --git a/src/process/capture/ProcessCaptureJournal.ts b/src/process/capture/ProcessCaptureJournal.ts index b8a0874d9..07c1f0351 100644 --- a/src/process/capture/ProcessCaptureJournal.ts +++ b/src/process/capture/ProcessCaptureJournal.ts @@ -13,6 +13,7 @@ import type { ProcessCaptureEventJournalEntry, RecordProcessCaptureEvent, } from "../../domain/process/processCapture.js"; +import { monotonicProcessCaptureClock } from "./ProcessCaptureClock.js"; /** Mutable observation-order ledger whose writer is shared by capture producers. */ export interface ProcessCaptureJournal { readonly entries: readonly ProcessCaptureEventJournalEntry[]; @@ -55,7 +56,10 @@ export const scheduleScenarioInteractions = ( const timer = scheduleProcessDelay(event.at_ms, () => { options.dispatchedEventIndexes.add(eventIndex); const terminal = getTerminal(); - const dispatchedAt = Math.max(0, Date.now() - started); + const dispatchedAt = Math.max( + 0, + monotonicProcessCaptureClock() - started, + ); let outcome: InteractionEvent["outcome"] = "dispatched"; if (terminal === undefined) outcome = "target_exited"; else { diff --git a/src/process/capture/ProcessCaptureLifecycle.test.ts b/src/process/capture/ProcessCaptureLifecycle.test.ts index 765635ccc..abad38ac2 100644 --- a/src/process/capture/ProcessCaptureLifecycle.test.ts +++ b/src/process/capture/ProcessCaptureLifecycle.test.ts @@ -5,6 +5,7 @@ import { parseProcessScenario } from "../../domain/process/processScenario.js"; import type { ProcessCaptureFinalization } from "../../domain/process/processCapture.js"; import { awaitTerminalExit } from "./ProcessCaptureLifecycle.js"; import type { ProcessTimer } from "./ProcessTimer.js"; +import { monotonicProcessCaptureClock } from "./ProcessCaptureClock.js"; type Delivery = ProcessCaptureFinalization["signals"][number]["delivery"]; @@ -79,8 +80,8 @@ const start = ( idle_timeout_ms: 10_000, ...scenario, }), - started: Date.now(), - lastOutput: () => Date.now(), + started: monotonicProcessCaptureClock(), + lastOutput: monotonicProcessCaptureClock, signal, signalTarget: fake.signalTarget, recordFinalization: (snapshot) => { diff --git a/src/process/capture/ProcessCaptureLifecycle.ts b/src/process/capture/ProcessCaptureLifecycle.ts index 2d2fcec00..ab9271dda 100644 --- a/src/process/capture/ProcessCaptureLifecycle.ts +++ b/src/process/capture/ProcessCaptureLifecycle.ts @@ -48,6 +48,7 @@ import { type ProcessCaptureTruncationDetails, } from "../../domain/process/processCaptureCoverage.js"; import { scheduleProcessInterval, type ProcessTimer } from "./ProcessTimer.js"; +import { monotonicProcessCaptureClock } from "./ProcessCaptureClock.js"; import type { FilesystemCheckpoint, @@ -266,10 +267,10 @@ export const settleProcessCaptureJournal = async ( quietMs = 25, maxWaitMs = 500, ): Promise => { - const deadline = Date.now() + maxWaitMs; + const deadline = monotonicProcessCaptureClock() + maxWaitMs; let observed = journal.length; - let lastChangeAt = Date.now(); - while (Date.now() < deadline) { + let lastChangeAt = monotonicProcessCaptureClock(); + while (monotonicProcessCaptureClock() < deadline) { await new Promise((resolve) => setTimeout(resolve, 4)); // A stalled event loop can leave timer and poll callbacks that were already // due queued behind this wake-up. Drain them before judging silence so a @@ -277,8 +278,8 @@ export const settleProcessCaptureJournal = async ( await setImmediate(); if (journal.length !== observed) { observed = journal.length; - lastChangeAt = Date.now(); - } else if (Date.now() - lastChangeAt >= quietMs) return; + lastChangeAt = monotonicProcessCaptureClock(); + } else if (monotonicProcessCaptureClock() - lastChangeAt >= quietMs) return; } }; @@ -337,6 +338,12 @@ export const buildCaptureResult = ( truncation_details: options.truncationDetails, limitations: [ "The executable digest is a prelaunch file sample; matching path metadata immediately after spawn does not prove an atomic operating-system image binding.", + ...(Date.parse(options.manifest.completed_at) < + Date.parse(options.manifest.started_at) + ? [ + "Wall-clock completion time precedes start time; elapsed capture timing is recorded separately and remains monotonic.", + ] + : []), "Process trees are sampled and may omit short-lived descendants.", ...(options.samplingPartial ? ["Process-tree sampling ended with an incomplete observation."] @@ -660,7 +667,7 @@ export const observeSettlement = async ( recordEvent("lifecycle", 1); return { state: "unverifiable", elapsed_ms: 0 }; } - const started = Date.now(); + const started = monotonicProcessCaptureClock(); let consecutiveEmpty = 0; let sawLive = false; let deadlineReached = false; @@ -678,19 +685,25 @@ export const observeSettlement = async ( [...observations.values()].some(({ state }) => state === "unverifiable") ) { recordEvent("lifecycle", 1); - return { state: "unverifiable", elapsed_ms: Date.now() - started }; + return { + state: "unverifiable", + elapsed_ms: monotonicProcessCaptureClock() - started, + }; } if ([...observations.values()].every(({ state }) => state === "empty")) { consecutiveEmpty += 1; if (consecutiveEmpty >= 2) { recordEvent("lifecycle", 1); - return { state: "quiesced", elapsed_ms: Date.now() - started }; + return { + state: "quiesced", + elapsed_ms: monotonicProcessCaptureClock() - started, + }; } } else { consecutiveEmpty = 0; sawLive = true; } - deadlineReached = Date.now() - started >= settleMs; + deadlineReached = monotonicProcessCaptureClock() - started >= settleMs; if (deadlineReached) break; await delay(50, undefined, { signal }); } @@ -698,8 +711,14 @@ export const observeSettlement = async ( // A lone empty observation proves neither liveness nor quiescence; only an // observed live member justifies alive_at_deadline. return sawLive - ? { state: "alive_at_deadline", elapsed_ms: Date.now() - started } - : { state: "unverifiable", elapsed_ms: Date.now() - started }; + ? { + state: "alive_at_deadline", + elapsed_ms: monotonicProcessCaptureClock() - started, + } + : { + state: "unverifiable", + elapsed_ms: monotonicProcessCaptureClock() - started, + }; }; /** Name why an attempt is unverified; a blank message never reaches the capture schema. */ @@ -786,7 +805,10 @@ export const awaitTerminalExit = async ({ if (finalizationStartedAt === undefined) return; const record: (typeof finalizationSignals)[number] = { signal: finalizationSignal, - sent_at_ms: Math.round(performance.now() - finalizationStartedAt), + sent_at_ms: Math.max( + 0, + monotonicProcessCaptureClock() - finalizationStartedAt, + ), delivery: "unverified" as FinalizationDelivery, reason: "delivery had not settled when the record was published", }; @@ -856,7 +878,7 @@ export const awaitTerminalExit = async ({ terminal.kill("SIGKILL"); return; } - finalizationStartedAt = performance.now(); + finalizationStartedAt = monotonicProcessCaptureClock(); attempt("SIGTERM"); }; terminal.onExit((exit) => { @@ -867,7 +889,7 @@ export const awaitTerminalExit = async ({ const finalizationElapsedMs = finalizationStartedAt === undefined ? undefined - : Math.round(performance.now() - finalizationStartedAt); + : Math.max(0, monotonicProcessCaptureClock() - finalizationStartedAt); recordEvent("lifecycle", 0); for (const [eventIndex, event] of scenario.events.entries()) { if (dispatchedEventIndexes.has(eventIndex)) continue; @@ -875,7 +897,10 @@ export const awaitTerminalExit = async ({ interactions.push({ sequence, scheduled_at_ms: event.at_ms, - dispatched_at_ms: Math.max(0, Date.now() - started), + dispatched_at_ms: Math.max( + 0, + monotonicProcessCaptureClock() - started, + ), type: event.type, data: event.type === "input" @@ -935,14 +960,20 @@ export const awaitTerminalExit = async ({ forceKill(); } else if (finalizationStartedAt !== undefined) { if ( - performance.now() - finalizationStartedAt >= + monotonicProcessCaptureClock() - finalizationStartedAt >= scenario.finalization_ms ) forceKill(); - } else if (Date.now() - started >= scenario.timeout_ms) { + } else if ( + monotonicProcessCaptureClock() - started >= + scenario.timeout_ms + ) { reason = "timeout"; terminateAtDeadline(); - } else if (Date.now() - lastOutput() >= scenario.idle_timeout_ms) { + } else if ( + monotonicProcessCaptureClock() - lastOutput() >= + scenario.idle_timeout_ms + ) { reason = "idle_timeout"; terminateAtDeadline(); } @@ -971,10 +1002,11 @@ const PROCESS_CLEANUP_VERIFICATION_INTERVAL_MS = 25; const verifyTokenOwnedProcessesUntilSettled = async ( verify: () => Promise, ): Promise => { - const deadline = Date.now() + PROCESS_CLEANUP_VERIFICATION_GRACE_MS; + const deadline = + monotonicProcessCaptureClock() + PROCESS_CLEANUP_VERIFICATION_GRACE_MS; let result = await verify(); while (!result.cleaned) { - const remaining = deadline - Date.now(); + const remaining = deadline - monotonicProcessCaptureClock(); if (remaining <= 0) return result; await new Promise((resolve) => setTimeout( @@ -1288,7 +1320,7 @@ export const captureTerminalFrames = (options: { } outputBytes += bytes; const atMs = normalizeProcessElapsedTime( - Date.now() - options.started, + monotonicProcessCaptureClock() - options.started, options.scenario.normalization.time_bucket_ms, ); const normalized = normalizeProcessText( diff --git a/src/process/capture/ProcessCaptureProgress.ts b/src/process/capture/ProcessCaptureProgress.ts index 83d5a51f5..205334db7 100644 --- a/src/process/capture/ProcessCaptureProgress.ts +++ b/src/process/capture/ProcessCaptureProgress.ts @@ -1,4 +1,5 @@ import type { ProcessCaptureCleanupReport } from "../../domain/process/processCapture.js"; +import { monotonicProcessCaptureClock } from "./ProcessCaptureClock.js"; /** * Progress port accepted by process capture. @@ -61,7 +62,7 @@ const formatProgressMessage = ( /** Serialize observed capture status through one rate-limited reporter. */ export const createProcessCaptureProgressTracker = ( progress: ProcessCaptureProgress | undefined, - now: () => number = Date.now, + now: () => number = monotonicProcessCaptureClock, ) => { const started = now(); let completed = 0; diff --git a/src/process/capture/ProcessHarness.ts b/src/process/capture/ProcessHarness.ts index 1033e68cd..847e512f8 100644 --- a/src/process/capture/ProcessHarness.ts +++ b/src/process/capture/ProcessHarness.ts @@ -70,6 +70,7 @@ import { observeProcessStartIdentity, signalProcessWithStartIdentity, } from "../ProcessOwnershipObservation.js"; +import { monotonicProcessCaptureClock } from "./ProcessCaptureClock.js"; interface StartedCaptureRuntime { readonly renderer: TerminalRenderer; @@ -268,7 +269,7 @@ const startCaptureRuntime = async ( options.signal, ); const startedAt = new Date(); - const started = Date.now(); + const started = monotonicProcessCaptureClock(); let lastOutput = started; renderer = createTerminalRenderer( scenario, @@ -296,7 +297,7 @@ const startCaptureRuntime = async ( ...options, terminal, started, - onOutput: () => (lastOutput = Date.now()), + onOutput: () => (lastOutput = monotonicProcessCaptureClock()), renderer, }); scheduleScenarioInteractions({ @@ -541,7 +542,7 @@ const completeCapture = async (options: { }, { name: "after_settlement", - at_ms: Math.max(0, Date.now() - runtime.started), + at_ms: Math.max(0, monotonicProcessCaptureClock() - runtime.started), files: after.files, effects: classifyFilesystemEffects(options.before, after), truncated: after.truncated, diff --git a/src/process/capture/ProcessSampling.ts b/src/process/capture/ProcessSampling.ts index 69e7dd343..59b67f577 100644 --- a/src/process/capture/ProcessSampling.ts +++ b/src/process/capture/ProcessSampling.ts @@ -6,6 +6,7 @@ import type { } from "../../domain/process/processCapture.js"; import { execFileOutput } from "../ExecFileOutput.js"; import { readProcessRunId } from "../ProcessOwnership.js"; +import { monotonicProcessCaptureClock } from "./ProcessCaptureClock.js"; const PROC_READ_CONCURRENCY = 64; interface ProcessRow { @@ -491,7 +492,7 @@ export const startProcessSampler = (options: { } return sampleProcesses({ rootPid, - elapsedMs: Date.now() - started, + elapsedMs: monotonicProcessCaptureClock() - started, limit: limit + 1, identities, signal: controller.signal, diff --git a/tests/boundary/filesystem/ghidraPspExtension.test.ts b/tests/boundary/filesystem/ghidraPspExtension.test.ts index 0b90bd194..65a4d1512 100644 --- a/tests/boundary/filesystem/ghidraPspExtension.test.ts +++ b/tests/boundary/filesystem/ghidraPspExtension.test.ts @@ -188,36 +188,6 @@ describe.skipIf(process.platform === "win32")( expect(missing.error.message).toContain("PSP_EXTENSION_UNAVAILABLE"); }); - it.each([ - { - form: "escaped key and value with colon separator", - properties: "n\\u0061me : ghidra-allegrex\nver\\u0073ion=12.1.3\n", - }, - { - form: "continued key and value lines", - properties: "name=ghidra-\\\n allegrex\nversion=12.1.\\\n 3\n", - }, - { - form: "duplicate keys use the last value", - properties: - "name=wrong\nname=ghidra-allegrex\nversion=12.1.4\nversion=12.1.3\n", - }, - ])( - "accepts Java Properties $form and hashes raw bytes", - async ({ properties }) => { - const { root } = await installation(); - const canonical = await inspectGhidraPspExtension(root, "12.1.3"); - const latin1Properties = Buffer.from( - `${properties}author=caf\u00e9\n`, - "latin1", - ); - await writeFile(join(root, "extension.properties"), latin1Properties); - const extension = await inspectGhidraPspExtension(root, "12.1.3"); - expect(extension.id).toBe("ghidra-allegrex"); - expect(extension.sha256).not.toBe(canonical.sha256); - }, - ); - it.each([ ["name=other\nversion=12.1.3\n", "does not match"], ["name=ghidra-allegrex\nversion=12.1.4\n", "does not match"], @@ -531,3 +501,38 @@ describe.skipIf(process.platform === "win32")( }); }, ); + +describe.skipIf(process.platform === "win32")( + "PSP extension property syntax", + () => { + it.each([ + { + form: "escaped key and value with colon separator", + properties: "n\\u0061me : ghidra-allegrex\nver\\u0073ion=12.1.3\n", + }, + { + form: "continued key and value lines", + properties: "name=ghidra-\\\n allegrex\nversion=12.1.\\\n 3\n", + }, + { + form: "duplicate keys use the last value", + properties: + "name=wrong\nname=ghidra-allegrex\nversion=12.1.4\nversion=12.1.3\n", + }, + ])( + "accepts Java Properties $form and hashes raw bytes", + async ({ properties }) => { + const { root } = await installation(); + const canonical = await inspectGhidraPspExtension(root, "12.1.3"); + const latin1Properties = Buffer.from( + `${properties}author=caf\u00e9\n`, + "latin1", + ); + await writeFile(join(root, "extension.properties"), latin1Properties); + const extension = await inspectGhidraPspExtension(root, "12.1.3"); + expect(extension.id).toBe("ghidra-allegrex"); + expect(extension.sha256).not.toBe(canonical.sha256); + }, + ); + }, +); diff --git a/tests/boundary/process/processCaptureLifecycle.test.ts b/tests/boundary/process/processCaptureLifecycle.test.ts index dcba0510f..c3dc21542 100644 --- a/tests/boundary/process/processCaptureLifecycle.test.ts +++ b/tests/boundary/process/processCaptureLifecycle.test.ts @@ -4,7 +4,7 @@ import { access, readFile, rm, symlink, writeFile } from "node:fs/promises"; import { dirname, join } from "node:path"; import { fileURLToPath } from "node:url"; import { promisify } from "node:util"; -import { expect } from "vitest"; +import { expect, vi } from "vitest"; import { createTestTempDirectory } from "../../fixtures/temporaryDirectory.js"; import { itWithCaptureCapability } from "./processCaptureCapability.js"; @@ -123,6 +123,93 @@ const terminateFixtureProcess = async (pid: number): Promise => { await waitForProcessExit(pid); }; +itWithCaptureCapability( + "keeps the process deadline bounded when the wall clock moves backward", + async () => { + const wallStart = Date.now(); + let wallReads = 0; + const now = vi.spyOn(Date, "now").mockImplementation(() => { + wallReads += 1; + return wallReads === 1 ? wallStart : wallStart - 60_000 + wallReads; + }); + const controller = new AbortController(); + const fallback = setTimeout(() => controller.abort(), 1_500); + try { + const result = await captureProcessScenario( + parseProcessScenario({ + executable: process.execPath, + arguments: [processFixture, "hang"], + working_directory: dirname(processFixture), + timeout_ms: 100, + idle_timeout_ms: 5_000, + }), + controller.signal, + ); + expect(result.ok).toBe(true); + if (!result.ok) throw result.error; + expect(result.value.exit.reason).toBe("timeout"); + } finally { + clearTimeout(fallback); + now.mockRestore(); + } + }, + 10_000, +); + +itWithCaptureCapability( + "preserves reversed wall-clock observations and monotonic frames across capture", + async () => { + vi.useFakeTimers({ toFake: ["Date"] }); + vi.setSystemTime(new Date("2026-01-02T00:00:00.000Z")); + try { + const result = await captureProcessScenario( + parseProcessScenario({ + executable: process.execPath, + arguments: [processFixture, "partial"], + working_directory: dirname(processFixture), + settle_ms: 0, + timeout_ms: 5_000, + idle_timeout_ms: 5_000, + }), + undefined, + process.platform, + process.env, + undefined, + undefined, + { + async report(update) { + if (update.phase === "running") + vi.setSystemTime(new Date("2026-01-01T00:00:00.000Z")); + }, + }, + ); + expect(result.ok).toBe(true); + if (!result.ok) throw result.error; + expect(result.value.frames.length).toBeGreaterThan(0); + expect(Date.parse(result.value.manifest.completed_at)).toBeLessThan( + Date.parse(result.value.manifest.started_at), + ); + expect(result.value.limitations).toContain( + "Wall-clock completion time precedes start time; elapsed capture timing is recorded separately and remains monotonic.", + ); + expect( + result.value.frames.map(({ at_ms }) => at_ms), + "capture-relative frame times stay ordered and nonnegative", + ).toEqual( + [...result.value.frames.map(({ at_ms }) => at_ms)].sort( + (left, right) => left - right, + ), + ); + expect(result.value.frames.every(({ at_ms }) => at_ms >= 0)).toBe(true); + expect(result.value.exit.reason).toBe("exited"); + expect(result.value.settlement.elapsed_ms).toBeGreaterThan(0); + } finally { + vi.useRealTimers(); + } + }, + 10_000, +); + itWithCaptureCapability( "cleans detached run-token children omitted by sampling and preserves an unowned neighbor", async () => {