diff --git a/.agents/skills/write-stable-tests/scripts/run-swift-tests-with-timing.mjs b/.agents/skills/write-stable-tests/scripts/run-swift-tests-with-timing.mjs index a0e1b7cd..d97bcee0 100755 --- a/.agents/skills/write-stable-tests/scripts/run-swift-tests-with-timing.mjs +++ b/.agents/skills/write-stable-tests/scripts/run-swift-tests-with-timing.mjs @@ -21,7 +21,7 @@ export function parseSwiftTimingLine(line) { }; } const swiftFinish = plain.match( - /(?:^|\s)Test (?!run\b|case\b)(.+?)(?: with (\d+) test cases)? (passed|failed|skipped) after ([0-9.]+) seconds\.$/, + /(?:^|\s)Test (?!run\b|case\b)(.+?)(?: with (\d+) test cases)? (passed|failed|skipped) after ([0-9.]+) seconds(?: with \d+ issues?)?\.$/, ); if (swiftFinish) { return { @@ -57,6 +57,17 @@ export function parseSwiftSuiteLine(line) { }; } +export function isSwiftTestCompletionFragment(fragment, testName) { + const plain = fragment.replace(/\u001B\[[0-9;]*m/g, ""); + const completed = parseSwiftTimingLine(plain); + if (completed && completed.event !== "started") return completed.name === testName; + + const result = plain.match(/(?:^|\s)[✔↷] Test (.+)$/u); + if (!result) return false; + const reported = result[1]; + return testName.startsWith(reported) || reported.startsWith(testName); +} + function parseArguments(arguments_) { const separator = arguments_.indexOf("--"); if (separator < 0 || separator === arguments_.length - 1) { @@ -83,7 +94,14 @@ function parseArguments(arguments_) { return options; } -export async function run(options, { runProcessImpl = runProcess } = {}) { +export async function run( + options, + { + runProcessImpl = runProcess, + setTimeoutImpl = setTimeout, + clearTimeoutImpl = clearTimeout, + } = {}, +) { mkdirSync(path.dirname(options.report), { recursive: true }); const logPath = options.report.replace(/\.json$/i, ".log"); const log = createWriteStream(logPath, { flags: "w" }); @@ -91,9 +109,22 @@ export async function run(options, { runProcessImpl = runProcess } = {}) { const records = []; let currentSuite = null; let timedOutTest = null; - let testTimer = null; let terminateChild = () => {}; + const clearTestTimer = (name) => { + const activeTest = active.get(name); + if (!activeTest || activeTest.timer === null) return; + clearTimeoutImpl(activeTest.timer); + activeTest.timer = null; + }; + + const recordPartialLine = (line) => { + const matchingTests = [...active.keys()].filter((name) => + isSwiftTestCompletionFragment(line, name), + ); + if (matchingTests.length === 1) clearTestTimer(matchingTests[0]); + }; + const recordLine = (line, stream) => { log.write(`${stream}: ${line}\n`); const suiteEvent = parseSwiftSuiteLine(line); @@ -102,22 +133,25 @@ export async function run(options, { runProcessImpl = runProcess } = {}) { const event = parseSwiftTimingLine(line); if (!event) return; if (event.event === "started") { - const startedAt = performance.now(); - active.set(event.name, { startedAt, suite: currentSuite }); - if (testTimer) clearTimeout(testTimer); - testTimer = setTimeout(() => { - timedOutTest = { name: event.name, suite: currentSuite }; - terminateChild(); + clearTestTimer(event.name); + const activeTest = { + startedAt: performance.now(), + suite: currentSuite, + timer: null, + }; + active.set(event.name, activeTest); + activeTest.timer = setTimeoutImpl(() => { + if (active.get(event.name) !== activeTest || timedOutTest) return; + timedOutTest = { name: event.name, suite: activeTest.suite }; + activeTest.timer = null; + void terminateChild(); }, options.maxMs); return; } const activeTest = active.get(event.name); + clearTestTimer(event.name); active.delete(event.name); - if (testTimer) { - clearTimeout(testTimer); - testTimer = null; - } records.push({ name: event.name, ...(activeTest?.suite ? { suite: activeTest.suite } : {}), @@ -134,18 +168,20 @@ export async function run(options, { runProcessImpl = runProcess } = {}) { command: options.command, args: options.commandArguments, cwd: REPOSITORY_ROOT, + env: { ...process.env, NSUnbufferedIO: "YES" }, timeoutMs: options.suiteTimeoutMs, onSpawn: ({ terminate }) => { terminateChild = terminate; }, onStdoutLine: (line) => recordLine(line, "stdout"), onStderrLine: (line) => recordLine(line, "stderr"), + onStdoutPartialLine: recordPartialLine, streamStdout: true, streamStderr: true, }); const result = await childPromise; - if (testTimer) clearTimeout(testTimer); + for (const name of active.keys()) clearTestTimer(name); await new Promise((resolve, reject) => { log.once("error", reject); log.end(resolve); diff --git a/.agents/skills/write-stable-tests/scripts/test-timing-lib.mjs b/.agents/skills/write-stable-tests/scripts/test-timing-lib.mjs index 5a3e7941..c20acf18 100755 --- a/.agents/skills/write-stable-tests/scripts/test-timing-lib.mjs +++ b/.agents/skills/write-stable-tests/scripts/test-timing-lib.mjs @@ -58,7 +58,7 @@ export async function terminateProcessTree( return waitForProcessGroupExit(child.pid, forcedTerminationTimeoutMs, pollIntervalMs); } -function lineCollector(callback) { +function lineCollector(callback, partialCallback = () => {}) { const decoder = new StringDecoder("utf8"); let pending = ""; return { @@ -67,6 +67,7 @@ function lineCollector(callback) { const lines = pending.split(/\r?\n/); pending = lines.pop() ?? ""; for (const line of lines) callback(line); + if (pending) partialCallback(pending); }, finish() { pending += decoder.end(); @@ -84,6 +85,8 @@ export function runProcess({ timeoutMs, onStdoutLine = () => {}, onStderrLine = () => {}, + onStdoutPartialLine = () => {}, + onStderrPartialLine = () => {}, onSpawn = () => {}, streamStdout = false, streamStderr = false, @@ -102,8 +105,8 @@ export function runProcess({ }); const stdoutChunks = []; const stderrChunks = []; - const stdoutLines = lineCollector(onStdoutLine); - const stderrLines = lineCollector(onStderrLine); + const stdoutLines = lineCollector(onStdoutLine, onStdoutPartialLine); + const stderrLines = lineCollector(onStderrLine, onStderrPartialLine); let timedOut = false; let timeout; let terminationPromise = null; diff --git a/.agents/skills/write-stable-tests/scripts/test-verify-test-stability.mjs b/.agents/skills/write-stable-tests/scripts/test-verify-test-stability.mjs index 19d8f39b..099a8a74 100755 --- a/.agents/skills/write-stable-tests/scripts/test-verify-test-stability.mjs +++ b/.agents/skills/write-stable-tests/scripts/test-verify-test-stability.mjs @@ -11,6 +11,7 @@ import { parseJUnitCases } from "./parse-junit-cases.mjs"; import { run as runBunTestsWithTiming } from "./run-bun-tests-with-timing.mjs"; import { run as runRustTestsWithTiming } from "./run-rust-tests-with-timing.mjs"; import { + isSwiftTestCompletionFragment, parseSwiftSuiteLine, parseSwiftTimingLine, run as runSwiftTestsWithTiming, @@ -160,10 +161,258 @@ assert.deepEqual( parseSwiftTimingLine("✔ Test parameterized(_:) with 4 test cases passed after 0.125 seconds."), { name: "parameterized(_:)", event: "passed", durationMs: 125, caseCount: 4 }, ); +assert.deepEqual( + parseSwiftTimingLine("✘ Test runBeforeTheSnapshot() failed after 30.259 seconds with 3 issues."), + { name: "runBeforeTheSnapshot()", event: "failed", durationMs: 30259, caseCount: null }, +); assert.deepEqual( parseSwiftSuiteLine('◇ Suite "App localization" started.'), { name: "App localization", event: "started" }, ); +assert.equal( + isSwiftTestCompletionFragment( + "✔ Test catalogHa", + "catalogHasStableUniqueCommandsAndConflictFreeDefaults()", + ), + true, +); +assert.equal( + isSwiftTestCompletionFragment( + "◇ Test catalogHasStableUniqueCommandsAndConflictFreeDefaults() started.", + "catalogHasStableUniqueCommandsAndConflictFreeDefaults()", + ), + false, +); +assert.equal( + isSwiftTestCompletionFragment("✔ Test anotherTest", "catalogHasStableUniqueCommands"), + false, +); +assert.equal( + isSwiftTestCompletionFragment( + "✘ Test runBeforeTheSnapshot() recorded an issue at RunEntryPointTests.swift:35:9", + "runBeforeTheSnapshot()", + ), + false, +); +assert.equal( + isSwiftTestCompletionFragment( + "✘ Test runBeforeTheSnapshot() failed after 30.259 seconds with 3 issues.", + "runBeforeTheSnapshot()", + ), + true, +); + +let observedPartialLine = null; +const partialLineResult = await runProcess({ + command: process.execPath, + args: ["-e", "process.stdout.write('✔ Test catalogHa')"], + timeoutMs: 1000, + onStdoutPartialLine: (line) => { + observedPartialLine = line; + }, +}); +assert.equal(partialLineResult.code, 0); +assert.equal(observedPartialLine, "✔ Test catalogHa"); + +const swiftFragmentRoot = mkdtempSync(path.join(os.tmpdir(), "lithe-swift-fragment-")); +try { + const reportPath = path.join(swiftFragmentRoot, "swift-fragment.json"); + const timeoutToken = Symbol("swift-test-timeout"); + let timeoutCleared = false; + let childTerminated = false; + await runSwiftTestsWithTiming( + { + warnMs: 50, + maxMs: 200, + suiteTimeoutMs: 500, + report: reportPath, + command: "swift", + commandArguments: ["test"], + }, + { + setTimeoutImpl: (callback) => { + assert.equal(typeof callback, "function"); + return timeoutToken; + }, + clearTimeoutImpl: (token) => { + assert.equal(token, timeoutToken); + timeoutCleared = true; + }, + runProcessImpl: async ({ onSpawn, onStdoutLine, onStdoutPartialLine }) => { + onSpawn({ + terminate: async () => { + childTerminated = true; + return true; + }, + }); + onStdoutLine('◇ Suite "Keyboard shortcuts" started.'); + onStdoutLine( + "◇ Test catalogHasStableUniqueCommandsAndConflictFreeDefaults() started.", + ); + onStdoutPartialLine("✔ Test catalogHa"); + assert.equal(timeoutCleared, true); + onStdoutLine( + "✔ Test catalogHasStableUniqueCommandsAndConflictFreeDefaults() passed after 0.001 seconds.", + ); + onStdoutLine('✔ Suite "Keyboard shortcuts" passed after 0.001 seconds.'); + return { + code: 0, + signal: null, + timedOut: false, + terminationConfirmed: true, + durationMs: 1, + stdout: "", + stderr: "", + }; + }, + }, + ); + assert.equal(childTerminated, false); + assert.deepEqual( + JSON.parse(readFileSync(reportPath, "utf8")).tests.map(({ name, status }) => ({ + name, + status, + })), + [ + { + name: "catalogHasStableUniqueCommandsAndConflictFreeDefaults()", + status: "passed", + }, + ], + ); + + const issueReportPath = path.join(swiftFragmentRoot, "swift-issue-fragment.json"); + let issueTimeout = null; + let issueTimerCleared = false; + let issueChildTerminated = false; + await assert.rejects( + runSwiftTestsWithTiming( + { + warnMs: 50, + maxMs: 200, + suiteTimeoutMs: 500, + report: issueReportPath, + command: "swift", + commandArguments: ["test"], + }, + { + setTimeoutImpl: (callback) => { + issueTimeout = callback; + return timeoutToken; + }, + clearTimeoutImpl: () => { + issueTimerCleared = true; + }, + runProcessImpl: async ({ onSpawn, onStdoutLine, onStdoutPartialLine }) => { + onSpawn({ + terminate: async () => { + issueChildTerminated = true; + return true; + }, + }); + onStdoutLine('◇ Suite "Run entry points" started.'); + onStdoutLine("◇ Test runBeforeTheSnapshot() started."); + onStdoutPartialLine( + "✘ Test runBeforeTheSnapshot() recorded an issue at RunEntryPointTests.swift:35:9", + ); + assert.equal(issueTimerCleared, false); + issueTimeout(); + assert.equal(issueChildTerminated, true); + return { + code: null, + signal: "SIGTERM", + timedOut: false, + terminationConfirmed: true, + durationMs: 200, + stdout: "", + stderr: "", + }; + }, + }, + ), + /Swift test exceeded 200ms: runBeforeTheSnapshot\(\)/, + ); + assert.deepEqual( + JSON.parse(readFileSync(issueReportPath, "utf8")).tests.map(({ name, status }) => ({ + name, + status, + })), + [{ name: "runBeforeTheSnapshot()", status: "timeout" }], + ); + + const interleavedReportPath = path.join(swiftFragmentRoot, "swift-interleaved.json"); + const scheduledTimers = new Map(); + let nextTimerID = 0; + let interleavedChildTerminated = false; + await assert.rejects( + runSwiftTestsWithTiming( + { + warnMs: 50, + maxMs: 200, + suiteTimeoutMs: 500, + report: interleavedReportPath, + command: "swift", + commandArguments: ["test"], + }, + { + setTimeoutImpl: (callback) => { + const timerID = ++nextTimerID; + scheduledTimers.set(timerID, callback); + return timerID; + }, + clearTimeoutImpl: (timerID) => { + assert.equal(scheduledTimers.delete(timerID), true); + }, + runProcessImpl: async ({ env, onSpawn, onStdoutLine }) => { + assert.equal(env.NSUnbufferedIO, "YES"); + onSpawn({ + terminate: async () => { + interleavedChildTerminated = true; + return true; + }, + }); + onStdoutLine('◇ Suite "Interleaved tests" started.'); + onStdoutLine("◇ Test firstTest() started."); + onStdoutLine("◇ Test secondTest() started."); + const firstTimer = 1; + const secondTimer = 2; + assert.deepEqual([...scheduledTimers.keys()], [firstTimer, secondTimer]); + + onStdoutLine("✔ Test secondTest() passed after 0.001 seconds."); + assert.equal(scheduledTimers.has(secondTimer), false); + assert.equal(scheduledTimers.has(firstTimer), true); + + const firstTimeout = scheduledTimers.get(firstTimer); + scheduledTimers.delete(firstTimer); + firstTimeout(); + assert.equal(interleavedChildTerminated, true); + return { + code: null, + signal: "SIGTERM", + timedOut: false, + terminationConfirmed: true, + durationMs: 200, + stdout: "", + stderr: "", + }; + }, + }, + ), + /Swift test exceeded 200ms: firstTest\(\)/, + ); + assert.deepEqual( + JSON.parse(readFileSync(interleavedReportPath, "utf8")).tests.map(({ name, status }) => ({ + name, + status, + })), + [ + { name: "secondTest()", status: "passed" }, + { name: "firstTest()", status: "timeout" }, + ], + ); +} finally { + rmSync(swiftFragmentRoot, { recursive: true, force: true }); +} assert.deepEqual( parseJUnitCases(