diff --git a/HANDOFF-TEMP.md b/HANDOFF-TEMP.md new file mode 100644 index 00000000000..639514d85d1 --- /dev/null +++ b/HANDOFF-TEMP.md @@ -0,0 +1,160 @@ +# Handoff — test verdict reliability (2026-07-28/29) + +Temporary. Delete once the follow-ups below are done or refiled as issues. + +## Why any of this happened + +CI reported ✅ on `egg-hunt-2026` while **19 tests were failing**. Not a flake — the +gate was structurally incapable of failing. Three independent faults stacked: + +1. `parseTestLogs` only looked for *evidence of failure*. No logs meant no evidence + meant pass. An empty log was a green check. +2. In batch mode the jest-failure check was skipped entirely when the log section was + empty, so the verdict fell through to the Luau `pcall` — "the script didn't throw", + which says nothing about tests. +3. The PR comment rendered `1 tested, 1 passed, 0 failed`. Those are **package** counts + in test-count phrasing, with no test numbers behind them. Indistinguishable from a + real result. + +Both are fixed and merged (#772). This document is about what is *not* finished. + +## Root cause of the missing logs (settled, with evidence) + +**Open Cloud retains only the tail of a task's log.** The head is discarded; what +survives is one contiguous block ending at the final line. + +Two 20,000-line probes plus the real suite: + +| run | messages | chars | survived | +|---|---|---|---| +| probe 1 (~20 char lines) | 6,715 | ~134,300 | lines 13286–20000 | +| probe 2 (~99 char lines) | 3,237 | 297,722 | lines 16765–20000 | +| egg-hunt | 2,531 | 330,778 | tail only | + +`===BATCH_TEST_BEGIN===` prints in the first moments of a run, so on any suite large +enough to overflow the window it is *always* the first casualty. That is why this +reproduced identically every time instead of flaking. + +**Ruled out with evidence** — do not re-investigate these: pagination (one page, no +continuation token), a message-count cap (6,715 vs 3,237 vs 2,531), a byte cap +(134 KB vs 298 KB vs 331 KB), marker formatting, and anything in the CLI. The exact +governing unit of the window is still unknown, deliberately: **no fix should depend on +its size.** + +Second, independent fault: **the API does not deliver messages in order.** Probe 1's +file began at index 13286 and ended at 16272 while containing the full range. Sorting +by `createTime` helps at second granularity but cannot order a burst — thousands of +lines share a timestamp at API precision. + +## State of the work + +**Merged:** #772 — verdicts require evidence; one shared rule; tracebacks always fail; +attribution by script path; unreadable output fails rather than passing. + +**Open:** #773 (branch `users/quenty/batch-chunking`) — batches run in chunks of 16 so +each task's log stays inside the window. **72/73 Nevermore packages pass, up from 59.** +Also: docs name which command is the gate, and per-phase timings. Safe to merge; CI was +green before the final timing commit. + +## The architectural question — answered by probe, not yet built + +**The CLI is using the log as a data channel, and Open Cloud provides a real one.** + +`LuauTask.output.results` is declared in `open-cloud-client.ts` ("Script return value, +populated on COMPLETE") and **read nowhere**. Probed 2026-07-29, it works: + +``` +[probe] task.output = {"results":["{\"probe\":\"return-channel\",\"capturedCount\":1,...}"]} +``` + +If `batch-test-runner.luau` *returns* the per-package summary instead of printing it, +verdicts and counts never touch the log. That subsumes nearly everything built on +2026-07-28/29: `END`-based sectioning, partial sections, the reordering guard, the +summary-array scan, chunking, and the flaky attribution below. + +**Decide this before extending chunking. They are alternatives, not layers.** + +Second probe result: `ScriptContext.Error` fires inside an Open Cloud task and *does* +catch deferred-callback crashes — the class jest cannot see, because they fire outside +any test. So the traceback gate can keep working while its source moves from regex to +engine events. + +``` +task.defer(function() error("PROBE_DEFERRED_CRASH") end) +→ capturedCount = 1, "TaskScript:16: PROBE_DEFERRED_CRASH" +``` + +**Caveat, unverified:** the `script` argument came back `nil` for an error raised inside +the `loadstring`'d task chunk, which is not a real `Script` instance. Errors from real +ModuleScripts should carry one — that is the shape attribution actually needs — but it +has **not** been probed. Do that before designing on it. + +## Open work + +| # | Item | Notes | +|---|---|---| +| 22 | Return batch results instead of printing them | Probed working. Highest payoff; decides 20/21 | +| 23 | Capture Luau errors in-engine | Probed working; ModuleScript attribution unverified | +| 14 | Thread jest config to the in-engine run | **On the critical path** — see the 300 s cap below | +| 16 | Baseline comparison | Depends on 14 | +| 21 | Packages whose END arrives out of order | Flaky false-red; superseded by 22 | +| 18 | Decide `passWithNoTests` (egg-hunt) | Deliberate for legacy packages; keep 2's rule compatible | +| 19 | **egg-hunt's 19 real test failures** | The only genuine test debt found | + +### The 300 s cap is a ceiling on a single suite + +egg-hunt's jest run reports `Time: 267.255 s` against a hard 300 s in-engine limit. +Chunking does **not** help — it splits *packages*, and egg-hunt is one package. When it +crosses, the task is cancelled server-side and the failure is uninformative. The only +ways out are splitting the game's specs across test targets, or scoping one suite over +several tasks, which needs #14. That is why #14 is not an ergonomics item. + +### egg-hunt's failures (#19) + +First readable numbers, from 2026-07-29: + +``` +Test Suites: 3 failed, 5 skipped, 32 passed, 35 of 40 total +Tests: 19 failed, 27 skipped, 470 passed, 516 total +``` + +400 raw tracebacks collapse to 5 distinct causes. First named failure: +`EggHuntPlayer datastore load failure › flags EggHuntDataStoreLoadingFailed when the +save-slot load fails`. Prior triage, now corroborated: 3 demo-area tests in +`EggHuntAccessService.spec` are order-dependent (pass alone, fail in a full run); the +other 16 fail consistently, including on `origin/main`. Suspected shared cause: raw +`player.UserId` against a `PlayerMock`, which is a Folder. `EggHuntAccessFacts.readUserId` +already has the `PlayerMock.read` fix; `PlayerBadgeHelper` → `BadgeRewardService` +(Nevermore) and `EggHuntPlayer:_logArrivalDiagnostic` do not. + +## Gotchas for whoever picks this up + +- **Nevermore itself has zero real test failures** under the strict rules. A large + failure count on an `--all` sweep means *unreadable*, not *broken* — check the reason + string before believing it. +- **`@quenty/steputils` fails intermittently** on `--all`, and the package will move + between runs. Its `END` arrives out of order and the guard refuses to let a stray + `END` claim a section. Fails closed, which is right, but it is noise (#21). +- **Verify against a real run, not just unit tests.** Two separate bugs this session + passed the unit suite and were caught only by running against the real place: the + terminal reporters keeping their own copy of the rendering, and per-phase timings + emitting 1,095 lines of `waiting took 0ms`. +- **`npm run lint:ts` from Windows** reports "No projects matched the filters" and exits + 0, because npm shells through `cmd.exe` where single quotes are literal. CI on Ubuntu + is fine. Use `--filter "./tools/*"` locally. + +## Reproducing + +```bash +# The gate command, as CI runs it +nevermore batch test --cloud --aggregated --base origin/main --yes --verbose --logs + +# Full sweep (chunked, ~5m30s) +nevermore batch test --cloud --aggregated --all --yes --verbose --logs + +# Probe arbitrary Luau; --logs is now on by default for this +nevermore test --cloud --script-text 'print("hi")' +``` + +`NO_COLOR=1` strips jest-lua's escape codes from echoed engine logs — they come from +inside Roblox and chalk never sees them. diff --git a/docs/testing/testing.md b/docs/testing/testing.md index 0c71c3f0bee..7a4e5f8a382 100644 --- a/docs/testing/testing.md +++ b/docs/testing/testing.md @@ -430,12 +430,28 @@ Options: | Flag | Description | |------|-------------| | `--cloud` | Run tests via Open Cloud instead of locally | -| `--logs` | Show execution logs | +| `--logs` | Show execution logs. On by default with `--script-text` | | `--api-key` | Roblox Open Cloud API key (`--cloud` only) | | `--universe-id` | Override universe ID from deploy.nevermore.json | | `--place-id` | Override place ID from deploy.nevermore.json | | `--script-template` | Override script template path | | `--script-text` | Luau code to execute directly instead of the configured template | +| `--timeout` | Max execution seconds, sent to Open Cloud. Max 300 (API limit), which is also the default | + +### Which command is the gate + +`nevermore batch test --cloud` is what CI runs, and it is the authority on whether +a commit is green. `nevermore test --cloud` runs a single package through the same +rules — useful while iterating, but it only sees the package you are standing in. + +Both apply one rule: a run passes when a test report is present, no suite or test +failed, and no Luau traceback appeared. **Tracebacks fail a run even when every +test passed** — jest cannot see a crash in a deferred callback, because it fires +outside any test, so a suite can report all-green while something is genuinely +broken. Failure output names each traceback and the package that owns it. + +A run with no test report is reported as failed rather than passed. A `--script-text` +probe is exempt, having no jest in it to report. ### Batch testing @@ -463,6 +479,19 @@ Options: | `--base` | Git ref to diff against (default: `origin/main`) | | `--concurrency` | Max parallel tests (default: 1 local, 3 cloud) | | `--output` | Write JSON results to a file | +| `--chunk-size` | Packages per execution task in `--aggregated` mode (default: 16) | + +#### Why batches run in chunks + +Open Cloud retains only the tail of a task's log. One task covering every package +therefore loses the output of the packages that ran first: measured across 73 +packages, the first 14 came back unreadable while the rest were fine. Those +packages are reported as failed — the CLI will not call a run green when it could +not read the result. + +Chunking keeps each task's log inside that window, and gives each chunk its own +execution budget rather than sharing a single 300s ceiling. Raise `--chunk-size` +only if your packages are quiet; lower it if a chunk starts losing its head. | `--limit` | Max number of packages to test | | `--logs` | Show execution logs for all packages | diff --git a/tools/cli-output-helpers/src/reporting/grouped-reporter.ts b/tools/cli-output-helpers/src/reporting/grouped-reporter.ts index 1ef4df0f644..5082c7a40ff 100644 --- a/tools/cli-output-helpers/src/reporting/grouped-reporter.ts +++ b/tools/cli-output-helpers/src/reporting/grouped-reporter.ts @@ -1,6 +1,6 @@ import { OutputHelper } from '../outputHelper.js'; import { formatDurationMs, isCI } from '../cli-utils.js'; -import { type PackageResult, BaseReporter } from './reporter.js'; +import { type JobPhase, type PackageResult, BaseReporter } from './reporter.js'; import { type IStateTracker } from './state/state-tracker.js'; import { formatProgressResult, @@ -8,6 +8,9 @@ import { isUnreportedTestRun, } from './progress-format.js'; +/** Below this, a phase timing is noise rather than information. */ +const PHASE_REPORT_FLOOR_MS = 1000; + export interface GroupedReporterOptions { showLogs: boolean; verbose: boolean; @@ -32,6 +35,8 @@ export class GroupedReporter extends BaseReporter { private _state: IStateTracker; private _options: GroupedReporterOptions; private _isCI: boolean; + private _phaseStartedMs = Date.now(); + private _lastPhase?: JobPhase; constructor(state: IStateTracker, options: GroupedReporterOptions) { super(); @@ -49,6 +54,30 @@ export class GroupedReporter extends BaseReporter { if (this._isCI) { console.log(`::group::${name}`); } + this._phaseStartedMs = Date.now(); + this._lastPhase = undefined; + } + + override onPackagePhaseChange(_name: string, phase: JobPhase): void { + if (!this._options.verbose || phase === this._lastPhase) { + // Aggregated mode broadcasts one transition to every package, so the same + // phase arrives dozens of times. Report the transition, not each recipient. + return; + } + + // Group output is buffered and flushed at the end, so every line lands on + // the same timestamp and a five-minute step reads as instantaneous. Report + // how long the phase just left actually took — but only when it was long + // enough to account for, or the timings bury what they were meant to show. + const now = Date.now(); + const elapsedMs = now - this._phaseStartedMs; + if (this._lastPhase !== undefined && elapsedMs >= PHASE_REPORT_FLOOR_MS) { + OutputHelper.info( + ` ${this._lastPhase} took ${formatDurationMs(elapsedMs)}` + ); + } + this._lastPhase = phase; + this._phaseStartedMs = now; } override onPackageResult( diff --git a/tools/nevermore-cli/src/commands/batch-command/batch-test-command.ts b/tools/nevermore-cli/src/commands/batch-command/batch-test-command.ts index 4e403fe819e..aec13f312db 100644 --- a/tools/nevermore-cli/src/commands/batch-command/batch-test-command.ts +++ b/tools/nevermore-cli/src/commands/batch-command/batch-test-command.ts @@ -51,6 +51,7 @@ interface BatchTestArgs extends NevermoreGlobalArgs { batchPlaceId?: number; batchUniverseId?: number; timeout?: number; + chunkSize?: number; } export const batchTestCommand: CommandModule< @@ -116,7 +117,12 @@ export const batchTestCommand: CommandModule< }) .option('timeout', { describe: - 'Max script execution time in seconds for the whole batch. Sent to the Open Cloud API so Roblox cancels server-side on overrun. Max 300s (API limit). (default: 300)', + 'Max script execution time in seconds per chunk. Sent to the Open Cloud API so Roblox cancels server-side on overrun. Max 300s (API limit). (default: 300)', + type: 'number', + }) + .option('chunk-size', { + describe: + 'Packages per execution task (--aggregated only). Open Cloud keeps only the tail of a task log, so one task for every package loses the ones that ran first. (default: 16)', type: 'number', }) // Accepted only to fail with a useful message. A batch runs one shared @@ -243,6 +249,7 @@ async function _runAsync(args: BatchTestArgs): Promise { batchPlaceId: args.batchPlaceId, batchUniverseId: args.batchUniverseId, batchTimeoutMs: timeoutMs, + chunkSize: args.chunkSize, reporter, }) : innerContext; diff --git a/tools/nevermore-cli/src/utils/job-context/batch-script-job-context.test.ts b/tools/nevermore-cli/src/utils/job-context/batch-script-job-context.test.ts new file mode 100644 index 00000000000..059ee63c78a --- /dev/null +++ b/tools/nevermore-cli/src/utils/job-context/batch-script-job-context.test.ts @@ -0,0 +1,43 @@ +import { describe, expect, it } from 'vitest'; + +import { chunkSlugMap } from './batch-script-job-context.js'; + +function buildSlugMap(count: number): Map { + return new Map( + Array.from({ length: count }, (_, i) => [`pkg${i}`, `slug${i}`]) + ); +} + +describe('chunkSlugMap', () => { + it('leaves a batch that already fits alone', () => { + const slugMap = buildSlugMap(8); + + const chunks = chunkSlugMap(slugMap, 16); + + expect(chunks).toHaveLength(1); + expect(chunks[0]).toBe(slugMap); + }); + + it('splits a batch too large for one task log', () => { + // 73 packages in one task lost the first 14 to the log window. + const chunks = chunkSlugMap(buildSlugMap(73), 16); + + expect(chunks).toHaveLength(5); + expect(chunks.at(-1)?.size).toBe(9); + }); + + it('covers every package exactly once', () => { + const chunks = chunkSlugMap(buildSlugMap(73), 16); + + const seen = chunks.flatMap((chunk) => [...chunk.keys()]); + + expect(seen).toHaveLength(73); + expect(new Set(seen).size).toBe(73); + }); + + it('treats a non-positive size as no chunking', () => { + const slugMap = buildSlugMap(20); + + expect(chunkSlugMap(slugMap, 0)).toEqual([slugMap]); + }); +}); diff --git a/tools/nevermore-cli/src/utils/job-context/batch-script-job-context.ts b/tools/nevermore-cli/src/utils/job-context/batch-script-job-context.ts index e3b2d8c81c4..05b5f6cc6e6 100644 --- a/tools/nevermore-cli/src/utils/job-context/batch-script-job-context.ts +++ b/tools/nevermore-cli/src/utils/job-context/batch-script-job-context.ts @@ -51,6 +51,7 @@ export class BatchScriptJobContext implements JobContext { private _batchPlaceId?: number; private _batchUniverseId?: number; private _batchTimeoutMs: number; + private _chunkSize: number; private _reporter?: Reporter; // Lazy-promise state @@ -70,6 +71,7 @@ export class BatchScriptJobContext implements JobContext { batchPlaceId?: number; batchUniverseId?: number; batchTimeoutMs?: number; + chunkSize?: number; reporter?: Reporter; } ) { @@ -79,6 +81,9 @@ export class BatchScriptJobContext implements JobContext { this._batchPlaceId = options?.batchPlaceId; this._batchUniverseId = options?.batchUniverseId; this._batchTimeoutMs = options?.batchTimeoutMs ?? 300_000; + // 16 keeps a chunk's log well inside the retained window: 8 packages came + // back at 65KB intact, while 73 at 272KB lost its first 14. + this._chunkSize = options?.chunkSize ?? 16; this._reporter = options?.reporter; } @@ -264,44 +269,90 @@ export class BatchScriptJobContext implements JobContext { ); const template = await fs.readFile(templatePath, 'utf-8'); - const slugArray = [...slugMap.values()]; - const batchScript = template.replaceAll( - '{{ PACKAGE_SLUGS_JSON }}', - JSON.stringify(slugArray) - ); + // Run in chunks. Open Cloud keeps only the tail of a task's log, so one + // task covering every package loses the packages that ran first — measured + // at 73 packages, the first 14 came back unreadable. Chunking keeps each + // task's output inside the window, and gives each its own execution budget + // instead of sharing one 300s ceiling. + const chunks = chunkSlugMap(slugMap, this._chunkSize); + const merged = new Map(); + + if (chunks.length > 1) { + OutputHelper.verbose( + `Executing ${slugMap.size} packages in ${chunks.length} chunks of up to ${this._chunkSize}` + ); + } - OutputHelper.verbose( - `Executing batch script for ${slugMap.size} packages (timeout: ${ - this._batchTimeoutMs / 1000 - }s)...` - ); + for (const [index, chunk] of chunks.entries()) { + const label = + chunks.length > 1 ? ` (chunk ${index + 1}/${chunks.length})` : ''; + const batchScript = template.replaceAll( + '{{ PACKAGE_SLUGS_JSON }}', + JSON.stringify([...chunk.values()]) + ); - const result = await this._inner.runScriptAsync(deployment, { - scriptContent: batchScript, - packageName: '_batch_', - timeoutMs: this._batchTimeoutMs, - }); + OutputHelper.verbose( + `Executing batch script for ${chunk.size} packages${label} (timeout: ${ + this._batchTimeoutMs / 1000 + }s)...` + ); + + const result = await this._inner.runScriptAsync(deployment, { + scriptContent: batchScript, + packageName: '_batch_', + timeoutMs: this._batchTimeoutMs, + }); - // Fetch the combined logs - const rawLogs = await this._inner.getLogsAsync(deployment); + const rawLogs = await this._inner.getLogsAsync(deployment); - if (!result.success) { - const stateInfo = result.taskState ? ` (state: ${result.taskState})` : ''; - OutputHelper.warn( - `Batch execution task did not complete successfully${stateInfo} — parsing partial results` - ); - if (result.errorMessage) { - OutputHelper.error(result.errorMessage); - } - if (!rawLogs || rawLogs.trim().length === 0) { + if (!result.success) { + const stateInfo = result.taskState + ? ` (state: ${result.taskState})` + : ''; OutputHelper.warn( - 'No logs were returned from the execution — the script may not have started' + `Batch execution task${label} did not complete successfully${stateInfo} — parsing partial results` ); + if (result.errorMessage) { + OutputHelper.error(result.errorMessage); + } + if (!rawLogs || rawLogs.trim().length === 0) { + OutputHelper.warn( + 'No logs were returned from the execution — the script may not have started' + ); + } + OutputHelper.verbose(`Raw batch logs:\n${rawLogs || '(empty)'}`); + } + + for (const [packageName, packageResult] of parseBatchTestLogs( + rawLogs, + chunk + )) { + merged.set(packageName, packageResult); } - OutputHelper.verbose(`Raw batch logs:\n${rawLogs || '(empty)'}`); } - // Parse into per-package results - return parseBatchTestLogs(rawLogs, slugMap); + return merged; + } +} + +/** + * Split the package map into chunks small enough for one task's log to survive. + * + * Sized by package count rather than bytes because output volume is not known + * until the run happens, and the retained window is not a fixed size either. + */ +export function chunkSlugMap( + slugMap: Map, + chunkSize: number +): Map[] { + const entries = [...slugMap.entries()]; + if (chunkSize <= 0 || entries.length <= chunkSize) { + return [slugMap]; + } + + const chunks: Map[] = []; + for (let i = 0; i < entries.length; i += chunkSize) { + chunks.push(new Map(entries.slice(i, i + chunkSize))); } + return chunks; } diff --git a/tools/nevermore-cli/src/utils/testing/parsers/batch-log-parser.ts b/tools/nevermore-cli/src/utils/testing/parsers/batch-log-parser.ts index c89bfee3e75..ea800324cd8 100644 --- a/tools/nevermore-cli/src/utils/testing/parsers/batch-log-parser.ts +++ b/tools/nevermore-cli/src/utils/testing/parsers/batch-log-parser.ts @@ -259,8 +259,12 @@ export function parseBatchTestLogs( // attribution is reason enough not to trust which package a line is from. success = false; reasons.push( - `no output could be attributed to this package ` + - `(${rawLogs.length} chars received, ${beginMarkersSeen} BEGIN markers found)` + strayEndMarkers > 0 + ? `no output could be attributed to this package — ${strayEndMarkers} marker(s) ` + + 'arrived out of order, so its section could not be closed without risking ' + + "another package's output" + : `no output could be attributed to this package ` + + `(${rawLogs.length} chars received, ${beginMarkersSeen} BEGIN markers found)` ); }