mirror of
https://github.com/okieselbach/AutopilotMonitor.git
synced 2026-10-24 12:42:38 +00:00
feat(web): P13 - CMTrace time provenance visible in the session timeline
The per-line self-anchoring provenance (sourceLocalTs, applied offset + origin, observational writer offset, derived/rejected markers) reaches the browser but was buried unlabeled in the raw JSON dump. Sequence stays THE sort order - without exception (now pinned by a regression test); the corrected UTC is display-only, and a backwards step of the displayed time within sequence order is marked as information instead of confusing the reader. - lib/timeProvenance.ts: readTimeProvenance (camelCase/snake_case, tolerant of truncated payloads) + classifyTimeJump with cause precedence derived > rejected-source > era-offset; era-offset requires applied offsets on BOTH rows - it never guesses. - TimeJumpBadge on the row AFTER the jump, computed against the previous RENDERED row (filters/phase boundaries respected); sky for known causes, amber otherwise; tooltip carries both times, the delta and the "true write order (sequence)" sentence. Threshold 5 min, field-calibrated on 20 sessions: 12/12 normal sessions show zero badges, the era-mixed regression session shows exactly its 6. - Clamped chip (rare) + TIME PROVENANCE detail section: only the applied offset says "(applied)"; the writer offset is explicitly observational (sticky after era flip-backs); origin chips with forward-compatible fallback for unknown values. - EnrollmentEvent gains timestampClamped/originalTimestamp (wire already carried them); formatUtcOffset joins lib/formatting. Verified: 814 web tests (19 new), tsc/eslint/build clean; Playwright against e9753578 (badges match the pre-measurement), 9f475bb2 (no badge on line-anchored rows, detail section correct, raw mode shows exactly the one predicted jump). Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
This commit is contained in:
@@ -4,6 +4,8 @@ import { useState, useMemo } from "react";
|
||||
import { EnrollmentEvent, Session } from "@/types";
|
||||
import { normalizeEventDataForDisplay, shortenBuildHashInMessage } from "../utils/eventHelpers";
|
||||
import { getEnrichedOrLookup, formatErrorCode, type ErrorCodeEntry } from "@/utils/errorCodeMap";
|
||||
import { readTimeProvenance, classifyTimeJump } from "@/lib/timeProvenance";
|
||||
import { formatDuration, formatUtcOffset } from "@/lib/formatting";
|
||||
|
||||
interface EventTimelineProps {
|
||||
filteredEvents: EnrollmentEvent[];
|
||||
@@ -184,7 +186,7 @@ export default function EventTimeline({
|
||||
<RawEventRow
|
||||
key={ev.eventId || `${ev.sessionId}-${ev.sequence}`}
|
||||
event={ev}
|
||||
prevDisplayTime={i > 0 ? getDisplayTime(sortedBySequence[i - 1]) : null}
|
||||
prevEvent={i > 0 ? sortedBySequence[i - 1] : null}
|
||||
/>
|
||||
))}
|
||||
</div>
|
||||
@@ -350,7 +352,7 @@ function PhaseSection({
|
||||
key={event.eventId || `${event.sessionId}-${event.sequence}`}
|
||||
event={event}
|
||||
showScriptOutput={showScriptOutput}
|
||||
prevDisplayTime={i > 0 ? getDisplayTime(events[i - 1]) : null}
|
||||
prevEvent={i > 0 ? events[i - 1] : null}
|
||||
/>
|
||||
))}
|
||||
</div>
|
||||
@@ -402,7 +404,53 @@ function GapBadge({ prevTime, eventTime }: { prevTime: Date | null; eventTime: D
|
||||
);
|
||||
}
|
||||
|
||||
function EventRow({ event, showScriptOutput, prevDisplayTime }: { event: EnrollmentEvent; showScriptOutput?: boolean; prevDisplayTime?: Date | null }) {
|
||||
// A displayed time stepping BACKWARDS within the sequence order is information, not a
|
||||
// rendering bug (P13): rows are ordered by the clock-immune sequence counter, while the
|
||||
// displayed time is corrected UTC — a backdated log line or an era-mixed log makes it
|
||||
// step back. Shown on the row AFTER the jump (GapBadge convention) and only at ≥5 min
|
||||
// (BACKWARD_JUMP_THRESHOLD_MS), so normal interleaved-writer jitter (≤2 min by the
|
||||
// agent's grid tolerance) never renders a badge. Known causes get the informational sky
|
||||
// tier; an unexplained backwards step gets amber.
|
||||
const TIME_JUMP_ORDER_NOTE = "Events are shown in true write order (sequence).";
|
||||
|
||||
function TimeJumpBadge({ prevEvent, event }: { prevEvent?: EnrollmentEvent | null; event: EnrollmentEvent }) {
|
||||
if (!prevEvent) return null;
|
||||
const jump = classifyTimeJump(
|
||||
{ displayTime: getDisplayTime(prevEvent), provenance: readTimeProvenance(prevEvent.data) },
|
||||
{ displayTime: getDisplayTime(event), provenance: readTimeProvenance(event.data) },
|
||||
);
|
||||
if (!jump) return null;
|
||||
|
||||
const label = jump.deltaMs >= 48 * 60 * 60 * 1000
|
||||
? `−${Math.round(jump.deltaMs / (24 * 60 * 60 * 1000))}d`
|
||||
: jump.deltaMs >= 60 * 60 * 1000
|
||||
? `−${Math.round(jump.deltaMs / (60 * 60 * 1000))}h`
|
||||
: `−${Math.round(jump.deltaMs / (60 * 1000))}m`;
|
||||
const human = formatDuration(jump.deltaMs / 1000);
|
||||
const times = `(${getDisplayTime(prevEvent).toLocaleTimeString()} → ${getDisplayTime(event).toLocaleTimeString()})`;
|
||||
|
||||
const title =
|
||||
jump.cause === "era-offset"
|
||||
? `Time moved backwards by ${human} vs the previous event ${times}. The two log lines were corrected with different UTC offsets (era-mixed log) — the jump reflects the offset change, not reordering. ${TIME_JUMP_ORDER_NOTE}`
|
||||
: jump.cause === "derived-timestamp"
|
||||
? `Backdated log line: written ${human} before the previous event's displayed time ${times}. Its own timestamp was unusable, so the agent's clock time is shown. ${TIME_JUMP_ORDER_NOTE}`
|
||||
: jump.cause === "rejected-source"
|
||||
? `Time moved backwards by ${human} vs the previous event ${times}. The line's own timestamp was rejected by the staleness clamp; the agent's clock time is shown instead. ${TIME_JUMP_ORDER_NOTE}`
|
||||
: `Time moved backwards by ${human} vs the previous event ${times}. ${TIME_JUMP_ORDER_NOTE} Displayed times are corrected UTC and can step backwards when the source log mixes clock eras.`;
|
||||
|
||||
const color = jump.cause ? "bg-sky-100 text-sky-800" : "bg-amber-100 text-amber-800";
|
||||
return (
|
||||
<span className={`px-1.5 py-0.5 rounded text-xs font-medium whitespace-nowrap flex-shrink-0 ${color}`} title={title}>
|
||||
↩ {label}
|
||||
</span>
|
||||
);
|
||||
}
|
||||
|
||||
const CLAMPED_TOOLTIP_PREFIX =
|
||||
"The device-reported timestamp was outside the accepted range and was clamped to server receive time on ingest.";
|
||||
|
||||
function EventRow({ event, showScriptOutput, prevEvent }: { event: EnrollmentEvent; showScriptOutput?: boolean; prevEvent?: EnrollmentEvent | null }) {
|
||||
const prevDisplayTime = prevEvent ? getDisplayTime(prevEvent) : null;
|
||||
const [showDetails, setShowDetails] = useState(false);
|
||||
const [showRaw, setShowRaw] = useState(false);
|
||||
const [copied, setCopied] = useState(false);
|
||||
@@ -489,6 +537,7 @@ function EventRow({ event, showScriptOutput, prevDisplayTime }: { event: Enrollm
|
||||
)}
|
||||
</span>
|
||||
<GapBadge prevTime={prevDisplayTime ?? null} eventTime={recordedAt ?? new Date(event.timestamp)} />
|
||||
<TimeJumpBadge prevEvent={prevEvent} event={event} />
|
||||
<SeverityBadge severity={event.severity} />
|
||||
{isBackfilled && (
|
||||
<span
|
||||
@@ -498,6 +547,14 @@ function EventRow({ event, showScriptOutput, prevDisplayTime }: { event: Enrollm
|
||||
⟲ Backfilled
|
||||
</span>
|
||||
)}
|
||||
{event.timestampClamped && (
|
||||
<span
|
||||
className="px-2 py-0.5 rounded text-xs font-medium bg-amber-100 text-amber-800"
|
||||
title={`${CLAMPED_TOOLTIP_PREFIX}${event.originalTimestamp ? ` Original device timestamp: ${event.originalTimestamp}.` : ""}`}
|
||||
>
|
||||
⧖ Clamped
|
||||
</span>
|
||||
)}
|
||||
<span className="text-sm font-medium text-gray-900">{event.eventType}</span>
|
||||
</div>
|
||||
<p className="mt-1 text-sm text-gray-600" title={event.message || undefined}>{shortenBuildHashInMessage(event.message)}</p>
|
||||
@@ -666,12 +723,12 @@ function EventRow({ event, showScriptOutput, prevDisplayTime }: { event: Enrollm
|
||||
)}
|
||||
</button>
|
||||
<div className="flex">
|
||||
<span className="w-16 flex-shrink-0 text-gray-400">EventId</span>
|
||||
<span className="w-24 flex-shrink-0 text-gray-400">EventId</span>
|
||||
<span className="font-mono">{event.eventId}</span>
|
||||
</div>
|
||||
{recordedAt && (
|
||||
<div className="flex mt-0.5">
|
||||
<span className="w-16 flex-shrink-0 text-gray-400">Recorded</span>
|
||||
<span className="w-24 flex-shrink-0 text-gray-400">Recorded</span>
|
||||
<span className="font-mono">
|
||||
{recordedAt.toISOString().replace('T', ' ').replace('Z', '')}
|
||||
<span className="text-gray-400 ml-1" title={BACKFILL_TOOLTIP}>(event log, pre-agent)</span>
|
||||
@@ -679,11 +736,11 @@ function EventRow({ event, showScriptOutput, prevDisplayTime }: { event: Enrollm
|
||||
</div>
|
||||
)}
|
||||
<div className="flex mt-0.5">
|
||||
<span className="w-16 flex-shrink-0 text-gray-400">Created</span>
|
||||
<span className="w-24 flex-shrink-0 text-gray-400">Created</span>
|
||||
<span className="font-mono">{event.timestamp}</span>
|
||||
</div>
|
||||
<div className="flex mt-0.5">
|
||||
<span className="w-16 flex-shrink-0 text-gray-400">Received</span>
|
||||
<span className="w-24 flex-shrink-0 text-gray-400">Received</span>
|
||||
<span className="font-mono">
|
||||
{event.receivedAt
|
||||
? new Date(event.receivedAt).toISOString().replace('T', ' ').replace('Z', '')
|
||||
@@ -701,10 +758,11 @@ function EventRow({ event, showScriptOutput, prevDisplayTime }: { event: Enrollm
|
||||
</div>
|
||||
{hasPhase && (
|
||||
<div className="flex mt-0.5">
|
||||
<span className="w-16 flex-shrink-0 text-gray-400">Phase</span>
|
||||
<span className="w-24 flex-shrink-0 text-gray-400">Phase</span>
|
||||
<span>{event.phaseName}</span>
|
||||
</div>
|
||||
)}
|
||||
<TimeProvenanceRows event={event} />
|
||||
</div>
|
||||
);
|
||||
})()}
|
||||
@@ -817,11 +875,111 @@ function EventRow({ event, showScriptOutput, prevDisplayTime }: { event: Enrollm
|
||||
);
|
||||
}
|
||||
|
||||
function RawEventRow({ event, prevDisplayTime }: { event: EnrollmentEvent; prevDisplayTime?: Date | null }) {
|
||||
// Origin chip styling/wording for the sourceOffsetOrigin provenance value. Unknown
|
||||
// values render verbatim in gray so a future agent origin never breaks the UI.
|
||||
const ORIGIN_CHIP: Record<string, { className: string; title: string }> = {
|
||||
"line-anchored": {
|
||||
className: "bg-sky-100 text-sky-800",
|
||||
title: "Offset anchored to a UTC reference line near this log line — the most precise source.",
|
||||
},
|
||||
bias: {
|
||||
className: "bg-slate-200 text-slate-600",
|
||||
title: "Offset taken from the log line's own timezone bias — declared by the writer, authoritative.",
|
||||
},
|
||||
"reader-zone-fallback": {
|
||||
className: "bg-amber-100 text-amber-800",
|
||||
title: "No anchor available — the reader's timezone was assumed for the whole file. Times are internally consistent but the absolute frame may be wrong.",
|
||||
},
|
||||
calibrated: {
|
||||
className: "bg-gray-100 text-gray-500",
|
||||
title: "Legacy origin emitted by older agents (retired).",
|
||||
},
|
||||
};
|
||||
|
||||
// The raw CMTrace time-resolution values (P13): how this event's UTC timestamp was
|
||||
// produced. Rendered inside the expanded metadata block only — per-row badges are
|
||||
// reserved for the rare jump/clamp cases, everything else lives here on demand.
|
||||
function TimeProvenanceRows({ event }: { event: EnrollmentEvent }) {
|
||||
const provenance = readTimeProvenance(event.data);
|
||||
if (!provenance && !event.timestampClamped) return null;
|
||||
|
||||
const origin = provenance?.sourceOffsetOrigin;
|
||||
const originChip = origin ? ORIGIN_CHIP[origin] ?? { className: "bg-gray-100 text-gray-500", title: origin } : null;
|
||||
|
||||
return (
|
||||
<div className="mt-1.5 pt-1.5 border-t border-gray-200">
|
||||
<div className="text-[10px] uppercase tracking-wide text-gray-400 mb-0.5">Time provenance</div>
|
||||
{provenance?.sourceLocalTs && (
|
||||
<div className="flex mt-0.5">
|
||||
<span className="w-24 flex-shrink-0 text-gray-400">Local time</span>
|
||||
<span className="font-mono">
|
||||
{provenance.sourceLocalTs}
|
||||
<span className="text-gray-400 ml-1 font-sans">(as written in the log)</span>
|
||||
</span>
|
||||
</div>
|
||||
)}
|
||||
{provenance?.sourceOffsetMinutes !== null && provenance?.sourceOffsetMinutes !== undefined && (
|
||||
<div className="flex mt-0.5 items-center">
|
||||
<span className="w-24 flex-shrink-0 text-gray-400">UTC offset</span>
|
||||
<span className="font-mono">{formatUtcOffset(provenance.sourceOffsetMinutes)}</span>
|
||||
<span className="text-gray-400 ml-1">(applied)</span>
|
||||
{originChip && origin && (
|
||||
<span className={`ml-2 px-1.5 py-0.5 rounded text-[10px] font-medium ${originChip.className}`} title={originChip.title}>
|
||||
{origin}
|
||||
{origin === "calibrated" && <span className="ml-1 font-normal">(retired)</span>}
|
||||
</span>
|
||||
)}
|
||||
</div>
|
||||
)}
|
||||
{provenance?.measuredWriterOffsetMinutes !== null && provenance?.measuredWriterOffsetMinutes !== undefined && (
|
||||
<div className="flex mt-0.5">
|
||||
<span className="w-24 flex-shrink-0 text-gray-400">Writer offset</span>
|
||||
<span
|
||||
className="font-mono"
|
||||
title="Measured from the log writer's paired local/UTC lines. Sticky after era flip-backs, so it can lag reality. The applied correction is the UTC offset above."
|
||||
>
|
||||
{formatUtcOffset(provenance.measuredWriterOffsetMinutes)}
|
||||
<span className="text-gray-400 ml-1 font-sans">(observed from the writer's own UTC lines — not the applied correction)</span>
|
||||
</span>
|
||||
</div>
|
||||
)}
|
||||
{provenance?.derivedTimestamp && (
|
||||
<div className="flex mt-0.5">
|
||||
<span className="w-24 flex-shrink-0 text-gray-400">Derived time</span>
|
||||
<span className="font-mono">
|
||||
{provenance.derivedTimestamp}
|
||||
<span className="text-gray-400 ml-1 font-sans">(line timestamp unusable — agent clock substituted)</span>
|
||||
</span>
|
||||
</div>
|
||||
)}
|
||||
{provenance?.rejectedSourceTimestamp && (
|
||||
<div className="flex mt-0.5">
|
||||
<span className="w-24 flex-shrink-0 text-gray-400">Rejected time</span>
|
||||
<span className="font-mono">
|
||||
{provenance.rejectedSourceTimestamp}
|
||||
<span className="text-gray-400 ml-1 font-sans">(rejected by the staleness clamp)</span>
|
||||
</span>
|
||||
</div>
|
||||
)}
|
||||
{event.timestampClamped && (
|
||||
<div className="flex mt-0.5">
|
||||
<span className="w-24 flex-shrink-0 text-gray-400">Original time</span>
|
||||
<span className="font-mono">
|
||||
{event.originalTimestamp ?? "—"}
|
||||
<span className="text-gray-400 ml-1 font-sans">(before ingest clamp)</span>
|
||||
</span>
|
||||
</div>
|
||||
)}
|
||||
</div>
|
||||
);
|
||||
}
|
||||
|
||||
function RawEventRow({ event, prevEvent }: { event: EnrollmentEvent; prevEvent?: EnrollmentEvent | null }) {
|
||||
const [expanded, setExpanded] = useState(false);
|
||||
const detailData = useMemo(() => normalizeEventDataForDisplay(event.data), [event.data]);
|
||||
const hasDetails = detailData && Object.keys(detailData).length > 0;
|
||||
const { isBackfilled, recordedAt } = getBackfillInfo(event);
|
||||
const prevDisplayTime = prevEvent ? getDisplayTime(prevEvent) : null;
|
||||
|
||||
const sevColor: Record<string, string> = {
|
||||
Trace: "text-purple-500",
|
||||
@@ -838,10 +996,14 @@ function RawEventRow({ event, prevDisplayTime }: { event: EnrollmentEvent; prevD
|
||||
<span className="text-gray-400 w-8 text-right flex-shrink-0">{event.sequence}</span>
|
||||
<span className="text-gray-500 flex-shrink-0">{(recordedAt ?? new Date(event.timestamp)).toLocaleTimeString()}</span>
|
||||
<GapBadge prevTime={prevDisplayTime ?? null} eventTime={recordedAt ?? new Date(event.timestamp)} />
|
||||
<TimeJumpBadge prevEvent={prevEvent} event={event} />
|
||||
<span className={`flex-shrink-0 w-14 ${sevColor[event.severity] || "text-gray-500"}`}>{event.severity}</span>
|
||||
{isBackfilled && (
|
||||
<span className="text-slate-500 flex-shrink-0" title={BACKFILL_TOOLTIP}>⟲</span>
|
||||
)}
|
||||
{event.timestampClamped && (
|
||||
<span className="text-amber-600 flex-shrink-0" title={`${CLAMPED_TOOLTIP_PREFIX}${event.originalTimestamp ? ` Original device timestamp: ${event.originalTimestamp}.` : ""}`}>⧖</span>
|
||||
)}
|
||||
<span className="text-gray-900 font-medium flex-shrink-0">{event.eventType}</span>
|
||||
<span className="text-gray-500 truncate flex-1 min-w-0" title={event.message || undefined}>{shortenBuildHashInMessage(event.message)}</span>
|
||||
{hasDetails && (
|
||||
|
||||
@@ -1,5 +1,5 @@
|
||||
import { describe, it, expect } from "vitest";
|
||||
import { formatBytes, formatThroughput, formatDuration, formatPercent } from "../formatting";
|
||||
import { formatBytes, formatThroughput, formatDuration, formatPercent, formatUtcOffset } from "../formatting";
|
||||
|
||||
describe("formatBytes", () => {
|
||||
it("returns the zero sentinel for 0 / negative / non-finite", () => {
|
||||
@@ -51,3 +51,17 @@ describe("formatPercent", () => {
|
||||
expect(formatPercent(5, 0)).toBe("—");
|
||||
});
|
||||
});
|
||||
|
||||
describe("formatUtcOffset", () => {
|
||||
it("renders signed HH:MM offsets, including quarter-hour zones", () => {
|
||||
expect(formatUtcOffset(0)).toBe("UTC+00:00");
|
||||
expect(formatUtcOffset(120)).toBe("UTC+02:00");
|
||||
expect(formatUtcOffset(-540)).toBe("UTC−09:00");
|
||||
expect(formatUtcOffset(345)).toBe("UTC+05:45"); // Nepal
|
||||
expect(formatUtcOffset(-270)).toBe("UTC−04:30");
|
||||
});
|
||||
|
||||
it("dashes on non-finite input", () => {
|
||||
expect(formatUtcOffset(NaN)).toBe("—");
|
||||
});
|
||||
});
|
||||
|
||||
@@ -0,0 +1,61 @@
|
||||
import { describe, it, expect } from "vitest";
|
||||
import { groupEventsByPhase } from "../../app/sessions/utils/eventHelpers";
|
||||
import type { EnrollmentEvent } from "@/types";
|
||||
|
||||
/**
|
||||
* Pins the P13 guardrail: the timeline orders by SEQUENCE, never by time. Sequence is a
|
||||
* persisted, strictly monotonic per-session counter assigned at emit time and immune to
|
||||
* every clock problem; the timestamp carries the device clock frame plus, for
|
||||
* CMTrace-derived events, the writer's timezone belief. A backdated line (the field case:
|
||||
* mdm_policy_reboot_required at −58 min amid live events) must stay at its sequence
|
||||
* position — the display marks the jump, the order never moves.
|
||||
*/
|
||||
|
||||
const PHASE_NAMES: Record<number, string> = { 0: "Unknown", 1: "Start" };
|
||||
const PHASE_ORDER = ["Start"];
|
||||
|
||||
function makeEvent(sequence: number, timestamp: string, phase = 0): EnrollmentEvent {
|
||||
return {
|
||||
eventId: `evt-${sequence}`,
|
||||
sessionId: "s",
|
||||
timestamp,
|
||||
eventType: "status_update",
|
||||
severity: "Info",
|
||||
source: "DecisionEngine",
|
||||
phase,
|
||||
message: "",
|
||||
sequence,
|
||||
};
|
||||
}
|
||||
|
||||
describe("groupEventsByPhase ordering", () => {
|
||||
it("orders strictly by sequence — a backdated timestamp never moves an event", () => {
|
||||
// Shuffled input; sequence 4 carries a timestamp 9 h EARLIER than its neighbors
|
||||
// (era-mixed CMTrace line). Time-based sorting would pull it to the front.
|
||||
const events = [
|
||||
makeEvent(5, "2026-08-20T10:05:00Z"),
|
||||
makeEvent(2, "2026-08-20T10:01:00Z"),
|
||||
makeEvent(4, "2026-08-20T01:03:00Z"), // backdated by ~9h, higher sequence
|
||||
makeEvent(1, "2026-08-20T10:00:00Z", 1),
|
||||
makeEvent(3, "2026-08-20T10:02:00Z"),
|
||||
];
|
||||
|
||||
const { eventsByPhase, orderedPhases } = groupEventsByPhase(events, PHASE_NAMES, PHASE_ORDER);
|
||||
|
||||
expect(orderedPhases).toEqual(["Start"]);
|
||||
expect(eventsByPhase["Start"].map(e => e.sequence)).toEqual([1, 2, 3, 4, 5]);
|
||||
});
|
||||
|
||||
it("uses the timestamp only as a tie-break for EQUAL sequence values", () => {
|
||||
// Equal sequences happen when the counter was not persisted across a reboot.
|
||||
const events = [
|
||||
makeEvent(1, "2026-08-20T10:00:00Z", 1),
|
||||
{ ...makeEvent(7, "2026-08-20T10:09:00Z"), eventId: "b" },
|
||||
{ ...makeEvent(7, "2026-08-20T10:07:00Z"), eventId: "a" },
|
||||
];
|
||||
|
||||
const { eventsByPhase } = groupEventsByPhase(events, PHASE_NAMES, PHASE_ORDER);
|
||||
|
||||
expect(eventsByPhase["Start"].map(e => e.eventId)).toEqual(["evt-1", "a", "b"]);
|
||||
});
|
||||
});
|
||||
@@ -0,0 +1,118 @@
|
||||
import { describe, it, expect } from "vitest";
|
||||
import {
|
||||
readTimeProvenance,
|
||||
classifyTimeJump,
|
||||
BACKWARD_JUMP_THRESHOLD_MS,
|
||||
type TimeJumpInput,
|
||||
} from "../timeProvenance";
|
||||
|
||||
const T0 = new Date("2026-08-20T10:00:00Z");
|
||||
const minutes = (m: number) => new Date(T0.getTime() + m * 60 * 1000);
|
||||
|
||||
function input(displayTime: Date, data?: Record<string, unknown>): TimeJumpInput {
|
||||
return { displayTime, provenance: readTimeProvenance(data) };
|
||||
}
|
||||
|
||||
describe("readTimeProvenance", () => {
|
||||
it("reads camelCase keys and parses numeric strings", () => {
|
||||
const p = readTimeProvenance({
|
||||
sourceLocalTs: "2026-08-20T05:31:46.5192284",
|
||||
sourceOffsetMinutes: "-540",
|
||||
sourceOffsetOrigin: "line-anchored",
|
||||
measuredWriterOffsetMinutes: "120",
|
||||
derivedTimestamp: "true",
|
||||
rejectedSourceTimestamp: "2026-08-13T09:00:00Z",
|
||||
});
|
||||
expect(p).not.toBeNull();
|
||||
expect(p!.sourceOffsetMinutes).toBe(-540);
|
||||
expect(p!.measuredWriterOffsetMinutes).toBe(120);
|
||||
expect(p!.sourceOffsetOrigin).toBe("line-anchored");
|
||||
expect(p!.derivedTimestamp).toBe("true");
|
||||
});
|
||||
|
||||
it("falls back to snake_case keys (historicReplay.ts convention)", () => {
|
||||
const p = readTimeProvenance({
|
||||
source_offset_minutes: "120",
|
||||
source_offset_origin: "reader-zone-fallback",
|
||||
});
|
||||
expect(p!.sourceOffsetMinutes).toBe(120);
|
||||
expect(p!.sourceOffsetOrigin).toBe("reader-zone-fallback");
|
||||
});
|
||||
|
||||
it("returns null when no provenance key is present (undefined data, truncated payload)", () => {
|
||||
expect(readTimeProvenance(undefined)).toBeNull();
|
||||
expect(readTimeProvenance(null)).toBeNull();
|
||||
expect(readTimeProvenance({})).toBeNull();
|
||||
// DataJson >30KB gets stored truncated; the UI then holds { _rawDataJson: "..." }.
|
||||
expect(readTimeProvenance({ _rawDataJson: '{"sourceOffsetMinutes":"120", …' })).toBeNull();
|
||||
expect(readTimeProvenance({ appId: "x", exitCode: "0" })).toBeNull();
|
||||
});
|
||||
|
||||
it("keeps partial provenance and nulls malformed numbers", () => {
|
||||
const p = readTimeProvenance({ sourceOffsetOrigin: "bias", sourceOffsetMinutes: "not-a-number" });
|
||||
expect(p).not.toBeNull();
|
||||
expect(p!.sourceOffsetOrigin).toBe("bias");
|
||||
expect(p!.sourceOffsetMinutes).toBeNull();
|
||||
expect(p!.sourceLocalTs).toBeNull();
|
||||
});
|
||||
|
||||
it("passes unknown origin strings through verbatim (forward compatibility)", () => {
|
||||
expect(readTimeProvenance({ sourceOffsetOrigin: "future-origin" })!.sourceOffsetOrigin).toBe("future-origin");
|
||||
});
|
||||
});
|
||||
|
||||
describe("classifyTimeJump", () => {
|
||||
it("pins the badge threshold at 5 minutes", () => {
|
||||
expect(BACKWARD_JUMP_THRESHOLD_MS).toBe(300_000);
|
||||
});
|
||||
|
||||
it("returns null without a previous rendered row", () => {
|
||||
expect(classifyTimeJump(null, input(T0))).toBeNull();
|
||||
});
|
||||
|
||||
it("ignores forward movement and sub-threshold backwards jitter", () => {
|
||||
expect(classifyTimeJump(input(T0), input(minutes(90)))).toBeNull();
|
||||
// 2 min backwards = interleaved-writer jitter inside the agent's grid tolerance.
|
||||
expect(classifyTimeJump(input(T0), input(minutes(-2)))).toBeNull();
|
||||
});
|
||||
|
||||
it("fires exactly at the threshold boundary", () => {
|
||||
expect(classifyTimeJump(input(T0), input(minutes(-5)))).toEqual({ deltaMs: 300_000, cause: null });
|
||||
expect(classifyTimeJump(input(T0), input(new Date(T0.getTime() - 299_999)))).toBeNull();
|
||||
});
|
||||
|
||||
it("names an era-mixed log when both rows carry differing applied offsets", () => {
|
||||
const prev = input(T0, { sourceOffsetMinutes: "120" });
|
||||
const curr = input(minutes(-540), { sourceOffsetMinutes: "-420" });
|
||||
expect(classifyTimeJump(prev, curr)).toEqual({ deltaMs: 540 * 60 * 1000, cause: "era-offset" });
|
||||
});
|
||||
|
||||
it("does not claim era-offset when either side lacks an offset", () => {
|
||||
const prev = input(T0);
|
||||
const curr = input(minutes(-540), { sourceOffsetMinutes: "-420" });
|
||||
expect(classifyTimeJump(prev, curr)!.cause).toBeNull();
|
||||
});
|
||||
|
||||
it("derivedTimestamp wins over era-offset (precedence)", () => {
|
||||
const prev = input(T0, { sourceOffsetMinutes: "120" });
|
||||
const curr = input(minutes(-540), { sourceOffsetMinutes: "-420", derivedTimestamp: "true" });
|
||||
expect(classifyTimeJump(prev, curr)!.cause).toBe("derived-timestamp");
|
||||
});
|
||||
|
||||
it("names a rejected source timestamp", () => {
|
||||
const curr = input(minutes(-30), { rejectedSourceTimestamp: "2026-08-13T09:00:00Z" });
|
||||
expect(classifyTimeJump(input(T0), curr)!.cause).toBe("rejected-source");
|
||||
});
|
||||
|
||||
it("classifies a week-old backdated replay with the correct magnitude", () => {
|
||||
const weekAgo = new Date(T0.getTime() - 7 * 24 * 60 * 60 * 1000);
|
||||
const jump = classifyTimeJump(input(T0), input(weekAgo));
|
||||
expect(jump).not.toBeNull();
|
||||
expect(jump!.deltaMs).toBe(7 * 24 * 60 * 60 * 1000);
|
||||
expect(jump!.cause).toBeNull();
|
||||
});
|
||||
|
||||
it("respects a caller-supplied threshold", () => {
|
||||
expect(classifyTimeJump(input(T0), input(minutes(-3)), 120_000)).toEqual({ deltaMs: 180_000, cause: null });
|
||||
});
|
||||
});
|
||||
@@ -50,3 +50,17 @@ export function formatPercent(numerator: number, denominator: number, decimals =
|
||||
if (!Number.isFinite(numerator) || !Number.isFinite(denominator) || denominator <= 0) return zero;
|
||||
return `${((numerator / denominator) * 100).toFixed(decimals)}%`;
|
||||
}
|
||||
|
||||
/**
|
||||
* Signed HH:MM UTC offset from a minutes value: 120 -> "UTC+02:00", -345 -> "UTC−05:45",
|
||||
* 0 -> "UTC+00:00". Quarter-hour zones (Nepal +05:45, Chatham +12:45) render exactly.
|
||||
* Non-finite returns `zero`.
|
||||
*/
|
||||
export function formatUtcOffset(minutes: number, zero = "—"): string {
|
||||
if (!Number.isFinite(minutes)) return zero;
|
||||
const sign = minutes < 0 ? "−" : "+";
|
||||
const abs = Math.abs(Math.round(minutes));
|
||||
const h = Math.floor(abs / 60);
|
||||
const m = abs % 60;
|
||||
return `UTC${sign}${String(h).padStart(2, "0")}:${String(m).padStart(2, "0")}`;
|
||||
}
|
||||
|
||||
@@ -0,0 +1,127 @@
|
||||
/**
|
||||
* CMTrace time-resolution provenance (P13): the agent's per-line self-anchoring stamps
|
||||
* CMTrace-derived events with how their UTC timestamp was produced — the raw local time
|
||||
* as written in the log, the applied UTC offset and its origin, the purely observational
|
||||
* per-file writer offset, and the clock-fallback markers. All values arrive as STRINGS
|
||||
* inside the event data payload (see docs/agent/cmtrace-time-resolution.md).
|
||||
*
|
||||
* The timeline sorts by sequence — always, never by time (user guardrail). A displayed
|
||||
* time that steps BACKWARDS within that order is therefore information, not a rendering
|
||||
* bug: a backdated log line, a staleness-clamp fallback, or an era-mixed log whose lines
|
||||
* were corrected with different offsets (session e9753578 carried ±9 h of exactly that).
|
||||
* `classifyTimeJump` names the phenomenon so the timeline can mark the spot instead of
|
||||
* leaving the reader to distrust the order.
|
||||
*/
|
||||
|
||||
export interface TimeProvenance {
|
||||
/** Raw local timestamp as written in the log line (no zone suffix, by design). */
|
||||
sourceLocalTs: string | null;
|
||||
/** UTC offset in minutes that was APPLIED to resolve the timestamp. */
|
||||
sourceOffsetMinutes: number | null;
|
||||
/** How the applied offset was obtained: "bias" | "line-anchored" | "reader-zone-fallback" | retired "calibrated". */
|
||||
sourceOffsetOrigin: string | null;
|
||||
/**
|
||||
* Observational per-file measurement from the writer's own UTC lines — NOT the applied
|
||||
* correction, and sticky after era flip-backs (the monotonicity guard rejects newer
|
||||
* anchors), so it can lag reality. Never present it as "what was applied".
|
||||
*/
|
||||
measuredWriterOffsetMinutes: number | null;
|
||||
/** "true" when the line's own timestamp was unusable and the agent clock was substituted. */
|
||||
derivedTimestamp: string | null;
|
||||
/** The line's own timestamp that the staleness clamp rejected (set alongside derivedTimestamp). */
|
||||
rejectedSourceTimestamp: string | null;
|
||||
}
|
||||
|
||||
function readString(data: Record<string, unknown>, camel: string, snake: string): string | null {
|
||||
const raw = data[camel] ?? data[snake];
|
||||
return typeof raw === "string" && raw.length > 0 ? raw : null;
|
||||
}
|
||||
|
||||
function readNumber(data: Record<string, unknown>, camel: string, snake: string): number | null {
|
||||
const raw = data[camel] ?? data[snake];
|
||||
if (typeof raw === "number") return Number.isFinite(raw) ? raw : null;
|
||||
if (typeof raw !== "string" || raw.length === 0) return null;
|
||||
const parsed = Number(raw);
|
||||
return Number.isFinite(parsed) ? parsed : null;
|
||||
}
|
||||
|
||||
/**
|
||||
* Reads the provenance fields from an event's data payload. Returns null when NO
|
||||
* provenance key is present — which also covers `data` being undefined and the
|
||||
* DataJson-truncation fallback (`_rawDataJson`), where the payload is not an object
|
||||
* of parsed keys at all.
|
||||
*/
|
||||
export function readTimeProvenance(data: Record<string, unknown> | undefined | null): TimeProvenance | null {
|
||||
if (!data || typeof data !== "object") return null;
|
||||
const provenance: TimeProvenance = {
|
||||
sourceLocalTs: readString(data, "sourceLocalTs", "source_local_ts"),
|
||||
sourceOffsetMinutes: readNumber(data, "sourceOffsetMinutes", "source_offset_minutes"),
|
||||
sourceOffsetOrigin: readString(data, "sourceOffsetOrigin", "source_offset_origin"),
|
||||
measuredWriterOffsetMinutes: readNumber(data, "measuredWriterOffsetMinutes", "measured_writer_offset_minutes"),
|
||||
derivedTimestamp: readString(data, "derivedTimestamp", "derived_timestamp"),
|
||||
rejectedSourceTimestamp: readString(data, "rejectedSourceTimestamp", "rejected_source_timestamp"),
|
||||
};
|
||||
const hasAny =
|
||||
provenance.sourceLocalTs !== null ||
|
||||
provenance.sourceOffsetMinutes !== null ||
|
||||
provenance.sourceOffsetOrigin !== null ||
|
||||
provenance.measuredWriterOffsetMinutes !== null ||
|
||||
provenance.derivedTimestamp !== null ||
|
||||
provenance.rejectedSourceTimestamp !== null;
|
||||
return hasAny ? provenance : null;
|
||||
}
|
||||
|
||||
/**
|
||||
* Row-badge threshold for a backwards step of the displayed time. Field-measured
|
||||
* (2026-08-20, 20 sessions): normal sessions max out at 0.6–1.7 min of interleaved-writer
|
||||
* jitter (the agent's own grid tolerance is 2 min), while every genuine offset phenomenon
|
||||
* starts at the 15-minute zone quantum. 5 min sits safely between the two — at this
|
||||
* threshold 12/12 normal sessions showed zero badges.
|
||||
*/
|
||||
export const BACKWARD_JUMP_THRESHOLD_MS = 5 * 60 * 1000;
|
||||
|
||||
export type TimeJumpCause = "era-offset" | "derived-timestamp" | "rejected-source" | null;
|
||||
|
||||
export interface TimeJump {
|
||||
/** Positive magnitude of the backwards step in milliseconds. */
|
||||
deltaMs: number;
|
||||
cause: TimeJumpCause;
|
||||
}
|
||||
|
||||
export interface TimeJumpInput {
|
||||
displayTime: Date;
|
||||
provenance: TimeProvenance | null;
|
||||
}
|
||||
|
||||
/**
|
||||
* Detects a backwards step of the displayed time versus the previous RENDERED row and
|
||||
* names its cause when the provenance identifies one. Cause precedence: a clock-fallback
|
||||
* (derived) timestamp explains the row by itself; a rejected source timestamp likewise;
|
||||
* only then is an offset difference between the two rows read as an era-mixed log.
|
||||
* Callers pass prev = null at phase-section starts (jump detection never spans sections).
|
||||
*/
|
||||
export function classifyTimeJump(
|
||||
prev: TimeJumpInput | null,
|
||||
curr: TimeJumpInput,
|
||||
thresholdMs: number = BACKWARD_JUMP_THRESHOLD_MS,
|
||||
): TimeJump | null {
|
||||
if (!prev) return null;
|
||||
const deltaMs = prev.displayTime.getTime() - curr.displayTime.getTime();
|
||||
if (!Number.isFinite(deltaMs) || deltaMs < thresholdMs) return null;
|
||||
|
||||
let cause: TimeJumpCause = null;
|
||||
if (curr.provenance?.derivedTimestamp) {
|
||||
cause = "derived-timestamp";
|
||||
} else if (curr.provenance?.rejectedSourceTimestamp) {
|
||||
cause = "rejected-source";
|
||||
} else if (
|
||||
prev.provenance?.sourceOffsetMinutes !== null &&
|
||||
prev.provenance?.sourceOffsetMinutes !== undefined &&
|
||||
curr.provenance?.sourceOffsetMinutes !== null &&
|
||||
curr.provenance?.sourceOffsetMinutes !== undefined &&
|
||||
prev.provenance.sourceOffsetMinutes !== curr.provenance.sourceOffsetMinutes
|
||||
) {
|
||||
cause = "era-offset";
|
||||
}
|
||||
return { deltaMs, cause };
|
||||
}
|
||||
@@ -11,6 +11,10 @@ export interface EnrollmentEvent {
|
||||
sequence: number;
|
||||
receivedAt?: string;
|
||||
data?: Record<string, unknown>;
|
||||
/** True when ingest clamped an out-of-range device timestamp to server time. */
|
||||
timestampClamped?: boolean;
|
||||
/** The pre-clamp device timestamp; only set when timestampClamped is true. */
|
||||
originalTimestamp?: string | null;
|
||||
}
|
||||
|
||||
export interface RuleResult {
|
||||
|
||||
Reference in New Issue
Block a user