olo-output-truth

1import type { EngineInterface, Register } from 'claude-code'
2
3import { analyze, type Finding, formatFindings, normalize, parseTaskNotification } from './analyze'
4
5// Tools whose text can carry a build or test log: a foreground run, or a log read back.
6const LOG_TOOLS = ['Bash', 'PowerShell', 'Read'] as const
7
8const FS_READ_LIMIT = 4 * 1024 * 1024
9const TAIL_BYTES = 3_000_000
10const REPEAT_WINDOW_MS = 10 * 60 * 1000
11
12// The same finding is reported once per window: re-reading a log to look at its errors
13// should not repeat the banner every time. Module state; a reload clears it, which costs
14// at most one repeat.
15const reported = new Map<string, number>()
16
17export const register: Register = on => {
18  on('tool.call', { tool: LOG_TOOLS }, async ($, e, next) => {
19    const ran = await next(e)
20    if (ran.deny !== undefined || typeof ran.text !== 'string' || ran.text.length === 0) {
21      return ran
22    }
23    const findings = await fresh($, analyze(normalize(ran.text, e.tool === 'Read')))
24    if (findings.length === 0) {
25      return ran
26    }
27    surface($, findings)
28    return { ...ran, context: [...(ran.context ?? []), formatFindings(findings)] }
29  })
30
31  // A backgrounded build or test run reports "completed (exit code 0)" in its
32  // notification whatever the log says. Read the log's tail and say what it says.
33  on('session.append', async ($, e, next) => {
34    const textBlocks = e.message.content.filter(
35      (b): b is { type: 'text'; text: string } => b.type === 'text' && typeof (b as { text?: unknown }).text === 'string',
36    )
37    const notification = parseTaskNotification(textBlocks.map(b => b.text).join('\n'))
38    if (notification === undefined || !notification.isShellCommand) {
39      return next(e)
40    }
41
42    const log = await readTail($, notification.outputFile)
43    if (log === undefined) {
44      return next(e)
45    }
46    const findings = await fresh($, analyze(normalize(log)))
47    if (findings.length === 0) {
48      return next(e)
49    }
50    surface($, findings)
51    const note = `${formatFindings(findings)}\n(read from the tail of ${notification.outputFile}; the task status above reflects the wrapper, not the build or test result)`
52    return next({ ...e, message: { ...e.message, content: [...e.message.content, { type: 'text', text: note }] } })
53  })
54}
55
56async function fresh($: EngineInterface, findings: Finding[]): Promise<Finding[]> {
57  const now = await $.clock.now()
58  return findings.filter(f => {
59    const last = reported.get(f.id)
60    if (last !== undefined && now - last < REPEAT_WINDOW_MS) {
61      return false
62    }
63    reported.set(f.id, now)
64    return true
65  })
66}
67
68function surface($: EngineInterface, findings: Finding[]): void {
69  const first = findings.find(f => f.severity === 'error')
70  if (first !== undefined) {
71    $.ui.toast(`olo-output-truth: ${first.message.split('\n')[0] ?? 'a failure'}`, { timeoutMs: 8000 })
72  }
73}
74
75/**
76 * A log's text: whole when `$.fs.read` takes it (up to 4 MiB), else its last few MB through
77 * this mod's scripts/tail.ps1 (`$.process.run` has no shell, and pwsh is always present
78 * here), else `tail` where one is on PATH.
79 */
80async function readTail($: EngineInterface, path: string): Promise<string | undefined> {
81  try {
82    const stat = await $.fs.stat(path)
83    if (stat.kind !== 'file') {
84      return undefined
85    }
86    if (stat.size <= FS_READ_LIMIT) {
87      return await $.fs.read(path)
88    }
89  } catch {
90    return undefined
91  }
92  const attempts: string[][] = [
93    ['pwsh', '-NoProfile', '-NonInteractive', '-File', `${$.plugin.root}/scripts/tail.ps1`, '-Path', path, '-Bytes', String(TAIL_BYTES)],
94    ['tail', '-c', String(TAIL_BYTES), path],
95  ]
96  for (const argv of attempts) {
97    try {
98      const r = await $.process.run(argv, { timeoutMs: 15_000 })
99      if (r.exitCode === 0) {
100        return r.stdout
101      }
102    } catch {
103      // Try the next way.
104    }
105  }
106  return undefined
107}
108

1// Pure analysis of build and test output. No engine calls here, so the tests can
2// exercise every rule without a session.
3//
4// Each rule exists because the failure it catches was hit on this repo and read as
5// success (see the memory notes named beside each rule).
6
7export type Severity = 'error' | 'warn'
8
9export type Finding = {
10  /** Stable identity, so the same finding is reported once and not on every re-read. */
11  id: string
12  severity: Severity
13  message: string
14}
15
16const MAX_LISTED = 12
17const MAX_LINE = 220
18
19/**
20 * Normalises tool output for line-anchored matching: drops NULs (the engine logger
21 * embeds them, which is why `grep` calls the test log binary) and ANSI colour sequences
22 * (gtest colours its markers with --gtest_color or on a terminal), folds CRLF, and for
23 * the Read tool strips its `cat -n` line-number gutter.
24 */
25export function normalize(text: string, isNumberedListing = false): string {
26  let t = text
27    .replace(/\u0000/g, '')
28    .replace(/\u001b\[[0-9;]*[A-Za-z]/g, '')
29    .replace(/\r\n?/g, '\n')
30  if (isNumberedListing) {
31    t = t.replace(/^ *\d+\t/gm, '')
32  }
33  return t
34}
35
36function clip(line: string): string {
37  const one = line.trim()
38  return one.length > MAX_LINE ? `${one.slice(0, MAX_LINE)}…` : one
39}
40
41function unique<T>(items: Iterable<T>): T[] {
42  return [...new Set(items)]
43}
44
45// ---------------------------------------------------------------- builds ---
46
47const NINJA_STOPPED = /^ninja: build stopped: (.*)$/m
48const NINJA_FAILED_STEP = /^FAILED: (.*)$/gm
49const MSBUILD_FAILED = /^\s*Build FAILED\.\s*$/m
50const MSBUILD_ERRORS = /^\s*([1-9]\d*) Error\(s\)\s*$/m
51const ERROR_LINE =
52  /(?:\berror\s+(?:C|LNK|MSB)\d{4}\b|: (?:fatal )?error:|^\s*(?:lld-link|ld\.lld|clang-cl|cl)(?:\.exe)?: (?:fatal )?error\b|\bundefined symbol\b|\bfatal error\b)/im
53
54/**
55 * A build failure that the surrounding command may report as success: build-lock.ps1
56 * propagates ninja's status (since #788), but a run piped into `tail` or `tee` reports
57 * the pipe's last command, and that is how "exit code 0" builds with errors were read
58 * as green here. Memory: build-lock-wrapper-swallows-ninja-exit-code.
59 */
60export function analyzeBuild(text: string): Finding[] {
61  const stopped = NINJA_STOPPED.exec(text)
62  const msbuild = MSBUILD_FAILED.test(text) || MSBUILD_ERRORS.test(text)
63  const failedSteps = [...text.matchAll(NINJA_FAILED_STEP)].map(m => m[1] ?? '')
64  if (!stopped && !msbuild && failedSteps.length === 0) {
65    return []
66  }
67
68  const errorLines = unique(
69    text
70      .split('\n')
71      .filter(line => ERROR_LINE.test(line))
72      .map(clip),
73  ).slice(0, 6)
74
75  const exitedZero = /\[exited with code 0\]|exit code 0\b/.test(text)
76  const headline = stopped
77    ? `ninja: build stopped: ${stopped[1]}`
78    : msbuild
79      ? 'MSBuild reported Build FAILED'
80      : `${failedSteps.length} ninja step(s) FAILED`
81
82  const lines = [
83    `BUILD FAILED (${headline}).`,
84    exitedZero
85      ? 'The exit code 0 reported for it is NOT evidence of success: build-lock.ps1 passes on the status of the LAST command in its -Command, so a pipe (`| tail`, `| tee`) or a statement after the build masks the build\'s status.'
86      : 'Read the log, not the exit status: a pipe (`| tail`, `| tee`) reports its last command\'s status, not the build\'s.',
87    errorLines.length > 0 ? `First errors:\n${errorLines.map(l => `  ${l}`).join('\n')}` : '',
88    failedSteps.length > 0 && errorLines.length === 0
89      ? `Failed steps:\n${unique(failedSteps.map(clip)).slice(0, 4).map(l => `  ${l}`).join('\n')}`
90      : '',
91  ].filter(Boolean)
92
93  return [
94    {
95      id: `build:${headline}:${errorLines[0] ?? failedSteps[0] ?? ''}`,
96      severity: 'error',
97      message: lines.join('\n'),
98    },
99  ]
100}
101
102// ----------------------------------------------------------------- gtest ---
103
104const GTEST_RUNNING = /^\[==========\] Running (\d+) tests? from (\d+) test suites?\.?\s*$/gm
105const GTEST_DONE = /^\[==========\] (\d+) tests? from (\d+) test suites? ran\./m
106const GTEST_FILTER = /^Note: Google Test filter = (.*)$/m
107const GTEST_RUN = /^\[ RUN      \] (\S+)/gm
108const GTEST_OK = /^\[       OK \] (\S+)/gm
109const GTEST_FAILED = /^\[  FAILED  \] ([^\s,]+\.[^\s,]+)/gm
110const GTEST_SKIPPED = /^\[  SKIPPED \] (\S+)/gm
111const CTEST_NONE = /^No tests were found!!!\s*$/m
112
113function names(text: string, re: RegExp): string[] {
114  return unique([...text.matchAll(re)].map(m => m[1] ?? ''))
115}
116
117/** Splits a log into one segment per `[==========] Running` header (sharded or repeated runs). */
118function gtestSegments(text: string): string[] {
119  const starts = [...text.matchAll(GTEST_RUNNING)].map(m => m.index ?? 0)
120  return starts.map((start, i) => text.slice(start, starts[i + 1] ?? text.length))
121}
122
123function listed(items: string[]): string {
124  const shown = items.slice(0, MAX_LISTED).join(', ')
125  return items.length > MAX_LISTED ? `${shown}, … (+${items.length - MAX_LISTED} more)` : shown
126}
127
128/**
129 * gtest / ctest output that looks fine and is not.
130 * Memories: new-test-file-needs-cmakelists-entry, attribution-filter-must-select-the-test,
131 * build-lock-wrapper-swallows-ninja-exit-code (the two-space `[  FAILED  ]` count trap),
132 * taskstop-leaves-bash-loop-children-running.
133 */
134export function analyzeTests(text: string): Finding[] {
135  const findings: Finding[] = []
136  const filter = GTEST_FILTER.exec(text)?.[1]?.trim()
137
138  if (CTEST_NONE.test(text)) {
139    findings.push({
140      id: 'ctest:none',
141      severity: 'error',
142      message:
143        'ctest found NO tests for this selection: nothing ran. Check the -R regex against `ctest -N`, and that the test is registered.',
144    })
145  }
146
147  // ctest's own summary (it prints no gtest header without -V).
148  const ctest = /^\s*\d+% tests passed, (\d+) tests? failed out of (\d+)/m.exec(text)
149  if (ctest !== null && Number(ctest[1]) > 0) {
150    const list = text.slice(text.indexOf('The following tests FAILED:'))
151    const failedTests = unique([...list.matchAll(/^\s*\d+ - (\S+) \(/gm)].map(m => m[1] ?? ''))
152    findings.push({
153      id: `ctest:failed:${failedTests.join(',') || ctest[1]}`,
154      severity: 'error',
155      message: `ctest: ${ctest[1]} of ${ctest[2]} test(s) FAILED${failedTests.length > 0 ? `: ${listed(failedTests)}` : ''}.`,
156    })
157  }
158
159  const segments = gtestSegments(text)
160  if (segments.length === 0) {
161    return findings
162  }
163
164  let zeroRuns = 0
165  const failed = new Set<string>()
166  const incomplete: string[] = []
167  const unfinished: string[] = []
168  let ran = 0
169  let skipped = 0
170
171  for (const segment of segments) {
172    const header = /\[==========\] Running (\d+) tests?/.exec(segment)
173    const declared = Number(header?.[1] ?? '0')
174    if (declared === 0) {
175      zeroRuns += 1
176      continue
177    }
178
179    const runs = names(segment, GTEST_RUN)
180    const oks = new Set(names(segment, GTEST_OK))
181    const fails = names(segment, GTEST_FAILED)
182    const skips = new Set(names(segment, GTEST_SKIPPED))
183    for (const name of fails) {
184      failed.add(name)
185    }
186    ran += runs.length
187    skipped += [...skips].filter(name => runs.includes(name)).length
188
189    // No final summary: the segment did not finish, whether or not its last test did.
190    if (!GTEST_DONE.test(segment)) {
191      const last = runs[runs.length - 1]
192      const settled = (name: string) => oks.has(name) || fails.includes(name) || skips.has(name)
193      if (last !== undefined && !settled(last)) {
194        incomplete.push(last)
195      } else {
196        unfinished.push(`${runs.length} of ${declared} declared test(s)${last !== undefined ? `, last ${last}` : ''}`)
197      }
198    }
199  }
200
201  if (zeroRuns > 0) {
202    findings.push({
203      id: `gtest:zero:${filter ?? ''}`,
204      severity: 'error',
205      message: [
206        `The gtest filter${filter ? ` \`${filter}\`` : ''} selected NO tests: nothing ran, so nothing passed.`,
207        'Check the suite name with `--gtest_list_tests` and the same filter (an evidence PNG name is not a suite name),',
208        'and that a new test .cpp is listed in OloEngine/tests/CMakeLists.txt (it lists every source; an unlisted file is never built).',
209      ].join(' '),
210    })
211  }
212
213  if (incomplete.length > 0) {
214    findings.push({
215      id: `gtest:incomplete:${incomplete.join(',')}`,
216      severity: 'error',
217      message:
218        `The log ends inside ${listed(incomplete)} with no result line and no final summary: the run is either still going or the process died there (crash, abort, timeout). ` +
219        'Treat it as NOT passed. If you stopped it, check for a surviving OloEngine-Tests.exe / bash loop from THIS worktree before rebuilding. (If this is only part of the log, read its end.)',
220    })
221  }
222
223  if (unfinished.length > 0) {
224    findings.push({
225      id: `gtest:unfinished:${unfinished.join(',')}`,
226      severity: 'error',
227      message:
228        `The run has no final \`[==========] … ran.\` summary after ${unfinished.join('; ')}: it stopped between tests (still going, or the process died). ` +
229        'Treat it as NOT passed. (If this is only part of the log, read its end.)',
230    })
231  }
232
233  const failedNames = [...failed]
234  if (failedNames.length > 0) {
235    findings.push({
236      id: `gtest:failed:${failedNames.join(',')}`,
237      severity: 'error',
238      message: `${failedNames.length} test(s) FAILED: ${listed(failedNames)}.`,
239    })
240  }
241
242  if (ran > 0 && skipped === ran) {
243    findings.push({
244      id: `gtest:all-skipped:${filter ?? ''}:${ran}`,
245      severity: 'warn',
246      message:
247        `All ${ran} selected test(s) SKIPPED: nothing was verified. Evidence tests skip without a GL 4.6 context and Vulkan device tests without a device; say so rather than reporting them as passing.`,
248    })
249  }
250
251  return findings
252}
253
254// ------------------------------------------------------------------ both ---
255
256export function analyze(text: string): Finding[] {
257  return [...analyzeBuild(text), ...analyzeTests(text)]
258}
259
260export function formatFindings(findings: readonly Finding[]): string {
261  const body = findings.map(f => `- ${f.severity === 'error' ? 'ERROR' : 'WARNING'}: ${f.message}`).join('\n')
262  return `olo-output-truth (a mod that reads build/test output for traps this repo has hit):\n${body}`
263}
264
265/** Pulls the output file and status out of a background task's notification text. */
266export function parseTaskNotification(
267  text: string,
268): { outputFile: string; summary: string; isShellCommand: boolean } | undefined {
269  if (!text.includes('<task-notification>')) {
270    return undefined
271  }
272  const outputFile = /<output-file>([^<]+)<\/output-file>/.exec(text)?.[1]?.trim()
273  if (!outputFile) {
274    return undefined
275  }
276  const summary = /<summary>([\s\S]*?)<\/summary>/.exec(text)?.[1]?.trim() ?? ''
277  // Only a shell command's log is worth reading: an agent's .output is its JSONL transcript.
278  const isShellCommand = /^Background command\b/.test(summary)
279  return { outputFile, summary, isShellCommand }
280}
281