From 8d1f770dfe403ee0146c3176cf6bb217467cd824 Mon Sep 17 00:00:00 2001 From: Tom Boucher Date: Wed, 19 Aug 2026 11:25:24 -0400 Subject: [PATCH] test(#3395): pin the clock and scope the stale-prose scan that reddened windows shard 2/3 (#3669) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit * test(#3395): failing-first coverage for the silently-ignored clock pin Lands the regression matrix BEFORE the fix so the failure is proven rather than asserted. Three assertions fail deterministically on this commit: 1. PINNED_ENV does not actually pin. `_pinnedNowMs()` (src/clock.cts) returns null unless GSD_TEST_MODE is set, so GSD_NOW_MS alone is discarded and last_updated is stamped from the live wall clock. An instant ending ...:35.149Z contains the substring 35.1, which is what reddens the windows-latest shard 2/3 lane roughly 1 run in 600. 2. The colliding-instant regression cannot reach its instant, for the same reason. 3. The #3052 same-date test never lands on 2020-09-10, so it has been exercising the different-date path and passing for the wrong reason. Also adds currentPositionBlock() plus boundary (ms 099/100/199/200, second 34/35/36, LF and CRLF) and two-arm fast-check coverage for the scoped read the fix will switch to. Refs #3395 * test(#3395): pin the clock and scope the stale-prose scan to the body Drives the failing-first coverage from a5a919ffb green. Two changes, both needed: 1. PINNED_ENV now sets GSD_TEST_MODE alongside GSD_NOW_MS. _pinnedNowMs() (src/clock.cts:44) returns null without it, so the pin was silently discarded and last_updated carried a live wall-clock instant. src/clock.cts is deliberately NOT changed: requiring both keys is what stops an ambient GSD_NOW_MS from freezing a production clock, so the caller was the side that was wrong. 2. The stale-prose assertion now reads currentPositionBlock(stateContent) instead of the whole document. Frontmatter is not phase prose, and an instant ending ...:35.149Z contains the substring 35.1 — which is exactly how a document with no stale prose in it produced 'the stale 35.1 phase prose must be refreshed away'. Confirmed hypothesis: the two defects compose. The inert pin supplies a live timestamp; the whole-document scan turns it into a failure. Either alone is latent, which is why this sat unnoticed for five days and then reddened a lane the release never touched. Also corrects two things the failing-first run exposed. The property test used fc.date() without noInvalidDate, so ~1 sample in 300 was an Invalid Date whose toISOString() threw (counterexample: new Date(NaN)); re-soaked at 5000 runs. And a precondition assertion added to the #3052 block was measured to pass with or without the pin, so it was removed rather than shipped as vacuous truth — last_activity there is body-derived, not clock-derived. Refs #3395 * test(#3395): apply review findings — pin #3052, one fixture builder, CRLF coverage Spec-axis review caught a real slip: the #3052 block carried a comment saying its pin was being added as hygiene, but the RED-state revert had removed GSD_TEST_MODE and the fix commit never restored it. A comment describing an action that was not taken is worse than either doing it or leaving it alone — the pin is now actually there. Standards-axis review flagged the same frontmatter+heading fixture shape being rebuilt in three tests. Extracted one stateDoc({iso, lines, eol}) builder; eol is a parameter rather than a constant because the helper's CRLF behavior is a claim under test. Self-review finding: CRLF was only exercised on a single-heading document, and the following-heading case only under LF — so the exact claim the helper's comment rests on (`\n## ` matches inside `\r\n## ` because the CR precedes the newline) was never actually run. The control test now loops both line endings WITH a following heading. Also drops a comment that restated the PINNED_INSTANT rationale verbatim. Refs #3395 --------- Co-authored-by: sim --- tests/state.test.cjs | 161 +++++++++++++++++++++++++++++++++++++++++-- 1 file changed, 157 insertions(+), 4 deletions(-) diff --git a/tests/state.test.cjs b/tests/state.test.cjs index 7ac1d3694..15c61fa4d 100644 --- a/tests/state.test.cjs +++ b/tests/state.test.cjs @@ -3661,10 +3661,17 @@ describe('#3052: planned-phase preserves same-date last_activity_desc', () => { ].join('\n'), ); + // GSD_TEST_MODE is required alongside GSD_NOW_MS or the pin is silently dropped + // (src/clock.cts `_pinnedNowMs`). Measured: this test's `last_activity` is derived + // from the BODY's `**Last Activity:**` line, so the same-date branch it exercises is + // reached either way — only `last_updated` was being stamped from the live wall + // clock. Pinning it is hygiene rather than a live-defect fix: a declared pin that + // silently does nothing is still wrong, and leaving it here teaches the pattern that + // put a wall-clock timestamp into the #3395 block below. const result = runGsdTools( ['state', 'planned-phase', '--phase', '1', '--plans', '3'], tmpDir, - { GSD_NOW_MS: String(Date.parse('2020-09-10T15:00:00.000Z')) }, + { GSD_TEST_MODE: '1', GSD_NOW_MS: String(Date.parse('2020-09-10T15:00:00.000Z')) }, ); assert.ok(result.success, `Command failed: ${result.error}`); @@ -3702,13 +3709,49 @@ describe('#3395: planned-phase refreshes the stale Phase line and persists --nam cleanup(tmpDir); }); - const PINNED_ENV = { GSD_NOW_MS: String(Date.parse('2026-08-14T15:00:00.000Z')) }; + // GSD_TEST_MODE is load-bearing here, not decoration. `_pinnedNowMs()` (src/clock.cts) + // opens with `if (!process.env.GSD_TEST_MODE) return null;`, so GSD_NOW_MS ALONE is + // silently discarded and every `last_updated` below is stamped from the live wall clock + // instead. That is what put a real timestamp into a document this block asserts over, + // and an instant ending `...:35.149Z` contains the substring `35.1` — reddening + // `full test (windows-latest, 24, shard 2/3)` about 1 run in 600 (second == 35 AND + // millisecond in 100..199). The pin is what makes that window unreachable; scoping the + // assertion to `## Current Position` below is what makes it HARMLESS even when a pinned + // value does collide. Both are needed: either alone leaves the defect latent. + const PINNED_INSTANT = '2026-08-14T15:00:00.000Z'; + const PINNED_ENV = { GSD_TEST_MODE: '1', GSD_NOW_MS: String(Date.parse(PINNED_INSTANT)) }; + + // An instant chosen to sit INSIDE that collision window on purpose, so the regression + // below reproduces the CI failure deterministically instead of 1-in-600. + const COLLIDING_INSTANT = '2026-08-14T15:00:35.149Z'; + const COLLIDING_ENV = { GSD_TEST_MODE: '1', GSD_NOW_MS: String(Date.parse(COLLIDING_INSTANT)) }; function frontmatterBlock(stateContent) { const m = stateContent.match(/^---\r?\n([\s\S]*?)\r?\n---/); return m ? m[1] : ''; } + // `## Current Position` is the body prose #3395 is about — the source `state json` + // re-derives current_phase from. Frontmatter is NOT phase prose: `last_updated`, + // `last_activity` and friends legitimately carry digit runs that can spell a phase id, + // so scanning the WHOLE document for a stale id reports staleness that does not exist. + // indexOf rather than a regex: nothing for local/no-unbounded-quantifier to flag, and + // `\n## ` still matches under CRLF because the `\r` precedes the newline. + function currentPositionBlock(stateContent) { + const start = stateContent.indexOf('## Current Position'); + if (start === -1) return ''; + const rest = stateContent.slice(start); + const nextHeading = rest.indexOf('\n## ', 1); + return nextHeading === -1 ? rest : rest.slice(0, nextHeading); + } + + // One builder for every synthetic STATE.md below — the frontmatter + heading shape was + // being rebuilt independently in three tests. `eol` is a parameter because the CRLF + // behavior of currentPositionBlock is a claim under test, not an assumption. + function stateDoc({ iso = PINNED_INSTANT, lines = [], eol = '\n' }) { + return ['---', `last_updated: "${iso}"`, '---', '', '## Current Position', '', ...lines, ''].join(eol); + } + // The issue's repro shape: frontmatter already carries the correct decimal // sub-phase, but the body's `## Current Position` still describes the // PREVIOUS phase's completion prose. @@ -3748,8 +3791,8 @@ describe('#3395: planned-phase refreshes the stale Phase line and persists --nam // The stale body source must not survive the transition that just // declared 35.3 planned — it is the source every body-derived consumer // (state json included) re-reads. - assert.ok(!stateContent.includes('35.1'), - `the stale 35.1 phase prose must be refreshed away; STATE.md was:\n${stateContent}`); + assert.ok(!currentPositionBlock(stateContent).includes('35.1'), + `the stale 35.1 phase prose must be refreshed away from ## Current Position; STATE.md was:\n${stateContent}`); assert.ok(/Phase: 35\.3 — READY TO EXECUTE/m.test(stateContent), `Current Position Phase line must read "Phase: 35.3 — READY TO EXECUTE"; STATE.md was:\n${stateContent}`); // The read path must agree with the write path. @@ -3758,6 +3801,116 @@ describe('#3395: planned-phase refreshes the stale Phase line and persists --nam `state json must report the refreshed phase, got: ${json.current_phase}`); }); + test('regression: PINNED_ENV actually pins the clock — GSD_NOW_MS needs GSD_TEST_MODE', () => { + writeStalePhaseLineFixture(); + const result = runGsdTools(['state', 'planned-phase', '--phase', '35.3', '--plans', '3'], tmpDir, PINNED_ENV); + assert.ok(result.success, `Command failed: ${result.error}`); + + const fm = frontmatterBlock(fs.readFileSync(path.join(tmpDir, '.planning', 'STATE.md'), 'utf-8')); + assert.ok(fm.includes(PINNED_INSTANT), + `last_updated must be the pinned instant ${PINNED_INSTANT} — GSD_NOW_MS is only honored when GSD_TEST_MODE is set too (src/clock.cts _pinnedNowMs); frontmatter was:\n${fm}`); + }); + + test('regression: a last_updated containing the phase-number substring does not trip the stale-prose check', () => { + writeStalePhaseLineFixture(); + const result = runGsdTools(['state', 'planned-phase', '--phase', '35.3', '--plans', '3'], tmpDir, COLLIDING_ENV); + assert.ok(result.success, `Command failed: ${result.error}`); + + const stateContent = fs.readFileSync(path.join(tmpDir, '.planning', 'STATE.md'), 'utf-8'); + // Precondition: we really are at the colliding instant. Fails loudly if the pin ever + // stops working again, rather than degrading this back into a 1-in-600 coin flip. + assert.ok(stateContent.includes(COLLIDING_INSTANT), + `precondition: the clock must be pinned to ${COLLIDING_INSTANT}; STATE.md was:\n${stateContent}`); + // Precondition: the OLD whole-file scan genuinely does match here. This is the exact + // CI failure, reproduced deterministically. + assert.ok(stateContent.includes('35.1'), + `precondition: the whole-document scan must see 35.1 at this instant; STATE.md was:\n${stateContent}`); + // The property actually under test. + assert.ok(!currentPositionBlock(stateContent).includes('35.1'), + `a timestamp containing 35.1 must not be read as stale phase prose; STATE.md was:\n${stateContent}`); + }); + + test('control: the narrowed scan still catches genuinely stale phase prose in the body', () => { + // Both line endings, and both WITH a following `## ` heading — that combination is the + // one the helper's CRLF claim actually rests on (`\n## ` matches inside `\r\n## ` + // because the `\r` precedes the newline). Testing CRLF only on a single-heading + // document would leave exactly that claim unexercised. + for (const eol of ['\n', '\r\n']) { + const stale = stateDoc({ + lines: [ + 'Phase: 35.1 (unattended-launch-prerequisites) — COMPLETE (4/4 plans)', + '', + '## Next', + '', + 'unrelated 35.1 mention outside the block', + ], + eol, + }); + // Narrowing must not defang the check the fix exists to keep. + assert.ok(currentPositionBlock(stale).includes('35.1'), + `genuinely stale phase prose inside ## Current Position must still be reported (eol=${JSON.stringify(eol)})`); + // The slice stops at the next heading, so the trailing mention is out of scope. + assert.ok(!currentPositionBlock(stale).includes('unrelated'), + `the block must end at the next ## heading (eol=${JSON.stringify(eol)})`); + } + // Missing-input class: no heading at all yields an empty block, never a throw. + assert.strictEqual(currentPositionBlock('# Project State\n\nno position heading\n'), ''); + }); + + test('boundary: the 35.1 collision window is exactly milliseconds 100-199 at second 35', () => { + // limit-1 / limit / limit+1 on BOTH axes of the collision. The scoped reader must be + // blind to every one of them; the whole-document reader must match exactly the window. + const cases = [ + { iso: '2026-08-14T15:00:35.099Z', collides: false, why: 'limit-1 (ms 099)' }, + { iso: '2026-08-14T15:00:35.100Z', collides: true, why: 'limit (ms 100)' }, + { iso: '2026-08-14T15:00:35.199Z', collides: true, why: 'limit (ms 199)' }, + { iso: '2026-08-14T15:00:35.200Z', collides: false, why: 'limit+1 (ms 200)' }, + { iso: '2026-08-14T15:00:34.149Z', collides: false, why: 'limit-1 (second 34)' }, + { iso: '2026-08-14T15:00:36.149Z', collides: false, why: 'limit+1 (second 36)' }, + ]; + for (const { iso, collides, why } of cases) { + for (const eol of ['\n', '\r\n']) { + const doc = stateDoc({ iso, lines: ['Phase: 35.3 — READY TO EXECUTE'], eol }); + assert.strictEqual(doc.includes('35.1'), collides, + `whole-document scan for ${iso} (${why}, eol=${JSON.stringify(eol)})`); + assert.ok(!currentPositionBlock(doc).includes('35.1'), + `scoped scan must never match a timestamp: ${iso} (${why}, eol=${JSON.stringify(eol)})`); + } + } + }); + + test('property: no last_updated value can trip the scoped check, and real stale prose always does', () => { + // Two arms against the SAME generated inputs. Arm 1 alone would be satisfied by a + // helper that always returns ''; arm 2 is what makes that impossible. + fc.assert(fc.property( + // noInvalidDate is load-bearing: without it fc.date() emits an Invalid Date about + // 1 sample in 300 and `.toISOString()` throws RangeError. Verified on fast-check + // 4.8.0 — 0 invalid in 300 samples with the flag, 1 without. + fc.date({ + min: new Date('2000-01-01T00:00:00.000Z'), + max: new Date('2099-12-31T23:59:59.999Z'), + noInvalidDate: true, + }), + fc.integer({ min: 1, max: 99 }), + fc.integer({ min: 1, max: 9 }), + (when, major, minor) => { + const iso = when.toISOString(); + const clean = stateDoc({ iso, lines: [`Phase: ${major}.${minor} — READY TO EXECUTE`] }); + // Deterministic guard: the frontmatter instant is NEVER inside the block. If the + // helper ever widened back to the whole document this fails on every run, not + // only on the runs where the generated timestamp happens to spell a phase id. + assert.ok(!currentPositionBlock(clean).includes(iso)); + // Arm 1: a clean block never reports the STALE id, whatever the timestamp is. + const staleId = `${major}.${minor}9`; + assert.ok(!currentPositionBlock(clean).includes(staleId)); + // Arm 2: inject genuinely stale prose and it is always reported. + const dirty = stateDoc({ iso, lines: [`Phase: ${staleId} (x) — COMPLETE`] }); + assert.ok(currentPositionBlock(dirty).includes(staleId)); + return true; + }, + ), { numRuns: 200 }); + }); + test('--name is persisted into the Phase line and frontmatter, not silently dropped', () => { writeStalePhaseLineFixture(); const result = runGsdTools(