Skip to content
Open
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
160 changes: 160 additions & 0 deletions HANDOFF-TEMP.md
Original file line number Diff line number Diff line change
@@ -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.
31 changes: 30 additions & 1 deletion docs/testing/testing.md
Original file line number Diff line number Diff line change
Expand Up @@ -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

Expand Down Expand Up @@ -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 |

Expand Down
31 changes: 30 additions & 1 deletion tools/cli-output-helpers/src/reporting/grouped-reporter.ts
Original file line number Diff line number Diff line change
@@ -1,13 +1,16 @@
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,
isEmptyTestRun,
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;
Expand All @@ -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();
Expand All @@ -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(
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -51,6 +51,7 @@ interface BatchTestArgs extends NevermoreGlobalArgs {
batchPlaceId?: number;
batchUniverseId?: number;
timeout?: number;
chunkSize?: number;
}

export const batchTestCommand: CommandModule<
Expand Down Expand Up @@ -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
Expand Down Expand Up @@ -243,6 +249,7 @@ async function _runAsync(args: BatchTestArgs): Promise<void> {
batchPlaceId: args.batchPlaceId,
batchUniverseId: args.batchUniverseId,
batchTimeoutMs: timeoutMs,
chunkSize: args.chunkSize,
reporter,
})
: innerContext;
Expand Down
Original file line number Diff line number Diff line change
@@ -0,0 +1,43 @@
import { describe, expect, it } from 'vitest';

import { chunkSlugMap } from './batch-script-job-context.js';

function buildSlugMap(count: number): Map<string, string> {
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]);
});
});
Loading
Loading