fix(process): preserve monotonic capture timing and observed wall dates

This commit is contained in:
morluto 2026-10-13 15:12:08 +08:00
parent 7fc0b5ec9c
commit 9049dbaf0c
11 changed files with 224 additions and 91 deletions

View File

@ -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[]) => {

View File

@ -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 = (

View File

@ -0,0 +1,3 @@
/** Keep wall-clock timestamps separate from capture-relative elapsed time. */
export const monotonicProcessCaptureClock = (): number =>
Math.floor(performance.now());

View File

@ -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 {

View File

@ -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) => {

View File

@ -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<void> => {
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<void>((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<ProcessCleanupResult>,
): Promise<ProcessCleanupResult> => {
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<void>((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(

View File

@ -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;

View File

@ -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,

View File

@ -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,

View File

@ -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);
},
);
},
);

View File

@ -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<void> => {
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 () => {