diff --git a/MEMORY.md b/MEMORY.md index e91bf2d45ff..0ac6f20d835 100644 --- a/MEMORY.md +++ b/MEMORY.md @@ -8,3 +8,4 @@ follow the regression convention: every bullet is pinned by a test in - 2026-07-01: `recordTrustDecision` must compute the graduation confidence from the same clock read it stores as `last_updated` — re-reading `Date.now()` inside `calculateConfidence` let a ≥1ms scheduler gap on loaded CI runners decay an exact-threshold confidence (4/5 = 0.80 vs 0.8 gate) below the gate, so `trust.graduated` never fired. (`tests/regression/test_trust-graduation-clock-skew.test.ts`) - 2026-07-01: brain tests that drive the ingest pipeline must `vi.mock('../embed.js')` (and qdrant.js) — an unmocked test cold-loads the real ~140MB transformers model on CI and `stopBrainIngest()`'s queue drain blows the 10s hook timeout; drain via `stopBrainIngest()` instead of sleeping past `maxLatencyMs` (fixed sleeps are the #89 flake class). (`tests/regression/test_brain-tests-mock-embed.test.ts`) +- 2026-07-16: never pass a caller-side `Date.now()` into a fixture that samples its own clock — JS evaluates arguments _before_ the call, so `seedItem({ pushed_at: Date.now() })` sampled `pushed_at` first and `detected_at` second, and a ≥1ms gap landed `pushed_at` 1ms _before_ `detected_at`, tripping `timestamps-monotonic` (~1 in 42k idle; far more on a loaded runner — bare re-runs went green, so it read as "just flaky"). Fixture defaults derive from the earliest stamp on the row; an explicit `detected_at` still wins so counter-examples stay constructible. Same family as the 2026-07-01 trust-graduation bullet: **two clock reads assumed to be one instant**. Loosening the predicate would have been wrong — it is already `>=`-tolerant, and the invariant is real. (`tests/regression/test_invariants-seed-clock-skew.test.ts`) diff --git a/src/__tests__/helpers/seed-tracked-item.ts b/src/__tests__/helpers/seed-tracked-item.ts new file mode 100644 index 00000000000..f077b1647e9 --- /dev/null +++ b/src/__tests__/helpers/seed-tracked-item.ts @@ -0,0 +1,56 @@ +/** + * Shared seeding fixture for the tracked_items invariant suites. + * + * Lives outside the *.test.ts glob so vitest treats it as a module, not a + * suite. Imported by src/__tests__/invariants-runtime-proof.test.ts and by + * tests/regression/test_invariants-seed-clock-skew.test.ts, so the regression + * test pins the real fixture rather than a copy of it. + */ +import { insertTrackedItem, type TrackedItem } from '../../tracked-items.js'; + +export function seedItem(overrides: Partial = {}): TrackedItem { + const now = Date.now(); + // JS evaluates argument expressions before the call, so a caller writing + // `seedItem({ pushed_at: Date.now() })` sampled that stamp *before* the + // `now` above. A millisecond tick in between (routine on a loaded CI + // runner) would seed detected_at 1ms after pushed_at and trip + // timestamps-monotonic. Derive the default from the earliest stamp on the + // row instead. An explicit detected_at in `overrides` still wins, so the + // time-reversal counter-examples stay constructible. + const detectedAt = Math.min( + now, + ...[overrides.pushed_at, overrides.resolved_at].filter( + (t): t is number => typeof t === 'number', + ), + ); + const item: TrackedItem = { + id: `item-${Math.random().toString(36).slice(2, 10)}`, + source: 'gmail', + source_id: `src-${Math.random().toString(36).slice(2, 10)}`, + group_name: 'main', + state: 'queued', + classification: 'push', + superpilot_label: null, + trust_tier: null, + title: 'test', + summary: null, + thread_id: 't', + detected_at: detectedAt, + pushed_at: null, + resolved_at: null, + resolution_method: null, + digest_count: 0, + telegram_message_id: null, + classification_reason: null, + metadata: { sender: 'x@example.com', account: 'me@gmail.com' }, + confidence: 0.9, + model_tier: 1, + action_intent: null, + facts_extracted: null, + repo_candidates: null, + reasons: null, + ...overrides, + }; + insertTrackedItem(item); + return item; +} diff --git a/src/__tests__/invariants-runtime-proof.test.ts b/src/__tests__/invariants-runtime-proof.test.ts index 53fb282de8c..3f888c9110a 100644 --- a/src/__tests__/invariants-runtime-proof.test.ts +++ b/src/__tests__/invariants-runtime-proof.test.ts @@ -31,50 +31,13 @@ import { handleDismiss, handleSnooze, } from '../triage/queue-actions.js'; -import { - insertTrackedItem, - transitionItemState, - type TrackedItem, -} from '../tracked-items.js'; +import { transitionItemState } from '../tracked-items.js'; +import { seedItem } from './helpers/seed-tracked-item.js'; import { STATE_MACHINE_INVARIANTS, mutedThreadsNeverVisible, } from '../../scripts/qa/invariant-predicates.js'; -function seedItem(overrides: Partial = {}): TrackedItem { - const now = Date.now(); - const item: TrackedItem = { - id: `item-${Math.random().toString(36).slice(2, 10)}`, - source: 'gmail', - source_id: `src-${Math.random().toString(36).slice(2, 10)}`, - group_name: 'main', - state: 'queued', - classification: 'push', - superpilot_label: null, - trust_tier: null, - title: 'test', - summary: null, - thread_id: 't', - detected_at: now, - pushed_at: null, - resolved_at: null, - resolution_method: null, - digest_count: 0, - telegram_message_id: null, - classification_reason: null, - metadata: { sender: 'x@example.com', account: 'me@gmail.com' }, - confidence: 0.9, - model_tier: 1, - action_intent: null, - facts_extracted: null, - repo_candidates: null, - reasons: null, - ...overrides, - }; - insertTrackedItem(item); - return item; -} - /** * Run every state-machine predicate against the test DB. Each must * return 0. The label is prefixed onto the assertion message so failures diff --git a/tests/regression/test_invariants-seed-clock-skew.test.ts b/tests/regression/test_invariants-seed-clock-skew.test.ts new file mode 100644 index 00000000000..facb80db035 --- /dev/null +++ b/tests/regression/test_invariants-seed-clock-skew.test.ts @@ -0,0 +1,72 @@ +// Lesson 2026-07-16: the seedItem fixture must derive its default detected_at +// from a clock read that cannot post-date a caller-supplied pushed_at / +// resolved_at. JS evaluates argument expressions BEFORE the call, so +// `seedItem({ state: 'pushed', pushed_at: Date.now() })` sampled pushed_at +// first and detected_at second; a >=1ms scheduler gap on a loaded CI runner +// landed pushed_at 1ms BEFORE detected_at and tripped the +// timestamps-monotonic invariant ("predicate returned 1 (want 0)" at +// invariants-runtime-proof.test.ts:90, run 29550755556, PR #98). Measured +// ~1 in 42k on an idle machine, which is why bare re-runs went green. +// +// Same root-cause family as the 2026-07-01 trust-graduation lesson: two +// Date.now() reads assumed to be the same instant. + +import { describe, it, expect, beforeEach, afterEach, vi } from 'vitest'; + +import { _initTestDatabase, _closeDatabase, getDb } from '../../src/db.js'; +import { handleDismiss } from '../../src/triage/queue-actions.js'; +import { seedItem } from '../../src/__tests__/helpers/seed-tracked-item.js'; +import { STATE_MACHINE_INVARIANTS } from '../../scripts/qa/invariant-predicates.js'; + +const monotonic = STATE_MACHINE_INVARIANTS.find( + (i) => i.name === 'timestamps-monotonic', +)!; + +function monotonicViolations(): number { + return (getDb().prepare(monotonic.countSql).get() as { n: number }).n; +} + +/** + * Advance the clock 1ms on every read. Models the scheduler gap a loaded + * runner can insert between two adjacent Date.now() calls — deterministically, + * instead of waiting ~42k runs for the real race. + */ +function mockTickingClock() { + const realNow = Date.now.bind(Date); + let tick = 0; + return vi.spyOn(Date, 'now').mockImplementation(() => realNow() + ++tick); +} + +describe('seedItem fixture under clock skew', () => { + beforeEach(() => _initTestDatabase()); + afterEach(() => { + vi.restoreAllMocks(); + _closeDatabase(); + }); + + it('a pushed row seeded with a caller-sampled pushed_at never inverts detected_at', () => { + mockTickingClock(); + + // Exact call shape from invariants-runtime-proof.test.ts:136 — the + // caller's Date.now() is evaluated before seedItem's own read. + const item = seedItem({ state: 'pushed', pushed_at: Date.now() }); + + expect(item.pushed_at!).toBeGreaterThanOrEqual(item.detected_at); + + handleDismiss(item.id); + expect(monotonicViolations()).toBe(0); + }); + + it('an explicit detected_at is still honoured verbatim (counter-examples must stay constructible)', () => { + // The fix derives only the *default* detected_at. A caller that states + // detected_at outright still gets it unchanged — otherwise the + // time-reversal counter-example at invariants-runtime-proof.test.ts:377 + // would be silently repaired and stop proving the predicate works. + mockTickingClock(); + + const pinned = 1_700_000_000_000; + const item = seedItem({ state: 'queued', detected_at: pinned }); + + expect(item.detected_at).toBe(pinned); + }); +});