diff --git a/config/scripts/check-job-log-byte-cap-benchmark.mjs b/config/scripts/check-job-log-byte-cap-benchmark.mjs index 3a8fd530919..3055d3bbd69 100644 --- a/config/scripts/check-job-log-byte-cap-benchmark.mjs +++ b/config/scripts/check-job-log-byte-cap-benchmark.mjs @@ -1,162 +1,579 @@ import assert from 'node:assert/strict' -import { readFileSync } from 'node:fs' +import { createHash } from 'node:crypto' +import { mkdtemp, readFile, rm, writeFile } from 'node:fs/promises' +import os from 'node:os' import path from 'node:path' +import { pathToFileURL } from 'node:url' import { performance } from 'node:perf_hooks' import { build } from 'esbuild' +import { runProcess } from '@orca/process-host' +import { createCheckLogFixture } from './check-job-log-test-fixture.mjs' +import { + assertWatchdogExit, + assertMeasurementRuntime, + validateChildProtocol, + adverseCaseKey, + auditBaselineCensoring +} from './check-job-log-watchdog-protocol.mjs' +import { + BASELINE_REF, + BASELINE_SOURCE_HASHES, + createManifest, + selectRequiredDescriptors +} from './check-job-log-performance-cases.mjs' -// Pipe the baseline check-job-log-tail-slice.ts on stdin; both arms use the actual UTF-8 implementation. -const entry = path.resolve('src/shared/check-job-log-tail-slice.ts') -const sources = [readFileSync(0, 'utf8'), readFileSync(entry, 'utf8')] -assert(sources.every((source) => source.includes('export function sliceCheckLogTail'))) +const shared = Object.keys(BASELINE_SOURCE_HASHES) +export const hash = (value) => createHash('sha256').update(value).digest('hex') +export const nodeExecutable = () => { + const executable = process.versions.bun + ? (process.env.ORCA_TEST_NODE_EXECUTABLE ?? process.env.npm_node_execpath) + : process.execPath + assert( + executable && path.isAbsolute(executable), + 'A verified absolute Node executable is required' + ) + return executable +} +const observationSource = ` +const counters = {}; +export function record(kind, value) { + const bytes = Buffer.byteLength(value); const item = counters[kind] ??= { calls: 0, maxBytes: 0, totalBytes: 0 }; + item.calls++; item.maxBytes = Math.max(item.maxBytes, bytes); item.totalBytes += bytes; +} +export function observations() { return structuredClone(counters); } +let phase = null; +export function setPhase(value) { phase = value; } +export function enterStrip() { if (phase) { process.stdout.write(JSON.stringify({ type: 'entered-strip', phase }) + '\\n'); phase = null; } } +export function resetObservations() { for (const key of Object.keys(counters)) delete counters[key]; } +` -async function load(source) { - const result = await build({ - entryPoints: [entry], - bundle: true, - platform: 'node', - format: 'esm', - write: false, - plugins: [ - { - name: 'log-excerpt-source', - setup(builder) { - builder.onLoad({ filter: /check-job-log-tail-slice\.ts$/ }, () => ({ - contents: source, - loader: 'ts', - resolveDir: path.dirname(entry) - })) +export async function prepareBenchmark( + root = process.cwd(), + { profile = false, compareBaseline = true } = {} +) { + const directory = await mkdtemp(path.join(os.tmpdir(), 'orca-check-log-benchmark-')) + try { + const baseline = new Map() + const current = new Map() + for (const name of [...shared, 'check-job-log-excerpt.ts']) { + const filename = path.join(root, 'src', 'shared', name) + current.set(name, await readFile(filename, 'utf8')) + if (!compareBaseline || !shared.includes(name)) { + continue + } + const result = await runProcess({ + program: 'git', + args: ['show', `${BASELINE_REF}:src/shared/${name}`], + cwd: root, + timeoutMs: 10_000, + maxOutputBytes: 64 * 1024, + env: { ...process.env, ORCA_BACKGROUND_LAUNCH: '1' } + }) + assert( + result.code === 0 && !result.signal && !result.timedOut && !result.outputTruncated, + 'Baseline source snapshot failed' + ) + baseline.set(name, result.stdout) + assert.equal( + hash(result.stdout), + BASELINE_SOURCE_HASHES[name], + `Baseline source changed: ${name}` + ) + if (!shared.slice(0, 2).includes(name)) { + assert.equal(hash(result.stdout), hash(current.get(name)), `Dependency drift: ${name}`) + } + } + const identity = { + baselineRef: BASELINE_REF, + measurementScriptHashes: Object.fromEntries( + await Promise.all( + [ + 'check-job-log-byte-cap-benchmark.mjs', + 'check-job-log-performance-cases.mjs', + 'check-job-log-test-fixture.mjs', + 'check-job-log-performance-child.mjs', + 'check-job-log-differential-cases.mjs', + 'check-job-log-watchdog-protocol.mjs' + ].map(async (name) => [ + name, + hash(await readFile(path.join(root, 'config', 'scripts', name))) + ]) + ) + ), + baselineSourceHashes: Object.fromEntries( + [...baseline].map(([name, value]) => [name, hash(value)]) + ), + proposedSourceHashes: Object.fromEntries( + [...current].map(([name, value]) => [name, hash(value)]) + ) + } + const bundles = {} + for (const arm of compareBaseline ? ['baseline', 'proposed'] : ['proposed']) { + for (const instrumented of arm === 'baseline' ? [false, true, 'negative'] : [false, true]) { + const sources = arm === 'baseline' ? baseline : current + const result = await build({ + stdin: { + contents: `export { sliceCheckLogTail } from './check-job-log-tail-slice'; export { stripAnsiEscapeSequences, TERMINAL_CONTROL_CHARACTER_PATTERN } from './ansi-escape-sequences'; export { ownRetainedString, resetOwnRetainedStringCopier } from './own-retained-string'; ${arm === 'proposed' ? "export { sanitizeCheckJobLogExcerpt } from './check-job-log-excerpt';" : ''} ${profile && arm === 'proposed' ? "export { hasErrorMarker } from './check-job-log-tail-slice'; export { stripControlStrings } from './ansi-escape-sequences'; export { isUtf8ByteLengthWithinLimit } from './utf8-byte-limits';" : ''} export { observations, resetObservations, setPhase } from 'check-log-observations';`, + resolveDir: path.join(root, 'src', 'shared'), + loader: 'ts' + }, + bundle: true, + platform: 'node', + format: 'esm', + write: false, + plugins: [ + { + name: 'source-pinned-log-text', + setup(builder) { + builder.onResolve({ filter: /^check-log-observations$/ }, () => ({ + path: 'check-log-observations', + namespace: 'observations' + })) + builder.onLoad({ filter: /.*/, namespace: 'observations' }, () => ({ + contents: observationSource, + loader: 'js' + })) + builder.onLoad( + { + filter: + /[\\/](?:ansi-escape-sequences|check-job-log-tail-slice|check-job-log-excerpt|utf8-byte-limits|own-retained-string|owned-utf16-suffix)\.ts$/ + }, + ({ path: filename }) => { + const name = path.basename(filename) + let contents = sources.get(name) + assert(contents, `Unexpected module in ${arm} graph: ${name}`) + if (profile && arm === 'proposed') { + contents = contents + .replace('function hasErrorMarker(', 'export function hasErrorMarker(') + .replace( + 'function stripControlStrings(', + 'export function stripControlStrings(' + ) + } + if (instrumented === 'negative') { + if (name === 'ansi-escape-sequences.ts') { + contents = + `import { enterStrip } from 'check-log-observations';\n${contents}`.replace( + 'export function stripAnsiEscapeSequences(value: string): string {', + 'export function stripAnsiEscapeSequences(value: string): string {\nenterStrip();' + ) + } + } else if (instrumented) { + contents = `import { record as __record } from 'check-log-observations';\n${contents}` + if (name === 'ansi-escape-sequences.ts') { + contents = contents.replace( + 'export function stripAnsiEscapeSequences(value: string): string {', + 'export function stripAnsiEscapeSequences(value: string): string {\n__record("strip", value);' + ) + } + if (name === 'utf8-byte-limits.ts') { + contents = contents.replace( + 'export function getUtf8ByteLength(text: string): number {', + 'export function getUtf8ByteLength(text: string): number {\n__record("exact", text);' + ) + } + if (name === 'check-job-log-tail-slice.ts') { + assert.equal( + contents.split('ERROR_LINE_PATTERN.test(').length, + 2, + 'Actual matcher injection changed' + ) + contents = `${contents + .replace( + 'stripAnsiEscapeSequences(candidate)', + '(__record("candidate", candidate), stripAnsiEscapeSequences(candidate))' + ) + .replace( + 'ERROR_LINE_PATTERN.test(', + '__match(' + )}\nfunction __match(value: string): boolean { __record("matcher", value); return ERROR_LINE_PATTERN.test(value); }` + } + } + return { contents, loader: 'ts', resolveDir: path.dirname(filename) } + } + ) + } + } + ] + }) + const text = result.outputFiles[0].text + const key = `${arm}${instrumented === 'negative' ? '-negative' : instrumented ? '-observed' : ''}` + const filename = path.join(directory, `${key}.mjs`) + await writeFile(filename, text) + bundles[key] = { filename, hash: hash(text) } + } + } + return { + root, + directory, + identity, + bundles, + cleanup: () => rm(directory, { recursive: true, force: true }) + } + } catch (error) { + await rm(directory, { recursive: true, force: true }) + throw error + } +} + +export async function runDescriptor(context, descriptor) { + const baseline = ['baseline', 'baseline-bounded', 'full-log'].includes(descriptor.arm) + const key = `${baseline ? 'baseline' : 'proposed'}${descriptor.baselineTimeoutAllowed ? '-negative' : descriptor.mode === 'coverage' ? '-observed' : ''}` + const bundle = context.bundles[key] + const identity = { ...context.identity, bundleHash: bundle.hash, id: descriptor.id } + const censored = (context.censoredBaselines ??= new Map()) + const initialTimeout = descriptor.baselineTimeoutAllowed + ? censored.get(adverseCaseKey(descriptor)) + : undefined + if (initialTimeout && descriptor.sample > 0) { + assertWatchdogExit(initialTimeout.watchdogTermination) + assertMeasurementRuntime(initialTimeout.runtime) + return { + ...descriptor, + capturePath: undefined, + status: 'baseline_censored', + attempted: false, + initialTimeoutId: initialTimeout.id, + identity, + runtime: initialTimeout.runtime, + inputBytes: initialTimeout.inputBytes, + codeUnits: initialTimeout.codeUnits, + inputHash: initialTimeout.inputHash, + unavailableSamples: descriptor.samples, + samples: [] + } + } + const started = performance.now() + const controller = new AbortController() + let outerTimer + const outer = new Promise((_resolve, reject) => { + outerTimer = setTimeout(() => { + controller.abort() + reject(new Error('Child exceeded its outer settlement budget')) + }, 15_000) + }) + let result + try { + result = await Promise.race([ + runProcess({ + signal: controller.signal, + program: nodeExecutable(), + args: [ + '--expose-gc', + path.join(context.root, 'config', 'scripts', 'check-job-log-performance-child.mjs'), + bundle.filename, + JSON.stringify(descriptor), + JSON.stringify(identity) + ], + cwd: context.root, + env: { ...process.env, ORCA_BACKGROUND_LAUNCH: '1' }, + timeoutMs: 10_000, + maxOutputBytes: 64 * 1024 + }), + outer + ]) + } finally { + clearTimeout(outerTimer) + } + const settlementMs = performance.now() - started + assert(settlementMs < 15_000, 'Child exceeded its outer settlement budget') + assert(!result.outputTruncated, 'Child protocol truncated') + assert(result.stderr.length === 0, 'Child emitted unexpected stderr') + const { ready, entered, completed, warmups } = validateChildProtocol(result.stdout, descriptor) + assert(!result.timedOut || completed.length === 0, 'Completed work cannot be censored') + assert( + ready && ready.identity.id === descriptor.id && ready.identity.bundleHash === bundle.hash, + 'Missing or mismatched pre-work identity' + ) + assert.deepEqual(ready.identity, identity) + assert.equal(ready.identity.baselineRef, BASELINE_REF) + assert(Number.isSafeInteger(ready.inputBytes) && ready.inputBytes >= 0) + assert(Number.isSafeInteger(ready.codeUnits) && ready.codeUnits >= 0) + assert(ready.inputBytes >= ready.codeUnits && ready.inputBytes <= ready.codeUnits * 3) + assert(typeof ready.inputHash === 'string' && /^[a-f0-9]{64}$/.test(ready.inputHash)) + if ( + descriptor.mode === 'direct' || + descriptor.mode === 'counts' || + (descriptor.mode === 'cpu' && descriptor.family === 'short-lines') + ) { + assert.equal(ready.inputBytes, descriptor.bytes, 'Generator byte size changed') + } + if (descriptor.mode === 'cpu' && ['actual', 'fixture'].includes(descriptor.family)) { + const input = + descriptor.family === 'actual' + ? await readFile(descriptor.capturePath, 'utf8') + : createCheckLogFixture().rawLog + assert.equal(ready.inputBytes, Buffer.byteLength(input), 'Captured input bytes changed') + assert.equal(ready.codeUnits, input.length, 'Captured input code units changed') + assert.equal(ready.inputHash, hash(input), 'Captured input hash changed') + } + if (descriptor.mode === 'watchdog') { + assert.equal(entered?.phase, 'watchdog', 'Watchdog did not enter the synchronous child') + assertWatchdogExit(result) + return { + ...descriptor, + status: 'watchdog_passed', + attempted: true, + settlementMs, + signal: result.signal, + code: result.code, + watchdogTermination: { timedOut: true, signal: result.signal, code: result.code }, + identity, + inputBytes: ready.inputBytes, + codeUnits: ready.codeUnits, + inputHash: ready.inputHash, + runtime: ready.runtime + } + } + if (result.timedOut && descriptor.baselineTimeoutAllowed) { + assertWatchdogExit(result) + assert( + descriptor.mode === 'direct' && + descriptor.arm === 'baseline' && + entered && + ['warmup', 'sample'].includes(entered.phase), + 'Invalid adverse baseline censoring' + ) + const record = { + ...descriptor, + capturePath: undefined, + status: 'baseline_timeout', + identity, + runtime: ready.runtime, + inputBytes: ready.inputBytes, + codeUnits: ready.codeUnits, + inputHash: ready.inputHash, + phase: entered.phase, + deadlineMs: 10_000, + settlementMs, + watchdogTermination: { timedOut: true, signal: result.signal, code: result.code }, + unavailableSamples: descriptor.samples, + samples: [] + } + record.attempted = true + if (descriptor.sample === 0) { + censored.set(adverseCaseKey(descriptor), record) + } + return record + } + assert( + !result.timedOut && result.code === 0 && !result.signal, + 'Workload child failed or timed out' + ) + assert.equal(completed.length, 1, 'Missing result protocol') + if (descriptor.mode === 'direct' || descriptor.mode === 'cpu') { + assert.equal(completed[0].samples.length, descriptor.samples, 'Incomplete timed samples') + assert.equal(warmups, descriptor.warmups ?? 3) + for (const sample of completed[0].samples) { + assert(Number.isSafeInteger(sample.calls) && sample.calls > 0) + for (const value of [ + sample.wallMs, + sample.cpu.user, + sample.cpu.system, + sample.timerLatenessMs, + sample.histogramMaxMs, + sample.utilization.active, + sample.utilization.idle, + sample.utilization.utilization + ]) { + assert(Number.isFinite(value) && value >= 0) + } + assert(sample.utilization.active > 0 && sample.utilization.utilization <= 1) + assert(sample.samplesBeforeWork > 0 && sample.finalCount > sample.postWorkCount) + if (descriptor.mode === 'direct' && descriptor.bytes <= 32768) { + assert(sample.wallMs >= 30, 'Tiny input batch did not reach its timing floor') + } + } + } + return { + ...descriptor, + capturePath: undefined, + ...completed[0], + ...completed[0].inputIdentity, + identity, + runtime: ready.runtime, + settlementMs, + status: 'completed', + attempted: true + } +} + +export function median(values) { + assert(values.length > 0 && values.every(Number.isFinite), 'Missing finite timing samples') + const sorted = [...values].sort((a, b) => a - b) + return sorted[Math.floor(sorted.length / 2)] +} + +export function auditResults(manifest, records, { compareBaseline = true } = {}) { + assert.equal( + new Set(manifest.map((item) => item.id)).size, + manifest.length, + 'Duplicate manifest IDs' + ) + assert.equal(records.length, manifest.length, 'Incomplete or duplicate descriptor coverage') + const byId = new Map(records.map((record) => [record.id, record])) + assert.equal(byId.size, manifest.length, 'Incomplete or duplicate descriptor coverage') + const expectedIds = new Set(manifest.map((item) => item.id)) + assert( + records.every((record) => expectedIds.has(record.id)), + 'Unexpected descriptor record' + ) + for (const descriptor of manifest) { + const record = byId.get(descriptor.id) + assert( + record && + ['completed', 'baseline_timeout', 'baseline_censored', 'watchdog_passed'].includes( + record.status + ), + `Failed descriptor: ${descriptor.id}` + ) + for (const field of ['mode', 'arm', 'family', 'width', 'bytes', 'sample']) { + assert.equal(record[field], descriptor[field], `Descriptor identity changed: ${field}`) + } + if (descriptor.arm === 'proposed') { + assert(!['baseline_timeout', 'baseline_censored'].includes(record.status)) + } + } + auditBaselineCensoring(manifest, byId) + const differentials = records.filter((record) => record.mode === 'differential') + assert.equal(differentials.length, compareBaseline ? 2 : 1) + assert.equal(differentials[0].cases, 5126) + if (compareBaseline) { + assert.equal( + differentials[0].outputHash, + differentials[1].outputHash, + 'Plain/LF differential changed' + ) + } + const candidateGroups = new Map() + for (const descriptor of manifest.filter( + (item) => item.mode === 'coverage' && item.arm === 'proposed' && item.bytes >= 32 * 1024 + )) { + const key = `${descriptor.family}:${descriptor.width}:${descriptor.position}:${descriptor.variant}:${descriptor.terminator}` + const values = candidateGroups.get(key) ?? [] + values.push(byId.get(descriptor.id).observations.candidate) + candidateGroups.set(key, values) + } + for (const values of candidateGroups.values()) { + assert(values.every((value) => value && value.maxBytes <= 8192)) + assert( + Math.max(...values.map((value) => value.totalBytes)) <= + Math.min(...values.map((value) => value.totalBytes)) + 64, + 'Candidate bytes grew with a raw line' + ) + assert( + Math.max(...values.map((value) => value.calls)) === + Math.min(...values.map((value) => value.calls)), + 'Candidate calls grew with a raw line' + ) + } + const scaling = [] + const groups = new Map() + for (const descriptor of manifest.filter( + (item) => item.mode === 'direct' && item.arm === 'proposed' + )) { + const key = `${descriptor.family}:${descriptor.width}` + const sizes = groups.get(key) ?? new Map() + const values = sizes.get(descriptor.bytes) ?? [] + values.push(...byId.get(descriptor.id).samples.map((sample) => sample.wallMs / sample.calls)) + sizes.set(descriptor.bytes, values) + groups.set(key, sizes) + } + for (const [family, sizes] of groups) { + const keys = [...sizes.keys()].sort((a, b) => a - b) + for (let index = 0; index < keys.length; index += 2) { + const small = sizes.get(keys[index]) + const large = sizes.get(keys[index + 1]) + assert.equal(small.length, 7) + assert.equal(large.length, 7) + const first = median(small) + const second = median(large) + assert(second <= 3 * first + 1, `Linear doubling gate failed: ${family} ${keys[index]}`) + scaling.push({ family, bytes: keys.slice(index, index + 2), medianMs: [first, second] }) + } + } + const retained = records.filter((record) => record.mode === 'retention') + const pinned = retained.find((record) => record.arm === 'pinned') + for (const record of retained.filter( + (item) => item.family === 'eight-parents' && item.arm !== 'pinned' + )) { + assert(record.growth.heapUsed < 4 * 1024 * 1024) + assert(record.growth.heapUsed < pinned.growth.heapUsed / 8, 'Owned strings pin raw parents') + } + const ordinary = [] + for (const family of compareBaseline ? ['actual', 'fixture', 'short-lines'] : []) { + for (const bytes of new Set( + manifest + .filter((item) => item.mode === 'cpu' && item.family === family) + .map((item) => item.bytes) + )) { + const comparisons = {} + for (const arm of ['baseline', 'proposed', 'baseline-bounded', 'full-log']) { + const measured = records + .filter( + (record) => + record.mode === 'cpu' && + record.family === family && + record.bytes === bytes && + record.arm === arm + ) + .flatMap((record) => record.samples) + comparisons[arm] = { + wallMs: median(measured.map((sample) => sample.wallMs)), + cpuMs: median(measured.map((sample) => (sample.cpu.user + sample.cpu.system) / 1000)), + timerLatenessMs: median(measured.map((sample) => sample.timerLatenessMs)) } } - ] - }) - const bundled = `${result.outputFiles[0].text}\n//# sourceURL=check-log-byte-cap-benchmark-bundle.js` - return import(`data:text/javascript;base64,${Buffer.from(bundled).toString('base64')}`) -} - -const modules = await Promise.all(sources.map(load)) -const arms = modules.map((module) => module.sliceCheckLogTail) -const limit = modules[0].PR_CHECK_LOG_TAIL_BYTES -assert.equal(modules[1].PR_CHECK_LOG_TAIL_BYTES, limit) -let seed = 0xc0ffee16 -function random(max) { - seed = (Math.imul(seed, 1664525) + 1013904223) >>> 0 - return (seed >>> 8) % max -} - -let comparisons = 0 -function compare(text) { - const expected = arms[0](text) - assert.equal(arms[1](text), expected) - assert(Buffer.byteLength(expected, 'utf8') <= limit) - comparisons++ - return expected -} - -const units = ['x', 'é', '界', '😀', '\ud83d', '\udc00', 'x\ud83d界\udc00'] -for (const unit of units) { - for (let delta = -4; delta <= 4; delta++) { - const text = unit.repeat(Math.floor(limit / Buffer.byteLength(unit)) + delta) - compare(text) - compare(`error: ${text}\n${'recent\n'.repeat(103)}`) - } -} -const endings = ['\n', '\r\n', '\r', ''] -const tokens = [ - 'plain text', - '##[error]', - '::error::', - 'error:', - 'FAILED', - 'exit code', - 'ENOENT', - 'EACCES', - 'panic:', - 'AssertionError', - 'emoji 😀', - '\ud83d', - '\udc00', - '\0', - '界', - 'é', - '\r' -] -for (let iteration = 0; iteration < 5000; iteration++) { - const rows = Array.from({ length: random(250) }, (_, index) => { - const token = tokens[random(tokens.length)] - if (index === 0 && iteration % 20 === 0) { - return `${token}${units[random(units.length)].repeat(limit + random(4))}` - } - return `${token} ${index} ${units[random(units.length)].repeat(random(30))}` - }) - compare(rows.join(endings[random(endings.length)]) + endings[random(endings.length)]) -} -console.log(`${comparisons} full-output differential cases passed`) - -const workloads = [ - ['short ASCII', 'log '.repeat(16)], - ['short Unicode', '🦀界'.repeat(20)], - ['8KiB ASCII', 'x'.repeat(8192)], - ['16KiB ASCII exact cap', 'x'.repeat(limit)], - ['8Ki code units / 24KiB Unicode', '界'.repeat(8192)], - ['2MiB ASCII line', 'x'.repeat(2 * 1024 * 1024)], - ['8MiB ASCII line', 'x'.repeat(8 * 1024 * 1024)], - ['2MiB Unicode line', '界'.repeat(Math.floor((2 * 1024 * 1024) / 3))], - [ - '2MiB earlier error context', - `error: ${'x'.repeat(2 * 1024 * 1024)}\n${'recent\n'.repeat(103)}` - ], - [ - '220 ordinary lines', - Array.from({ length: 220 }, (_, i) => `line ${i} ${'text'.repeat(8)}`).join('\n') - ], - [ - '220 lines / small earlier error', - Array.from( - { length: 220 }, - (_, i) => `${i === 30 ? 'error:' : 'line'} ${i} ${'text'.repeat(8)}` - ).join('\n') - ] -] - -function sample(arm, input, expected, repeats) { - const started = performance.now() - let output - for (let i = 0; i < repeats; i++) { - output = arm(input) - } - const elapsed = (performance.now() - started) / repeats - assert.equal(output, expected) - return elapsed -} - -console.log( - JSON.stringify({ - node: process.version, - platform: process.platform, - arch: process.arch, - pairs: 8, - unit: 'ms' - }) -) -for (const [name, input] of workloads) { - const expected = compare(input) - for (const arm of arms) { - const until = performance.now() + 80 - while (performance.now() < until) { - sample(arm, input, expected, 1) + const before = comparisons.baseline + const after = comparisons.proposed + const threshold = bytes === 63 * 1024 * 1024 ? 15 : 5 + const review = ['wallMs', 'cpuMs', 'timerLatenessMs'].some( + (key) => after[key] > before[key] * 1.25 && after[key] - before[key] > threshold + ) + ordinary.push({ family, bytes, comparisons, reviewRequired: review }) } } - const repeats = Math.max(1, Math.min(100000, Math.ceil(40 / sample(arms[0], input, expected, 1)))) - /** @type {number[][]} */ - const samples = [[], []] - for (let pair = 0; pair < 8; pair++) { - for (const index of pair % 2 ? [1, 0] : [0, 1]) { - samples[index].push(sample(arms[index], input, expected, repeats)) + return { + descriptors: manifest.length, + proposed: manifest.filter((item) => item.arm === 'proposed').length, + censoredBaselines: records.filter((record) => record.status === 'baseline_timeout').length, + censoredSampleSlots: records.filter((record) => record.status === 'baseline_censored').length, + attemptedDescriptors: records.filter((record) => record.attempted !== false).length, + scaling, + ordinary + } +} + +// Manual before/after comparison requires the pinned baseline in local Git history. +if (process.argv[1] && pathToFileURL(path.resolve(process.argv[1])).href === import.meta.url) { + const context = await prepareBenchmark() + const manifest = selectRequiredDescriptors( + createManifest({ capturePath: process.env.ORCA_CHECK_LOG_CAPTURE }) + ) + const records = [] + try { + for (const descriptor of manifest) { + try { + records.push(await runDescriptor(context, descriptor)) + } catch (error) { + records.push({ id: descriptor.id, status: 'failed', reason: error.message.split('\n')[0] }) + } + if (process.env.ORCA_CHECK_LOG_REPORT) { + await writeFile( + process.env.ORCA_CHECK_LOG_REPORT, + JSON.stringify({ identity: context.identity, records }) + ) + } } + const summary = auditResults(manifest, records) + if (process.env.ORCA_CHECK_LOG_REPORT) { + await writeFile( + process.env.ORCA_CHECK_LOG_REPORT, + JSON.stringify({ identity: context.identity, summary, records }) + ) + } + console.log(JSON.stringify(summary)) + } finally { + await context.cleanup() } - const median = samples.map((values) => { - values.sort((a, b) => a - b) - return (values[3] + values[4]) / 2 - }) - console.log(JSON.stringify({ name, repeats, median, samples })) } diff --git a/config/scripts/check-job-log-component-profile.mjs b/config/scripts/check-job-log-component-profile.mjs new file mode 100644 index 00000000000..fb91b5f5e15 --- /dev/null +++ b/config/scripts/check-job-log-component-profile.mjs @@ -0,0 +1,144 @@ +import assert from 'node:assert/strict' +import { Session } from 'node:inspector/promises' +import { performance } from 'node:perf_hooks' +import { readFile, writeFile } from 'node:fs/promises' +import { pathToFileURL } from 'node:url' +import { prepareBenchmark, hash } from './check-job-log-byte-cap-benchmark.mjs' +import { workload } from './check-job-log-performance-cases.mjs' + +assert(!process.versions.bun && typeof globalThis.gc === 'function') +const context = await prepareBenchmark(process.cwd(), { profile: true }) +const records = [] +const profileNames = [ + 'isUtf8ByteLengthWithinLimit', + 'hasErrorMarker', + 'matches', + 'matchesErrorMarker', + 'stripAnsiEscapeSequences', + 'stripControlStrings', + 'appendSpan', + 'ownRetainedString', + 'copyUtf16SuffixToOwnedString' +] +async function measure(name, operation, calls, input) { + for (let warmup = 0; warmup < 3; warmup++) { + operation() + } + globalThis.gc() + const session = new Session() + session.connect() + try { + await session.post('Profiler.enable') + await session.post('Profiler.setSamplingInterval', { interval: 100 }) + await session.post('Profiler.start') + const cpuBefore = process.cpuUsage() + const started = performance.now() + for (let call = 0; call < calls; call++) { + operation() + } + const wallMs = performance.now() - started + const cpu = process.cpuUsage(cpuBefore) + const { profile } = await session.post('Profiler.stop') + const nodes = new Map(profile.nodes.map((node) => [node.id, node])) + const parents = new Map( + profile.nodes.flatMap((node) => (node.children ?? []).map((id) => [id, node.id])) + ) + const timings = Object.fromEntries( + profileNames.map((fn) => [fn, { selfMs: 0, inclusiveMs: 0 }]) + ) + for (let sample = 0; sample < (profile.samples?.length ?? 0); sample++) { + let id = profile.samples[sample] + const duration = profile.timeDeltas[sample] / 1000 + const fn = nodes.get(id)?.callFrame.functionName + if (timings[fn]) { + timings[fn].selfMs += duration + } + const names = new Set() + while (id !== undefined) { + names.add(nodes.get(id)?.callFrame.functionName) + id = parents.get(id) + } + for (const fn of names) { + if (timings[fn]) { + timings[fn].inclusiveMs += duration + } + } + } + records.push({ + name, + calls, + wallMs, + cpuMs: (cpu.user + cpu.system) / 1000, + inputBytes: Buffer.byteLength(input), + codeUnits: input.length, + inputHash: hash(input), + timings + }) + } finally { + session.disconnect() + } +} +try { + const module = await import(pathToFileURL(context.bundles.proposed.filename).href) + const line = workload({ mode: 'cpu', family: 'short-lines', bytes: 8 * 1024 * 1024 }).text.split( + '\n' + )[0] + const count = 100000 + await measure( + 'bounded-byte-fit', + () => module.isUtf8ByteLengthWithinLimit(line, 16384), + count, + line + ) + await measure('candidate-stripper', () => module.stripAnsiEscapeSequences(line), count, line) + const plain = module.stripAnsiEscapeSequences(line) + await measure( + 'candidate-control-cleanup', + () => plain.replace(module.TERMINAL_CONTROL_CHARACTER_PATTERN, ''), + count, + plain + ) + await measure('candidate-total', () => module.hasErrorMarker(line), count, line) + for (const bytes of [8 * 1024 * 1024, 63 * 1024 * 1024]) { + let input = workload({ mode: 'cpu', family: 'short-lines', bytes }).text + await measure( + `extraction-short-lines-${bytes}`, + () => module.sliceCheckLogTail(input), + 3, + input + ) + input = '' + } + for (const family of ['dense-osc', 'dense-string', 'sparse', 'mixed']) { + let input = workload({ + mode: 'direct', + family, + width: family === 'mixed' ? 0 : 7, + bytes: 8 * 1024 * 1024, + variant: 'unfinished' + }).text + await measure(`collector-${family}`, () => module.stripAnsiEscapeSequences(input), 3, input) + input = '' + } + if (process.env.ORCA_CHECK_LOG_CAPTURE) { + let input = await readFile(process.env.ORCA_CHECK_LOG_CAPTURE, 'utf8') + await measure('extraction-actual', () => module.sliceCheckLogTail(input), 15, input) + input = '' + } + const report = { + identity: context.identity, + profilerScriptHash: hash(await readFile(new URL(import.meta.url))), + runtime: { node: process.version, platform: process.platform, arch: process.arch }, + purpose: 'Targeted sampled diagnosis; instrumentation timings are not acceptance medians', + records + } + assert(process.env.ORCA_CHECK_LOG_PROFILE_REPORT) + await writeFile(process.env.ORCA_CHECK_LOG_PROFILE_REPORT, JSON.stringify(report, null, 2)) + console.log( + JSON.stringify( + records.map(({ name, wallMs, cpuMs, timings }) => ({ name, wallMs, cpuMs, timings })) + ) + ) +} finally { + await context.cleanup() +} diff --git a/config/scripts/check-job-log-consumer-oracles.mjs b/config/scripts/check-job-log-consumer-oracles.mjs new file mode 100644 index 00000000000..dd8c524bb10 --- /dev/null +++ b/config/scripts/check-job-log-consumer-oracles.mjs @@ -0,0 +1,50 @@ +import assert from 'node:assert/strict' +import { mkdtemp, rm, writeFile } from 'node:fs/promises' +import os from 'node:os' +import path from 'node:path' +import { pathToFileURL } from 'node:url' +import { build } from 'esbuild' + +// Runtime bundling keeps independent consumer assertions outside shared project type graphs. +export async function loadAnsiConsumers(root = process.cwd()) { + const entries = [ + ['parseAnsiSegments', 'renderer/src/components/editor/ipynb-ansi'], + [ + 'restoredSnapshotPaintsPrintableContent', + 'renderer/src/components/terminal-pane/restored-snapshot-coverage' + ], + ['parseCodexLoginAuthUrl', 'main/codex-accounts/codex-login-auth-url'], + ['TerminalCommandPaint', 'main/runtime/terminal-command-paint'], + ['claudePermissionSubject', 'main/claude/claude-permission-presentation'], + ['terminalSafe', 'cli/agent-session-search-format'], + [ + 'createAutomationRunOutputSnapshotBuffer', + 'renderer/src/components/automations/automation-run-output-snapshot' + ] + ] + const bundle = await build({ + stdin: { + contents: entries + .map(([name, filename]) => `export { ${name} } from './${filename}';`) + .join('\n'), + resolveDir: path.join(root, 'src'), + loader: 'ts' + }, + bundle: true, + platform: 'node', + format: 'esm', + write: false + }) + const directory = await mkdtemp(path.join(os.tmpdir(), 'orca-check-log-consumers-')) + try { + const filename = path.join(directory, 'consumers.mjs') + await writeFile(filename, bundle.outputFiles[0].text) + const consumers = await import(pathToFileURL(filename).href) + for (const [name] of entries) { + assert.equal(typeof consumers[name], 'function', `Missing actual consumer: ${name}`) + } + return consumers + } finally { + await rm(directory, { recursive: true, force: true }) + } +} diff --git a/config/scripts/check-job-log-differential-cases.mjs b/config/scripts/check-job-log-differential-cases.mjs new file mode 100644 index 00000000000..96afa968f57 --- /dev/null +++ b/config/scripts/check-job-log-differential-cases.mjs @@ -0,0 +1,43 @@ +import { LIMIT, SEED } from './check-job-log-performance-cases.mjs' + +// No controls or CR: these cases retain the original full-output contract. +export function* plainLogDifferentialCases() { + const units = ['x', 'é', '界', '😀', '\ud83d', '\udc00', 'x\ud83d界\udc00'] + for (const unit of units) { + for (let delta = -4; delta <= 4; delta++) { + const text = unit.repeat(Math.floor(LIMIT / Buffer.byteLength(unit)) + delta) + yield text + yield `error: ${text}\n${'recent\n'.repeat(103)}` + } + } + let seed = SEED + const random = (max) => { + seed = (Math.imul(seed, 1664525) + 1013904223) >>> 0 + return (seed >>> 8) % max + } + const tokens = [ + 'plain text', + '##[error]', + '::error::', + 'error:', + 'FAILED', + 'exit code', + 'ENOENT', + 'EACCES', + 'panic:', + 'AssertionError', + 'emoji 😀', + '\ud83d', + '\udc00', + '界', + 'é' + ] + for (let iteration = 0; iteration < 5000; iteration++) { + const rows = Array.from({ length: random(250) }, (_, index) => { + const token = tokens[random(tokens.length)] + const count = index === 0 && iteration % 20 === 0 ? LIMIT + random(4) : random(30) + return `${token} ${index} ${units[random(units.length)].repeat(count)}` + }) + yield rows.join('\n') + (iteration % 2 ? '\n' : '') + } +} diff --git a/config/scripts/check-job-log-fix-smoke.mjs b/config/scripts/check-job-log-fix-smoke.mjs new file mode 100644 index 00000000000..17c6639174e --- /dev/null +++ b/config/scripts/check-job-log-fix-smoke.mjs @@ -0,0 +1,35 @@ +import assert from 'node:assert/strict' +import { readFile, writeFile } from 'node:fs/promises' +import { createManifest } from './check-job-log-performance-cases.mjs' +import { prepareBenchmark, runDescriptor, hash } from './check-job-log-byte-cap-benchmark.mjs' + +assert(process.env.ORCA_CHECK_LOG_SMOKE_REPORT) +const context = await prepareBenchmark() +const manifest = createManifest({ + capturePath: process.env.ORCA_CHECK_LOG_CAPTURE +}).filter( + (item) => item.mode === 'cpu' && ['baseline', 'proposed'].includes(item.arm) && item.sample < 3 +) +const records = [] +try { + for (const descriptor of manifest) { + records.push(await runDescriptor(context, descriptor)) + } + await writeFile( + process.env.ORCA_CHECK_LOG_SMOKE_REPORT, + JSON.stringify( + { + purpose: + 'Selected three-sample CPU smoke; final prescribed medians and audit remain pending', + identity: context.identity, + selectionScriptHash: hash(await readFile(new URL(import.meta.url))), + records + }, + null, + 2 + ) + ) + console.log(JSON.stringify({ completed: records.length })) +} finally { + await context.cleanup() +} diff --git a/config/scripts/check-job-log-performance-cases.mjs b/config/scripts/check-job-log-performance-cases.mjs new file mode 100644 index 00000000000..90db90623ca --- /dev/null +++ b/config/scripts/check-job-log-performance-cases.mjs @@ -0,0 +1,294 @@ +import assert from 'node:assert/strict' +import { readFileSync } from 'node:fs' +import { createCheckLogFixture } from './check-job-log-test-fixture.mjs' + +export const BASELINE_REF = 'c745051d7d6885b86f27120b616f15396404ba3d' +export const BASELINE_SOURCE_HASHES = { + 'ansi-escape-sequences.ts': '75c79a88fb91c8b7a128a1ccc133051cde9e3e09f553d4d4fbb8887f89b6d217', + 'check-job-log-tail-slice.ts': '24ccf1fc3a0a5b2da7eb3a218a7b3fb7e85e6100e8b60e0b7f6c9fe5665413e4', + 'utf8-byte-limits.ts': '01574b287b2d6ab0758112887e356c0d270b25db1b72651925ba8329eb4224e6', + 'own-retained-string.ts': 'addea88bc11c725192be2ff617b91315a875113844c95de03e5529cf3d7ef2e2', + 'owned-utf16-suffix.ts': '1ca0bb35dfff2d9f3c02caee3d05b0e0c97378df71c878622acf703524d2c475' +} +export const LIMIT = 16 * 1024 +export const SEED = 0xc0ffee16 +const mib = 1024 * 1024 +export const directSizes = [ + 16 * 1024, + 32 * 1024, + mib, + 2 * mib, + 8 * mib, + 16 * mib, + 31.5 * mib, + 63 * mib +] +export const extractionSizes = [16 * 1024, 32 * 1024, 2 * mib, 8 * mib, 63 * mib] +export const families = [ + ...[ + ['osc', '\x1b]', '\x9d'], + ['dcs', '\x1bP', '\x90'], + ['apc', '\x1b_', '\x9f'], + ['pm', '\x1b^', '\x9e'], + ['sos', '\x1bX', '\x98'], + ['csi', '\x1b[', '\x9b'] + ].flatMap(([family, seven, eight]) => [ + { family, width: 7, pattern: `${seven}111`, survivor: '111', adverse: family !== 'csi' }, + { family, width: 8, pattern: `${eight}111`, survivor: `${eight}111`, adverse: family !== 'csi' } + ]), + { family: 'partial-esc', width: 7, pattern: '\x1b ', survivor: '\x1b ', adverse: false }, + { family: 'dense-osc', width: 7, pattern: '\x1b]body\x07x', survivor: 'x', adverse: false }, + { family: 'dense-osc', width: 8, pattern: '\x9dbody\x9cx', survivor: 'x', adverse: false }, + { family: 'dense-string', width: 7, pattern: '\x1bPbody\x1b\\x', survivor: 'x', adverse: false }, + { family: 'dense-string', width: 8, pattern: '\x90body\x9cx', survivor: 'x', adverse: false }, + { + family: 'mixed', + width: 0, + pattern: '\x1b]a\x07界\x90b\x9cx\x1b[31m😀\x1b[0m', + survivor: '界x😀', + adverse: false + }, + { + family: 'sparse', + width: 7, + pattern: `${'a'.repeat(4096)}\x1b]body\x07`, + survivor: 'a'.repeat(4096), + adverse: false + }, + { + family: 'plain', + width: 0, + pattern: 'ordinary 界😀 text ', + survivor: 'ordinary 界😀 text ', + adverse: false + } +] + +export function repeatBytes(pattern, bytes) { + const width = Buffer.byteLength(pattern) + const copies = Math.floor(bytes / width) + return { + text: pattern.repeat(copies) + 'x'.repeat(bytes - copies * width), + copies, + padding: bytes - copies * width + } +} + +export function workload(descriptor) { + if (descriptor.mode === 'cpu') { + if (descriptor.family === 'actual') { + return { text: readFileSync(descriptor.capturePath, 'utf8') } + } + if (descriptor.family === 'fixture') { + return { text: createCheckLogFixture().rawLog } + } + const line = '2026-10-10T05:41:30.4306569Z \x1b[32mordinary successful output 界\x1b[0m\n' + const suffix = '\n\x1b[31merror: CPU_DIAGNOSTIC\x1b[0m\n at CPU_FRAME.ts:18:8\n' + return { text: repeatBytes(line, descriptor.bytes - Buffer.byteLength(suffix)).text + suffix } + } + const family = families.find( + (value) => value.family === descriptor.family && value.width === descriptor.width + ) + assert(family, 'unknown family') + const terminator = + descriptor.variant === 'late' + ? family.family === 'csi' + ? 'm' + : family.family === 'partial-esc' + ? '@' + : descriptor.terminator + : '' + const prefix = + descriptor.mode === 'coverage' && descriptor.position === 'earlier' ? 'error: EDGE ' : '' + const generated = repeatBytes( + family.pattern, + descriptor.bytes - Buffer.byteLength(terminator) - Buffer.byteLength(prefix) + ) + const text = prefix + generated.text + terminator + let expected = family.survivor.repeat(generated.copies) + 'x'.repeat(generated.padding) + if (family.family === 'csi' && generated.padding > 0) { + expected = + family.survivor.repeat(Math.max(0, generated.copies - 1)) + 'x'.repeat(generated.padding - 1) + } + if (terminator) { + if (family.adverse) { + expected = '' + } else if (family.family === 'csi') { + expected = family.survivor.repeat(Math.max(0, generated.copies - 1)) + } else if (family.family === 'partial-esc') { + expected = family.survivor.repeat(Math.max(0, generated.copies - 1)) + } + } + if (descriptor.mode === 'coverage') { + const tail = Array.from({ length: 210 }, (_, index) => `recent ${index}`).join('\n') + return { + text: + descriptor.position === 'earlier' + ? `${text}\n${tail}` + : descriptor.position === 'tail' + ? `${tail}\n${text}` + : `${text}\n${tail}`, + lineBytes: descriptor.bytes + } + } + return { text, expected } +} + +function item(mode, arm, fields) { + const value = { + mode, + arm, + variant: 'unfinished', + seed: SEED, + generator: 'repeated-byte-pattern-v1', + ...fields + } + value.id = [ + mode, + arm, + value.family, + value.width, + value.bytes, + value.position, + value.variant, + value.terminator === '\x1b\\' + ? 'st7' + : value.terminator === '\x9c' + ? 'st8' + : value.terminator === '\x07' + ? 'bel' + : '', + value.sample, + value.noBuffer ? 'no-buffer' : '' + ] + .filter((x) => x !== undefined) + .join(':') + return value +} + +export function createManifest({ capturePath } = {}) { + const manifest = [ + item('control', 'proposed', { family: 'monitor', sample: 0 }), + item('control', 'proposed', { family: 'cleanup', sample: 0 }), + item('watchdog', 'proposed', { family: 'watchdog', sample: 0 }) + ] + for (const family of families.slice(0, 13)) { + for (const bytes of extractionSizes) { + for (const position of ['earlier', 'tail', 'fallback']) { + for (const variant of ['unfinished', 'late']) { + for (const terminator of variant === 'late' && family.adverse + ? ['\x1b\\', '\x9c', ...(family.family === 'osc' ? ['\x07'] : [])] + : ['']) { + manifest.push( + item('coverage', 'proposed', { + family: family.family, + width: family.width, + bytes, + position, + variant, + terminator + }) + ) + } + } + } + } + } + for (const arm of ['proposed', 'baseline']) { + manifest.push(item('differential', arm, { family: 'plain-lf' })) + } + for (const family of families) { + for (const bytes of [16 * 1024, 32 * 1024]) { + manifest.push( + item('counts', 'proposed', { family: family.family, width: family.width, bytes }) + ) + } + } + for (const family of families.filter((value) => + ['dense-osc', 'dense-string', 'mixed', 'sparse'].includes(value.family) + )) { + for (const bytes of [16 * 1024, 32 * 1024]) { + manifest.push( + item('counts', 'proposed', { + family: family.family, + width: family.width, + bytes, + noBuffer: true + }) + ) + } + } + // Parent ordering alternates every direct pair; each child gets fresh three warmups. + for (const family of families) { + for (let pair = 0; pair < directSizes.length; pair += 2) { + const sizes = directSizes.slice(pair, pair + 2) + for (let sample = 0; sample < 7; sample++) { + for (const arm of sample % 2 ? ['baseline', 'proposed'] : ['proposed', 'baseline']) { + for (const bytes of sample % 2 ? sizes.toReversed() : sizes) { + manifest.push( + item('direct', arm, { + family: family.family, + width: family.width, + bytes, + sample, + samples: 1, + baselineTimeoutAllowed: arm === 'baseline' && family.adverse + }) + ) + } + } + } + } + } + const cpuCases = [ + { family: 'fixture', bytes: 0, samples: 15, warmups: 3 }, + ...(capturePath ? [{ family: 'actual', capturePath, bytes: 0, samples: 15, warmups: 3 }] : []), + ...[8 * mib, 63 * mib].map((bytes) => ({ + family: 'short-lines', + bytes, + samples: 5, + warmups: 1 + })) + ] + for (const fields of cpuCases) { + for (let sample = 0; sample < fields.samples; sample++) { + for (const arm of sample % 2 + ? ['full-log', 'baseline-bounded', 'proposed', 'baseline'] + : ['baseline', 'proposed', 'baseline-bounded', 'full-log']) { + manifest.push(item('cpu', arm, { ...fields, samples: 1, sample })) + } + } + } + for (const arm of ['pinned', 'baseline', 'proposed', 'no-buffer']) { + manifest.push(item('retention', arm, { family: 'eight-parents' })) + } + for (const arm of ['proposed', 'no-buffer']) { + manifest.push(item('retention', arm, { family: 'cache', count: 128 })) + } + manifest.push(item('retention', 'proposed', { family: 'near-cap', count: 3 })) + return manifest +} + +export function selectRequiredDescriptors(manifest) { + return manifest.filter((descriptor) => { + if (descriptor.mode === 'coverage') { + return ( + ['osc', 'dcs', 'apc', 'pm', 'sos'].includes(descriptor.family) && + [16 * 1024, 32 * 1024, 2 * mib, 63 * mib].includes(descriptor.bytes) && + ['earlier', 'tail'].includes(descriptor.position) && + descriptor.variant === 'unfinished' + ) + } + if (descriptor.mode === 'direct') { + return ( + descriptor.bytes <= 32 * 1024 || + (descriptor.arm === 'proposed' && + descriptor.bytes >= 31.5 * mib && + ['osc', 'dcs', 'dense-osc', 'dense-string', 'mixed', 'sparse'].includes( + descriptor.family + )) + ) + } + return true + }) +} diff --git a/config/scripts/check-job-log-performance-child.mjs b/config/scripts/check-job-log-performance-child.mjs new file mode 100644 index 00000000000..531487b8273 --- /dev/null +++ b/config/scripts/check-job-log-performance-child.mjs @@ -0,0 +1,418 @@ +import assert from 'node:assert/strict' +import { createHash } from 'node:crypto' +import { readFileSync } from 'node:fs' +import { pathToFileURL } from 'node:url' +import { monitorEventLoopDelay, performance } from 'node:perf_hooks' +import { plainLogDifferentialCases } from './check-job-log-differential-cases.mjs' +import { LIMIT, workload } from './check-job-log-performance-cases.mjs' +import { createCheckLogFixture } from './check-job-log-test-fixture.mjs' + +assert(!process.versions.bun, 'Measurement child must use Node') +const [bundlePath, serialized, identityJson] = process.argv.slice(2) +const descriptor = JSON.parse(serialized) +const identity = JSON.parse(identityJson) +const digest = (value) => createHash('sha256').update(value).digest('hex') +assert.equal(digest(readFileSync(bundlePath)), identity.bundleHash) +for (const [name, expectedHash] of Object.entries(identity.measurementScriptHashes)) { + assert.equal( + digest(readFileSync(new URL(name, import.meta.url))), + expectedHash, + `Measurement script changed: ${name}` + ) +} +const module = await import(pathToFileURL(bundlePath).href) +const runtime = { + node: process.version, + platform: process.platform, + arch: process.arch, + bun: false +} +const emit = (record) => process.stdout.write(`${JSON.stringify(record)}\n`) +const timers = new Set() +const delay = (ms) => + new Promise((resolve) => { + const timer = setTimeout(() => { + timers.delete(timer) + resolve(performance.now()) + }, ms) + timers.add(timer) + }) +const boundaries = [] +const memory = (label) => { + const value = process.memoryUsage() + boundaries.push({ label, ...value }) + return value +} +const gc = () => { + assert.equal(typeof globalThis.gc, 'function') + void /probe/.test('probe') + globalThis.gc() + globalThis.gc() +} + +async function measure(operation, tiny = false, control = false) { + const histogram = monitorEventLoopDelay({ resolution: 1 }) + try { + histogram.enable() + await delay(5) + await delay(5) + histogram.reset() + await delay(5) + assert(histogram.count > 0, 'Monitor has no real post-reset samples') + const samplesBeforeWork = histogram.count + const before = memory('before-timed-work') + const utilizationBefore = performance.eventLoopUtilization() + const cpuBefore = process.cpuUsage() + const armed = performance.now() + const primary = delay(5) + const started = performance.now() + let output + let calls = 0 + do { + output = operation() + calls++ + } while (tiny && performance.now() - started < 30) + const wallMs = performance.now() - started + const cpu = process.cpuUsage(cpuBefore) + const utilization = performance.eventLoopUtilization(utilizationBefore) + const after = memory('after-timed-work') + const fired = await primary + const postWorkCount = histogram.count + await delay(5) + assert(histogram.count > postWorkCount, 'Monitor has no post-work sampling tick') + const histogramMaxMs = histogram.max / 1e6 + const timerLatenessMs = Math.max(0, fired - armed - 5) + for (const key of ['active', 'idle', 'utilization']) { + assert(Number.isFinite(utilization[key]) && utilization[key] >= 0) + } + assert(utilization.active > 0 && utilization.utilization <= 1) + if (control) { + assert(timerLatenessMs >= 30) + assert(histogramMaxMs >= 30) + } + return { + output, + sample: { + calls, + wallMs, + cpu, + utilization, + timerLatenessMs, + histogramMaxMs, + samplesBeforeWork, + postWorkCount, + finalCount: histogram.count, + before, + after + } + } + } finally { + assert(histogram.disable()) + assert(!histogram.disable()) + for (const timer of timers) { + clearTimeout(timer) + } + timers.clear() + } +} + +let inputIdentity +function ready(input = '') { + inputIdentity = { + inputBytes: Buffer.byteLength(input), + codeUnits: input.length, + inputHash: digest(input) + } + emit({ + type: 'ready', + identity, + runtime, + ...inputIdentity + }) +} +function result(fields) { + const maxima = (field) => Math.max(0, ...boundaries.map((item) => item[field])) + emit({ + type: 'result', + id: descriptor.id, + mode: descriptor.mode, + arm: descriptor.arm, + family: descriptor.family, + width: descriptor.width, + bytes: descriptor.bytes, + inputIdentity, + variant: descriptor.variant, + ...fields, + processLifetimeMaxRssKiB: process.resourceUsage().maxRSS, + maxObservedBoundaryHeapUsedBytes: maxima('heapUsed'), + maxObservedBoundaryExternalBytes: maxima('external'), + maxObservedBoundaryArrayBuffersBytes: maxima('arrayBuffers'), + boundaries + }) +} + +function assertSafe(output) { + assert(Buffer.byteLength(output) <= LIMIT, 'Excerpt exceeded 16 KiB') + assert(!module.TERMINAL_CONTROL_CHARACTER_PATTERN.test(output), 'Unsafe excerpt controls') + assert(!output.includes('\r'), 'Unnormalized CR') +} +function legacySanitize(value) { + return module.ownRetainedString( + module + .stripAnsiEscapeSequences(value) + .replace(/\r\n?/g, '\n') + .replace(module.TERMINAL_CONTROL_CHARACTER_PATTERN, '') + ) +} + +function retained() { + if (descriptor.arm === 'no-buffer') { + globalThis.Buffer = undefined + module.resetOwnRetainedStringCopier() + } + const byteLength = new TextEncoder() + const size = descriptor.family === 'near-cap' ? 63 * 1024 * 1024 : 2 * 1024 * 1024 + const count = descriptor.count ?? 8 + for (let index = 0; index < 3; index++) { + module.ownRetainedString('warm owned string '.repeat(1000)) + } + gc() + const before = memory('warmed-retention-baseline') + let excerpts = [] + let encodedTotal = 0 + for (let index = 0; index < count; index++) { + const unit = + descriptor.family === 'cache' + ? ['plain ', '界😀', '\x9dunfinished ', '\ud800a\udfff'][index % 4] + : 'x' + const chunk = unit.repeat(1024) + let parent = [ + `${index}:`, + ...Array.from({ length: Math.ceil(size / chunk.length) }, () => chunk) + ].join('') + // The flat parent is distinct for each retained result; source references die each iteration. + const output = + descriptor.arm === 'pinned' + ? parent.slice(-LIMIT) + : descriptor.arm === 'baseline' + ? module.sliceCheckLogTail(parent) + : module.sanitizeCheckJobLogExcerpt(parent) + const bytes = byteLength.encode(output).length + assert(bytes <= LIMIT) + encodedTotal += bytes + excerpts.push(output) + parent = '' + } + gc() + const retainedMemory = memory('retained-excerpts-after-double-gc') + assert(encodedTotal <= 2 * 1024 * 1024) + const retainedCount = excerpts.length + excerpts = [] + gc() + const released = memory('released-excerpts-after-double-gc') + const delta = (value) => + Object.fromEntries( + ['heapUsed', 'external', 'arrayBuffers', 'rss'].map((field) => [ + field, + value[field] - before[field] + ]) + ) + const growth = delta(retainedMemory) + const release = delta(released) + if (descriptor.family !== 'near-cap') { + assert(release.heapUsed < 4 * 1024 * 1024, 'Excerpts did not release near the warmed heap') + } + result({ retainedCount, encodedTotal, growth, release, samples: [] }) +} + +try { + if (descriptor.mode === 'retention') { + ready() + retained() + } else if (descriptor.mode === 'watchdog') { + ready() + emit({ type: 'entered', phase: 'watchdog' }) + while (true) {} + } else if (descriptor.mode === 'control') { + ready() + memory('after-setup') + if (descriptor.family === 'cleanup') { + const monitor = monitorEventLoopDelay({ resolution: 1 }) + try { + monitor.enable() + void delay(1000) + throw new Error('cleanup-sentinel') + } catch (error) { + assert.equal(error.message, 'cleanup-sentinel') + } finally { + assert(monitor.disable()) + assert(!monitor.disable()) + for (const timer of timers) { + clearTimeout(timer) + } + timers.clear() + } + result({ samples: [], cleaned: true }) + } else { + const measured = await measure( + () => { + const start = performance.now() + while (performance.now() - start < 50) {} + return '' + }, + false, + true + ) + result({ samples: [measured.sample] }) + } + } else if (descriptor.mode === 'differential') { + ready() + let cases = 0 + const outputs = createHash('sha256') + memory('before-differential') + for (const input of plainLogDifferentialCases()) { + const output = module.sliceCheckLogTail(input) + assert(Buffer.byteLength(output) <= LIMIT) + outputs.update(JSON.stringify(output)) + cases++ + } + memory('after-differential') + result({ samples: [], cases, outputHash: outputs.digest('hex') }) + } else { + const generated = workload(descriptor) + let input = generated.text + let expected = generated.expected + const expectedHash = expected === undefined ? undefined : digest(expected) + expected = undefined + generated.expected = undefined + generated.text = undefined + ready(input) + memory('after-setup') + if (descriptor.mode === 'coverage') { + module.resetObservations() + const output = module.sliceCheckLogTail(input) + if (descriptor.arm === 'proposed') { + assertSafe(output) + } else { + assert(Buffer.byteLength(output) <= LIMIT) + } + const observations = module.observations() + if (descriptor.arm === 'proposed') { + assert((observations.strip?.maxBytes ?? 0) <= LIMIT) + assert( + (observations.candidate?.maxBytes ?? 0) <= (descriptor.bytes > LIMIT ? LIMIT / 2 : LIMIT) + ) + assert( + (observations.matcher?.maxBytes ?? 0) <= (descriptor.bytes > LIMIT ? LIMIT / 2 : LIMIT) + ) + assert((observations.exact?.maxBytes ?? 0) <= LIMIT) + } + memory('after-coverage') + result({ + samples: [], + observations, + outputBytes: Buffer.byteLength(output), + outputHash: digest(output) + }) + } else if (descriptor.mode === 'counts') { + const original = String.prototype.charCodeAt + let reads = 0 + const originalBuffer = globalThis.Buffer + if (descriptor.noBuffer) { + globalThis.Buffer = undefined + module.resetOwnRetainedStringCopier() + } + try { + String.prototype.charCodeAt = function (index) { + reads++ + return original.call(this, index) + } + const output = module.stripAnsiEscapeSequences(input) + globalThis.Buffer = originalBuffer + assert.equal(digest(output), expectedHash) + } finally { + globalThis.Buffer = originalBuffer + module.resetOwnRetainedStringCopier() + String.prototype.charCodeAt = original + } + assert(reads >= 0 && reads <= 12 * input.length + 64) + if ( + ['osc', 'dcs', 'apc', 'pm', 'sos', 'dense-osc', 'dense-string', 'mixed', 'sparse'].includes( + descriptor.family + ) + ) { + assert(reads > 0) + } + result({ samples: [], reads, codeUnits: input.length }) + } else { + const operation = + descriptor.mode === 'direct' + ? () => module.stripAnsiEscapeSequences(input) + : descriptor.arm === 'full-log' + ? () => module.sliceCheckLogTail(legacySanitize(input)) + : descriptor.arm === 'baseline-bounded' + ? () => legacySanitize(module.sliceCheckLogTail(input)) + : () => module.sliceCheckLogTail(input) + const warmups = descriptor.warmups ?? 3 + memory('before-warmup') + for (let warmup = 0; warmup < warmups; warmup++) { + module.setPhase('warmup') + emit({ type: 'entered', phase: 'warmup', warmup }) + operation() + } + memory('after-warmup') + gc() + const samples = [] + let outputBytes = 0 + let outputHash = '' + let diagnosticRetained = false + let stackRetained = false + for (let sample = 0; sample < descriptor.samples; sample++) { + module.setPhase('sample') + emit({ type: 'entered', phase: 'sample', sample }) + const measured = await measure( + operation, + descriptor.mode === 'direct' && descriptor.bytes <= 32 * 1024 + ) + if (expectedHash) { + assert.equal(digest(measured.output), expectedHash, 'Direct output changed') + } + if (descriptor.mode === 'cpu') { + assert(Buffer.byteLength(measured.output) <= LIMIT) + if (descriptor.arm !== 'baseline') { + assertSafe(measured.output) + } + const plain = + descriptor.arm === 'baseline' ? legacySanitize(measured.output) : measured.output + diagnosticRetained = plain.includes( + descriptor.family === 'short-lines' + ? 'error: CPU_DIAGNOSTIC' + : descriptor.family === 'fixture' + ? createCheckLogFixture().expectedDiagnostic + : 'No "Copy" export is defined on the "lucide-react" mock' + ) + stackRetained = plain.includes( + descriptor.family === 'short-lines' + ? 'CPU_FRAME.ts:18:8' + : descriptor.family === 'fixture' + ? createCheckLogFixture().expectedStackFrame + : 'CopyTabIdMenuItem.tsx:18:8' + ) + assert(diagnosticRetained && stackRetained) + } + outputBytes = Buffer.byteLength(measured.output) + outputHash = digest(measured.output) + samples.push(measured.sample) + } + result({ samples, outputBytes, outputHash, diagnosticRetained, stackRetained }) + } + input = '' + } + assert.equal(timers.size, 0) + assert.equal(process.getActiveResourcesInfo().filter((name) => name === 'Timeout').length, 0) +} finally { + for (const timer of timers) { + clearTimeout(timer) + } + timers.clear() +} diff --git a/config/scripts/check-job-log-test-fixture.mjs b/config/scripts/check-job-log-test-fixture.mjs new file mode 100644 index 00000000000..4b8654b691f --- /dev/null +++ b/config/scripts/check-job-log-test-fixture.mjs @@ -0,0 +1,20 @@ +export function createCheckLogFixture() { + const expectedDiagnostic = 'Error: expected 200, received 500' + const expectedStackFrame = 'request.test.ts:18:8' + const benignMarker = 'stderr | request test: retrying connection' + const genericExitMarker = '##[error]Process completed with exit code 1.' + return { + expectedDiagnostic, + expectedStackFrame, + benignMarker, + genericExitMarker, + rawLog: [ + `\x1b[90m${benignMarker}\x1b[0m`, + '\x1b[41m FAIL \x1b[0m request test', + `\x1b[31mError\x1b[0m: expected 200, received 500`, + ` at handleRequest (${expectedStackFrame})`, + genericExitMarker, + '' + ].join('\n') + } +} diff --git a/config/scripts/check-job-log-watchdog-protocol.mjs b/config/scripts/check-job-log-watchdog-protocol.mjs new file mode 100644 index 00000000000..4422a12260c --- /dev/null +++ b/config/scripts/check-job-log-watchdog-protocol.mjs @@ -0,0 +1,184 @@ +import assert from 'node:assert/strict' +import { BASELINE_REF } from './check-job-log-performance-cases.mjs' + +export function assertWatchdogExit(result) { + const signalExit = result.code === null && ['SIGTERM', 'SIGKILL'].includes(result.signal) + assert(result.timedOut === true && signalExit, 'Unverified watchdog termination') +} + +export function assertMeasurementRuntime(runtime) { + assert( + runtime?.bun === false && + typeof runtime.node === 'string' && + /^v\d+\.\d+\.\d+(?:[-+][\w.-]+)?$/.test(runtime.node) && + typeof runtime.platform === 'string' && + /^[a-z][a-z0-9]*$/.test(runtime.platform) && + typeof runtime.arch === 'string' && + /^[a-z][a-z0-9]*$/.test(runtime.arch), + 'Measurement requires verified Node' + ) +} + +export function validateChildProtocol(stdout, descriptor) { + const protocol = stdout + .trim() + .split('\n') + .filter(Boolean) + .map((line) => JSON.parse(line)) + assert(protocol.every((record) => record && typeof record === 'object')) + const readyRecords = protocol.filter((record) => record.type === 'ready') + const completed = protocol.filter((record) => record.type === 'result') + assert(readyRecords.length === 1 && protocol[0] === readyRecords[0], 'Invalid ready framing') + assert( + completed.length <= 1 && (!completed.length || protocol.at(-1) === completed[0]), + 'Invalid result framing' + ) + const ready = readyRecords[0] + assertMeasurementRuntime(ready.runtime) + if (completed.length) { + for (const field of ['id', 'mode', 'arm']) { + assert.equal(completed[0][field], descriptor[field], `Completion ${field} changed`) + } + assert.deepEqual( + completed[0].inputIdentity, + { inputBytes: ready.inputBytes, codeUnits: ready.codeUnits, inputHash: ready.inputHash }, + 'Completion input identity changed' + ) + } + const entries = protocol.slice(1, completed.length ? -1 : undefined) + let entered + let pendingStrip + let warmups = 0 + let samples = 0 + for (const entry of entries) { + if (descriptor.mode === 'watchdog') { + assert( + entries.length === 1 && entry.type === 'entered' && entry.phase === 'watchdog', + 'Invalid watchdog entry' + ) + } else if (entry.type === 'entered-strip') { + assert( + descriptor.baselineTimeoutAllowed && + descriptor.mode === 'direct' && + descriptor.arm === 'baseline' && + ['warmup', 'sample'].includes(entry.phase) && + ((pendingStrip && pendingStrip.phase === entry.phase) || entries.length === 1), + 'Invalid strip entry' + ) + pendingStrip = undefined + } else { + assert( + ['direct', 'cpu'].includes(descriptor.mode) && entry.type === 'entered' && !pendingStrip, + 'Invalid workload entry' + ) + if (entry.phase === 'warmup') { + assert(samples === 0 && warmups < (descriptor.warmups ?? 3)) + assert.equal(entry.warmup, warmups++, 'Invalid warmup order') + } else { + assert(entry.phase === 'sample' && warmups === (descriptor.warmups ?? 3)) + assert(samples < descriptor.samples) + assert.equal(entry.sample, samples++, 'Invalid sample order') + } + if (descriptor.baselineTimeoutAllowed) { + pendingStrip = entry + } + } + entered = + entry.type === (descriptor.baselineTimeoutAllowed ? 'entered-strip' : 'entered') + ? entry + : undefined + } + assert(!completed.length || !pendingStrip, 'Completion preceded strip entry') + return { ready, entered, completed, warmups } +} + +export const adverseCaseKey = (descriptor) => + JSON.stringify([ + descriptor.family, + descriptor.width, + descriptor.bytes, + descriptor.variant, + descriptor.terminator, + descriptor.seed, + descriptor.generator + ]) + +export function auditBaselineCensoring(manifest, byId) { + for (const descriptor of manifest) { + const record = byId.get(descriptor.id) + if (descriptor.mode === 'watchdog' || record.status === 'watchdog_passed') { + assert( + descriptor.mode === 'watchdog' && + record.status === 'watchdog_passed' && + record.attempted === true + ) + assert(record.settlementMs < 15000) + assert.equal(record.identity.baselineRef, BASELINE_REF) + assertMeasurementRuntime(record.runtime) + assertWatchdogExit(record.watchdogTermination) + assert.equal(record.code, record.watchdogTermination.code) + assert.equal(record.signal, record.watchdogTermination.signal) + } + if (record.status === 'baseline_timeout') { + assert( + descriptor.baselineTimeoutAllowed && + descriptor.arm === 'baseline' && + descriptor.mode === 'direct' + ) + assert(record.attempted === true && ['warmup', 'sample'].includes(record.phase)) + assert.equal(record.deadlineMs, 10000) + assert(record.settlementMs < 15000) + assert.equal(record.identity.baselineRef, BASELINE_REF) + assertMeasurementRuntime(record.runtime) + assertWatchdogExit(record.watchdogTermination) + } + if (record.status === 'baseline_censored') { + const initial = byId.get(record.initialTimeoutId) + assert( + descriptor.baselineTimeoutAllowed && descriptor.sample > 0 && record.attempted === false + ) + assert( + initial?.status === 'baseline_timeout' && + initial.sample === 0 && + initial.attempted === true, + 'Missing verified initial adverse attempt' + ) + assert.equal( + adverseCaseKey(record), + adverseCaseKey(initial), + 'Censoring crossed adverse cases' + ) + assertWatchdogExit(initial.watchdogTermination) + assert.deepEqual(record.identity, { ...initial.identity, id: descriptor.id }) + for (const field of ['inputBytes', 'codeUnits', 'inputHash']) { + assert.equal(record[field], initial[field]) + } + } + } + for (const descriptor of manifest.filter( + (item) => item.mode === 'direct' && item.baselineTimeoutAllowed && item.sample === 0 + )) { + const slots = manifest.filter( + (item) => + item.mode === 'direct' && + item.baselineTimeoutAllowed && + adverseCaseKey(item) === adverseCaseKey(descriptor) + ) + assert.equal(slots.length, 7, 'Incomplete adverse baseline logical slots') + assert.deepEqual( + slots.map((item) => item.sample).toSorted((a, b) => a - b), + [0, 1, 2, 3, 4, 5, 6] + ) + for (const slot of slots) { + const record = byId.get(slot.id) + assert( + record.attempted === true || record.status === 'baseline_censored', + 'Unattempted baseline sample' + ) + assert.equal( + record.status === 'completed' ? record.samples.length : record.unavailableSamples, + 1 + ) + } + } +} diff --git a/src/shared/ansi-escape-sequences-consumers.test.ts b/src/shared/ansi-escape-sequences-consumers.test.ts new file mode 100644 index 00000000000..54fe2b05315 --- /dev/null +++ b/src/shared/ansi-escape-sequences-consumers.test.ts @@ -0,0 +1,96 @@ +import { beforeAll, describe, expect, it } from 'vitest' +import { loadAnsiConsumers } from '../../config/scripts/check-job-log-consumer-oracles.mjs' +import { gitLabJobTraceToLogExcerpt } from './gitlab-job-log-excerpt' +import { surfaceNativeChatCommandOutputs } from './native-chat-command-output' +import type { NativeChatMessage } from './native-chat-types' +import { normalizeNativeChatUserText } from './native-chat-image-transcript-markers' + +let consumers: Awaited> +beforeAll(async () => { + consumers = await loadAnsiConsumers() +}) + +const mixed = '\x1bPleft\x1b]hidden\x1b\\right\x1b\\KEEP' + +describe('ANSI consumer compatibility with independent literal oracles', () => { + it('preserves notebook malformed 8-bit and unrelated controls', () => { + expect(consumers.parseAnsiSegments('\x9dunfinished')).toEqual([{ text: '\x9dunfinished' }]) + expect(consumers.parseAnsiSegments('\x00\t\r\n\x85')).toEqual([{ text: '\x00\t\r\n\x85' }]) + expect(consumers.parseAnsiSegments(mixed)).toEqual([{ text: 'KEEP' }]) + }) + it('keeps GitLab visible CR section headers after ANSI stripping', () => { + expect( + gitLabJobTraceToLogExcerpt( + `section_start:123:test\r\x1b[0KHeader\n${mixed}\nsection_end:124:test\r\x1b[0K\n` + ) + ).toBe('Header\nKEEP') + }) + it('requires a complete Codex URL terminated by whitespace', () => { + const prefix = `${mixed}\nNavigate to this URL to authenticate: ` + expect( + consumers.parseCodexLoginAuthUrl(`${prefix}https://auth.example.test/path?state=public`) + ).toBeNull() + expect( + consumers.parseCodexLoginAuthUrl( + `${prefix}\x1b[32mhttps://auth.example.test/path?state=public\x1b[0m\n` + ) + ).toBe('https://auth.example.test/path?state=public') + }) + it('keeps terminal-safe CLI and permission text literal', () => { + expect(consumers.terminalSafe(`\x00${mixed}\r\n\t\x85`)).toBe('KEEP\r\n\t') + expect(consumers.claudePermissionSubject('ExitPlanMode', { plan: `\x00${mixed}\x85` })).toEqual( + { + kind: 'plan', + text: 'KEEP' + } + ) + }) + it('distinguishes control-only snapshots and command paint from visible text', () => { + const invisible = '\x1b]title\x07\x1b[0m\x00\x85 \n' + expect(consumers.restoredSnapshotPaintsPrintableContent({ data: invisible })).toBe(false) + expect(consumers.restoredSnapshotPaintsPrintableContent({ scrollbackAnsi: mixed })).toBe(true) + const paint = new consumers.TerminalCommandPaint() + paint.observe('\x1b]133;C\x07', '') + paint.observe(invisible, invisible) + expect(paint.hasPainted()).toBe(false) + paint.observe(mixed, mixed) + expect(paint.hasPainted()).toBe(true) + }) + it('surfaces ordered stripped command output', () => { + const rows: NativeChatMessage[] = [ + { + id: 'parent', + role: 'user', + timestamp: 100, + source: 'transcript', + blocks: [ + { + type: 'text', + text: '/contextcontext' + } + ] + }, + { + id: 'reply', + parentId: 'parent', + role: 'user', + timestamp: 100, + source: 'transcript', + blocks: [{ type: 'text', text: `${mixed}` }] + } + ] + expect(surfaceNativeChatCommandOutputs(rows, 'openclaude')[1]?.blocks).toEqual([ + { type: 'text', text: 'KEEP', presentation: 'command-output' } + ]) + }) + it('preserves pending echo and automation snapshots with literal oracles', () => { + expect(normalizeNativeChatUserText(`\x00${mixed}\r\n\tword`)).toBe('KEEP word') + const output = consumers.createAutomationRunOutputSnapshotBuffer() + output.append(`\x00${mixed}\r\n\tword\x85`) + expect(output.snapshot()).toMatchObject({ + format: 'plain_text', + content: 'KEEP\n\tword', + truncated: false + }) + }) +}) diff --git a/src/shared/ansi-escape-sequences.test.ts b/src/shared/ansi-escape-sequences.test.ts new file mode 100644 index 00000000000..e65f250652a --- /dev/null +++ b/src/shared/ansi-escape-sequences.test.ts @@ -0,0 +1,151 @@ +import { afterAll, beforeAll, describe, expect, it, vi } from 'vitest' +import { + prepareBenchmark, + runDescriptor +} from '../../config/scripts/check-job-log-byte-cap-benchmark.mjs' +import { createManifest } from '../../config/scripts/check-job-log-performance-cases.mjs' +import { ESCAPE_SEQUENCE_PATTERN, stripAnsiEscapeSequences } from './ansi-escape-sequences' +import { sanitizeCheckJobLogExcerpt } from './check-job-log-excerpt' + +const strings = [ + ['DCS', '\x1bP', '\x90'], + ['APC', '\x1b_', '\x9f'], + ['PM', '\x1b^', '\x9e'], + ['SOS', '\x1bX', '\x98'] +] as const +const st = ['\x1b\\', '\x9c'] + +describe('ordered linear ANSI stripping', () => { + it.each(['\x1b]', '\x9d'])('removes OSC introduced by %j with all terminators', (intro) => { + for (const end of ['\x07', ...st]) { + expect(stripAnsiEscapeSequences(`界\t${intro}title\nbody${end}😀\r\n`)).toBe('界\t😀\r\n') + expect(stripAnsiEscapeSequences(`a${intro}${end}b`)).toBe('ab') + } + }) + it.each(strings)('removes %s with ST, treating BEL as payload', (_family, seven, eight) => { + for (const intro of [seven, eight]) { + for (const end of st) { + expect(stripAnsiEscapeSequences(`a${intro}left\x07right\n${end}b`)).toBe('ab') + expect(stripAnsiEscapeSequences(`a${intro}${end}b`)).toBe('ab') + } + expect(stripAnsiEscapeSequences(`${intro}body\x07`)).toBe( + intro === seven ? 'body\x07' : `${intro}body\x07` + ) + } + }) + it.each(['\x1b[', '\x9b'])('removes valid CSI %j and preserves failed bytes', (intro) => { + for (const body of ['31m', '?25l', '1;2H', '0K', '1 q']) { + expect(stripAnsiEscapeSequences(`a${intro}${body}b`)).toBe('ab') + } + const leftover = intro === '\x1b[' ? '' : intro + for (const body of ['', '31', '1 ', '12\x00m', '1\x18m']) { + expect(stripAnsiEscapeSequences(`${intro}${body}`)).toBe(`${leftover}${body}`) + } + }) + it('preserves unrelated controls and incomplete generic escapes', () => { + expect(stripAnsiEscapeSequences('a\x1b(Bb\x1bc\x1b\\c')).toBe('abc') + expect(stripAnsiEscapeSequences('\x00\x01\x18\x1a\x7f\x9c\t\r\n\x1b ')).toBe( + '\x00\x01\x18\x1a\x7f\x9c\t\r\n\x1b ' + ) + }) + it('matches the exported generic grammar at every byte and intermediate boundary', () => { + for (const intermediates of ['', ' ', ' /']) { + for (let unit = 0; unit <= 0xff; unit++) { + const input = `a\x1b${intermediates}${String.fromCharCode(unit)}` + expect(stripAnsiEscapeSequences(input)).toBe(input.replace(ESCAPE_SEQUENCE_PATTERN, '')) + } + } + }) + it.each([ + ['a\x1b /\x1bc', 'a\x1b /'], + ['a\x1b /\x00\x1b~b', 'a\x1b /\x00b'], + ['a\x1b\x1b /0b', 'a\x1bb'], + ['a\x1b /\x7fb\x1b ', 'a\x1b /\x7fb\x1b '] + ])('keeps failed generic matches literal before later escapes in %j', (input, expected) => { + expect(stripAnsiEscapeSequences(input)).toBe(expected) + }) + it('collects dense generic removals across owned block boundaries without altering UTF-16', () => { + const visible = '界\ud800a😀\udfff' + const input = `${visible}\x1b(B`.repeat(4097) + expect(stripAnsiEscapeSequences(input)).toBe(visible.repeat(4097)) + }) + it.each([ + ['\x1b]a\x1b\\KEEP\x1b]b\x07', 'KEEP'], + ['\x1bPleft\x07right\x1b\\KEEP', 'KEEP'], + ['\x1bPleft\x1b]hidden\x1b\\right\x1b\\KEEP', 'KEEP'], + ['\x1b]body\x1b\x1b\\KEEP', 'KEEP'], + ['\x1b]body\x1b', 'body\x1b'], + ['\x1b]a\x07KEEP\x1b]b\x1b\\TAIL', 'KEEPTAIL'], + ['\x1b]a\x07\x1b\\\x1b]b\x1b\\KEEP', 'KEEP'], + ['\x1b]a\x9cKEEP\x1bPb\x1b\\TAIL', 'KEEPTAIL'], + ['\x1b]a\x1b]b\x1bPc', 'abc'] + ])('pins terminator cache edges for %j', (input, expected) => { + expect(stripAnsiEscapeSequences(input)).toBe(expected) + }) + it('sanitizes a partial ST without completing it', () => { + expect(sanitizeCheckJobLogExcerpt('\x1b]body\x1b')).toBe('body') + }) + it.each(['\x1b]', '\x9d', ...strings.flatMap(([, seven, eight]) => [seven, eight])])( + 'preserves printable fragments of unfinished %j', + (intro) => { + const expected = intro.length === 2 ? 'body' : `${intro}body` + expect(stripAnsiEscapeSequences(`${intro}body`)).toBe(expected) + expect(stripAnsiEscapeSequences(`\x1b[31mOK\x1b[0m${intro}body`)).toBe(`OK${expected}`) + expect(stripAnsiEscapeSequences(`${intro}body\x1b`)).toBe(`${expected}\x1b`) + } + ) + it.each([16 * 1024, 32 * 1024])('bounds actual scanner reads with cached EOF at %i', (size) => { + const input = '\x1b]a\x1b]b\x1bPc'.repeat(Math.ceil(size / 9)).slice(0, size) + const read = String.prototype.charCodeAt + let reads = 0 + const spy = vi.spyOn(String.prototype, 'charCodeAt').mockImplementation(function ( + this: string, + index: number + ) { + reads++ + return read.call(this, index) + }) + try { + stripAnsiEscapeSequences(input) + expect(reads).toBeGreaterThan(size) + expect(reads).toBeLessThanOrEqual(12 * size + 64) + } finally { + spy.mockRestore() + spy.mockClear() + } + }) +}) + +// Manual benchmark: opt in with ORCA_CHECK_LOG_PERF=1. +describe.runIf(process.env.ORCA_CHECK_LOG_PERF === '1')( + 'near-cap unfinished 7-bit stripping completion', + { concurrent: false }, + () => { + let context: Awaited> + beforeAll(async () => { + context = await prepareBenchmark(process.cwd(), { compareBaseline: false }) + }, 15_000) + afterAll(async () => { + await context?.cleanup() + }) + it.each(['osc', 'dcs'])( + 'completes %s warmups and a sample under the unchanged child watchdog', + async (family) => { + const descriptor = createManifest().find( + (item) => + item.mode === 'direct' && + item.arm === 'proposed' && + item.family === family && + item.width === 7 && + item.bytes === 63 * 1024 * 1024 && + item.sample === 0 + ) + expect(descriptor).toBeDefined() + const result = await runDescriptor(context, descriptor) + expect(result.status).toBe('completed') + expect(result.samples).toHaveLength(1) + }, + 15_000 + ) + } +) diff --git a/src/shared/ansi-escape-sequences.ts b/src/shared/ansi-escape-sequences.ts index 1d914900c24..6220e99c3b8 100644 --- a/src/shared/ansi-escape-sequences.ts +++ b/src/shared/ansi-escape-sequences.ts @@ -1,10 +1,6 @@ /* eslint-disable no-control-regex -- these patterns exist to match terminal control bytes. */ +import { ownRetainedString } from './own-retained-string' -/** OSC title/progress frames, 7-bit (ESC ]) and 8-bit (U+009D) introducers. */ -export const OSC_SEQUENCE_PATTERN = /(?:\u001b\]|\u009d)[\s\S]*?(?:\u0007|\u001b\\|\u009c)/g -/** DCS/APC/PM/SOS string sequences terminated by ST. */ -export const STRING_SEQUENCE_PATTERN = - /(?:\u001b[P_^X]|\u0090|\u0098|\u009e|\u009f)[\s\S]*?(?:\u001b\\|\u009c)/g /** CSI sequences (colors, cursor moves, `\u001b[0K` erase-to-EOL). */ export const CSI_SEQUENCE_PATTERN = /(?:\u001b\[|\u009b)[0-?]*[ -/]*[@-~]/g /** Remaining two/three-byte escape sequences (charset selection, RIS, ...). */ @@ -13,15 +9,142 @@ export const ESCAPE_SEQUENCE_PATTERN = /\u001b[ -/]*[0-~]/g export const TERMINAL_CONTROL_CHARACTER_PATTERN = /[\u0000-\u0008\u000b\u000c\u000e-\u001f\u007f-\u009f]/g +type TerminatorSearch = { cursor: number; start: number; end: number } +const OSC_INTRODUCER_PATTERN = /\u001b\]|\u009d/ +const STRING_INTRODUCER_PATTERN = /\u001b[P_^X]|[\u0090\u0098\u009e\u009f]/ +const CONTROL_STRING_INTRODUCER_PATTERN = /\u001b[\]P_^X]|[\u0090\u0098\u009d-\u009f]/ +const ANSI_INTRODUCER_PATTERN = /[\u001b\u0090\u0098\u009b\u009d-\u009f]/ + +function nextSt(value: string, payloadStart: number, search: TerminatorSearch): void { + if (search.start >= payloadStart || search.cursor === value.length) { + return + } + for (let index = Math.max(search.cursor, payloadStart); index < value.length; index += 1) { + const unit = value.charCodeAt(index) + const width = unit === 0x9c ? 1 : unit === 0x1b && value.charCodeAt(index + 1) === 0x5c ? 2 : 0 + if (width) { + search.start = index + search.end = index + width + search.cursor = search.end + return + } + } + search.start = -1 + search.cursor = value.length +} + +function createAnsiSpanCollector(value: string) { + let block = '' + const blocks: string[] = [] + const appendSpan = (start: number, end: number): void => { + while (start < end) { + const next = Math.min(end, start + 4096 - block.length) + block += value.slice(start, next) + start = next + if (block.length === 4096) { + blocks.push(ownRetainedString(block)) + block = '' + } + } + } + return { + appendSpan, + finish: (): string => { + if (block) { + blocks.push(ownRetainedString(block)) + } + return blocks.join('') + } + } +} + +function stripControlStrings(value: string, osc: boolean): string { + if (!(osc ? OSC_INTRODUCER_PATTERN : STRING_INTRODUCER_PATTERN).test(value)) { + return value + } + const st: TerminatorSearch = { cursor: 0, start: -1, end: 0 } + let bel = -1 + let belExhausted = false + let spanStart = 0 + let collector: ReturnType | undefined + for (let index = 0; index < value.length; index += 1) { + const unit = value.charCodeAt(index) + let width = 0 + if (unit === 0x1b) { + const next = value.charCodeAt(index + 1) + if (osc ? next === 0x5d : next === 0x50 || next === 0x5f || next === 0x5e || next === 0x58) { + width = 2 + } + } else if ( + osc ? unit === 0x9d : unit === 0x90 || unit === 0x98 || unit === 0x9e || unit === 0x9f + ) { + width = 1 + } + if (!width) { + continue + } + const payloadStart = index + width + nextSt(value, payloadStart, st) + if (osc && bel < payloadStart && !belExhausted) { + bel = value.indexOf('\u0007', payloadStart) + belExhausted = bel === -1 + } + const useBel = osc && bel >= payloadStart && (st.start < payloadStart || bel < st.start) + const end = useBel ? bel + 1 : st.start >= payloadStart ? st.end : -1 + if (end === -1) { + continue + } + collector ??= createAnsiSpanCollector(value) + collector.appendSpan(spanStart, index) + spanStart = end + index = end - 1 + } + if (!collector) { + return value + } + collector.appendSpan(spanStart, value.length) + return collector.finish() +} + +function stripGenericEscapes(value: string): string { + let index = value.indexOf('\u001b') + let spanStart = 0 + let collector: ReturnType | undefined + // Dense unfinished 7-bit strings must not allocate a global replacement entry per introducer. + while (index !== -1) { + let end = index + 1 + let unit = value.charCodeAt(end) + while (unit >= 0x20 && unit <= 0x2f) { + end += 1 + unit = value.charCodeAt(end) + } + if (unit >= 0x30 && unit <= 0x7e) { + collector ??= createAnsiSpanCollector(value) + collector.appendSpan(spanStart, index) + end += 1 + spanStart = end + } + index = value.indexOf('\u001b', end) + } + if (!collector) { + return value + } + collector.appendSpan(spanStart, value.length) + return collector.finish() +} + /** * Remove ANSI escape sequences while preserving text, tabs and line breaks. * Ordering matters: OSC/string sequences must be consumed before the generic * escape pattern, which would otherwise eat only their introducer. */ export function stripAnsiEscapeSequences(value: string): string { - return value - .replace(OSC_SEQUENCE_PATTERN, '') - .replace(STRING_SEQUENCE_PATTERN, '') - .replace(CSI_SEQUENCE_PATTERN, '') - .replace(ESCAPE_SEQUENCE_PATTERN, '') + if (!ANSI_INTRODUCER_PATTERN.test(value)) { + return value + } + const stripped = CONTROL_STRING_INTRODUCER_PATTERN.test(value) + ? stripControlStrings(stripControlStrings(value, true), false) + : value + const withoutCsi = stripped.replace(CSI_SEQUENCE_PATTERN, '') + return stripGenericEscapes(withoutCsi) } diff --git a/src/shared/check-job-log-byte-cap.test.ts b/src/shared/check-job-log-byte-cap.test.ts index 13785b28674..091066d8e13 100644 --- a/src/shared/check-job-log-byte-cap.test.ts +++ b/src/shared/check-job-log-byte-cap.test.ts @@ -29,7 +29,7 @@ describe('check log excerpt byte-cap work', () => { it.each(['x', 'é', '界', '😀', '\ud83d', '\udc00'])( 'preserves byte boundaries for %j', (unit) => { - const width = Buffer.byteLength(unit) + const width = new TextEncoder().encode(unit).byteLength for (const delta of [-1, 0, 1]) { const count = Math.floor(PR_CHECK_LOG_TAIL_BYTES / width) + delta const input = unit.repeat(count) @@ -37,7 +37,9 @@ describe('check log excerpt byte-cap work', () => { expect(output).toBe( unit.repeat(Math.min(count, Math.floor(PR_CHECK_LOG_TAIL_BYTES / width))) ) - expect(Buffer.byteLength(output)).toBeLessThanOrEqual(PR_CHECK_LOG_TAIL_BYTES) + expect(new TextEncoder().encode(output).byteLength).toBeLessThanOrEqual( + PR_CHECK_LOG_TAIL_BYTES + ) } } ) diff --git a/src/shared/check-job-log-excerpt.test.ts b/src/shared/check-job-log-excerpt.test.ts new file mode 100644 index 00000000000..5c4846c783f --- /dev/null +++ b/src/shared/check-job-log-excerpt.test.ts @@ -0,0 +1,122 @@ +import { afterEach, describe, expect, it, vi } from 'vitest' +import { createCheckLogFixture } from '../../config/scripts/check-job-log-test-fixture.mjs' +import { PR_CHECK_LOG_TAIL_BYTES, sanitizeCheckJobLogExcerpt } from './check-job-log-excerpt' +import * as ansi from './ansi-escape-sequences' +import * as ownership from './own-retained-string' +import * as bytes from './utf8-byte-limits' + +const limit = PR_CHECK_LOG_TAIL_BYTES +const fixture = createCheckLogFixture() + +describe('bounded owned check log sanitation', () => { + afterEach(() => { + vi.restoreAllMocks() + ownership.resetOwnRetainedStringCopier() + }) + it('normalizes separators and unsafe controls while preserving layout', () => { + const raw = ' α\t\x1b[31merror:\x1b[0m\r\n界\r😀\n\x00\x01\x08\x0b\x0c\x1f\x7f\x85\x9c\n' + expect(sanitizeCheckJobLogExcerpt(raw)).toBe(' α\terror:\n界\n😀\n\n') + }) + it.each(['x', 'é', '界', '😀', '\ud800', '\udfff'])('caps UTF-8 %j at byte edges', (unit) => { + const width = bytes.getUtf8ByteLength(unit) + for (const delta of [-1, 0, 1]) { + const input = unit.repeat(Math.floor(limit / width) + delta) + const result = sanitizeCheckJobLogExcerpt(input) + expect(result).toBe( + unit.repeat(Math.min(Math.floor(limit / width), input.length / unit.length)) + ) + expect(bytes.getUtf8ByteLength(result)).toBeLessThanOrEqual(limit) + expect(sanitizeCheckJobLogExcerpt(result)).toBe(result) + } + }) + it('bounds raw text before ANSI, counting or copying, with no refill', () => { + const strip = vi.spyOn(ansi, 'stripAnsiEscapeSequences') + const count = vi.spyOn(bytes, 'getUtf8ByteLength') + const own = vi.spyOn(ownership, 'ownRetainedString') + const input = `${'omitted'.repeat(limit)}${'\x1b[31m'.repeat(4000)}LAST` + const result = sanitizeCheckJobLogExcerpt(input) + expect(result).toBe('LAST') + expect(strip).toHaveBeenCalledTimes(1) + expect( + strip.mock.calls.every(([value]) => bytes.measureUtf8ByteLength(value).byteLength <= limit) + ).toBe(true) + expect(count).not.toHaveBeenCalled() + expect(own).toHaveBeenLastCalledWith('LAST') + strip.mockClear() + own.mockClear() + }) + it.each(['x', 'é', '界', '😀', '\ud800', '\udfff'])( + 'preserves precise byte edges for %j', + (unit) => { + const width = bytes.getUtf8ByteLength(unit) + for (const delta of [-1, 0, 1]) { + const count = Math.floor((limit + delta) / width) + const padding = 'x'.repeat((limit + delta) % width) + const input = unit.repeat(count) + padding + expect(bytes.getUtf8ByteLength(input)).toBe(limit + delta) + expect(sanitizeCheckJobLogExcerpt(input)).toBe( + unit.repeat(count - (delta > 0 ? 1 : 0)) + padding + ) + } + } + ) + it.each([ + ['\x1b[31m', '[31m'], + ['\x1b]body', ']body'], + ['\x1bPbody', 'Pbody'], + ['\x1b_body', '_body'], + ['\x1b^body', '^body'], + ['\x1bXbody', 'Xbody'] + ])('uses fresh state when the raw tail cuts an introducer %j', (sequence, fragment) => { + const retained = fragment + 'x'.repeat(limit - fragment.length) + expect( + sanitizeCheckJobLogExcerpt( + `${'omitted'.repeat(limit)}${sequence}${'x'.repeat(limit - fragment.length)}` + ) + ).toBe(retained) + }) + it('always owns an unchanged plain excerpt', () => { + const own = vi.spyOn(ownership, 'ownRetainedString') + const input = ' plain unchanged\ttext\n' + expect(sanitizeCheckJobLogExcerpt(input)).toBe(input) + expect(own).toHaveBeenCalledTimes(1) + expect(own).toHaveBeenLastCalledWith(input) + }) + it('owns without Buffer and preserves source lone surrogates', () => { + vi.stubGlobal('Buffer', undefined) + ownership.resetOwnRetainedStringCopier() + try { + expect(sanitizeCheckJobLogExcerpt(`${'x'.repeat(20000)}\ud800a\udfff\n`)).toBe( + `${'x'.repeat(limit - 8)}\ud800a\udfff\n` + ) + } finally { + vi.unstubAllGlobals() + ownership.resetOwnRetainedStringCopier() + } + }) + it.each([ + ['\x1b', ''], + ['\x1b[31', '31'], + ['\x9b31', '31'], + ['\x1b]body\x1b', 'body'], + ['\x9dbody', 'body'], + ['\x1bPbody\x1b', 'body'], + ['\x90body', 'body'], + ['payload\x1b\\TAIL', 'payloadTAIL'], + ['payload\x9cTAIL', 'payloadTAIL'] + ])('keeps literal fragments at a cut %j', (suffix, expected) => { + expect(sanitizeCheckJobLogExcerpt(suffix)).toBe(expected) + expect(sanitizeCheckJobLogExcerpt(`${'z'.repeat(2 * limit)}${suffix}`)).toBe( + `${'z'.repeat(limit - bytes.getUtf8ByteLength(suffix))}${expected}` + ) + }) + it('keeps failure diagnostic and nearby stack', () => { + const result = sanitizeCheckJobLogExcerpt(fixture.rawLog) + expect(result).toContain(fixture.expectedDiagnostic) + expect(result).toContain(fixture.expectedStackFrame) + expect(result).toContain(fixture.benignMarker) + expect(result).toContain(fixture.genericExitMarker) + expect(ansi.TERMINAL_CONTROL_CHARACTER_PATTERN.test(result)).toBe(false) + expect(sanitizeCheckJobLogExcerpt(result)).toBe(result) + }) +}) diff --git a/src/shared/check-job-log-excerpt.ts b/src/shared/check-job-log-excerpt.ts new file mode 100644 index 00000000000..15109d6ec9a --- /dev/null +++ b/src/shared/check-job-log-excerpt.ts @@ -0,0 +1,19 @@ +import { + stripAnsiEscapeSequences, + TERMINAL_CONTROL_CHARACTER_PATTERN +} from './ansi-escape-sequences' +import { ownRetainedString } from './own-retained-string' +import { clampUtf8TextTail, isUtf8ByteLengthWithinLimit } from './utf8-byte-limits' + +export const PR_CHECK_LOG_TAIL_BYTES = 16 * 1024 + +export function sanitizeCheckJobLogExcerpt(value: string): string { + const bounded = isUtf8ByteLengthWithinLimit(value, PR_CHECK_LOG_TAIL_BYTES) + ? value + : clampUtf8TextTail(value, PR_CHECK_LOG_TAIL_BYTES).text + return ownRetainedString( + stripAnsiEscapeSequences(bounded) + .replace(/\r\n?/g, '\n') + .replace(TERMINAL_CONTROL_CHARACTER_PATTERN, '') + ) +} diff --git a/src/shared/check-job-log-marker-candidates.test.ts b/src/shared/check-job-log-marker-candidates.test.ts new file mode 100644 index 00000000000..39f9d8477fe --- /dev/null +++ b/src/shared/check-job-log-marker-candidates.test.ts @@ -0,0 +1,142 @@ +import { afterEach, describe, expect, it, vi } from 'vitest' +import * as ansi from './ansi-escape-sequences' +import * as byteLimits from './utf8-byte-limits' +import { createCheckLogFixture } from '../../config/scripts/check-job-log-test-fixture.mjs' +import { + PR_CHECK_LOG_TAIL_BYTES, + PR_CHECK_LOG_TAIL_EARLIER_SEPARATOR, + sliceCheckLogTail +} from './check-job-log-tail-slice' + +const trailing = Array.from({ length: 210 }, (_, index) => `recent ${index}`).join('\n') +const fixture = createCheckLogFixture() +const earlier = (line: string): string => `${line}\n${trailing}` + +describe('bounded ANSI-aware marker candidates', () => { + afterEach(() => vi.restoreAllMocks()) + it.each([ + '##[error]', + '::error::', + '::error', + 'error:', + 'FAILED', + 'exit code', + 'ENOENT', + 'EACCES', + 'panic:', + 'AssertionError' + ])('recognizes interrupted and surrounded %s before recent lines', (marker) => { + for (const color of ['\x1b[31m', '\x9b31m']) { + const line = `unique ${color}${marker.slice(0, 3)}${color}${marker.slice(3)}\x1b[0m` + expect(sliceCheckLogTail(earlier(line))).toContain(`unique ${marker}`) + expect(sliceCheckLogTail(earlier(line))).toContain(PR_CHECK_LOG_TAIL_EARLIER_SEPARATOR) + } + }) + it.each(['\x1b]', '\x9d', '\x1bP', '\x90', '\x1b_', '\x9f', '\x1b^', '\x9e', '\x1bX', '\x98'])( + 'ignores invisible markers in complete %j payloads', + (intro) => { + const input = earlier(`hidden ${intro}error: invisible\x1b\\ suffix`) + expect(sliceCheckLogTail(input)).not.toContain(PR_CHECK_LOG_TAIL_EARLIER_SEPARATOR) + } + ) + it.each([ + ['er', 'ror:'], + ['::er', 'ror::'], + ['er\x1b', '[31mror:'], + ['::er\x1b[31m', 'ror::'] + ])('does not join independent %j/%j windows', (left, right) => { + const window = PR_CHECK_LOG_TAIL_BYTES / 2 + const line = `${'x'.repeat(window - left.length)}${left}${'m'.repeat(20000)}${right}${'x'.repeat(window - right.length)}` + expect(sliceCheckLogTail(earlier(line))).not.toContain(PR_CHECK_LOG_TAIL_EARLIER_SEPARATOR) + }) + it.each(['prefix', 'tail', 'middle'] as const)( + 'limits oversized %s markers to independent edges', + (position) => { + const marker = 'error: EDGE' + const line = + position === 'prefix' + ? `${marker}${'x'.repeat(40000)}` + : position === 'tail' + ? `${'x'.repeat(40000)} ${marker}` + : `${'x'.repeat(20000)} ${marker}${'x'.repeat(20000)}` + expect(sliceCheckLogTail(earlier(line)).includes(PR_CHECK_LOG_TAIL_EARLIER_SEPARATOR)).toBe( + position !== 'middle' + ) + } + ) + it.each(['x', '界', '😀', '\ud800', '\udfff'])( + 'bounds actual normalization and marker inputs for %j', + (unit) => { + const input = earlier(`error: ${unit.repeat(20000)}`) + const strip = vi.spyOn(ansi, 'stripAnsiEscapeSequences') + const count = vi.spyOn(byteLimits, 'getUtf8ByteLength') + const fit = vi.spyOn(byteLimits, 'isUtf8ByteLengthWithinLimit') + const test = RegExp.prototype.test + const matcherBytes: number[] = [] + const pattern = vi.spyOn(RegExp.prototype, 'test').mockImplementation(function ( + this: RegExp, + value: string + ) { + if (this.source.includes('AssertionError')) { + matcherBytes.push(byteLimits.measureUtf8ByteLength(value).byteLength) + } + return test.call(this, value) + }) + try { + const output = sliceCheckLogTail(input) + const normalized = strip.mock.calls.map( + ([value]) => byteLimits.measureUtf8ByteLength(value).byteLength + ) + expect(Math.max(...normalized)).toBeLessThanOrEqual(PR_CHECK_LOG_TAIL_BYTES) + expect(normalized.slice(0, -1).every((bytes) => bytes <= PR_CHECK_LOG_TAIL_BYTES / 2)).toBe( + true + ) + expect(Math.max(...matcherBytes)).toBeLessThanOrEqual(PR_CHECK_LOG_TAIL_BYTES / 2) + expect(count.mock.calls.every(([value]) => value.length <= PR_CHECK_LOG_TAIL_BYTES)).toBe( + true + ) + expect(fit.mock.calls.every(([, limit]) => limit === PR_CHECK_LOG_TAIL_BYTES)).toBe(true) + expect(byteLimits.measureUtf8ByteLength(output).byteLength).toBeLessThanOrEqual( + PR_CHECK_LOG_TAIL_BYTES + ) + } finally { + strip.mockClear() + count.mockClear() + fit.mockClear() + pattern.mockRestore() + } + } + ) + it('preserves failure context in recent and generated earlier modes', () => { + const recent = sliceCheckLogTail(fixture.rawLog) + expect(recent).toContain(fixture.expectedDiagnostic) + expect(recent).toContain(fixture.expectedStackFrame) + const rawRows = fixture.rawLog.split('\n') + const diagnostic = + rawRows.find((line) => + ansi.stripAnsiEscapeSequences(line).includes(fixture.expectedDiagnostic) + ) ?? '' + const frame = rawRows.find((line) => line.includes(fixture.expectedStackFrame)) ?? '' + const output = sliceCheckLogTail(`${diagnostic}\n${frame}\n${trailing}`) + expect(output).toContain(fixture.expectedDiagnostic) + expect(output).toContain(fixture.expectedStackFrame) + expect(output).toContain(PR_CHECK_LOG_TAIL_EARLIER_SEPARATOR) + }) + it.each(['\n', '\r\n', '\r'])( + 'splits raw %j while preserving selection and trailing empty entry', + (separator) => { + const rows = [ + 'first', + 'error: retained', + '', + ...Array.from({ length: 210 }, (_, i) => `row ${i}`), + '' + ] + expect(sliceCheckLogTail(rows.join(separator))).toBe(sliceCheckLogTail(rows.join('\n'))) + expect(sliceCheckLogTail(`a${separator}${separator}b${separator}`)).toBe('a\n\nb\n') + } + ) + it('handles mixed CR/CRLF/LF without merging lines', () => { + expect(sliceCheckLogTail('a\rb\r\nc\n\r\nd\r')).toBe('a\nb\nc\n\nd\n') + }) +}) diff --git a/src/shared/check-job-log-performance-harness.test.ts b/src/shared/check-job-log-performance-harness.test.ts new file mode 100644 index 00000000000..baef85b2c29 --- /dev/null +++ b/src/shared/check-job-log-performance-harness.test.ts @@ -0,0 +1,721 @@ +import { afterEach, describe, expect, it, vi } from 'vitest' +import { createHash } from 'node:crypto' +import { + auditResults, + prepareBenchmark, + runDescriptor +} from '../../config/scripts/check-job-log-byte-cap-benchmark.mjs' +import { + BASELINE_REF, + createManifest, + selectRequiredDescriptors +} from '../../config/scripts/check-job-log-performance-cases.mjs' +import { adverseCaseKey } from '../../config/scripts/check-job-log-watchdog-protocol.mjs' + +const launcher = vi.hoisted(() => vi.fn()) +vi.mock('@orca/process-host', () => ({ runProcess: launcher })) +afterEach(() => { + launcher.mockReset() + context.censoredBaselines?.clear() + vi.unstubAllEnvs() +}) + +const context = { + censoredBaselines: new Map(), + root: process.cwd(), + identity: { + baselineRef: BASELINE_REF, + baselineSourceHashes: { ansi: 'frozen' }, + proposedSourceHashes: { ansi: 'current' } + }, + bundles: { + 'baseline-negative': { filename: 'baseline.mjs', hash: 'negative-bundle' }, + baseline: { filename: 'baseline.mjs', hash: 'baseline-bundle' }, + proposed: { filename: 'proposed.mjs', hash: 'proposed-bundle' } + } +} +const adverse = { + id: 'negative-case', + mode: 'direct', + arm: 'baseline', + family: 'osc', + width: 7, + bytes: 16384, + samples: 7, + sample: 0, + baselineTimeoutAllowed: true +} +const ready = (id = adverse.id, bundleHash = context.bundles['baseline-negative'].hash) => ({ + type: 'ready', + identity: { ...context.identity, id, bundleHash }, + runtime: { node: process.version, platform: process.platform, arch: process.arch, bun: false }, + inputBytes: 16384, + codeUnits: 16384, + inputHash: createHash('sha256').update('x'.repeat(16384)).digest('hex') +}) +const protocol = (records: unknown[]): string => + `${records.map((record) => JSON.stringify(record)).join('\n')}\n` +const timeoutResult = () => ({ + code: null, + signal: 'SIGTERM', + timedOut: true, + outputTruncated: false, + stderr: '', + stdout: protocol([ready(), { type: 'entered-strip', phase: 'warmup' }]) +}) +const watchdogExits = [ + { label: 'SIGTERM', signal: 'SIGTERM', code: null, accepted: true }, + { label: 'SIGKILL', signal: 'SIGKILL', code: null, accepted: true }, + { label: 'numeric one', signal: null, code: 1, accepted: false }, + { label: 'numeric two', signal: null, code: 2, accepted: false }, + { label: 'maximum safe integer', signal: null, code: Number.MAX_SAFE_INTEGER, accepted: false }, + { label: 'unsigned access violation', signal: null, code: 3221225477, accepted: false }, + { label: 'signed access violation', signal: null, code: -1073741819, accepted: false }, + { label: 'fractional code', signal: null, code: 1.5, accepted: false }, + { label: 'zero code', signal: null, code: 0, accepted: false }, + { label: 'null/null', signal: null, code: null, accepted: false }, + { label: 'unexpected signal', signal: 'SIGSEGV', code: null, accepted: false }, + { label: 'unexpected signal/code', signal: 'SIGSEGV', code: 1, accepted: false }, + { label: 'SIGINT', signal: 'SIGINT', code: null, accepted: false }, + { label: 'SIGTERM/code', signal: 'SIGTERM', code: 1, accepted: false }, + { label: 'SIGKILL/code', signal: 'SIGKILL', code: 2, accepted: false } +] as const +const adverseSlots = () => + Array.from({ length: 7 }, (_, sample) => ({ + ...adverse, + id: sample ? `slot-${sample}` : adverse.id, + samples: 1, + sample + })) +const differentials = ['baseline', 'proposed'].map((arm) => ({ + id: `diff-${arm}`, + mode: 'differential', + arm +})) +const differentialRecords = differentials.map((item) => ({ + ...item, + status: 'completed', + cases: 5126, + outputHash: 'same' +})) +const watchdog = { id: 'watchdog', mode: 'watchdog', arm: 'proposed' } +const terminationProtocol = (descriptor: typeof adverse | typeof watchdog, platform: string) => + protocol([ + { + ...ready( + descriptor.id, + context.bundles[descriptor.mode === 'direct' ? 'baseline-negative' : 'proposed'].hash + ), + runtime: { node: process.version, platform, arch: 'x64', bun: false } + }, + { + type: descriptor.mode === 'direct' ? 'entered-strip' : 'entered', + phase: descriptor.mode === 'direct' ? 'warmup' : 'watchdog' + } + ]) + +const malformedProtocols = (descriptor: typeof adverse | typeof watchdog) => { + const prework = ready( + descriptor.id, + context.bundles[descriptor.mode === 'direct' ? 'baseline-negative' : 'proposed'].hash + ) + const entry = { + type: descriptor.mode === 'direct' ? 'entered-strip' : 'entered', + phase: descriptor.mode === 'direct' ? 'warmup' : 'watchdog' + } + const result = { + type: 'result', + id: descriptor.id, + mode: descriptor.mode, + arm: descriptor.arm, + inputIdentity: { + inputBytes: prework.inputBytes, + codeUnits: prework.codeUnits, + inputHash: prework.inputHash + } + } + return [ + { label: 'wrong result id', records: [prework, entry, { ...result, id: 'wrong' }] }, + { label: 'wrong result mode', records: [prework, entry, { ...result, mode: 'wrong' }] }, + { label: 'wrong result arm', records: [prework, entry, { ...result, arm: 'wrong' }] }, + { label: 'wrong result input', records: [prework, entry, { ...result, inputIdentity: {} }] }, + { label: 'duplicate ready', records: [prework, prework, entry] }, + { + label: 'mismatched second ready', + records: [prework, { ...prework, identity: { ...prework.identity, id: 'wrong' } }, entry] + }, + { label: 'entry before ready', records: [entry, prework] }, + { label: 'duplicate result', records: [prework, entry, result, result] }, + { label: 'result before entry', records: [prework, result, entry] }, + { label: 'completed timeout', records: [prework, entry, result] }, + { label: 'duplicate entry', records: [prework, entry, entry] }, + { + label: 'pre-call after strip entry', + records: [prework, entry, { type: 'entered', phase: 'warmup', warmup: 0 }] + }, + { + label: 'invalid warmup index', + records: [prework, { type: 'entered', phase: 'warmup', warmup: -1 }, entry] + }, + { + label: 'sample before warmups', + records: [prework, { type: 'entered', phase: 'sample', sample: 0 }, entry] + }, + { label: 'unknown entry', records: [prework, { ...entry, type: 'unknown' }, entry] }, + { label: 'invalid entry phase', records: [prework, { ...entry, phase: 'startup' }] }, + { label: 'null record', records: [prework, null, entry] }, + { + label: 'truthy malformed runtime', + records: [ + { ...prework, runtime: { node: 'not-node', platform: 42, arch: {}, bun: 0 } }, + entry + ] + }, + ...[ + { node: 'not-node' }, + { node: 26 }, + { platform: 42 }, + { arch: {} }, + { bun: 0 }, + { bun: true }, + { platform: '' }, + { arch: '' } + ].map((runtime) => ({ + label: `invalid runtime ${Object.keys(runtime)[0]}=${JSON.stringify(Object.values(runtime)[0])}`, + records: [{ ...prework, runtime: { ...prework.runtime, ...runtime } }, entry] + })) + ] +} + +describe('performance watchdog failure precedence and completeness', () => { + it('prepares current implementation checks without Git history', async () => { + const prepared = await prepareBenchmark(process.cwd(), { compareBaseline: false }) + try { + expect(launcher).not.toHaveBeenCalled() + expect(Object.keys(prepared.bundles).sort()).toEqual(['proposed', 'proposed-observed']) + expect(prepared.identity.baselineSourceHashes).toEqual({}) + } finally { + await prepared.cleanup() + } + }) + it('rejects changed historical source in the manual comparison', async () => { + const success = { code: 0, signal: null, timedOut: false, outputTruncated: false } + launcher.mockResolvedValueOnce({ ...success, stdout: 'changed historical ANSI source' }) + await expect(prepareBenchmark()).rejects.toThrow( + 'Baseline source changed: ansi-escape-sequences.ts' + ) + expect(launcher).toHaveBeenCalledTimes(1) + }) + describe.each(['adverse', 'watchdog'])('%s protocol framing', (branch) => { + const descriptor = branch === 'adverse' ? adverse : watchdog + it.each(malformedProtocols(descriptor))( + 'rejects $label before timeout acceptance', + async (fixture) => { + launcher.mockResolvedValue({ ...timeoutResult(), stdout: protocol(fixture.records) }) + await expect(runDescriptor(context, descriptor)).rejects.toThrow() + expect(context.censoredBaselines.size).toBe(0) + } + ) + }) + it.each(malformedProtocols(adverse))( + '$label cannot suppress later attempts or pass audit', + async (fixture) => { + const slots = adverseSlots() + const records: object[] = [] + launcher.mockResolvedValue({ ...timeoutResult(), stdout: protocol(fixture.records) }) + await expect(runDescriptor(context, slots[0])).rejects.toThrow() + records.push({ ...slots[0], status: 'failed' }) + for (const slot of slots.slice(1)) { + launcher.mockResolvedValue({ + ...timeoutResult(), + stdout: terminationProtocol(slot, 'darwin') + }) + records.push(await runDescriptor(context, slot)) + } + expect(launcher).toHaveBeenCalledTimes(7) + expect(records.slice(1).every((record) => Object.hasOwn(record, 'watchdogTermination'))).toBe( + true + ) + expect(context.censoredBaselines.size).toBe(0) + expect(() => + auditResults([...slots, ...differentials], [...records, ...differentialRecords]) + ).toThrow('Failed descriptor') + } + ) + it.each(['warmup', 'sample'])('preserves a verified partial %s strip entry', async (phase) => { + launcher.mockResolvedValue({ + ...timeoutResult(), + stdout: protocol([ready(), { type: 'entered-strip', phase }]) + }) + const record = await runDescriptor(context, adverse) + expect(record.status).toBe('baseline_timeout') + expect(record.samples).toEqual([]) + expect(record.unavailableSamples).toBe(7) + expect(record.deadlineMs).toBe(10000) + expect(launcher).toHaveBeenCalledWith( + expect.objectContaining({ + timeoutMs: 10000, + maxOutputBytes: 65536, + env: expect.objectContaining({ ORCA_BACKGROUND_LAUNCH: '1' }) + }) + ) + }) + it.each([ + 'startup', + 'identity', + 'truncated', + 'stderr', + 'crash', + 'unexpected-signal', + 'pre-call-only' + ])('rejects %s failures rather than labeling them baseline timeouts', async (failure) => { + const result = timeoutResult() + if (failure === 'startup') { + result.stdout = '' + } + if (failure === 'identity') { + result.stdout = protocol([ready('wrong-case'), { type: 'entered-strip', phase: 'warmup' }]) + } + if (failure === 'truncated') { + result.outputTruncated = true + } + if (failure === 'stderr') { + result.stderr = 'sentinel fixture construction failure' + } + if (failure === 'crash') { + result.timedOut = false + result.signal = 'SIGSEGV' + } + if (failure === 'unexpected-signal') { + result.signal = 'SIGSEGV' + } + if (failure === 'pre-call-only') { + result.stdout = protocol([ready(), { type: 'entered', phase: 'warmup' }]) + } + launcher.mockResolvedValue(result) + await expect(runDescriptor(context, adverse)).rejects.toThrow() + }) + it.each(['proposed', 'ordinary-baseline'])('rejects %s workload timeouts', async (arm) => { + const baseline = arm === 'ordinary-baseline' + const descriptor = { + ...adverse, + arm: baseline ? 'baseline' : 'proposed', + baselineTimeoutAllowed: false + } + launcher.mockResolvedValue({ + ...timeoutResult(), + stdout: protocol([ + ready(descriptor.id, context.bundles[baseline ? 'baseline' : 'proposed'].hash), + { type: 'entered', phase: 'warmup', warmup: 0 } + ]) + }) + await expect(runDescriptor(context, descriptor)).rejects.toThrow( + 'Workload child failed or timed out' + ) + }) + it('censors only remaining slots of the exact verified initial adverse timeout', async () => { + const initial = { ...adverse, samples: 1 } + launcher.mockResolvedValue(timeoutResult()) + await runDescriptor(context, initial) + const later = { ...initial, id: 'later-slot', sample: 1 } + const record = await runDescriptor(context, later) + expect(record).toMatchObject({ + status: 'baseline_censored', + attempted: false, + initialTimeoutId: initial.id, + unavailableSamples: 1, + samples: [] + }) + expect(launcher).toHaveBeenCalledTimes(1) + expect(record).not.toHaveProperty('settlementMs') + launcher.mockResolvedValue({ ...timeoutResult(), stdout: '' }) + await expect(runDescriptor(context, { ...later, bytes: 32768 })).rejects.toThrow() + expect(launcher).toHaveBeenCalledTimes(2) + }) + it('audits seven logical adverse slots and their initial termination proof', async () => { + const slots = Array.from({ length: 7 }, (_, sample) => ({ + ...adverse, + id: sample ? `slot-${sample}` : adverse.id, + samples: 1, + sample + })) + launcher.mockResolvedValue(timeoutResult()) + const records: Awaited>[] = [] + for (const slot of slots) { + records.push(await runDescriptor(context, slot)) + } + const differentials = ['baseline', 'proposed'].map((arm) => ({ + id: `diff-${arm}`, + mode: 'differential', + arm + })) + const results = [ + ...records, + ...differentials.map((item) => ({ + ...item, + status: 'completed', + cases: 5126, + outputHash: 'same' + })) + ] + const summary = auditResults([...slots, ...differentials], results) + expect(summary).toMatchObject({ + descriptors: 9, + attemptedDescriptors: 3, + censoredSampleSlots: 6, + censoredBaselines: 1 + }) + expect(() => + auditResults( + [...slots, ...differentials], + results.map((item) => (item.id === adverse.id ? { ...item, phase: 'startup' } : item)) + ) + ).toThrow() + expect(() => + auditResults( + [...slots, ...differentials], + results.map((item) => + item.id === 'slot-1' ? { ...item, initialTimeoutId: 'missing' } : item + ) + ) + ).toThrow('Missing verified initial') + }) + describe.each(['win32', 'linux', 'darwin'])('%s watchdog evidence', (platform) => { + describe.each(['adverse', 'watchdog'])('%s classifier and parent audit', (mode) => { + it.each(watchdogExits)( + 'classifies $label through the actual launcher result', + async (exit) => { + const descriptor = mode === 'adverse' ? adverse : watchdog + launcher.mockResolvedValue({ + ...timeoutResult(), + code: exit.code, + signal: exit.signal, + stdout: terminationProtocol(descriptor, platform) + }) + if (exit.accepted) { + expect((await runDescriptor(context, descriptor)).status).toBe( + mode === 'adverse' ? 'baseline_timeout' : 'watchdog_passed' + ) + } else { + await expect(runDescriptor(context, descriptor)).rejects.toThrow( + 'Unverified watchdog termination' + ) + expect(context.censoredBaselines.size).toBe(0) + } + } + ) + it.each(watchdogExits)('audits independently constructed $label records', (exit) => { + const slots = adverseSlots() + const input = ready() + const initial = { + ...slots[0], + status: 'baseline_timeout', + attempted: true, + phase: 'warmup', + deadlineMs: 10000, + settlementMs: 10001, + identity: input.identity, + runtime: { ...input.runtime, platform }, + inputBytes: input.inputBytes, + codeUnits: input.codeUnits, + inputHash: input.inputHash, + watchdogTermination: { timedOut: true, signal: exit.signal, code: exit.code }, + unavailableSamples: 1, + samples: [] + } + const manifest = mode === 'adverse' ? slots : [watchdog] + const records = + mode === 'adverse' + ? slots.map((slot) => ({ + ...initial, + ...slot, + identity: { ...initial.identity, id: slot.id }, + ...(slot.sample + ? { + status: 'baseline_censored', + attempted: false, + initialTimeoutId: initial.id + } + : {}) + })) + : [ + { + ...watchdog, + status: 'watchdog_passed', + attempted: true, + settlementMs: initial.settlementMs, + identity: { ...input.identity, id: watchdog.id }, + runtime: initial.runtime, + code: exit.code, + signal: exit.signal, + watchdogTermination: initial.watchdogTermination + } + ] + const audit = () => + auditResults([...manifest, ...differentials], [...records, ...differentialRecords]) + if (exit.accepted) { + expect(audit().descriptors).toBe(manifest.length + 2) + } else { + expect(audit).toThrow('Unverified watchdog termination') + } + }) + }) + }) + it.each(watchdogExits)( + 'revalidates cached initial $label evidence before censoring', + async (exit) => { + const input = ready() + const initial = { + ...adverse, + status: 'baseline_timeout', + attempted: true, + phase: 'warmup', + identity: input.identity, + runtime: input.runtime, + inputBytes: input.inputBytes, + codeUnits: input.codeUnits, + inputHash: input.inputHash, + deadlineMs: 10000, + settlementMs: 10001, + watchdogTermination: { timedOut: true, signal: exit.signal, code: exit.code } + } + context.censoredBaselines.set(adverseCaseKey(adverse), initial) + const run = runDescriptor(context, { ...adverse, id: 'cached-slot', samples: 1, sample: 1 }) + if (exit.accepted) { + expect(await run).toMatchObject({ status: 'baseline_censored', attempted: false }) + } else { + await expect(run).rejects.toThrow('Unverified watchdog termination') + } + expect(launcher).not.toHaveBeenCalled() + } + ) + it.each(watchdogExits.filter((exit) => !exit.accepted))( + 'an initial $label failure leaves all seven slots attempted', + async (exit) => { + for (const slot of adverseSlots()) { + launcher.mockResolvedValue({ + ...timeoutResult(), + code: exit.code, + signal: exit.signal, + stdout: terminationProtocol(slot, 'win32') + }) + await expect(runDescriptor(context, slot)).rejects.toThrow( + 'Unverified watchdog termination' + ) + } + expect(launcher).toHaveBeenCalledTimes(7) + expect(context.censoredBaselines.size).toBe(0) + } + ) + it.each(['adverse', 'watchdog'])( + 'rejects every %s exit without a fired watchdog', + async (mode) => { + const descriptor = mode === 'adverse' ? adverse : watchdog + for (const exit of watchdogExits) { + launcher.mockResolvedValue({ + ...timeoutResult(), + timedOut: false, + code: exit.code, + signal: exit.signal, + stdout: terminationProtocol(descriptor, 'win32') + }) + await expect(runDescriptor(context, descriptor)).rejects.toThrow() + } + expect(context.censoredBaselines.size).toBe(0) + } + ) + it('audits the actual self-control record and rejects altered status or exit fields', async () => { + launcher.mockResolvedValue({ + ...timeoutResult(), + stdout: terminationProtocol(watchdog, 'win32') + }) + const record = await runDescriptor(context, watchdog) + const manifest = [watchdog, ...differentials] + expect(auditResults(manifest, [record, ...differentialRecords]).descriptors).toBe(3) + for (const altered of [ + { ...record, status: 'completed' }, + { ...record, code: 1 }, + { ...record, signal: 'SIGSEGV' } + ]) { + expect(() => auditResults(manifest, [altered, ...differentialRecords])).toThrow() + } + }) + it('alternates seven parent-selected pairs at every direct size', () => { + const direct = createManifest().filter( + (item) => item.mode === 'direct' && item.family === 'plain' + ) + for (let pair = 0; pair < direct.length; pair += 28) { + const sizes = direct.slice(pair, pair + 2).map((item) => item.bytes) + for (let sample = 0; sample < 7; sample++) { + const expectedArms = sample % 2 ? ['baseline', 'proposed'] : ['proposed', 'baseline'] + const expectedSizes = sample % 2 ? sizes.toReversed() : sizes + expect( + direct + .slice(pair + sample * 4, pair + sample * 4 + 4) + .map((item) => [item.arm, item.bytes, item.sample, item.samples]) + ).toEqual( + expectedArms.flatMap((arm) => expectedSizes.map((bytes) => [arm, bytes, sample, 1])) + ) + } + } + }) + it('predeclares full proposed coverage before adverse baseline descriptors', () => { + const manifest = createManifest() + const firstBaseline = manifest.findIndex((item) => item.arm === 'baseline') + const lastCoverage = manifest.findLastIndex((item) => item.mode === 'coverage') + expect(lastCoverage).toBeLessThan(firstBaseline) + expect(new Set(manifest.map((item) => item.id)).size).toBe(manifest.length) + expect( + manifest + .filter((item) => item.baselineTimeoutAllowed) + .every( + (item) => + item.arm === 'baseline' && + item.mode === 'direct' && + ['osc', 'dcs', 'apc', 'pm', 'sos'].includes(item.family) + ) + ).toBe(true) + expect( + manifest.some( + (item) => + item.mode === 'coverage' && + item.bytes === 63 * 1024 * 1024 && + item.width === 8 && + item.position === 'earlier' + ) + ).toBe(true) + }) + it('selects the required ordered 944 or 1004 descriptors with complete measurement groups', () => { + const full = createManifest({ capturePath: 'capture.stdout' }) + const selected = selectRequiredDescriptors(full) + expect(selected).toHaveLength(1004) + expect(selectRequiredDescriptors(createManifest())).toHaveLength(944) + expect(full.filter((descriptor) => selected.includes(descriptor))).toEqual(selected) + const coverage = selected.filter((descriptor) => descriptor.mode === 'coverage') + const expectedCoverage = ['osc', 'dcs', 'apc', 'pm', 'sos'].flatMap((family) => + [7, 8].flatMap((width) => + [16384, 32768, 2 * 1024 * 1024, 63 * 1024 * 1024].flatMap((bytes) => + ['earlier', 'tail'].map((position) => [family, width, bytes, position]) + ) + ) + ) + expect( + coverage.map(({ family, width, bytes, position }) => [family, width, bytes, position]) + ).toEqual(expectedCoverage) + expect(coverage.every((descriptor) => descriptor.variant === 'unfinished')).toBe(true) + expect(selected.filter((descriptor) => descriptor.mode === 'counts')).toHaveLength(52) + expect(selected.filter((descriptor) => descriptor.mode === 'retention')).toHaveLength(7) + for (const family of ['fixture', 'actual']) { + expect( + selected.filter((descriptor) => descriptor.mode === 'cpu' && descriptor.family === family) + ).toHaveLength(60) + } + for (const arm of ['baseline', 'proposed', 'baseline-bounded', 'full-log']) { + expect( + selected.filter((descriptor) => descriptor.mode === 'cpu' && descriptor.arm === arm) + ).toHaveLength(40) + } + const direct = selected.filter((descriptor) => descriptor.mode === 'direct') + expect(direct.filter((descriptor) => descriptor.arm === 'baseline')).toHaveLength(280) + expect( + direct.filter((descriptor) => descriptor.arm === 'proposed' && descriptor.bytes <= 32768) + ).toHaveLength(280) + expect(direct.filter((descriptor) => descriptor.bytes > 32768)).toHaveLength(140) + const groups = new Map() + for (const descriptor of direct) { + const key = JSON.stringify([descriptor.arm, descriptor.family, descriptor.width]) + groups.set(key, [...(groups.get(key) ?? []), descriptor]) + } + for (const group of groups.values()) { + const sizes = [...new Set(group.map((descriptor) => descriptor.bytes))].sort( + (a, b) => Number(a) - Number(b) + ) + expect(sizes.slice(0, 2)).toEqual([16384, 32768]) + if (sizes.length > 2) { + expect(sizes.slice(2)).toEqual([31.5 * 1024 * 1024, 63 * 1024 * 1024]) + } + for (const bytes of sizes) { + expect( + group + .filter((descriptor) => descriptor.bytes === bytes) + .map((descriptor) => descriptor.sample) + ).toEqual([0, 1, 2, 3, 4, 5, 6]) + } + } + }) + it('fails missing records and never turns an ordinary failure into completed coverage', () => { + expect(() => auditResults([adverse], [])).toThrow('Incomplete') + expect(() => auditResults([adverse], [{ id: adverse.id, status: 'failed' }])).toThrow( + 'Failed descriptor' + ) + }) + it('rejects extra, duplicate, unexpected records and duplicate manifest IDs explicitly', () => { + const record = { id: adverse.id, status: 'baseline_timeout' } + expect(() => auditResults([adverse], [record, record])).toThrow('duplicate descriptor') + expect(() => auditResults([adverse, { ...adverse, id: 'other' }], [record, record])).toThrow( + 'duplicate descriptor' + ) + expect(() => auditResults([adverse], [{ ...record, id: 'unexpected' }])).toThrow( + 'Unexpected descriptor' + ) + expect(() => auditResults([adverse, adverse], [record, record])).toThrow('Duplicate manifest') + }) + it.each(['bytes', 'units', 'hash'])( + 'rejects invalid pre-work input %s identities', + async (field) => { + const identity = ready() + if (field === 'bytes') { + identity.inputBytes++ + } + if (field === 'units') { + identity.codeUnits = -1 + } + if (field === 'hash') { + identity.inputHash = 'unverified' + } + launcher.mockResolvedValue({ + ...timeoutResult(), + stdout: protocol([identity, { type: 'entered-strip', phase: 'warmup' }]) + }) + await expect(runDescriptor(context, adverse)).rejects.toThrow() + } + ) + it('validates completion input identity against the pre-work protocol', async () => { + const descriptor = { id: 'control', mode: 'control', arm: 'proposed' } + const prework = ready(descriptor.id, context.bundles.proposed.hash) + const inputIdentity = { + inputBytes: prework.inputBytes, + codeUnits: prework.codeUnits, + inputHash: prework.inputHash + } + launcher.mockResolvedValue({ + ...timeoutResult(), + timedOut: false, + code: 0, + signal: null, + stdout: protocol([prework, { type: 'result', ...descriptor, samples: [], inputIdentity }]) + }) + expect(await runDescriptor(context, descriptor)).toMatchObject({ + ...inputIdentity, + status: 'completed' + }) + launcher.mockResolvedValue({ + ...timeoutResult(), + timedOut: false, + code: 0, + signal: null, + stdout: protocol([ + prework, + { + type: 'result', + ...descriptor, + samples: [], + inputIdentity: { ...inputIdentity, codeUnits: 1 } + } + ]) + }) + await expect(runDescriptor(context, descriptor)).rejects.toThrow( + 'Completion input identity changed' + ) + }) +}) diff --git a/src/shared/check-job-log-retention.test.ts b/src/shared/check-job-log-retention.test.ts index a1ca9505140..8272654160e 100644 --- a/src/shared/check-job-log-retention.test.ts +++ b/src/shared/check-job-log-retention.test.ts @@ -1,6 +1,8 @@ -import { describe, expect, it } from 'vitest' +import { describe, expect, it, vi } from 'vitest' import { PR_CHECK_LOG_TAIL_BYTES, sliceCheckLogTail } from './check-job-log-tail-slice' import { gitLabJobTraceToLogExcerpt } from './gitlab-job-log-excerpt' +import { sanitizeCheckJobLogExcerpt } from './check-job-log-excerpt' +import { resetOwnRetainedStringCopier } from './own-retained-string' function heapAfterGc(): number { if (!('gc' in globalThis) || typeof globalThis.gc !== 'function') { @@ -30,6 +32,21 @@ describe('retained CI log excerpts', () => { 'GitLab raw trace', (index: number) => `${index}:${'x'.repeat(PARENT_CHARS)}`, gitLabJobTraceToLogExcerpt + ], + [ + 'plain legacy excerpt', + (index: number) => `${index}:${'x'.repeat(PARENT_CHARS)}`.slice(-PR_CHECK_LOG_TAIL_BYTES), + sanitizeCheckJobLogExcerpt + ], + [ + 'Unicode legacy excerpt', + (index: number) => `${index}:${'界😀'.repeat(PARENT_CHARS / 3)}`, + sanitizeCheckJobLogExcerpt + ], + [ + 'malformed legacy excerpt', + (index: number) => `${index}:${'x'.repeat(PARENT_CHARS)}\x9dunfinished\x1b`, + sanitizeCheckJobLogExcerpt ] ] as const)('releases the parent of a %s', (_label, makeLog, excerpt) => { const before = heapAfterGc() @@ -42,4 +59,24 @@ describe('retained CI log excerpts', () => { expect(retained.every((text) => Buffer.byteLength(text) <= PR_CHECK_LOG_TAIL_BYTES)).toBe(true) expect(growth).toBeLessThan(PARENT_CHARS * 2) }) + + it('releases plain parent slices with the Buffer-free copier', () => { + try { + vi.stubGlobal('Buffer', undefined) + resetOwnRetainedStringCopier() + sanitizeCheckJobLogExcerpt('warm fallback '.repeat(1000)) + const before = heapAfterGc() + const retained = Array.from({ length: COUNT }, (_, index) => + sanitizeCheckJobLogExcerpt( + `${index}:${'x'.repeat(PARENT_CHARS)}`.slice(-PR_CHECK_LOG_TAIL_BYTES) + ) + ) + void /probe/.test('probe') + expect(heapAfterGc() - before).toBeLessThan(PARENT_CHARS * 2) + expect(retained.every((text) => text.length === PR_CHECK_LOG_TAIL_BYTES)).toBe(true) + } finally { + vi.unstubAllGlobals() + resetOwnRetainedStringCopier() + } + }) }) diff --git a/src/shared/check-job-log-tail-slice.ts b/src/shared/check-job-log-tail-slice.ts index 17b03190875..0838d602f79 100644 --- a/src/shared/check-job-log-tail-slice.ts +++ b/src/shared/check-job-log-tail-slice.ts @@ -1,13 +1,19 @@ import { + clampUtf8TextPrefix, clampUtf8TextTail, getUtf8ByteLength, isUtf8ByteLengthWithinLimit } from './utf8-byte-limits' -import { ownRetainedString } from './own-retained-string' +import { + stripAnsiEscapeSequences, + TERMINAL_CONTROL_CHARACTER_PATTERN +} from './ansi-escape-sequences' +import { PR_CHECK_LOG_TAIL_BYTES, sanitizeCheckJobLogExcerpt } from './check-job-log-excerpt' + +export { PR_CHECK_LOG_TAIL_BYTES } from './check-job-log-excerpt' export const PR_CHECK_LOG_TAIL_LINES = 200 export const PR_CHECK_LOG_TAIL_RECENT_LINES = 100 -export const PR_CHECK_LOG_TAIL_BYTES = 16 * 1024 export const PR_CHECK_LOG_TAIL_ERROR_CONTEXT_LINES = 2 export const PR_CHECK_LOG_TAIL_MAX_EARLIER_LINES = 30 export const PR_CHECK_LOG_TAIL_EARLIER_SEPARATOR = '… earlier errors …' @@ -17,6 +23,23 @@ export const PR_CHECK_LOG_TAIL_EARLIER_SEPARATOR = '… earlier errors …' const ERROR_LINE_PATTERN = /(?:##\[error\]|::error::|::error\b|\berror:|FAILED|exit code|ENOENT|EACCES|panic:|AssertionError)/i +function matchesErrorMarker(candidate: string): boolean { + return ERROR_LINE_PATTERN.test( + stripAnsiEscapeSequences(candidate).replace(TERMINAL_CONTROL_CHARACTER_PATTERN, '') + ) +} + +function hasErrorMarker(rawLine: string): boolean { + if (isUtf8ByteLengthWithinLimit(rawLine, PR_CHECK_LOG_TAIL_BYTES)) { + return matchesErrorMarker(rawLine) + } + const windowBytes = PR_CHECK_LOG_TAIL_BYTES / 2 + return ( + matchesErrorMarker(clampUtf8TextPrefix(rawLine, windowBytes)) || + matchesErrorMarker(clampUtf8TextTail(rawLine, windowBytes).text) + ) +} + function applyLogTailByteCap(text: string): string { if (isUtf8ByteLengthWithinLimit(text, PR_CHECK_LOG_TAIL_BYTES)) { return text @@ -26,9 +49,12 @@ function applyLogTailByteCap(text: string): string { function joinLogExcerptWithByteCap(prefixLines: string[], recentLines: string[]): string { const prefix = prefixLines.join('\n') - // UTF-16 length is a lower bound; oversized prefixes need no exact byte count. + // Oversized prefixes need no exact byte count, including multibyte text. const prefixByteLength = - prefix.length >= PR_CHECK_LOG_TAIL_BYTES ? PR_CHECK_LOG_TAIL_BYTES : getUtf8ByteLength(prefix) + prefix.length >= PR_CHECK_LOG_TAIL_BYTES || + !isUtf8ByteLengthWithinLimit(prefix, PR_CHECK_LOG_TAIL_BYTES) + ? PR_CHECK_LOG_TAIL_BYTES + : getUtf8ByteLength(prefix) if (prefixByteLength >= PR_CHECK_LOG_TAIL_BYTES) { return clampUtf8TextTail(prefix, PR_CHECK_LOG_TAIL_BYTES).text } @@ -43,7 +69,7 @@ function collectEarlierErrorLineIndexes(lines: string[], recentStart: number): n const indexes = new Set() // Newest-first errors and descending windows add the newest unique indexes first. for (let index = recentStart - 1; index >= 0; index -= 1) { - if (!ERROR_LINE_PATTERN.test(lines[index] ?? '')) { + if (!hasErrorMarker(lines[index] ?? '')) { continue } const contextStart = Math.max(0, index - PR_CHECK_LOG_TAIL_ERROR_CONTEXT_LINES) @@ -59,7 +85,7 @@ function collectEarlierErrorLineIndexes(lines: string[], recentStart: number): n } function buildCheckLogTail(logText: string): string { - const lines = logText.split(/\r?\n/) + const lines = logText.split(/\r\n|\r|\n/) const recentStart = Math.max(0, lines.length - PR_CHECK_LOG_TAIL_RECENT_LINES) const recentLines = lines.slice(recentStart) @@ -84,5 +110,5 @@ function buildCheckLogTail(logText: string): string { export function sliceCheckLogTail(logText: string): string { // Cached excerpts must not pin the downloaded log behind a small V8 slice. - return ownRetainedString(buildCheckLogTail(logText)) + return sanitizeCheckJobLogExcerpt(buildCheckLogTail(logText)) } diff --git a/src/shared/check-job-log-text-performance.test.ts b/src/shared/check-job-log-text-performance.test.ts new file mode 100644 index 00000000000..73f8705aeca --- /dev/null +++ b/src/shared/check-job-log-text-performance.test.ts @@ -0,0 +1,52 @@ +import { afterAll, beforeAll, describe, expect, it } from 'vitest' +import { + auditResults, + prepareBenchmark, + runDescriptor +} from '../../config/scripts/check-job-log-byte-cap-benchmark.mjs' +import { + createManifest, + selectRequiredDescriptors +} from '../../config/scripts/check-job-log-performance-cases.mjs' + +const root = process.cwd() +const manifest = selectRequiredDescriptors( + createManifest({ + capturePath: process.env.ORCA_CHECK_LOG_CAPTURE + }) +).filter((descriptor) => ['proposed', 'no-buffer', 'pinned'].includes(descriptor.arm)) +let context: Awaited> +const records: Awaited>[] = [] +// Manual benchmark: opt in with ORCA_CHECK_LOG_PERF=1. +const runPerformance = process.env.ORCA_CHECK_LOG_PERF === '1' + +describe.runIf(runPerformance)( + 'current CI log performance regressions', + { concurrent: false }, + () => { + beforeAll(async () => { + context = await prepareBenchmark(root, { compareBaseline: false }) + }, 15_000) + afterAll(async () => { + await context?.cleanup() + }) + for (const descriptor of manifest) { + it( + descriptor.id, + async () => { + const record = await runDescriptor(context, descriptor) + records.push(record) + expect(record.id).toBe(descriptor.id) + }, + 15_000 + ) + } + it('audits current implementation coverage and scaling', () => { + const summary = auditResults(manifest, records, { compareBaseline: false }) + expect(summary.descriptors).toBe(manifest.length) + expect(summary.scaling.every((item) => item.medianMs[1] <= 3 * item.medianMs[0] + 1)).toBe( + true + ) + }) + } +)