From 1ab5ba0c5aaf0f45b638037dc53f14aeeb928a9b Mon Sep 17 00:00:00 2001 From: James Onnen Date: Mon, 10 Aug 2026 17:17:40 -0700 Subject: [PATCH 1/2] test(nevermore-cli): pin batch log parser behavior before refactoring Characterization tests for the parts of parseBatchTestLogs that nothing covered: END markers without a PASS/FAIL suffix or a duration, the END-marker duration fallback, the single-dropped-head rule, the two distinct summary failure reasons, reason joining, malformed markers being content, tracebacks failing a run, single-package fallback logs, and the empty section that reports no counts. These lock in the current observable values so the upcoming Pass 1 restructure can be checked against them. --- .../testing/parsers/batch-log-parser.test.ts | 235 ++++++++++++++++++ 1 file changed, 235 insertions(+) diff --git a/tools/nevermore-cli/src/utils/testing/parsers/batch-log-parser.test.ts b/tools/nevermore-cli/src/utils/testing/parsers/batch-log-parser.test.ts index acbf190909..6c3a340317 100644 --- a/tools/nevermore-cli/src/utils/testing/parsers/batch-log-parser.test.ts +++ b/tools/nevermore-cli/src/utils/testing/parsers/batch-log-parser.test.ts @@ -151,6 +151,241 @@ describe('parseBatchTestLogs', () => { expect(result?.testCounts?.failed).toBe(0); expect(result?.tracebackCount).toBe(1); }); + + it('fails a section containing a traceback', () => { + const logs = buildLogs( + [ + 'Tests: 155 passed, 155 total', + 'PlayerBadgeHelper: attempt to index nil', + 'Stack Begin', + "Script 'PlayerBadgeHelper', Line 365", + 'Stack End', + ].join('\n') + ); + + const result = parseBatchTestLogs(logs, SLUG_MAP).get('egghunt2026'); + + expect(result?.success).toBe(false); + expect(result?.error).toContain('Luau traceback(s)'); + }); + + it('takes the whole inner string as the slug when END has no PASS or FAIL', () => { + const logs = [ + '===BATCH_TEST_BEGIN egghunt2026===', + 'Tests: 5 passed, 5 total', + '===BATCH_TEST_END egghunt2026===', + '===BATCH_TEST_SUMMARY===', + '[{"slug":"egghunt2026","success":true}]', + ].join('\n'); + + const result = parseBatchTestLogs(logs, SLUG_MAP).get('egghunt2026'); + + expect(result?.success).toBe(true); + expect(result?.testCounts).toEqual({ passed: 5, failed: 0, total: 5 }); + }); + + it('records no duration for an END that carries none', () => { + const logs = [ + '===BATCH_TEST_BEGIN egghunt2026===', + 'Tests: 5 passed, 5 total', + '===BATCH_TEST_END egghunt2026 PASS===', + '===BATCH_TEST_SUMMARY===', + '[{"slug":"egghunt2026","success":true}]', + ].join('\n'); + + const result = parseBatchTestLogs(logs, SLUG_MAP).get('egghunt2026'); + + expect(result?.durationMs).toBeUndefined(); + }); + + it('falls back to the END marker duration when the summary entry omits one', () => { + const logs = [ + '===BATCH_TEST_BEGIN egghunt2026===', + 'Tests: 5 passed, 5 total', + '===BATCH_TEST_END egghunt2026 PASS 4242===', + '===BATCH_TEST_SUMMARY===', + '[{"slug":"egghunt2026","success":true}]', + ].join('\n'); + + const result = parseBatchTestLogs(logs, SLUG_MAP).get('egghunt2026'); + + expect(result?.durationMs).toBe(4242); + }); + + it('lets only the first BEGIN-less END claim the output above it', () => { + const twoPackages = new Map([ + ['alpha', 'alpha'], + ['beta', 'beta'], + ]); + const logs = [ + 'Tests: 10 passed, 10 total', + '===BATCH_TEST_END alpha PASS 10===', + 'Tests: 20 passed, 20 total', + '===BATCH_TEST_END beta PASS 20===', + '===BATCH_TEST_SUMMARY===', + '[{"slug":"alpha","success":true},{"slug":"beta","success":true}]', + ].join('\n'); + + const results = parseBatchTestLogs(logs, twoPackages); + + expect(results.get('alpha')?.testCounts?.total).toBe(10); + expect(results.get('beta')?.testCounts).toBeUndefined(); + expect(results.get('beta')?.logs).toBe(''); + expect(results.get('beta')?.error).toContain( + 'no output could be attributed' + ); + }); + + it('distinguishes a reported Luau error from an absent summary entry', () => { + const twoPackages = new Map([ + ['alpha', 'alpha'], + ['beta', 'beta'], + ]); + const logs = [ + '===BATCH_TEST_BEGIN alpha===', + 'Tests: 10 passed, 10 total', + '===BATCH_TEST_END alpha FAIL 10===', + '===BATCH_TEST_BEGIN beta===', + 'Tests: 20 passed, 20 total', + '===BATCH_TEST_END beta PASS 20===', + '===BATCH_TEST_SUMMARY===', + '[{"slug":"alpha","success":false,"error":"boom"}]', + ].join('\n'); + + const results = parseBatchTestLogs(logs, twoPackages); + + expect(results.get('alpha')?.success).toBe(false); + expect(results.get('alpha')?.error).toBe( + 'the batch runner reported a Luau error' + ); + expect(results.get('beta')?.success).toBe(false); + expect(results.get('beta')?.error).toBe( + 'this package is missing from the batch summary' + ); + }); + + it('reads every package as missing when the summary payload is not JSON', () => { + const twoPackages = new Map([ + ['alpha', 'alpha'], + ['beta', 'beta'], + ]); + const logs = [ + '===BATCH_TEST_BEGIN alpha===', + 'Tests: 10 passed, 10 total', + '===BATCH_TEST_END alpha PASS 10===', + '===BATCH_TEST_BEGIN beta===', + 'Tests: 20 passed, 20 total', + '===BATCH_TEST_END beta PASS 20===', + '===BATCH_TEST_SUMMARY===', + 'not json at all', + ].join('\n'); + + const results = parseBatchTestLogs(logs, twoPackages); + + expect(results.get('alpha')?.error).toBe( + 'this package is missing from the batch summary' + ); + expect(results.get('beta')?.error).toBe( + 'this package is missing from the batch summary' + ); + }); + + it('reads every package as missing when no summary arrived at all', () => { + const twoPackages = new Map([ + ['alpha', 'alpha'], + ['beta', 'beta'], + ]); + const logs = [ + '===BATCH_TEST_BEGIN alpha===', + 'Tests: 10 passed, 10 total', + '===BATCH_TEST_END alpha PASS 10===', + '===BATCH_TEST_BEGIN beta===', + 'Tests: 20 passed, 20 total', + '===BATCH_TEST_END beta PASS 20===', + ].join('\n'); + + const results = parseBatchTestLogs(logs, twoPackages); + + expect(results.get('alpha')?.error).toBe( + 'this package is missing from the batch summary' + ); + expect(results.get('beta')?.error).toBe( + 'this package is missing from the batch summary' + ); + }); + + it('joins several failure reasons with a semicolon', () => { + const logs = [ + '===BATCH_TEST_BEGIN egghunt2026===', + 'Tests: 2 failed, 8 passed, 10 total', + 'Test Suites: 1 failed, 3 total', + '===BATCH_TEST_END egghunt2026 FAIL 10===', + '===BATCH_TEST_SUMMARY===', + '[{"slug":"egghunt2026","success":false}]', + ].join('\n'); + + const result = parseBatchTestLogs(logs, SLUG_MAP).get('egghunt2026'); + + expect(result?.error).toBe( + 'the batch runner reported a Luau error; ' + + '1 test suite(s) failed; 2 test(s) failed' + ); + }); + + it('treats a marker missing its trailing delimiter as ordinary content', () => { + const logs = [ + '===BATCH_TEST_BEGIN egghunt2026===', + '===BATCH_TEST_BEGIN egghunt2026', + 'Tests: 5 passed, 5 total', + '===BATCH_TEST_END egghunt2026 PASS 5===', + '===BATCH_TEST_SUMMARY===', + '[{"slug":"egghunt2026","success":true}]', + ].join('\n'); + + const result = parseBatchTestLogs(logs, SLUG_MAP).get('egghunt2026'); + + expect(result?.logs).toContain('===BATCH_TEST_BEGIN egghunt2026'); + expect(result?.testCounts).toEqual({ passed: 5, failed: 0, total: 5 }); + }); + + it('hands unattributable output to the first package only', () => { + const threePackages = new Map([ + ['alpha', 'alpha'], + ['beta', 'beta'], + ['gamma', 'gamma'], + ]); + const logs = [ + 'PlayerBadgeHelper: attempt to index nil', + '===BATCH_TEST_SUMMARY===', + '[{"slug":"alpha","success":true},{"slug":"beta","success":true},' + + '{"slug":"gamma","success":true}]', + ].join('\n'); + + const results = parseBatchTestLogs(logs, threePackages); + + expect(results.get('alpha')?.logs).toContain('PlayerBadgeHelper'); + expect(results.get('beta')?.logs).toBe(''); + expect(results.get('gamma')?.logs).toBe(''); + }); + + it('fails an empty section for having no jest report, with no counts', () => { + const logs = [ + '===BATCH_TEST_BEGIN egghunt2026===', + '===BATCH_TEST_END egghunt2026 PASS 0===', + '===BATCH_TEST_SUMMARY===', + '[{"slug":"egghunt2026","success":true}]', + ].join('\n'); + + const result = parseBatchTestLogs(logs, SLUG_MAP).get('egghunt2026'); + + expect(result?.success).toBe(false); + expect(result?.logs).toBe(''); + expect(result?.error).toBe( + 'no jest report in output — nothing proves any test ran' + ); + // No counts were seen, so none are reported — an empty section is not zero. + expect(result?.testCounts).toBeUndefined(); + }); }); describe('findSummaryEntries', () => { From dbeecef06300df3986141b22f5fc9a44a4336bfa Mon Sep 17 00:00:00 2001 From: James Onnen Date: Mon, 10 Aug 2026 17:32:43 -0700 Subject: [PATCH 2/2] refactor(nevermore-cli): split batch log parsing into tokenize then fold Pass 1 carried twelve mutable bindings through one loop, and its diagnostic counters doubled as control flow, so any change to the splitting rules risked the verdict. Lines are now classified into tokens first and folded into sections second, which leaves the fold three pieces of state and lets the warning counts be read back off the token list instead of accumulated beside it. The three bindings that spelled out "the head of the log is still unclaimed" collapse into one: a section can only be open once a BEGIN has arrived, so testing for no open section was redundant with testing for no BEGIN. Two anomalies that used to pass silently are now reported, without changing any verdict: a second BEGIN arriving while a section is still open (its output is discarded), and an END naming a slug that is not in this batch. Every observable value is unchanged, as the characterization tests added in the previous commit assert. --- .../utils/testing/parsers/batch-log-parser.ts | 355 +++++++++++++----- 1 file changed, 265 insertions(+), 90 deletions(-) diff --git a/tools/nevermore-cli/src/utils/testing/parsers/batch-log-parser.ts b/tools/nevermore-cli/src/utils/testing/parsers/batch-log-parser.ts index b1d0b60f97..e1e97a932e 100644 --- a/tools/nevermore-cli/src/utils/testing/parsers/batch-log-parser.ts +++ b/tools/nevermore-cli/src/utils/testing/parsers/batch-log-parser.ts @@ -26,6 +26,10 @@ export interface BatchPackageResult { const BEGIN_MARKER = '===BATCH_TEST_BEGIN '; const END_MARKER = '===BATCH_TEST_END '; const SUMMARY_MARKER = '===BATCH_TEST_SUMMARY==='; +const MARKER_SUFFIX = '==='; + +// Matches " PASS|FAIL []" — slugs have no whitespace. +const END_INNER_PATTERN = /^(\S+)\s+(?:PASS|FAIL)(?:\s+(\d+))?$/; interface SummaryEntry { slug: string; @@ -34,6 +38,54 @@ interface SummaryEntry { error?: string; } +interface BeginToken { + kind: 'begin'; + slug: string; +} + +interface EndToken { + kind: 'end'; + slug: string; + durationMs?: number; +} + +interface SummaryToken { + kind: 'summary'; + /** Where the marker sat, so the JSON payload can be looked up around it. */ + lineIndex: number; +} + +interface SummaryPayloadToken { + kind: 'summaryPayload'; +} + +interface ContentToken { + kind: 'content'; + /** The untrimmed line, since section logs are shown to a human verbatim. */ + line: string; +} + +/** One log line, classified. Every line becomes exactly one token. */ +type BatchLogToken = + | BeginToken + | EndToken + | SummaryToken + | SummaryPayloadToken + | ContentToken; + +interface FoldedSections { + /** Log text of each section that closed, by slug. */ + sections: Map; + /** Sections closed by an END whose BEGIN never arrived — start of output lost. */ + partialSections: Set; + /** Durations read off END markers, by slug. */ + markerDurations: Map; + /** Slugs of ENDs that closed nothing, so claimed no output. */ + strayEndSlugs: string[]; + /** Slugs of sections a second BEGIN reopened, discarding their output. */ + orphanedBeginSlugs: string[]; +} + /** * Parse the single batch execution's logs into per-package results. * @@ -63,94 +115,27 @@ export function parseBatchTestLogs( // ── Pass 1: Extract per-package log sections from markers ── - const logSections = new Map(); - /** Sections closed by an END whose BEGIN never arrived — start of output lost. */ - const partialSections = new Set(); - const markerDurations = new Map(); - let currentSlug: string | null = null; - let currentLines: string[] = []; - let summaryLineIndex = -1; - /** True between the summary marker and its JSON payload. */ - let summaryPayloadPending = false; - let beginMarkersSeen = 0; - let endMarkersSeen = 0; - let strayEndMarkers = 0; - /** Only one section can have lost its head: the one the log was cut inside. */ - let headSectionClaimed = false; - - // Matches " PASS|FAIL []" — slugs have no whitespace. - const endInnerPattern = /^(\S+)\s+(?:PASS|FAIL)(?:\s+(\d+))?$/; - - for (let i = 0; i < lines.length; i++) { - const trimmed = lines[i].trimEnd(); - - if (trimmed.startsWith(BEGIN_MARKER) && trimmed.endsWith('===')) { - currentSlug = trimmed.slice(BEGIN_MARKER.length, -3); - currentLines = []; - beginMarkersSeen++; - continue; - } - - if (trimmed.startsWith(END_MARKER) && trimmed.endsWith('===')) { - const inner = trimmed.slice(END_MARKER.length, -3); - endMarkersSeen++; - const match = endInnerPattern.exec(inner); - const endSlug = match ? match[1] : inner; - const durationStr = match?.[2]; - - // A section normally closes on the END matching its own BEGIN. - const closesOwnSection = endSlug === currentSlug; - - // Open Cloud keeps only the tail of a long run's log, so BEGIN — printed - // first — can be lost while END and the summary survive. Recovering that - // means letting an END with no open section claim what precedes it, but - // only where the head can actually have been dropped: before any BEGIN - // has survived, and only once. Past that point the log is well-formed, - // and a BEGIN-less END is a message delivered out of order (the API does - // not order them), which must not be allowed to claim another package's - // output. - const closesDroppedHead = - currentSlug === null && beginMarkersSeen === 0 && !headSectionClaimed; - - if (closesOwnSection || closesDroppedHead) { - logSections.set(endSlug, currentLines.join('\n')); - if (closesDroppedHead) { - partialSections.add(endSlug); - headSectionClaimed = true; - } - if (durationStr !== undefined) { - markerDurations.set(endSlug, parseInt(durationStr, 10)); - } - currentSlug = null; - currentLines = []; - } else { - // Reordered marker from another package. Ignore it without resetting - // state, so the section it interrupted still closes on its own END. - strayEndMarkers++; - } - continue; - } - - if (trimmed === SUMMARY_MARKER) { - // Keep scanning: the summary prints last but is not always delivered last, - // and a section's END can follow it. - if (summaryLineIndex < 0) { - summaryLineIndex = i; - } - summaryPayloadPending = true; - continue; - } - - // The summary's JSON payload belongs to no section. - if (summaryPayloadPending && trimmed.trimStart().startsWith('[')) { - summaryPayloadPending = false; - continue; - } - - // Accumulate unconditionally: output that precedes the first surviving - // BEGIN still belongs to whichever package's END closes it. - currentLines.push(lines[i]); - } + const tokens = tokenizeBatchLog(lines); + const { + sections: logSections, + partialSections, + markerDurations, + strayEndSlugs, + orphanedBeginSlugs, + } = foldTokensIntoSections(tokens); + + // Diagnostics are read back off the token list rather than counted alongside + // the fold, so nothing the warnings report can also steer the parse. + const beginMarkersSeen = tokensOfKind(tokens, 'begin').length; + const endMarkersSeen = tokensOfKind(tokens, 'end').length; + const summaryLineIndex = tokensOfKind(tokens, 'summary')[0]?.lineIndex ?? -1; + const unknownEndSlugs = [ + ...new Set( + tokensOfKind(tokens, 'end') + .map((token) => token.slug) + .filter((slug) => !slugToPackage.has(slug)) + ), + ]; // ── Pass 2: Parse the JSON summary for authoritative pcall results ── @@ -188,13 +173,32 @@ export function parseBatchTestLogs( // ── Warn when the batch produced no recognizable output ── - if (strayEndMarkers > 0) { + if (strayEndSlugs.length > 0) { OutputHelper.verbose( - `[batch-log-parser] Ignored ${strayEndMarkers} out-of-order END marker(s); ` + + `[batch-log-parser] Ignored ${strayEndSlugs.length} out-of-order END marker(s); ` + 'their sections closed on their own boundaries.' ); } + // Reported, not acted on: a slug the batch never asked for means the markers + // and the package list disagree, which no per-package verdict can express. + if (unknownEndSlugs.length > 0) { + OutputHelper.warn( + `[batch-log-parser] END marker(s) for slug(s) not in this batch: ` + + `${unknownEndSlugs.join(', ')}.` + ); + } + + if (orphanedBeginSlugs.length > 0) { + OutputHelper.warn( + `[batch-log-parser] ${orphanedBeginSlugs.length} section(s) reopened by a ` + + `second BEGIN before their own END arrived (${orphanedBeginSlugs.join( + ', ' + )}); ` + + 'the output collected so far was discarded.' + ); + } + const noOutputAtAll = logSections.size === 0 && summaryResults.size === 0; if (noOutputAtAll) { OutputHelper.warn( @@ -325,6 +329,177 @@ export function parseBatchTestLogs( return results; } +/** + * Classify every log line, so section splitting reads tokens instead of text. + */ +function tokenizeBatchLog(lines: string[]): BatchLogToken[] { + const tokens: BatchLogToken[] = []; + /** True between the summary marker and its JSON payload. */ + let summaryPayloadPending = false; + + for (let i = 0; i < lines.length; i++) { + const trimmed = lines[i].trimEnd(); + + if (trimmed.startsWith(BEGIN_MARKER) && trimmed.endsWith(MARKER_SUFFIX)) { + tokens.push({ + kind: 'begin', + slug: trimmed.slice(BEGIN_MARKER.length, -MARKER_SUFFIX.length), + }); + continue; + } + + if (trimmed.startsWith(END_MARKER) && trimmed.endsWith(MARKER_SUFFIX)) { + tokens.push( + parseEndToken(trimmed.slice(END_MARKER.length, -MARKER_SUFFIX.length)) + ); + continue; + } + + if (trimmed === SUMMARY_MARKER) { + // Keep scanning: the summary prints last but is not always delivered last, + // and a section's END can follow it. + tokens.push({ kind: 'summary', lineIndex: i }); + summaryPayloadPending = true; + continue; + } + + // The summary's JSON payload belongs to no section. + if (summaryPayloadPending && trimmed.trimStart().startsWith('[')) { + summaryPayloadPending = false; + tokens.push({ kind: 'summaryPayload' }); + continue; + } + + tokens.push({ kind: 'content', line: lines[i] }); + } + + return tokens; +} + +/** + * Read an END marker's inner text. + * + * The PASS|FAIL verdict and the duration are both optional, so inner text that + * does not parse is taken whole as the slug rather than dropped. + */ +function parseEndToken(inner: string): EndToken { + const match = END_INNER_PATTERN.exec(inner); + if (!match) { + return { kind: 'end', slug: inner }; + } + + const durationStr = match[2]; + return { + kind: 'end', + slug: match[1], + durationMs: + durationStr === undefined ? undefined : parseInt(durationStr, 10), + }; +} + +/** + * Fold tokens into per-package log sections. + * + * Sections close on END, not on the next BEGIN, because END is what survives: + * see the head-claiming rule below. + */ +function foldTokensIntoSections( + tokens: readonly BatchLogToken[] +): FoldedSections { + const sections = new Map(); + const partialSections = new Set(); + const markerDurations = new Map(); + const strayEndSlugs: string[] = []; + const orphanedBeginSlugs: string[] = []; + + let openSlug: string | null = null; + let openLines: string[] = []; + /** + * Whether the log can still be one whose head was dropped. + * + * Open Cloud keeps only the tail of a long run's log, so BEGIN — printed + * first — can be lost while END and the summary survive. Recovering that + * means letting an END with no open section claim what precedes it, but + * only where the head can actually have been dropped: before any BEGIN + * has survived, and only once. Past that point the log is well-formed, + * and a BEGIN-less END is a message delivered out of order (the API does + * not order them), which must not be allowed to claim another package's + * output. + */ + let headClaimable = true; + + for (const token of tokens) { + switch (token.kind) { + case 'begin': { + if (openSlug !== null) { + orphanedBeginSlugs.push(openSlug); + } + openSlug = token.slug; + openLines = []; + headClaimable = false; + break; + } + + case 'end': { + // A section normally closes on the END matching its own BEGIN. + const closesOwnSection = token.slug === openSlug; + // Mutually exclusive with the above: an unclaimed head means no BEGIN + // has arrived, so no section is open to match. + const closesDroppedHead = headClaimable; + + if (!closesOwnSection && !closesDroppedHead) { + // Reordered marker from another package. Ignore it without resetting + // state, so the section it interrupted still closes on its own END. + strayEndSlugs.push(token.slug); + break; + } + + sections.set(token.slug, openLines.join('\n')); + if (closesDroppedHead) { + partialSections.add(token.slug); + } + if (token.durationMs !== undefined) { + markerDurations.set(token.slug, token.durationMs); + } + openSlug = null; + openLines = []; + headClaimable = false; + break; + } + + case 'content': { + // Accumulate unconditionally: output that precedes the first surviving + // BEGIN still belongs to whichever package's END closes it. + openLines.push(token.line); + break; + } + + case 'summary': + case 'summaryPayload': { + break; + } + } + } + + return { + sections, + partialSections, + markerDurations, + strayEndSlugs, + orphanedBeginSlugs, + }; +} + +/** Select the tokens of one kind, for counting and reporting. */ +function tokensOfKind( + tokens: readonly BatchLogToken[], + kind: K +): Extract[] { + return tokens.filter( + (token): token is Extract => token.kind === kind + ); +} + /** * Find the summary array in the lines following the summary marker. *