fix(artifacts): event appends and materialize keep working after the host clock steps back - #1211
Conversation
… back After the wall clock stepped back behind the last event in a run's events.jsonl (an NTP step, a VM snapshot restore, a manual correction), every appendEvent call failed with "event journal timestamps are not ordered at record N" until the clock caught up. #1195 let the clean, materialize and dashboard audit journals accept such a step but kept this journal's rule, so `ultrafuzz materialize --confirm` still copied its files and wrote its audit record and then threw, and a rerun failed with MATERIALIZE_DESTINATION_EXISTS. Sync, resume, replay, fork, pause, cancel and the workflow-link commit append events the same way. When the current time is earlier than the journal's final event, appendEvent now stamps the new event one millisecond after that event. Timestamps stay nondecreasing, so the journal's ordering rule and its readers are unchanged. The stamped event is later than every recorded one, so an event identical to the final one still gets a new ID; reusing the final timestamp would have made it a rejected duplicate. A timestamp the caller passes explicitly is still rejected when it is earlier. The final event comes from the same read that fences the write: appendStrictJsonlRecordsAfterTail becomes appendStrictJsonlRecordAfterTail, which builds its one record from the journal's final record. Its window is now the trailing records that share the final record's timestamp rather than the new record's. That still holds every record a new ID can repeat, because a new record either shares the final timestamp or is later than every recorded one. Co-Authored-By: Claude Opus 5.5 <[email protected]>
The first version built every event record inside appendStrictJsonlRecordAfterTail, between the journal read that sets the fence size and the fenced write. Building a record redacts its payload, which costs about 4 ms for a 1.8 KB materialize-selection payload against 0.06 ms for the canonicalization origin/main already runs there, so more concurrent appends failed the size fence. appendEvent again builds the record before the read, as origin/main does. The builder rebuilds it 1 ms after the final event only when the record's time is earlier than that event's: after the wall clock steps back, or when another process appended since the record was built, which origin/main rejected as out of order. The duplicate window stays keyed on the prebuilt record's timestamp; when the record is rebuilt, the window holds only the final event and no recorded event shares the new time. parseStrictJsonlTail and the inWindow signature are origin/main's again. The artifacts test now also checks that an append after an older final event takes the current time. The event journal reference says event times can run ahead of the wall clock after a backward clock step. Co-Authored-By: Claude Opus 5.5 <[email protected]>
Brings in #1202 (modal) and #1203 (runtime tests). Neither touches the files this branch changes, and the merge had no conflicts. Co-Authored-By: Claude Opus 5.5 <[email protected]>
| input.timestamp === undefined && final !== undefined && record.timestamp < final.timestamp | ||
| ? createEventRecord(layout, { ...input, timestamp: new Date(Date.parse(final.timestamp) + 1).toISOString() }) |
There was a problem hiding this comment.
Future timestamps reject valid attempts
When a watched eval run resumes after the host clock steps back, this branch can stamp the controller invocation ahead of the wall clock. Attempt started_at values still come from Smithers NodeStarted events. If an attempt starts before the clock catches up, the recovery-equivalence check treats it as preceding its controller submission, rejects valid lineage, and prevents the eval row from being recorded as terminal.
Prompt To Fix With AI
This is a comment left during a code review.
Path: packages/artifacts/src/events.ts
Line: 1192-1193
Comment:
**Future timestamps reject valid attempts**
When a watched eval run resumes after the host clock steps back, this branch can stamp the controller invocation ahead of the wall clock. Attempt `started_at` values still come from Smithers `NodeStarted` events. If an attempt starts before the clock catches up, the recovery-equivalence check treats it as preceding its controller submission, rejects valid lineage, and prevents the eval row from being recorded as terminal.
---
For each issue above, determine whether it is valid and should be fixed. If so, fix it directly.| // identical event still gets a new ID. | ||
| (final) => | ||
| input.timestamp === undefined && final !== undefined && record.timestamp < final.timestamp | ||
| ? createEventRecord(layout, { ...input, timestamp: new Date(Date.parse(final.timestamp) + 1).toISOString() }) |
There was a problem hiding this comment.
Offset timestamps still block appends
If the journal ends with a valid timestamp using a positive UTC offset, this conversion can produce a UTC string that sorts before the final timestamp even though it represents a later instant. For example, 2026-09-30T16:00:00+05:00 becomes 2026-09-30T11:00:00.001Z. Event history compares the strings, so an append after a backward clock step still throws timestamps are not ordered.
Prompt To Fix With AI
This is a comment left during a code review.
Path: packages/artifacts/src/events.ts
Line: 1193
Comment:
**Offset timestamps still block appends**
If the journal ends with a valid timestamp using a positive UTC offset, this conversion can produce a UTC string that sorts *before* the final timestamp even though it represents a later instant. For example, `2026-09-30T16:00:00+05:00` becomes `2026-09-30T11:00:00.001Z`. Event history compares the strings, so an append after a backward clock step still throws `timestamps are not ordered`.
---
For each issue above, determine whether it is valid and should be fixed. If so, fix it directly.
Problem
materializestops halfway (Greptile, P1, raised on fix: symlinked project roots, locale-independent ordering, clock-skew-tolerant audit journals and other small verified bugs #1195). fix: symlinked project roots, locale-independent ordering, clock-skew-tolerant audit journals and other small verified bugs #1195 let the clean, materialize and dashboard audit journals accept a clock step. It kept the run event journal's rule that timestamps never decrease, which dates from feat: add strict producer-visible JSON contracts with release-lane fix #558. Suppose the wall clock steps back behind a run's last event (an NTP step, a VM snapshot restore, a manual correction). Until the clock passes that event again, everyappendEventcall throwsevent journal timestamps are not ordered at record N.ultrafuzz materialize --confirmcopies the files and appends its audit record, then throws on the event append. The run journal gets nomaterialize-selectionevent. A rerun returnsMATERIALIZE_DESTINATION_EXISTSunless--allow-overwriteis given. The repro againstorigin/mainshows exactly this (run on 2cacf4c; the artifacts and runtime sources are unchanged through 142ba80).Change
appendEvent(packages/artifacts/src/events.ts). It still builds the record before reading the journal, as before. Once the read has found the journal's final event, the record is rebuilt one millisecond after that event when two things hold: the caller passed no timestamp, and the record's time is earlier than the final event's. Otherwise the prebuilt record is appended unchanged.origin/mainrejected that append asnot ordered(see Verification).appendEventcalls in package sources omit it, checked by walking their argument objects with the TypeScript parser. The one spread argument is typedOmit<…, "nodeId" | "runId" | "timestamp">.appendStrictJsonlRecordsAfterTailbecomesappendStrictJsonlRecordAfterTail(packages/artifacts/src/strict-jsonl.ts). It takes a builder in place of the records array, calls it with the final record, and returns the record it appended.appendEventwas its only caller (git grep).materialize-selectionpayload. The canonicalizationorigin/mainalready runs between the read and the fenced write costs 0.06 ms for the same payload. Because the record is prebuilt, redaction stays out of that window, as onorigin/main. Only a rebuilt record is built inside it.docs/reference/artifacts-reports.mdsays that event times can run ahead of the wall clock after a backward clock step.materialize.tsis unchanged.Size: 2 source files +20/−11, 2 test files +48, 1 doc +6/−4.
Deliberately not fixed
appendEventstill rejects a caller-supplied timestamp that is earlier than the final event. That timestamp is the caller's statement of when something happened, and rewriting it would record a false time. Only tests pass one, andan event append refuses a repeated or out-of-order event without changing the journalstill pins the rejection.materializeSelectionstill copies, then appends the audit record, then appends the event. This change removes the finding's trigger. An event append that fails for another reason, such as a full disk or a torn journal, still leaves the copied files and the audit record behind. Making the three steps atomic is a separate change.appendBytesDurableAtchecks the file size, then writes at that offset, with no lock. Two processes can both pass the check and write at the same offset. The result is a lost record, or a leftover tail that makes every later append and replay of that journal fail. The entry points take different locks or none. Sync takes its.workflow-synclock, and launch takes the control lock. Resume, replay and fork take the lifecycle lock, andcancelRunandmaterializeSelectiontake none. So their appends to oneevents.jsonlcan overlap.origin/mainand in 3 of 7 here. In the rounds that did not tear, 0 to 6 records per round were missing although both writers had reported success.Verification
Both new tests fail on
origin/mainand pass on this branch. For theorigin/mainruns, the two source files came fromorigin/mainand the@ultrafuzz/artifactsdist was rebuilt.origin/mainevent appends take the wall clock and keep working after it steps back behind the journalError: event journal timestamps are not ordered at record 2materializeSelection records its event after the host clock steps back behind the run's eventsError: event journal timestamps are not ordered at record 2, thrown bymaterializeSelectionok: true, and the journal's last event is the one the result namesAblations, each run on this branch with one line changed:
record.timestamp < final.timestampfrom the condition, so every append after the first is stamped 1 ms after the final event: the artifacts test fails withstamped 2026-09-29T12:54:00.806Z, wall clock was 2026-09-29T13:54:00.805Z.event journal contains a duplicate identity "evt-…" at record 2.The verifier's repro script calls
materializeSelectionafter a future-dated event. Against this branch's build, the first call returnsok: trueand records its event, and a retry returnsMATERIALIZE_DESTINATION_EXISTS. Onorigin/main, the first call throwsevent journal timestamps are not ordered at record 2after copying.Two-writer contention. Each round, two processes each appended 300
materialize-selectionevents with 1.8 KB payloads to one journal. There were 7 rounds per build, alternating builds.append path changed size) per round: 9 to 51 onorigin/main, 15 to 52 here.timestamps are not orderedfailures: everyorigin/mainround had them (3 to 28 in the 4 rounds that counted them). No round here had any.Suites run on this branch after merging
origin/main142ba80:materialize.test.jsandaudit-contracts.test.js: 9/9.runtime.test.jstests of sync, status, health, resume, launch and workflow linking. 15 of them nameevents.jsonl,replayEventsorappendEventdirectly: 18/18.verified-output.test.js, whose fixtures append events, andclean.test.js: 54/54.lifecycle-inspection.test.js, including thecancelRunandgetRunTimelinetests: 52/52.dynamic-lifecycle.test.js, the two tests that readevents.jsonl: 2/2.npx prettier --checkandnpx eslinton the changed files.CI=1 ESLINT_PLUGIN_DIFF_COMMIT=origin/main pnpm -w lint:strict:ci.pnpm -w lint.pnpm --filter @ultrafuzz/artifacts --filter @ultrafuzz/runtime typecheck.pnpm -w knip.node scripts/docs-check.mjs.Risk / compatibility
origin/main.controller_invoked_at,lifecycle_result_atandlink_event_attake the time from the recordappendEventreturns. Their readers compare it for equality, so they still match. The controller-generation journal checksevent_atordering against wall-clock times, but nothing has written that journal since fix(runtime): restore native Smithers continuation #961..timestamp,controller_invoked_atandlink_event_at). It rejects a node attempt whosestarted_at(taken from the runner'sNodeStartedevent) is earlier than its generation'scontroller_invoked_at. Take an eval run that is resumed while the clock is behind. Its stampedcontroller_invoked_atcan be later than the attempts that resume started, so the scorer rejects that run's lineage. Onorigin/mainthe resume itself failed. The eval runner never resumes runs itself:packages/evals/srchas noresumeRunorreplayRuncall. The campaign path does not read this scorer.queryEventssince/untilfilters and the dashboard show the stamped time for such events.appendStrictJsonlRecordAfterTailreplacesappendStrictJsonlRecordsAfterTailin@ultrafuzz/artifacts, a private workspace package. refactor(artifacts): delete never-dispatched gates, production-dead code, and the unread event index #1181 added the old name, and no release tag contains it.events.ts,strict-jsonl.ts,materialize.tsor the two test files. That was checked against each branch's diff and each PR's file list; fix(modal): keep the model-work flag when a model node has no run-state record #1202 has merged. x01, feat(topology)!: a failed property lens no longer skips the rest of the campaign #1198, refactor!: remove per-node cloud execution (execution.mode = "cloud") #1197 and fix(runtime): record final-report producer selections in the run instead of querying smithers #1183 edit other sections ofdocs/reference/artifacts-reports.md, from line 180 on. This branch edits lines 38–47. A trialgit merge-treeagainst each merges that file cleanly.Changelog entry
Run event appends no longer fail after the host clock steps back behind a run's last event. Until the clock catches up, a new event is stamped one millisecond after the last one.
materialize --confirmnow records its event instead of failing after it has copied files, and sync, resume and cancel keep working.Greptile follow-up
timestamps are not ordered, so the command fails outright. Greptile's scenario also needs an operator to resume an eval's run by hand in that window, because the eval runner never resumes runs (packages/evals/srchas noresumeRunorreplayRun). The recovery-equivalence risk is listed under Risk.appendEventcall omitstimestamp, so every recorded event carries atoISOString()value inZform. The only explicit timestamps come from tests, and an earlier explicit timestamp is still rejected.🤖 Generated with Claude Code