[mogul]

🤖: AI agent (First Mate) — AI-assisted PR (OpenCode, claude-sonnet-5.5), human review required before merge.

Context

The bash 3.2 CI job already runs with ACQ_BATS_TIMING=1, but the per-test timings are only visible by downloading a ~150 KB log. Two recent runs of the same job took 8.5 min and 15.7 min against a 25 min timeout-minutes. This PR adds the tool that makes slowdowns visible before they hit the timeout.

This is part 1 of 2. It contains the script, its tests, and docs. It does not touch .github/workflows/*: the token used by the agent has no workflow scope. Part 2 (the workflow wiring) is a separate commit that a human with that scope must push (see the end of this description).

Plan / what changed

• scripts/summarize-bats-timing (Python 3, stdlib only, like the repo's other helper tooling such as probe-msb-startup): reads the TAP-with-timing stream and writes Markdown (totals, summed test time vs wall time, 15 slowest tests, 10 slowest files, margin to the timeout, failed tests) plus a JSON record (--json), appends to --summary-file ($GITHUB_STEP_SUMMARY), and can emit a ::warning above a configurable fraction (default 70%) of the timeout.
• Test → file attribution is done by matching test names to the @test declarations in test/bats, so scripts/test-acq-bats is unchanged (the TAP stream carries no file names). Against the real suite all 1074 names map to exactly one file.
• It never fails the job: it always exits 0; bad arguments, a missing or partial log, unwritable outputs and internal errors become a short note in the summary.
• Partial or cancelled runs: a log with fewer results than the 1..N plan is flagged "Run incomplete", and the wall time is elapsed-until-now instead of the last write time.
• Shard label: --shard / $ACQ_SHARD_ID, default all.
• test/bats/155-summarize-bats-timing.bats (19 tests): normal run, failing tests, no timings, empty/missing input, bad arguments, partial run, Markdown/pipe/control-character/bidi/autolink escaping, workflow-command injection (::set-output, ::stop-commands, ...), warning threshold, JSON content, shard defaulting, wall time sources, a 60,000-test log with a 1 MB line, absurd durations and non-finite arguments, unwritable outputs and closed stdout.
• .pre-commit-config.yaml: run the bats hook when the script changes. CONTRIBUTING.md: usage.

Verification transcript

• bats test/bats/155-summarize-bats-timing.bats: 19/19 ok. 150-exec-bits.bats and 01-test-runner.bats ok (script is 100755 in the index).
• Run against real CI logs of the job. Fast runner (8.5 min): 972 tests, 30m 36s summed, 8m 31s wall, 3.6x parallel, 34% of the timeout. Slow runner (15.7 min): 1059 tests, 54m 58s summed, 15m 42s wall, 63% of the timeout; 113-host-port-override.bats is the slowest file at 4m 54s and one test took 1m 10s.
• Two independent adversarial reviews (sub-agents): round 1 found no blockers and I fixed all majors (artifact name collision on re-run, OverflowError on a hostile duration, error notes not reaching the summary file) and most minors; round 2 found no blockers or majors (one minor, absurd numeric arguments, fixed).
• Not run here: ShellCheck is not installed in this environment (the script is Python; the .bats file follows the existing conventions) and the full suite was not completed locally. CI will run both.

Security impact

No change to authentication, secrets or attack surface. Test names are untrusted text rendered as Markdown: they are sanitized (control, bidi and zero-width characters stripped), escaped (| < > & \ * _ [ ] ~), and ://, www., @, #and$are broken up so nothing autolinks. The only workflow command the tool can print is::warning, built from numbers alone; tests assert that log text cannot start a ::` line.

Rollback

Revert this PR; nothing else depends on the script until the workflow part lands.

Part 2 (needs a human with workflow scope)

Branch ci/bats-timing-summary-wf / the attached patch adds only: a tee of the suite output plus a start-epoch file, an if: always() summary step, an if: always() artifact upload (bats-timing-<shard>-<run_attempt>, overwrite: true; both steps continue-on-error and time-boxed), and the script in the changes path filter. It is designed to merge cleanly with a matrix change (shard id comes from ACQ_SHARD_ID, default all).

[basiliskus]

Verdict: request changes — 0326479aaaecd0c97fad4b367b10e1c1952730c7

The timing parser does not recognize the output produced by the repository’s pinned Bats formatter. bats-format-tap emits:

ok 1 test name # in 123 ms

but RESULT_RE expects:

ok 1 test name in 123ms

A representative real-format log therefore reports Timing | none, timed: 0, and sum_ms: 0, so the script cannot produce its primary slow-test/file metrics. The tests currently use the same non-Bats syntax as the parser and therefore miss the integration failure. Please parse the pinned formatter’s actual output and add representative fixtures.

Also, scripts/summarize-bats-timing is 495 lines and render is 58 lines, exceeding the repository’s documented 400-line file and 50-line function limits.

Assisted-by: OpenCode [gpt-5.6-sol-latest-guardrails-defaultv2] skill:change-review

[mogul]

🤖: AI agent (First Mate) — addressed review on 0326479; new head bd2f68d.

1. Parser did not recognize pinned Bats output — fixed. I ran the pinned bats-core (v1.14.0) with --timing and found two real formats:

• ok N name in 123ms / not ok N name in 4ms # timeout after 1s: raw stream from bats' cat formatter (plain bats --timing, --jobs, and the test-acq-bats xargs fallback, which is what the CI logs show). Source: bats-exec-test BATS_TEST_TIME.
• ok N name # in 123 ms / # timeout after 1 s (skips carry no timing: # skip reason): bats-format-tap, used when a report formatter is requested.

RESULT_RE now accepts both, anchored at end of line, so names containing in 5ms or # in 5 ms keep their full name (near-miss suffixes stay untimed). Tests: trimmed real captures in test/bats/fixtures/ (raw and formatter, including skip/fail/timeout), plus live tests that run the pinned bats and scripts/test-acq-bats (explicit file and 2-worker whole-suite) and feed the true output to the summarizer. The old parser reports Timing none on the formatter fixture; the new one reports 1.1s summed.

2. Size limits (CONTRIBUTING.md Development Standards: functions ≤50 lines, files ≤400 lines) — fixed. summarize-bats-timing 495 → 168 lines; new bats_timing_core.py (221, parsing/sanitizing) and bats_timing_render.py (166, rendering/JSON). Longest function is now 26 lines (render 58 → split). Python 3 stdlib only; still always exits 0 (now also with a note if sibling modules fail to import), same Markdown escaping and ::warning-from-numbers-only. Pre-commit file filter updated. Real-output tests live in the new 156-summarize-bats-timing-real.bats so 155 stays under 400 lines.

Blocking adversarial review: no blockers; its non-blocking items (import-failure exit 0, untimed message wording, flaky sum_ms>0 assertion on 1s-resolution bats, near-miss tests) were applied.

CI on bd2f68d: pre-commit pass, bash 3.2 build pass (15m26s), Markdown Lint, Link Check, Conventional Commit Title pass. AI-assisted; needs human review. Not merged.

[basiliskus]

Verdict: approve — bd2f68d17d9c391183e74a1e1ffc25c499d156d7

Both findings from the prior review of GSA-TTS/agentic-coding-quickstart#652 are resolved: the parser recognizes both pinned Bats timing formats, with representative captures and live integration tests, and the implementation meets the repository's file/function size limits. No new findings.

The exact-head CI logs confirm that all 26 summarizer tests executed and passed. This review covers the script-only change; the separately proposed workflow wiring is not reviewed here.

Assisted-by: OpenCode [gpt-6.1-sol-latest-guardrails-defaultv2] skill:change-review