From 0326479aaaecd0c97fad4b367b10e1c1952730c7 Mon Sep 17 00:00:00 2001 From: Bret Mogilefsky Date: Thu, 29 Oct 2026 00:10:25 +0000 Subject: [PATCH 1/3] feat(scripts): add summarize-bats-timing for bats TAP timings Add an advisory Python 3 (stdlib only) helper that reads the ACQ_BATS_TIMING=1 TAP stream and emits a Markdown summary (totals, summed vs wall time, 15 slowest tests, 10 slowest files, margin to the job timeout) and a JSON record for comparing runs. Files are attributed by matching test names to the @test declarations in test/bats, so the runner is unchanged. The tool always exits 0, escapes untrusted test names for Markdown, and can only print a workflow command built from numbers. Covered by test/bats/155-summarize-bats-timing.bats. Co-authored-by: OpenCode Agent --- .pre-commit-config.yaml | 2 +- CONTRIBUTING.md | 7 + scripts/summarize-bats-timing | 495 +++++++++++++++++++++++ test/bats/155-summarize-bats-timing.bats | 296 ++++++++++++++ 4 files changed, 799 insertions(+), 1 deletion(-) create mode 100755 scripts/summarize-bats-timing create mode 100644 test/bats/155-summarize-bats-timing.bats diff --git a/.pre-commit-config.yaml b/.pre-commit-config.yaml index 580ddfa7..b1a15b31 100644 --- a/.pre-commit-config.yaml +++ b/.pre-commit-config.yaml @@ -111,7 +111,7 @@ repos: entry: bash scripts/test-acq-bats language: system pass_filenames: false - files: '^(acq|acq\.backends/.*|scripts/(test-acq-lib\.sh|test-acq-bats|run-shellcheck|probe-msb-node-startup|test-probe-msb-node-startup\.py|fix-exec-bits|verify-backends)|test/bats/.*)$' + files: '^(acq|acq\.backends/.*|scripts/(test-acq-lib\.sh|test-acq-bats|run-shellcheck|probe-msb-node-startup|test-probe-msb-node-startup\.py|fix-exec-bits|verify-backends|summarize-bats-timing)|test/bats/.*)$' - id: test-probe-msb-startup name: MSB startup probe offline tests diff --git a/CONTRIBUTING.md b/CONTRIBUTING.md index c2e35518..4d6e0ab5 100644 --- a/CONTRIBUTING.md +++ b/CONTRIBUTING.md @@ -205,6 +205,13 @@ network), built on [bats-core](https://github.com/bats-core/bats-core) (ADR-0025 pre-commit output so successful runs retain measurements. The fallback buffers output per file, so log-arrival timestamps are not test durations. + `scripts/summarize-bats-timing` turns the timing output into a Markdown table + (slowest tests and files, summed vs wall time, margin to a job timeout) and a + JSON record for comparing runs. It is advisory and always exits 0. Run it with + `ACQ_BATS_TIMING=1 ./scripts/test-acq-bats 2>&1 | tee bats.log` and then + `python3 scripts/summarize-bats-timing --log bats.log --timeout-minutes 25`. + Files are attributed by matching test names against `test/bats/*.bats`. + The shared harness uses an offline Git transport fixture for the exact pinned Patterns kit fetch. Local fixture repositories still use real Git; unhandled remote transports fail locally. This covers direct provider-input discovery as diff --git a/scripts/summarize-bats-timing b/scripts/summarize-bats-timing new file mode 100755 index 00000000..adc70abb --- /dev/null +++ b/scripts/summarize-bats-timing @@ -0,0 +1,495 @@ +#!/usr/bin/env python3 +"""Summarize bats `--timing` TAP output as Markdown plus a JSON record. + +Reads the TAP stream scripts/test-acq-bats prints when ACQ_BATS_TIMING=1 +(`ok N in Xms`), from a file or stdin, and reports the slowest tests, +the slowest files, and the margin to the CI job timeout, so a slowdown is +visible long before it hits the timeout. Python 3 standard library only. + +This tool is advisory. It ALWAYS exits 0 (a bad argument, a missing log, or an +internal error becomes a short note in the summary, never a failed job). + +Untrusted text: test names come from repository content and the output is +rendered Markdown in the Actions UI. Every name is sanitized and escaped before +it reaches Markdown or JSON, and the only workflow command this tool can print +(`::warning`) is built from numbers alone, never from the log. + +Files are attributed by matching each test name against the `@test` lines in +--tests-dir (default test/bats): the TAP stream carries no file names, and the +runner's parallel and fallback paths number tests differently. + +Usage: + summarize-bats-timing --log bats.log --timeout-minutes 25 \\ + --summary-file "$GITHUB_STEP_SUMMARY" --json timing.json +""" + +import argparse +import heapq +import calendar +import json +import math +import os +import re +import sys +import time +import unicodedata + +TOP_TESTS = 15 +TOP_FILES = 10 +MAX_FAILED_SHOWN = 20 +JSON_MAX_TESTS = 200 +MAX_LINE = 4096 +MAX_NAME = 160 +UNMAPPED = "(unmapped)" +AMBIGUOUS = "(ambiguous name)" + +ANSI_RE = re.compile(r"\x1b\[[0-9;]*[A-Za-z]") +STAMP_RE = re.compile(r"^(\d{4}-\d\d-\d\dT\d\d:\d\d:\d\d)(\.\d+)?Z ") +RESULT_RE = re.compile( + r"^(not )?ok (\d+) (.*?)(?: in (\d{1,9})ms)?(?: # (?:skip|SKIP|todo|TODO)\b.*)?$" +) +SKIP_RE = re.compile(r" # (?:skip|SKIP)\b") +PLAN_RE = re.compile(r"^1\.\.(\d+)$") +WORKERS_RE = re.compile(r"test-acq-bats: workers=(\d+)\b") +TEST_DECL_RE = re.compile(r"^\s*@test\s+(.*[^\s])\s+\{") +SHARD_RE = re.compile(r"[^A-Za-z0-9._-]") + + +class Note(Exception): + """A user-facing, fixed-text problem (never carries untrusted text).""" + + +def parse_stamp(line): + m = STAMP_RE.match(line) + if not m: + return None + try: + return calendar.timegm(time.strptime(m.group(1), "%Y-%m-%dT%H:%M:%S")) + ( + float(m.group(2)) if m.group(2) else 0.0 + ) + except (ValueError, OverflowError): + return None + + +def clean(text, limit=MAX_NAME): + out = [] + for ch in text: + # Control, format (bidi/zero-width), line/paragraph separators, surrogates. + bad = unicodedata.category(ch) in ("Cc", "Cf", "Cs", "Co", "Cn", "Zl", "Zp") + out.append(" " if bad else ch) + s = "".join(out).strip() + return s if len(s) <= limit else s[: limit - 1] + "\u2026" + + +_MD_ESC = {"&": "&", "<": "<", ">": ">", "|": "|"} +_MD_BACKSLASH = set("\\`*_[]~") +_ZWSP = "\u200b" # breaks GFM autolinks/mentions/math; inserted after these +_MD_BREAK_AFTER = set("@#$") + + +def md(text, limit=MAX_NAME): + out = [] + for ch in clean(text, limit): + if ch in _MD_ESC: + out.append(_MD_ESC[ch]) + elif ch in _MD_BACKSLASH: + out.append("\\" + ch) + elif ch in _MD_BREAK_AFTER: + out.append(ch + _ZWSP) + else: + out.append(ch) + return "".join(out).replace("://", ":" + _ZWSP + "//").replace("www.", "www" + _ZWSP + ".") + + +def unquote_test_name(expr): + if len(expr) >= 2 and expr[0] == expr[-1] == '"': + return re.sub(r'\\(["\\$`])', r"\1", expr[1:-1]) + if len(expr) >= 2 and expr[0] == expr[-1] == "'": + return expr[1:-1] + return expr + + +def load_name_map(tests_dir): + """Map test name -> sorted list of .bats basenames declaring it.""" + names = {} + try: + entries = sorted(os.listdir(tests_dir)) + except OSError: + return names + for entry in entries: + if not entry.endswith(".bats"): + continue + try: + with open(os.path.join(tests_dir, entry), encoding="utf-8", errors="replace") as fh: + for line in fh: + m = TEST_DECL_RE.match(line) + if m: + files = names.setdefault(unquote_test_name(m.group(1)), []) + if entry not in files: + files.append(entry) + except OSError: + continue + return names + + +class Stats: + def __init__(self, name_map): + self.name_map = name_map + self.passed = self.failed = self.skipped = self.untimed = 0 + self.planned = 0 + self.sum_ms = 0 + self.workers = None + self.slow = [] # min-heap of (ms, -seq, name, file, status) + self.files = {} # file -> [tests, ms, max_ms] + self.failed_names = [] + self.seq = 0 + self.first_stamp = self.last_stamp = self.workers_stamp = None + + def file_for(self, name): + cands = self.name_map.get(name) + if not cands: + return UNMAPPED + return cands[0] if len(cands) == 1 else AMBIGUOUS + + def add_result(self, failed, name, ms, skipped): + file = self.file_for(name) + if skipped: + self.skipped += 1 + elif failed: + self.failed += 1 + if len(self.failed_names) < MAX_FAILED_SHOWN: + self.failed_names.append((name, file)) + else: + self.passed += 1 + entry = self.files.setdefault(file, [0, 0, 0]) + entry[0] += 1 + if ms is None: + self.untimed += 1 + return + if skipped: + return + self.sum_ms += ms + entry[1] += ms + entry[2] = max(entry[2], ms) + self.seq += 1 + item = (ms, -self.seq, name, file, "not ok" if failed else "ok") + if len(self.slow) < JSON_MAX_TESTS: + heapq.heappush(self.slow, item) + elif item > self.slow[0]: + heapq.heapreplace(self.slow, item) + + @property + def total(self): + return self.passed + self.failed + self.skipped + + @property + def timed(self): + return self.total - self.untimed + + +def consume(stream, stats): + while True: + raw = stream.readline(MAX_LINE) + if not raw: + break + while len(raw) == MAX_LINE and not raw.endswith("\n"): + chunk = stream.readline(MAX_LINE) # drop the rest of an over-long line + if not chunk or chunk.endswith("\n"): + break + line = ANSI_RE.sub("", raw).rstrip("\r\n") + stamp = parse_stamp(line) + body = STAMP_RE.sub("", line, count=1) if stamp is not None else line + m = WORKERS_RE.search(body) + if m and stats.workers is None: + stats.workers = int(m.group(1)) + stats.workers_stamp = stamp + m = PLAN_RE.match(body) + if m: + stats.planned += int(m.group(1)) + if stamp is not None and stats.first_stamp is None: + stats.first_stamp = stamp + continue + m = RESULT_RE.match(body) + if not m: + continue + ms = int(m.group(4)) if m.group(4) is not None else None + stats.add_result(bool(m.group(1)), m.group(3), ms, bool(SKIP_RE.search(body))) + if stamp is not None: + if stats.first_stamp is None: + stats.first_stamp = stamp + stats.last_stamp = stamp + + +def fmt_ms(ms): + if ms < 1000: + return "%dms" % ms + return fmt_secs(ms / 1000.0, tenths=True) + + +def fmt_secs(secs, tenths=False): + if secs < 60: + return "%.1fs" % secs if tenths or secs < 10 else "%ds" % round(secs) + secs = int(round(secs)) + return "%dm %02ds" % (secs // 60, secs % 60) + + +def read_epoch(path): + try: + with open(path, encoding="ascii") as fh: + return float(fh.read(64).strip()) + except (OSError, ValueError): + return None + + +def wall_seconds(args, stats): + if args.wall_seconds is not None: + return args.wall_seconds + if args.start_epoch_file and args.log and args.log != "-": + start = read_epoch(args.start_epoch_file) + try: + end = os.stat(args.log).st_mtime + except OSError: + end = None + if stats.planned and stats.total < stats.planned: + # Incomplete run (cancelled or timed out): the last write understates + # how long the suite ran before it was killed; elapsed-until-now does not. + end = time.time() + if start is not None and end is not None and end >= start: + return end - start + if stats.last_stamp is not None: + begin = stats.workers_stamp if stats.workers_stamp is not None else stats.first_stamp + if begin is not None and stats.last_stamp >= begin: + return stats.last_stamp - begin + return None + + +def render(args, stats, wall, shard, notes): + lines = ["## bats timing (shard: %s)" % shard, ""] + lines.extend(notes) + if notes: + lines.append("") + if stats.total == 0: + lines.append("No bats test results were found in the log.") + return lines + lines.append("| Metric | Value |") + lines.append("| --- | --- |") + lines.append( + "| Tests reported | %d (%d passed, %d failed, %d skipped) |" + % (stats.total, stats.passed, stats.failed, stats.skipped) + ) + if stats.planned and stats.total < stats.planned: + lines.append( + "| Run incomplete | %d of %d planned tests reported (cancelled, timed out or crashed?) |" + % (stats.total, stats.planned) + ) + if stats.timed == 0: + lines.append("| Timing | none |") + lines.append("") + lines.append( + "No per-test timings were present (`in Nms` suffixes). " + "Run the suite with `ACQ_BATS_TIMING=1` to get slowest-test and slowest-file tables." + ) + return lines + failed_section(stats) + lines.append("| Summed test time | %s (setup and teardown included) |" % fmt_secs(stats.sum_ms / 1000.0, True)) + if wall is not None and wall > 0: + par = "%s wall" % fmt_secs(wall, True) + par += ", %.1fx parallel" % (stats.sum_ms / 1000.0 / wall) + if stats.workers: + par += " (%d workers)" % stats.workers + lines.append("| Suite wall time | %s |" % par) + else: + lines.append("| Suite wall time | unknown |") + if args.timeout_minutes: + limit = args.timeout_minutes * 60.0 + if wall is not None and wall > 0 and limit > 0: + lines.append( + "| Margin to %g min job timeout | %s left, suite used %.0f%% (suite only; checkout, setup and bash build also count) |" + % (args.timeout_minutes, fmt_secs(max(limit - wall, 0)), 100.0 * wall / limit) + ) + else: + lines.append("| Margin to %g min job timeout | unknown (no wall time) |" % args.timeout_minutes) + unmapped = sum(v[0] for k, v in stats.files.items() if k in (UNMAPPED, AMBIGUOUS)) + if unmapped: + lines.append("| Tests not attributable to a file | %d |" % unmapped) + ranked = sorted(stats.slow, reverse=True)[:TOP_TESTS] + lines += ["", "### Slowest %d tests" % len(ranked), "", "| # | Time | File | Test |", "| ---: | ---: | --- | --- |"] + for i, (ms, _seq, name, file, _st) in enumerate(ranked, 1): + lines.append("| %d | %s | %s | %s |" % (i, fmt_ms(ms), md(file), md(name))) + files = sorted(stats.files.items(), key=lambda kv: (-kv[1][1], kv[0]))[:TOP_FILES] + lines += ["", "### Slowest %d files (summed test time)" % len(files), "", + "| # | File | Tests | Total | Slowest test |", "| ---: | --- | ---: | ---: | ---: |"] + for i, (file, (n, ms, mx)) in enumerate(files, 1): + lines.append("| %d | %s | %d | %s | %s |" % (i, md(file), n, fmt_ms(ms), fmt_ms(mx))) + return lines + failed_section(stats) + + +def failed_section(stats): + if not stats.failed: + return [] + out = ["", "### Failed tests", ""] + for name, file in stats.failed_names: + out.append("- %s: %s" % (md(file), md(name))) + if stats.failed > len(stats.failed_names): + out.append("- ... and %d more" % (stats.failed - len(stats.failed_names))) + return out + + +def build_json(args, stats, wall, shard): + limit = args.timeout_minutes * 60.0 if args.timeout_minutes else None + return { + "schema": 1, + "shard": shard, + "generated_at": int(time.time()), + "tests": stats.total, + "passed": stats.passed, + "failed": stats.failed, + "skipped": stats.skipped, + "planned": stats.planned, + "timed": stats.timed, + "sum_ms": stats.sum_ms, + "wall_seconds": None if wall is None else round(wall, 3), + "workers": stats.workers, + "timeout_minutes": args.timeout_minutes, + "wall_fraction": None if (wall is None or not limit) else round(wall / limit, 4), + "files": [ + {"file": clean(f), "tests": v[0], "ms": v[1], "max_ms": v[2]} + for f, v in sorted(stats.files.items(), key=lambda kv: (-kv[1][1], kv[0])) + ], + "slowest_tests": [ + {"ms": ms, "file": clean(file), "name": clean(name), "status": st} + for ms, _s, name, file, st in sorted(stats.slow, reverse=True) + ], + } + + +def write_text(path, text, append): + try: + with open(path, "a" if append else "w", encoding="utf-8") as fh: + fh.write(text) + except (OSError, UnicodeError) as exc: + safe_stderr("summarize-bats-timing: cannot write %s (%s)\n" % (clean(path, 200), type(exc).__name__)) + + +def open_input(path): + if path in (None, "-"): + return sys.stdin + try: + return open(path, encoding="utf-8", errors="replace") + except OSError: + raise Note("No bats log was found (the test step may not have started).") + + +def run(args): + shard = SHARD_RE.sub("_", args.shard or "all")[:40] or "all" + stats = Stats(load_name_map(args.tests_dir)) + notes = [] + try: + stream = open_input(args.log) + try: + consume(stream, stats) + finally: + if stream is not sys.stdin: + stream.close() + except Note as note: + notes.append(str(note)) + wall = wall_seconds(args, stats) + lines = render(args, stats, wall, shard, notes) + text = "\n".join(lines) + "\n" + if args.summary_file: + write_text(args.summary_file, text + "\n", append=True) + else: + sys.stdout.write(text) + if args.json: + write_text(args.json, json.dumps(build_json(args, stats, wall, shard), indent=1, allow_nan=False) + "\n", append=False) + if wall is not None and args.timeout_minutes and args.warn_fraction > 0: + frac = wall / (args.timeout_minutes * 60.0) + if frac >= args.warn_fraction: + sys.stdout.write( + "::warning title=bats suite slow::suite wall time %s is %.0f%% of the %g minute job timeout\n" + % (fmt_secs(wall), 100.0 * frac, args.timeout_minutes) + ) + + +def finite_number(text): + value = float(text) + if not math.isfinite(value) or value < 0 or value > 1e9: + raise ValueError(text) + return value + + +class QuietParser(argparse.ArgumentParser): + def error(self, message): + raise Note("Invalid arguments to summarize-bats-timing; no summary produced.") + + +def parse_args(argv): + default_tests = os.path.join(os.path.dirname(os.path.abspath(__file__)), "..", "test", "bats") + p = QuietParser(description="Summarize bats --timing TAP output.", allow_abbrev=False, add_help=False) + p.add_argument("--log", default="-", help="TAP log file (default: stdin)") + p.add_argument("--tests-dir", default=default_tests, help="directory of .bats files for file attribution") + p.add_argument("--timeout-minutes", type=finite_number, default=None, help="job timeout, for the margin") + p.add_argument("--warn-fraction", type=finite_number, default=0.7, help="emit ::warning at this fraction of the timeout (0 disables)") + p.add_argument("--wall-seconds", type=finite_number, default=None, help="explicit suite wall time") + p.add_argument("--start-epoch-file", default=None, help="file with the suite start epoch; the log mtime is the end") + p.add_argument("--summary-file", default=None, help="append Markdown here (e.g. $GITHUB_STEP_SUMMARY); default stdout") + p.add_argument("--json", default=None, help="write the machine-readable record here") + p.add_argument("--shard", default=os.environ.get("ACQ_SHARD_ID") or "all", help="shard label (default $ACQ_SHARD_ID or 'all')") + return p.parse_args(argv) + + +def safe_stderr(text): + try: + sys.stderr.write(text) + except Exception: + pass + + +def fallback_note(summary_file, text): + note = "## bats timing\n\n%s\n" % text + if summary_file: + write_text(summary_file, note + "\n", append=True) + else: + try: + sys.stdout.write(note) + except Exception: + pass + + +def argv_value(argv, flag): + for i, item in enumerate(argv[:-1]): + if item == flag: + return argv[i + 1] + return None + + +def main(argv): + for stream in (sys.stdout, sys.stdin): + try: + stream.reconfigure(encoding="utf-8", errors="replace") + except Exception: + pass + try: + run(parse_args(argv)) + except Note as note: + fallback_note(argv_value(argv, "--summary-file"), str(note)) + except BaseException as exc: # advisory tool: never fail the job + safe_stderr("summarize-bats-timing: internal error (%s)\n" % type(exc).__name__) + fallback_note( + argv_value(argv, "--summary-file"), + "The timing summary could not be produced (%s)." % type(exc).__name__, + ) + try: + sys.stdout.flush() + except Exception: + pass + return 0 + + +if __name__ == "__main__": + code = main(sys.argv[1:]) + for stream in (sys.stdout, sys.stderr): + try: + stream.flush() + except Exception: + pass + os._exit(code) diff --git a/test/bats/155-summarize-bats-timing.bats b/test/bats/155-summarize-bats-timing.bats new file mode 100644 index 00000000..7a627b4c --- /dev/null +++ b/test/bats/155-summarize-bats-timing.bats @@ -0,0 +1,296 @@ +#!/usr/bin/env bats +# +# 155-summarize-bats-timing.bats — contract tests for scripts/summarize-bats-timing, +# the advisory CI helper that turns `ACQ_BATS_TIMING=1` TAP output into a Markdown +# job summary and a JSON record. It must never fail a job, must degrade gracefully +# on missing or partial input, and must treat test names as untrusted text. +# +# shellcheck shell=bats + +load 'helper' + +setup() { + command -v python3 >/dev/null 2>&1 || skip "python3 unavailable" + SUMMARIZE="$REPO_ROOT/scripts/summarize-bats-timing" + W="$BATS_TEST_TMPDIR" + TESTS="$W/tests" + mkdir -p "$TESTS" + # Declared via printf: a literal @test line inside a heredoc would be + # rewritten by bats' own preprocessor. + local t='@test' + printf '%s "alpha one" { true; }\n%s "alpha two" { true; }\n%s "alpha | pipe" { true; }\n' "$t" "$t" "$t" > "$TESTS/10-alpha.bats" + printf '%s "beta one" { true; }\n%s "beta shared" { true; }\n' "$t" "$t" > "$TESTS/20-beta.bats" + printf '%s "gamma shared" { true; }\n%s "beta shared" { true; }\n' "$t" "$t" > "$TESTS/30-gamma.bats" +} + +summarize() { python3 "$SUMMARIZE" --tests-dir "$TESTS" "$@"; } + +@test "summarize: reports totals, slowest tests and files, and the timeout margin" { + cat > "$W/ok.tap" <<'EOF' +test-acq-bats: workers=2; per-test timings include setup and teardown +1..5 +ok 1 alpha one in 1500ms +ok 2 alpha two in 500ms +ok 3 beta one in 9000ms +ok 4 gamma shared in 40ms +ok 5 alpha | pipe in 10ms # skip not today +EOF + run summarize --log "$W/ok.tap" --timeout-minutes 25 --wall-seconds 600 + assert_success + assert_output --partial 'Tests reported | 5 (4 passed, 0 failed, 1 skipped)' + assert_output --partial 'Summed test time | 11.0s' + assert_output --partial '10m 00s wall, 0.0x parallel (2 workers)' + assert_output --partial 'Margin to 25 min job timeout | 15m 00s left, suite used 40%' + assert_output --partial '| 1 | 9.0s | 20-beta.bats | beta one |' + assert_output --partial '| 1 | 20-beta.bats | 1 | 9.0s | 9.0s |' + assert_output --partial '| 2 | 10-alpha.bats | 3 | 2.0s | 1.5s |' + refute_output --partial '::warning' +} + +@test "summarize: tests with the same name in several files are not guessed at" { + printf '1..1\nok 1 beta shared in 5ms\n' > "$W/amb.tap" + run summarize --log "$W/amb.tap" + assert_success + assert_output --partial '(ambiguous name)' + assert_output --partial 'Tests not attributable to a file | 1' +} + +@test "summarize: failing tests are listed and counted" { + cat > "$W/fail.tap" <<'EOF' +1..3 +ok 1 alpha one in 10ms +not ok 2 beta one in 2500ms +# (in test file x.bats, line 3) +not ok 3 mystery test in 5ms +EOF + run summarize --log "$W/fail.tap" + assert_success + assert_output --partial '(1 passed, 2 failed, 0 skipped)' + assert_output --partial '### Failed tests' + assert_output --partial '- 20-beta.bats: beta one' + assert_output --partial '- (unmapped): mystery test' +} + +@test "summarize: a log without timings says so and still counts results" { + printf '1..2\nok 1 alpha one\nnot ok 2 beta one\n' > "$W/untimed.tap" + run summarize --log "$W/untimed.tap" --timeout-minutes 25 + assert_success + assert_output --partial 'Tests reported | 2 (1 passed, 1 failed, 0 skipped)' + assert_output --partial 'No per-test timings were present' + assert_output --partial 'ACQ_BATS_TIMING=1' + refute_output --partial 'Slowest 15 tests' +} + +@test "summarize: empty input and a missing log degrade to a clear message and exit 0" { + : > "$W/empty.tap" + run summarize --log "$W/empty.tap" + assert_success + assert_output --partial 'No bats test results were found in the log.' + + run summarize --log "$W/does-not-exist.tap" + assert_success + assert_output --partial 'No bats log was found' + + run bash -c ': | python3 "$1" --tests-dir "$2" --log -' _ "$SUMMARIZE" "$TESTS" + assert_success + assert_output --partial 'No bats test results were found' +} + +@test "summarize: bad arguments never fail the job" { + run summarize --no-such-flag + assert_success + assert_output --partial 'Invalid arguments' + run summarize --timeout-minutes notanumber + assert_success + assert_output --partial 'Invalid arguments' +} + +@test "summarize: partial output from a cancelled run is flagged as incomplete" { + printf '1..400\nok 1 alpha one in 30ms\nok 2 alpha two in 40ms\n' > "$W/partial.tap" + run summarize --log "$W/partial.tap" --timeout-minutes 25 + assert_success + assert_output --partial 'Run incomplete | 2 of 400 planned tests reported' +} + +@test "summarize: names with pipes, markup and control characters cannot break the Markdown" { + local tap="$W/evil.tap" + { + printf '1..3\n' + printf 'ok 1 a | b [link](http://x) `tick` *bold* in 900ms\n' + printf 'ok 2 tab\there and \033[31mcolor\033[0m in 800ms\n' + printf 'ok 3 %s in 700ms\n' "$(printf 'x%.0s' $(seq 1 600))" + } > "$tap" + run summarize --log "$tap" + assert_success + assert_output --partial 'a | b <img src=x onerror=1> \[link\]' + assert_output --partial '\`tick\` \*bold\*' + refute_output --partial ' "$tap" + run summarize --log "$tap" --timeout-minutes 1 --wall-seconds 55 + assert_success + # the only line allowed to start with :: is our own numeric warning + run bash -c 'python3 "$1" --tests-dir "$2" --log "$3" --timeout-minutes 1 --wall-seconds 55 | grep -c "^::"' _ "$SUMMARIZE" "$TESTS" "$tap" + assert_output '1' + run bash -c 'python3 "$1" --tests-dir "$2" --log "$3" --timeout-minutes 1 --wall-seconds 55 | grep "^::"' _ "$SUMMARIZE" "$TESTS" "$tap" + assert_output --regexp '^::warning title=bats suite slow::suite wall time [0-9a-z ]+ is [0-9]+% of the [0-9.]+ minute job timeout$' + # and the same text written to a summary file never starts a line with :: + run summarize --log "$tap" --summary-file "$W/summary.md" + assert_success + run grep -c '^::' "$W/summary.md" + assert_output '0' +} + +@test "summarize: warning annotation fires only above the configured fraction" { + printf '1..1\nok 1 alpha one in 10ms\n' > "$W/w.tap" + run summarize --log "$W/w.tap" --timeout-minutes 10 --wall-seconds 419 + refute_output --partial '::warning' + run summarize --log "$W/w.tap" --timeout-minutes 10 --wall-seconds 421 + assert_output --partial '::warning title=bats suite slow::suite wall time 7m 01s is 70% of the 10 minute job timeout' + run summarize --log "$W/w.tap" --timeout-minutes 10 --wall-seconds 421 --warn-fraction 0 + refute_output --partial '::warning' + run summarize --log "$W/w.tap" --timeout-minutes 10 --wall-seconds 100 --warn-fraction 0.1 + assert_output --partial '::warning' +} + +@test "summarize: writes a machine-readable record and appends Markdown to the summary file" { + printf '1..2\nok 1 alpha one in 1200ms\nok 2 beta one in 3400ms\n' > "$W/j.tap" + printf 'existing\n' > "$W/summary.md" + run summarize --log "$W/j.tap" --timeout-minutes 25 --wall-seconds 100 --shard 'shard 2/4;x' --json "$W/t.json" --summary-file "$W/summary.md" + assert_success + assert_output '' + run head -1 "$W/summary.md" + assert_output 'existing' + run grep -F '## bats timing (shard: shard_2_4_x)' "$W/summary.md" + assert_success + run python3 - "$W/t.json" <<'PY' +import json, sys +d = json.load(open(sys.argv[1])) +assert d["schema"] == 1 and d["shard"] == "shard_2_4_x", d["shard"] +assert d["tests"] == 2 and d["sum_ms"] == 4600 and d["wall_seconds"] == 100.0 +assert d["timeout_minutes"] == 25.0 and d["wall_fraction"] == round(100 / 1500, 4) +assert [t["name"] for t in d["slowest_tests"]] == ["beta one", "alpha one"] +assert d["files"][0] == {"file": "20-beta.bats", "tests": 1, "ms": 3400, "max_ms": 3400} +print("json ok") +PY + assert_success + assert_output 'json ok' +} + +@test "summarize: the shard label defaults to ACQ_SHARD_ID, then to all" { + printf '1..1\nok 1 alpha one in 10ms\n' > "$W/s.tap" + run env ACQ_SHARD_ID=3 python3 "$SUMMARIZE" --tests-dir "$TESTS" --log "$W/s.tap" + assert_output --partial '(shard: 3)' + run env -u ACQ_SHARD_ID python3 "$SUMMARIZE" --tests-dir "$TESTS" --log "$W/s.tap" + assert_output --partial '(shard: all)' +} + +@test "summarize: wall time comes from the start-epoch file and log mtime" { + printf '1..1\nok 1 alpha one in 10ms\n' > "$W/m.tap" + touch -d '2026-01-01 00:10:00 UTC' "$W/m.tap" 2>/dev/null || touch -t 202601010010 "$W/m.tap" + local end + end="$(python3 -c 'import os,sys;print(int(os.stat(sys.argv[1]).st_mtime))' "$W/m.tap")" + printf '%s\n' "$((end - 300))" > "$W/start" + run summarize --log "$W/m.tap" --start-epoch-file "$W/start" --timeout-minutes 10 + assert_success + assert_output --partial '5m 00s wall' + assert_output --partial '5m 00s left, suite used 50%' +} + +@test "summarize: a very large log is summarized quickly and keeps bounded output" { + python3 - "$W/big.tap" <<'PY' +import sys +with open(sys.argv[1], "w") as fh: + fh.write("1..60000\n") + for i in range(1, 60001): + fh.write("ok %d generated test %d in %dms\n" % (i, i % 997, (i * 7919) % 5000)) + fh.write("x" * 1000000 + "\n") +PY + run summarize --log "$W/big.tap" --timeout-minutes 25 --wall-seconds 60 --json "$W/big.json" + assert_success + assert_output --partial 'Tests reported | 60000 (60000 passed' + assert_output --partial 'Slowest 15 tests' + [ "${#lines[@]}" -lt 80 ] + run wc -c < "$W/big.json" + [ "$output" -lt 200000 ] +} + +@test "summarize: reads a timestamped CI log and derives wall time from its timestamps" { + cat > "$W/ci.log" <<'EOF' +2026-10-28T22:46:39.5248848Z test-acq-bats: workers=4; per-test timings include setup and teardown +2026-10-28T22:46:57.2065672Z 1..2 +2026-10-28T22:47:06.8428017Z ok 1 alpha one in 913ms +2026-10-28T22:50:09.5005398Z ok 2 beta one in 859ms +EOF + run summarize --log "$W/ci.log" --timeout-minutes 25 + assert_success + assert_output --partial '3m 30s wall' + assert_output --partial '(4 workers)' +} + +@test "summarize: an absurd duration or non-finite argument never discards the summary or fails" { + local big + big="$(printf '9%.0s' $(seq 1 400))" + printf '1..2\nok 1 alpha one in %sms\nok 2 alpha two in 5ms\n' "$big" > "$W/huge.tap" + run summarize --log "$W/huge.tap" + assert_success + assert_output --partial 'Tests reported | 2' + for v in inf nan -5 1e999 abc; do + run summarize --log "$W/huge.tap" --wall-seconds "$v" + assert_success + assert_output --partial 'Invalid arguments' + done + run summarize --help + assert_success + assert_output --partial 'Invalid arguments' +} + +@test "summarize: invalid-argument and failure notes land in the summary file, not just stdout" { + run summarize --bogus --summary-file "$W/s.md" + assert_success + assert_output '' + run grep -F 'Invalid arguments' "$W/s.md" + assert_success +} + +@test "summarize: unwritable outputs and a closed stdout still exit 0" { + printf '1..1\nok 1 alpha one in 10ms\n' > "$W/u.tap" + run summarize --log "$W/u.tap" --json "$W/no/such/dir/t.json" --summary-file "$W/no/such/dir/s.md" + assert_success + run bash -c 'python3 "$1" --tests-dir "$2" --log "$3" >&-' _ "$SUMMARIZE" "$TESTS" "$W/u.tap" + assert_success + run bash -c 'python3 "$1" --tests-dir "$2" --log "$3" | true' _ "$SUMMARIZE" "$TESTS" "$W/u.tap" + assert_success + run summarize --log "$W" + assert_success +} + +@test "summarize: bidi/zero-width characters are neutralized and autolinks are broken up" { + { + printf '1..1\n' + printf 'ok 1 evil \xe2\x80\xae gnp.txt http://evil.example www.evil.example @someone in 100ms\n' + } > "$W/b.tap" + run summarize --log "$W/b.tap" + assert_success + refute_output --partial $'\xe2\x80\xae' + refute_output --partial 'http://evil' + refute_output --partial 'www.evil' + refute_output --partial '@someone' +} From 19ca6c73787c7661f0f2f30029058c441df5198b Mon Sep 17 00:00:00 2001 From: Bret Mogilefsky Date: Fri, 30 Oct 2026 00:35:33 +0000 Subject: [PATCH 2/3] fix(scripts): parse real bats timing formats and split summarize-bats-timing The summarizer only understood `ok N name in 123ms`. The bats `tap` formatter (used with --report-formatter) prints `ok N name # in 123 ms` and `# timeout after N s`, which reported "Timing none". Accept both formats, anchored at end of line so names containing "in 5ms" are not misparsed. Add trimmed real captures from the pinned bats-core plus live tests that run bats and scripts/test-acq-bats and feed the true output to the summarizer. Split the 495-line script into an entry point and two sibling modules so every file is <=400 lines and every function <=50 lines. Co-authored-by: OpenCode Agent --- .pre-commit-config.yaml | 2 +- CONTRIBUTING.md | 7 + scripts/bats_timing_core.py | 221 ++++++++++++ scripts/bats_timing_render.py | 166 +++++++++ scripts/summarize-bats-timing | 335 +----------------- test/bats/155-summarize-bats-timing.bats | 103 ++++++ .../fixtures/bats-formatter-tap-timing.tap | 7 + test/bats/fixtures/bats-raw-timing.tap | 7 + 8 files changed, 516 insertions(+), 332 deletions(-) create mode 100644 scripts/bats_timing_core.py create mode 100644 scripts/bats_timing_render.py create mode 100644 test/bats/fixtures/bats-formatter-tap-timing.tap create mode 100644 test/bats/fixtures/bats-raw-timing.tap diff --git a/.pre-commit-config.yaml b/.pre-commit-config.yaml index b1a15b31..a1758699 100644 --- a/.pre-commit-config.yaml +++ b/.pre-commit-config.yaml @@ -111,7 +111,7 @@ repos: entry: bash scripts/test-acq-bats language: system pass_filenames: false - files: '^(acq|acq\.backends/.*|scripts/(test-acq-lib\.sh|test-acq-bats|run-shellcheck|probe-msb-node-startup|test-probe-msb-node-startup\.py|fix-exec-bits|verify-backends|summarize-bats-timing)|test/bats/.*)$' + files: '^(acq|acq\.backends/.*|scripts/(test-acq-lib\.sh|test-acq-bats|run-shellcheck|probe-msb-node-startup|test-probe-msb-node-startup\.py|fix-exec-bits|verify-backends|summarize-bats-timing|bats_timing_(core|render)\.py)|test/bats/.*)$' - id: test-probe-msb-startup name: MSB startup probe offline tests diff --git a/CONTRIBUTING.md b/CONTRIBUTING.md index 4d6e0ab5..62242802 100644 --- a/CONTRIBUTING.md +++ b/CONTRIBUTING.md @@ -211,6 +211,13 @@ network), built on [bats-core](https://github.com/bats-core/bats-core) (ADR-0025 `ACQ_BATS_TIMING=1 ./scripts/test-acq-bats 2>&1 | tee bats.log` and then `python3 scripts/summarize-bats-timing --log bats.log --timeout-minutes 25`. Files are attributed by matching test names against `test/bats/*.bats`. + It reads both timing formats the pinned bats prints: `ok N name in 123ms` + (plain `bats --timing`, `--jobs`, and the xargs fallback) and + `ok N name # in 123 ms` (the `tap` formatter behind `--report-formatter`). + Real captures live in `test/bats/fixtures/` and are checked in + `test/bats/155-summarize-bats-timing.bats`. The tool is split into + `scripts/summarize-bats-timing` (entry point) and `scripts/bats_timing_core.py` / + `scripts/bats_timing_render.py` to stay within the size limits in Development Standards. The shared harness uses an offline Git transport fixture for the exact pinned Patterns kit fetch. Local fixture repositories still use real Git; unhandled diff --git a/scripts/bats_timing_core.py b/scripts/bats_timing_core.py new file mode 100644 index 00000000..900d3b4e --- /dev/null +++ b/scripts/bats_timing_core.py @@ -0,0 +1,221 @@ +"""Parsing and sanitizing half of summarize-bats-timing (Python 3 stdlib only). + +Turns a bats TAP stream into `Stats`. Every test name is untrusted text; `clean` +and `md` are the only routes from the log to Markdown or JSON. + +Result-line formats the pinned bats-core emits with --timing (ADR-0025): + + ok 1 name in 123ms raw stream: the `cat` formatter, i.e. any + not ok 2 name in 4ms # timeout after 5s plain `bats --timing` run, `--jobs`, and + ok 3 name in 6ms # skip reason the xargs fallback in test-acq-bats + ok 1 name # in 123 ms bats-format-tap: used when a report + not ok 2 name # in 4 ms # timeout after 5 s formatter is requested + ok 3 name # skip reason skipped tests carry no timing here + +The duration and timeout markers are matched only at the end of the line, so a +test name that merely contains "in 5ms" is not mistaken for a duration. +""" + +import calendar +import heapq +import os +import re +import time +import unicodedata + +TOP_TESTS = 15 +TOP_FILES = 10 +MAX_FAILED_SHOWN = 20 +JSON_MAX_TESTS = 200 +MAX_LINE = 4096 +MAX_NAME = 160 +UNMAPPED = "(unmapped)" +AMBIGUOUS = "(ambiguous name)" + +ANSI_RE = re.compile(r"\x1b\[[0-9;]*[A-Za-z]") +STAMP_RE = re.compile(r"^(\d{4}-\d\d-\d\dT\d\d:\d\d:\d\d)(\.\d+)?Z ") +RESULT_RE = re.compile( + r"^(?Pnot )?ok (?P\d+) (?P.*?)" + r"(?: (?:# in (?P\d{1,9}) ms|in (?P\d{1,9})ms))?" + r"(?: # timeout after \d{1,9} ?s)?" + r"(?P # (?:skip|SKIP|todo|TODO)\b.*)?$" +) +SKIP_RE = re.compile(r" # (?:skip|SKIP)\b") +PLAN_RE = re.compile(r"^1\.\.(\d+)$") +WORKERS_RE = re.compile(r"test-acq-bats: workers=(\d+)\b") +TEST_DECL_RE = re.compile(r"^\s*@test\s+(.*[^\s])\s+\{") +SHARD_RE = re.compile(r"[^A-Za-z0-9._-]") + + + +class Note(Exception): + """A user-facing, fixed-text problem (never carries untrusted text).""" + + + +def parse_stamp(line): + m = STAMP_RE.match(line) + if not m: + return None + try: + return calendar.timegm(time.strptime(m.group(1), "%Y-%m-%dT%H:%M:%S")) + ( + float(m.group(2)) if m.group(2) else 0.0 + ) + except (ValueError, OverflowError): + return None + + +def clean(text, limit=MAX_NAME): + out = [] + for ch in text: + # Control, format (bidi/zero-width), line/paragraph separators, surrogates. + bad = unicodedata.category(ch) in ("Cc", "Cf", "Cs", "Co", "Cn", "Zl", "Zp") + out.append(" " if bad else ch) + s = "".join(out).strip() + return s if len(s) <= limit else s[: limit - 1] + "\u2026" + + +_MD_ESC = {"&": "&", "<": "<", ">": ">", "|": "|"} +_MD_BACKSLASH = set("\\`*_[]~") +_ZWSP = "\u200b" # breaks GFM autolinks/mentions/math; inserted after these +_MD_BREAK_AFTER = set("@#$") + + +def md(text, limit=MAX_NAME): + out = [] + for ch in clean(text, limit): + if ch in _MD_ESC: + out.append(_MD_ESC[ch]) + elif ch in _MD_BACKSLASH: + out.append("\\" + ch) + elif ch in _MD_BREAK_AFTER: + out.append(ch + _ZWSP) + else: + out.append(ch) + return "".join(out).replace("://", ":" + _ZWSP + "//").replace("www.", "www" + _ZWSP + ".") + + +def unquote_test_name(expr): + if len(expr) >= 2 and expr[0] == expr[-1] == '"': + return re.sub(r'\\(["\\$`])', r"\1", expr[1:-1]) + if len(expr) >= 2 and expr[0] == expr[-1] == "'": + return expr[1:-1] + return expr + + +def load_name_map(tests_dir): + """Map test name -> sorted list of .bats basenames declaring it.""" + names = {} + try: + entries = sorted(os.listdir(tests_dir)) + except OSError: + return names + for entry in entries: + if not entry.endswith(".bats"): + continue + try: + with open(os.path.join(tests_dir, entry), encoding="utf-8", errors="replace") as fh: + for line in fh: + m = TEST_DECL_RE.match(line) + if m: + files = names.setdefault(unquote_test_name(m.group(1)), []) + if entry not in files: + files.append(entry) + except OSError: + continue + return names + +class Stats: + def __init__(self, name_map): + self.name_map = name_map + self.passed = self.failed = self.skipped = self.untimed = 0 + self.planned = 0 + self.sum_ms = 0 + self.workers = None + self.slow = [] # min-heap of (ms, -seq, name, file, status) + self.files = {} # file -> [tests, ms, max_ms] + self.failed_names = [] + self.seq = 0 + self.first_stamp = self.last_stamp = self.workers_stamp = None + + def file_for(self, name): + cands = self.name_map.get(name) + if not cands: + return UNMAPPED + return cands[0] if len(cands) == 1 else AMBIGUOUS + + def add_result(self, failed, name, ms, skipped): + file = self.file_for(name) + if skipped: + self.skipped += 1 + elif failed: + self.failed += 1 + if len(self.failed_names) < MAX_FAILED_SHOWN: + self.failed_names.append((name, file)) + else: + self.passed += 1 + entry = self.files.setdefault(file, [0, 0, 0]) + entry[0] += 1 + if ms is None: + self.untimed += 1 + return + if skipped: + return + self.sum_ms += ms + entry[1] += ms + entry[2] = max(entry[2], ms) + self.seq += 1 + item = (ms, -self.seq, name, file, "not ok" if failed else "ok") + if len(self.slow) < JSON_MAX_TESTS: + heapq.heappush(self.slow, item) + elif item > self.slow[0]: + heapq.heapreplace(self.slow, item) + + @property + def total(self): + return self.passed + self.failed + self.skipped + + @property + def timed(self): + return self.total - self.untimed + + +def consume(stream, stats): + while True: + raw = stream.readline(MAX_LINE) + if not raw: + break + while len(raw) == MAX_LINE and not raw.endswith("\n"): + chunk = stream.readline(MAX_LINE) # drop the rest of an over-long line + if not chunk or chunk.endswith("\n"): + break + consume_line(ANSI_RE.sub("", raw).rstrip("\r\n"), stats) + + +def consume_line(line, stats): + stamp = parse_stamp(line) + body = STAMP_RE.sub("", line, count=1) if stamp is not None else line + m = WORKERS_RE.search(body) + if m and stats.workers is None: + stats.workers = int(m.group(1)) + stats.workers_stamp = stamp + m = PLAN_RE.match(body) + if m: + stats.planned += int(m.group(1)) + if stamp is not None and stats.first_stamp is None: + stats.first_stamp = stamp + return + m = RESULT_RE.match(body) + if not m: + return + ms = m.group("fmt_ms") if m.group("fmt_ms") is not None else m.group("raw_ms") + stats.add_result( + bool(m.group("not")), + m.group("name"), + None if ms is None else int(ms), + bool(m.group("skip") and SKIP_RE.match(m.group("skip"))), + ) + if stamp is not None: + if stats.first_stamp is None: + stats.first_stamp = stamp + stats.last_stamp = stamp diff --git a/scripts/bats_timing_render.py b/scripts/bats_timing_render.py new file mode 100644 index 00000000..c8ddfdf5 --- /dev/null +++ b/scripts/bats_timing_render.py @@ -0,0 +1,166 @@ +"""Rendering half of summarize-bats-timing (Python 3 stdlib only). + +Builds the Markdown summary and JSON record from `Stats`. Names reach the output +only through `md` and `clean`; the one workflow command is built from numbers. +""" + +import os +import time + +from bats_timing_core import AMBIGUOUS, TOP_FILES, TOP_TESTS, UNMAPPED, clean, md + + +def fmt_ms(ms): + if ms < 1000: + return "%dms" % ms + return fmt_secs(ms / 1000.0, tenths=True) + + +def fmt_secs(secs, tenths=False): + if secs < 60: + return "%.1fs" % secs if tenths or secs < 10 else "%ds" % round(secs) + secs = int(round(secs)) + return "%dm %02ds" % (secs // 60, secs % 60) + + +def read_epoch(path): + try: + with open(path, encoding="ascii") as fh: + return float(fh.read(64).strip()) + except (OSError, ValueError): + return None + + +def wall_seconds(args, stats): + if args.wall_seconds is not None: + return args.wall_seconds + if args.start_epoch_file and args.log and args.log != "-": + start = read_epoch(args.start_epoch_file) + try: + end = os.stat(args.log).st_mtime + except OSError: + end = None + if stats.planned and stats.total < stats.planned: + # Incomplete run (cancelled or timed out): the last write understates + # how long the suite ran before it was killed; elapsed-until-now does not. + end = time.time() + if start is not None and end is not None and end >= start: + return end - start + if stats.last_stamp is not None: + begin = stats.workers_stamp if stats.workers_stamp is not None else stats.first_stamp + if begin is not None and stats.last_stamp >= begin: + return stats.last_stamp - begin + return None + + +def render(args, stats, wall, shard, notes): + lines = ["## bats timing (shard: %s)" % shard, ""] + lines.extend(notes) + if notes: + lines.append("") + if stats.total == 0: + lines.append("No bats test results were found in the log.") + return lines + lines.extend(["| Metric | Value |", "| --- | --- |"]) + lines.append( + "| Tests reported | %d (%d passed, %d failed, %d skipped) |" + % (stats.total, stats.passed, stats.failed, stats.skipped) + ) + if stats.planned and stats.total < stats.planned: + lines.append( + "| Run incomplete | %d of %d planned tests reported (cancelled, timed out or crashed?) |" + % (stats.total, stats.planned) + ) + if stats.timed == 0: + return lines + untimed_section() + failed_section(stats) + lines.extend(metric_rows(args, stats, wall)) + return lines + slowest_tables(stats) + failed_section(stats) + + +def untimed_section(): + return [ + "| Timing | none |", + "", + "No per-test timings were present (`in Nms` suffixes). " + "Run the suite with `ACQ_BATS_TIMING=1` to get slowest-test and slowest-file tables.", + ] + + +def metric_rows(args, stats, wall): + rows = ["| Summed test time | %s (setup and teardown included) |" % fmt_secs(stats.sum_ms / 1000.0, True)] + if wall is not None and wall > 0: + par = "%s wall" % fmt_secs(wall, True) + par += ", %.1fx parallel" % (stats.sum_ms / 1000.0 / wall) + if stats.workers: + par += " (%d workers)" % stats.workers + rows.append("| Suite wall time | %s |" % par) + else: + rows.append("| Suite wall time | unknown |") + if args.timeout_minutes: + rows.append(margin_row(args.timeout_minutes, wall)) + unmapped = sum(v[0] for k, v in stats.files.items() if k in (UNMAPPED, AMBIGUOUS)) + if unmapped: + rows.append("| Tests not attributable to a file | %d |" % unmapped) + return rows + + +def margin_row(timeout_minutes, wall): + limit = timeout_minutes * 60.0 + if wall is not None and wall > 0 and limit > 0: + return ( + "| Margin to %g min job timeout | %s left, suite used %.0f%% (suite only; checkout, setup and bash build also count) |" + % (timeout_minutes, fmt_secs(max(limit - wall, 0)), 100.0 * wall / limit) + ) + return "| Margin to %g min job timeout | unknown (no wall time) |" % timeout_minutes + + +def slowest_tables(stats): + ranked = sorted(stats.slow, reverse=True)[:TOP_TESTS] + lines = ["", "### Slowest %d tests" % len(ranked), "", "| # | Time | File | Test |", "| ---: | ---: | --- | --- |"] + for i, (ms, _seq, name, file, _st) in enumerate(ranked, 1): + lines.append("| %d | %s | %s | %s |" % (i, fmt_ms(ms), md(file), md(name))) + files = sorted(stats.files.items(), key=lambda kv: (-kv[1][1], kv[0]))[:TOP_FILES] + lines += ["", "### Slowest %d files (summed test time)" % len(files), "", + "| # | File | Tests | Total | Slowest test |", "| ---: | --- | ---: | ---: | ---: |"] + for i, (file, (n, ms, mx)) in enumerate(files, 1): + lines.append("| %d | %s | %d | %s | %s |" % (i, md(file), n, fmt_ms(ms), fmt_ms(mx))) + return lines + + +def failed_section(stats): + if not stats.failed: + return [] + out = ["", "### Failed tests", ""] + for name, file in stats.failed_names: + out.append("- %s: %s" % (md(file), md(name))) + if stats.failed > len(stats.failed_names): + out.append("- ... and %d more" % (stats.failed - len(stats.failed_names))) + return out + + +def build_json(args, stats, wall, shard): + limit = args.timeout_minutes * 60.0 if args.timeout_minutes else None + return { + "schema": 1, + "shard": shard, + "generated_at": int(time.time()), + "tests": stats.total, + "passed": stats.passed, + "failed": stats.failed, + "skipped": stats.skipped, + "planned": stats.planned, + "timed": stats.timed, + "sum_ms": stats.sum_ms, + "wall_seconds": None if wall is None else round(wall, 3), + "workers": stats.workers, + "timeout_minutes": args.timeout_minutes, + "wall_fraction": None if (wall is None or not limit) else round(wall / limit, 4), + "files": [ + {"file": clean(f), "tests": v[0], "ms": v[1], "max_ms": v[2]} + for f, v in sorted(stats.files.items(), key=lambda kv: (-kv[1][1], kv[0])) + ], + "slowest_tests": [ + {"ms": ms, "file": clean(file), "name": clean(name), "status": st} + for ms, _s, name, file, st in sorted(stats.slow, reverse=True) + ], + } diff --git a/scripts/summarize-bats-timing b/scripts/summarize-bats-timing index adc70abb..b33b49c9 100755 --- a/scripts/summarize-bats-timing +++ b/scripts/summarize-bats-timing @@ -2,7 +2,7 @@ """Summarize bats `--timing` TAP output as Markdown plus a JSON record. Reads the TAP stream scripts/test-acq-bats prints when ACQ_BATS_TIMING=1 -(`ok N in Xms`), from a file or stdin, and reports the slowest tests, +(`ok N in Xms` or `ok N # in X ms`), from a file or stdin, and reports the slowest tests, the slowest files, and the margin to the CI job timeout, so a slowdown is visible long before it hits the timeout. Python 3 standard library only. @@ -24,342 +24,15 @@ Usage: """ import argparse -import heapq -import calendar import json import math import os -import re import sys -import time -import unicodedata -TOP_TESTS = 15 -TOP_FILES = 10 -MAX_FAILED_SHOWN = 20 -JSON_MAX_TESTS = 200 -MAX_LINE = 4096 -MAX_NAME = 160 -UNMAPPED = "(unmapped)" -AMBIGUOUS = "(ambiguous name)" +sys.dont_write_bytecode = True # keep __pycache__ out of scripts/ -ANSI_RE = re.compile(r"\x1b\[[0-9;]*[A-Za-z]") -STAMP_RE = re.compile(r"^(\d{4}-\d\d-\d\dT\d\d:\d\d:\d\d)(\.\d+)?Z ") -RESULT_RE = re.compile( - r"^(not )?ok (\d+) (.*?)(?: in (\d{1,9})ms)?(?: # (?:skip|SKIP|todo|TODO)\b.*)?$" -) -SKIP_RE = re.compile(r" # (?:skip|SKIP)\b") -PLAN_RE = re.compile(r"^1\.\.(\d+)$") -WORKERS_RE = re.compile(r"test-acq-bats: workers=(\d+)\b") -TEST_DECL_RE = re.compile(r"^\s*@test\s+(.*[^\s])\s+\{") -SHARD_RE = re.compile(r"[^A-Za-z0-9._-]") - - -class Note(Exception): - """A user-facing, fixed-text problem (never carries untrusted text).""" - - -def parse_stamp(line): - m = STAMP_RE.match(line) - if not m: - return None - try: - return calendar.timegm(time.strptime(m.group(1), "%Y-%m-%dT%H:%M:%S")) + ( - float(m.group(2)) if m.group(2) else 0.0 - ) - except (ValueError, OverflowError): - return None - - -def clean(text, limit=MAX_NAME): - out = [] - for ch in text: - # Control, format (bidi/zero-width), line/paragraph separators, surrogates. - bad = unicodedata.category(ch) in ("Cc", "Cf", "Cs", "Co", "Cn", "Zl", "Zp") - out.append(" " if bad else ch) - s = "".join(out).strip() - return s if len(s) <= limit else s[: limit - 1] + "\u2026" - - -_MD_ESC = {"&": "&", "<": "<", ">": ">", "|": "|"} -_MD_BACKSLASH = set("\\`*_[]~") -_ZWSP = "\u200b" # breaks GFM autolinks/mentions/math; inserted after these -_MD_BREAK_AFTER = set("@#$") - - -def md(text, limit=MAX_NAME): - out = [] - for ch in clean(text, limit): - if ch in _MD_ESC: - out.append(_MD_ESC[ch]) - elif ch in _MD_BACKSLASH: - out.append("\\" + ch) - elif ch in _MD_BREAK_AFTER: - out.append(ch + _ZWSP) - else: - out.append(ch) - return "".join(out).replace("://", ":" + _ZWSP + "//").replace("www.", "www" + _ZWSP + ".") - - -def unquote_test_name(expr): - if len(expr) >= 2 and expr[0] == expr[-1] == '"': - return re.sub(r'\\(["\\$`])', r"\1", expr[1:-1]) - if len(expr) >= 2 and expr[0] == expr[-1] == "'": - return expr[1:-1] - return expr - - -def load_name_map(tests_dir): - """Map test name -> sorted list of .bats basenames declaring it.""" - names = {} - try: - entries = sorted(os.listdir(tests_dir)) - except OSError: - return names - for entry in entries: - if not entry.endswith(".bats"): - continue - try: - with open(os.path.join(tests_dir, entry), encoding="utf-8", errors="replace") as fh: - for line in fh: - m = TEST_DECL_RE.match(line) - if m: - files = names.setdefault(unquote_test_name(m.group(1)), []) - if entry not in files: - files.append(entry) - except OSError: - continue - return names - - -class Stats: - def __init__(self, name_map): - self.name_map = name_map - self.passed = self.failed = self.skipped = self.untimed = 0 - self.planned = 0 - self.sum_ms = 0 - self.workers = None - self.slow = [] # min-heap of (ms, -seq, name, file, status) - self.files = {} # file -> [tests, ms, max_ms] - self.failed_names = [] - self.seq = 0 - self.first_stamp = self.last_stamp = self.workers_stamp = None - - def file_for(self, name): - cands = self.name_map.get(name) - if not cands: - return UNMAPPED - return cands[0] if len(cands) == 1 else AMBIGUOUS - - def add_result(self, failed, name, ms, skipped): - file = self.file_for(name) - if skipped: - self.skipped += 1 - elif failed: - self.failed += 1 - if len(self.failed_names) < MAX_FAILED_SHOWN: - self.failed_names.append((name, file)) - else: - self.passed += 1 - entry = self.files.setdefault(file, [0, 0, 0]) - entry[0] += 1 - if ms is None: - self.untimed += 1 - return - if skipped: - return - self.sum_ms += ms - entry[1] += ms - entry[2] = max(entry[2], ms) - self.seq += 1 - item = (ms, -self.seq, name, file, "not ok" if failed else "ok") - if len(self.slow) < JSON_MAX_TESTS: - heapq.heappush(self.slow, item) - elif item > self.slow[0]: - heapq.heapreplace(self.slow, item) - - @property - def total(self): - return self.passed + self.failed + self.skipped - - @property - def timed(self): - return self.total - self.untimed - - -def consume(stream, stats): - while True: - raw = stream.readline(MAX_LINE) - if not raw: - break - while len(raw) == MAX_LINE and not raw.endswith("\n"): - chunk = stream.readline(MAX_LINE) # drop the rest of an over-long line - if not chunk or chunk.endswith("\n"): - break - line = ANSI_RE.sub("", raw).rstrip("\r\n") - stamp = parse_stamp(line) - body = STAMP_RE.sub("", line, count=1) if stamp is not None else line - m = WORKERS_RE.search(body) - if m and stats.workers is None: - stats.workers = int(m.group(1)) - stats.workers_stamp = stamp - m = PLAN_RE.match(body) - if m: - stats.planned += int(m.group(1)) - if stamp is not None and stats.first_stamp is None: - stats.first_stamp = stamp - continue - m = RESULT_RE.match(body) - if not m: - continue - ms = int(m.group(4)) if m.group(4) is not None else None - stats.add_result(bool(m.group(1)), m.group(3), ms, bool(SKIP_RE.search(body))) - if stamp is not None: - if stats.first_stamp is None: - stats.first_stamp = stamp - stats.last_stamp = stamp - - -def fmt_ms(ms): - if ms < 1000: - return "%dms" % ms - return fmt_secs(ms / 1000.0, tenths=True) - - -def fmt_secs(secs, tenths=False): - if secs < 60: - return "%.1fs" % secs if tenths or secs < 10 else "%ds" % round(secs) - secs = int(round(secs)) - return "%dm %02ds" % (secs // 60, secs % 60) - - -def read_epoch(path): - try: - with open(path, encoding="ascii") as fh: - return float(fh.read(64).strip()) - except (OSError, ValueError): - return None - - -def wall_seconds(args, stats): - if args.wall_seconds is not None: - return args.wall_seconds - if args.start_epoch_file and args.log and args.log != "-": - start = read_epoch(args.start_epoch_file) - try: - end = os.stat(args.log).st_mtime - except OSError: - end = None - if stats.planned and stats.total < stats.planned: - # Incomplete run (cancelled or timed out): the last write understates - # how long the suite ran before it was killed; elapsed-until-now does not. - end = time.time() - if start is not None and end is not None and end >= start: - return end - start - if stats.last_stamp is not None: - begin = stats.workers_stamp if stats.workers_stamp is not None else stats.first_stamp - if begin is not None and stats.last_stamp >= begin: - return stats.last_stamp - begin - return None - - -def render(args, stats, wall, shard, notes): - lines = ["## bats timing (shard: %s)" % shard, ""] - lines.extend(notes) - if notes: - lines.append("") - if stats.total == 0: - lines.append("No bats test results were found in the log.") - return lines - lines.append("| Metric | Value |") - lines.append("| --- | --- |") - lines.append( - "| Tests reported | %d (%d passed, %d failed, %d skipped) |" - % (stats.total, stats.passed, stats.failed, stats.skipped) - ) - if stats.planned and stats.total < stats.planned: - lines.append( - "| Run incomplete | %d of %d planned tests reported (cancelled, timed out or crashed?) |" - % (stats.total, stats.planned) - ) - if stats.timed == 0: - lines.append("| Timing | none |") - lines.append("") - lines.append( - "No per-test timings were present (`in Nms` suffixes). " - "Run the suite with `ACQ_BATS_TIMING=1` to get slowest-test and slowest-file tables." - ) - return lines + failed_section(stats) - lines.append("| Summed test time | %s (setup and teardown included) |" % fmt_secs(stats.sum_ms / 1000.0, True)) - if wall is not None and wall > 0: - par = "%s wall" % fmt_secs(wall, True) - par += ", %.1fx parallel" % (stats.sum_ms / 1000.0 / wall) - if stats.workers: - par += " (%d workers)" % stats.workers - lines.append("| Suite wall time | %s |" % par) - else: - lines.append("| Suite wall time | unknown |") - if args.timeout_minutes: - limit = args.timeout_minutes * 60.0 - if wall is not None and wall > 0 and limit > 0: - lines.append( - "| Margin to %g min job timeout | %s left, suite used %.0f%% (suite only; checkout, setup and bash build also count) |" - % (args.timeout_minutes, fmt_secs(max(limit - wall, 0)), 100.0 * wall / limit) - ) - else: - lines.append("| Margin to %g min job timeout | unknown (no wall time) |" % args.timeout_minutes) - unmapped = sum(v[0] for k, v in stats.files.items() if k in (UNMAPPED, AMBIGUOUS)) - if unmapped: - lines.append("| Tests not attributable to a file | %d |" % unmapped) - ranked = sorted(stats.slow, reverse=True)[:TOP_TESTS] - lines += ["", "### Slowest %d tests" % len(ranked), "", "| # | Time | File | Test |", "| ---: | ---: | --- | --- |"] - for i, (ms, _seq, name, file, _st) in enumerate(ranked, 1): - lines.append("| %d | %s | %s | %s |" % (i, fmt_ms(ms), md(file), md(name))) - files = sorted(stats.files.items(), key=lambda kv: (-kv[1][1], kv[0]))[:TOP_FILES] - lines += ["", "### Slowest %d files (summed test time)" % len(files), "", - "| # | File | Tests | Total | Slowest test |", "| ---: | --- | ---: | ---: | ---: |"] - for i, (file, (n, ms, mx)) in enumerate(files, 1): - lines.append("| %d | %s | %d | %s | %s |" % (i, md(file), n, fmt_ms(ms), fmt_ms(mx))) - return lines + failed_section(stats) - - -def failed_section(stats): - if not stats.failed: - return [] - out = ["", "### Failed tests", ""] - for name, file in stats.failed_names: - out.append("- %s: %s" % (md(file), md(name))) - if stats.failed > len(stats.failed_names): - out.append("- ... and %d more" % (stats.failed - len(stats.failed_names))) - return out - - -def build_json(args, stats, wall, shard): - limit = args.timeout_minutes * 60.0 if args.timeout_minutes else None - return { - "schema": 1, - "shard": shard, - "generated_at": int(time.time()), - "tests": stats.total, - "passed": stats.passed, - "failed": stats.failed, - "skipped": stats.skipped, - "planned": stats.planned, - "timed": stats.timed, - "sum_ms": stats.sum_ms, - "wall_seconds": None if wall is None else round(wall, 3), - "workers": stats.workers, - "timeout_minutes": args.timeout_minutes, - "wall_fraction": None if (wall is None or not limit) else round(wall / limit, 4), - "files": [ - {"file": clean(f), "tests": v[0], "ms": v[1], "max_ms": v[2]} - for f, v in sorted(stats.files.items(), key=lambda kv: (-kv[1][1], kv[0])) - ], - "slowest_tests": [ - {"ms": ms, "file": clean(file), "name": clean(name), "status": st} - for ms, _s, name, file, st in sorted(stats.slow, reverse=True) - ], - } +from bats_timing_core import SHARD_RE, Note, Stats, clean, consume, load_name_map # noqa: E402 +from bats_timing_render import build_json, fmt_secs, render, wall_seconds # noqa: E402 def write_text(path, text, append): diff --git a/test/bats/155-summarize-bats-timing.bats b/test/bats/155-summarize-bats-timing.bats index 7a627b4c..072d3660 100644 --- a/test/bats/155-summarize-bats-timing.bats +++ b/test/bats/155-summarize-bats-timing.bats @@ -294,3 +294,106 @@ EOF refute_output --partial 'www.evil' refute_output --partial '@someone' } + +# --- real bats output ------------------------------------------------------- +# The fixtures under test/bats/fixtures are trimmed captures from the pinned +# bats-core (test/vendor/bats-core) so the parser is checked against what bats +# really prints, not against syntax this file invented. The live tests below +# re-capture the same streams so a bats bump cannot silently break the parser. + +FIXTURES="$BATS_TEST_DIRNAME/fixtures" + +real_tests_dir() { + local t='@test' + printf '%s "fast one" { true; }\n%s "name with in 5ms inside" { true; }\n' "$t" "$t" > "$TESTS/60-real.bats" + printf '%s "skipped one" { true; }\n%s "bare skip" { true; }\n%s "fails" { true; }\n%s "slow one" { true; }\n' "$t" "$t" "$t" "$t" >> "$TESTS/60-real.bats" +} + +@test "summarize: parses the raw bats --timing stream (in Nms)" { + real_tests_dir + run summarize --log "$FIXTURES/bats-raw-timing.tap" --wall-seconds 10 + assert_success + assert_output --partial 'Tests reported | 6 (2 passed, 2 failed, 2 skipped)' + assert_output --partial 'Summed test time | 1.1s' + assert_output --partial '| 1 | 1.1s | 60-real.bats | slow one |' + assert_output --partial '| 60-real.bats | 6 |' + refute_output --partial 'No per-test timings' + refute_output --partial '(unmapped)' +} + +@test "summarize: parses the bats-format-tap stream (# in N ms, # timeout after N s)" { + real_tests_dir + run summarize --log "$FIXTURES/bats-formatter-tap-timing.tap" --wall-seconds 10 + assert_success + assert_output --partial 'Tests reported | 6 (2 passed, 2 failed, 2 skipped)' + assert_output --partial 'Summed test time | 1.1s' + assert_output --partial '| 1 | 1.0s | 60-real.bats | slow one |' + refute_output --partial 'No per-test timings' + refute_output --partial '(unmapped)' +} + +@test "summarize: a test name containing 'in 5ms' keeps its full name in both formats" { + real_tests_dir + printf '1..1\nok 1 name with in 5ms inside in 19ms\n' > "$W/a.tap" + printf '1..1\nok 1 name with in 5ms inside # in 28 ms\n' > "$W/b.tap" + printf '1..1\nok 1 name with in 5ms inside\n' > "$W/c.tap" + run summarize --log "$W/a.tap" --json "$W/a.json" + assert_output --partial '| name with in 5ms inside |' + run summarize --log "$W/b.tap" + assert_output --partial '| name with in 5ms inside |' + assert_output --partial '| 1 | 28ms | 60-real.bats | name with in 5ms inside |' + run summarize --log "$W/c.tap" + assert_output --partial 'No per-test timings' +} + +# Run the pinned bats from a clean environment: this file already runs inside +# bats, whose BATS_* variables would otherwise leak into the inner run. +inner_bats() { + env -i PATH="$PATH" HOME="$W" TMPDIR="$W" "$@" +} + +make_tiny_suite() { + local t='@test' + mkdir -p "$W/tiny" + printf '%s "tiny pass in 5ms" { sleep 0.01; }\n%s "tiny skip" { skip "why"; }\n%s "tiny fail" { false; }\n' \ + "$t" "$t" "$t" > "$W/tiny/tiny.bats" +} + +@test "summarize: live pinned bats --timing output (raw and formatter) is understood" { + make_tiny_suite + local bats="$REPO_ROOT/test/vendor/bats-core/bin/bats" + inner_bats "$bats" --timing "$W/tiny/tiny.bats" > "$W/live-raw.tap" 2>&1 || true + inner_bats "$bats" --timing --tap --report-formatter tap -o "$W" "$W/tiny/tiny.bats" > "$W/live-fmt.tap" 2>&1 || true + local f + for f in live-raw live-fmt; do + run summarize --log "$W/$f.tap" --tests-dir "$W/tiny" --json "$W/$f.json" + assert_success + assert_output --partial 'Tests reported | 3 (1 passed, 1 failed, 1 skipped)' + refute_output --partial 'No per-test timings' + refute_output --partial '(unmapped)' + run python3 -c 'import json,sys; d=json.load(open(sys.argv[1])); sys.exit(0 if d["timed"] >= 2 and d["sum_ms"] > 0 else 1)' "$W/$f.json" + assert_success + done +} + +@test "summarize: live scripts/test-acq-bats output (explicit file and whole-suite runner) is understood" { + make_tiny_suite + local root="$W/runner" + mkdir -p "$root/scripts" "$root/test/vendor" "$root/test/bats" + cp "$REPO_ROOT/scripts/test-acq-bats" "$root/scripts/test-acq-bats" + ln -s "$REPO_ROOT/test/vendor/bats-core" "$root/test/vendor/bats-core" + cp "$W/tiny/tiny.bats" "$root/test/bats/a-tiny.bats" + sed 's/tiny/other/g' "$W/tiny/tiny.bats" > "$root/test/bats/b-other.bats" + inner_bats ACQ_BATS_TIMING=1 bash "$root/scripts/test-acq-bats" "$root/test/bats/a-tiny.bats" > "$W/run-file.log" 2>&1 || true + inner_bats ACQ_BATS_TIMING=1 ACQ_BATS_JOBS=2 bash "$root/scripts/test-acq-bats" > "$W/run-suite.log" 2>&1 || true + run summarize --log "$W/run-file.log" --tests-dir "$root/test/bats" + assert_success + assert_output --partial 'Tests reported | 3 (1 passed, 1 failed, 1 skipped)' + refute_output --partial 'No per-test timings' + run summarize --log "$W/run-suite.log" --tests-dir "$root/test/bats" --wall-seconds 5 + assert_success + assert_output --partial 'Tests reported | 6 (2 passed, 2 failed, 2 skipped)' + assert_output --partial '(2 workers)' + refute_output --partial 'No per-test timings' + refute_output --partial '(unmapped)' +} diff --git a/test/bats/fixtures/bats-formatter-tap-timing.tap b/test/bats/fixtures/bats-formatter-tap-timing.tap new file mode 100644 index 00000000..90c09329 --- /dev/null +++ b/test/bats/fixtures/bats-formatter-tap-timing.tap @@ -0,0 +1,7 @@ +1..6 +ok 1 fast one # in 2 ms +ok 2 name with in 5ms inside # in 28 ms +ok 3 skipped one # skip why not +ok 4 bare skip # skip +not ok 5 fails # in 2 ms +not ok 6 slow one # in 1025 ms # timeout after 1 s diff --git a/test/bats/fixtures/bats-raw-timing.tap b/test/bats/fixtures/bats-raw-timing.tap new file mode 100644 index 00000000..12cd9894 --- /dev/null +++ b/test/bats/fixtures/bats-raw-timing.tap @@ -0,0 +1,7 @@ +1..6 +ok 1 fast one in 8ms +ok 2 name with in 5ms inside in 19ms +ok 3 skipped one in 42ms # skip why not +ok 4 bare skip in 14ms # skip +not ok 5 fails in 2ms +not ok 6 slow one in 1081ms # timeout after 1s From bd2f68d17d9c391183e74a1e1ffc25c499d156d7 Mon Sep 17 00:00:00 2001 From: Bret Mogilefsky Date: Fri, 30 Oct 2026 00:40:28 +0000 Subject: [PATCH 3/3] fix(scripts): harden summarizer load path and split live tests Address adversarial review: make the entry point exit 0 with a note when its sibling modules cannot be imported, resolve them via the real script path, mention both suffix forms in the untimed message, and move the real-output tests to 156-summarize-bats-timing-real.bats so 155 stays under 400 lines. Drop the sum_ms>0 assertion that is flaky where bats only has 1s resolution. Co-authored-by: OpenCode Agent --- scripts/bats_timing_render.py | 2 +- scripts/summarize-bats-timing | 13 +- test/bats/155-summarize-bats-timing.bats | 103 ------------- test/bats/156-summarize-bats-timing-real.bats | 142 ++++++++++++++++++ 4 files changed, 153 insertions(+), 107 deletions(-) create mode 100644 test/bats/156-summarize-bats-timing-real.bats diff --git a/scripts/bats_timing_render.py b/scripts/bats_timing_render.py index c8ddfdf5..c6fea490 100644 --- a/scripts/bats_timing_render.py +++ b/scripts/bats_timing_render.py @@ -81,7 +81,7 @@ def untimed_section(): return [ "| Timing | none |", "", - "No per-test timings were present (`in Nms` suffixes). " + "No per-test timings were present (`in Nms` or `# in N ms` suffixes). " "Run the suite with `ACQ_BATS_TIMING=1` to get slowest-test and slowest-file tables.", ] diff --git a/scripts/summarize-bats-timing b/scripts/summarize-bats-timing index b33b49c9..ca136ad7 100755 --- a/scripts/summarize-bats-timing +++ b/scripts/summarize-bats-timing @@ -30,9 +30,16 @@ import os import sys sys.dont_write_bytecode = True # keep __pycache__ out of scripts/ - -from bats_timing_core import SHARD_RE, Note, Stats, clean, consume, load_name_map # noqa: E402 -from bats_timing_render import build_json, fmt_secs, render, wall_seconds # noqa: E402 +sys.path.insert(0, os.path.dirname(os.path.realpath(__file__))) + +try: + from bats_timing_core import SHARD_RE, Note, Stats, clean, consume, load_name_map + from bats_timing_render import build_json, fmt_secs, render, wall_seconds +except BaseException as exc: # advisory tool: a broken install must not fail the job + sys.stderr.write("summarize-bats-timing: cannot load modules (%s)\n" % type(exc).__name__) + sys.stdout.write("## bats timing\n\nThe timing summary could not be produced (module load failed).\n") + sys.stdout.flush() + os._exit(0) def write_text(path, text, append): diff --git a/test/bats/155-summarize-bats-timing.bats b/test/bats/155-summarize-bats-timing.bats index 072d3660..7a627b4c 100644 --- a/test/bats/155-summarize-bats-timing.bats +++ b/test/bats/155-summarize-bats-timing.bats @@ -294,106 +294,3 @@ EOF refute_output --partial 'www.evil' refute_output --partial '@someone' } - -# --- real bats output ------------------------------------------------------- -# The fixtures under test/bats/fixtures are trimmed captures from the pinned -# bats-core (test/vendor/bats-core) so the parser is checked against what bats -# really prints, not against syntax this file invented. The live tests below -# re-capture the same streams so a bats bump cannot silently break the parser. - -FIXTURES="$BATS_TEST_DIRNAME/fixtures" - -real_tests_dir() { - local t='@test' - printf '%s "fast one" { true; }\n%s "name with in 5ms inside" { true; }\n' "$t" "$t" > "$TESTS/60-real.bats" - printf '%s "skipped one" { true; }\n%s "bare skip" { true; }\n%s "fails" { true; }\n%s "slow one" { true; }\n' "$t" "$t" "$t" "$t" >> "$TESTS/60-real.bats" -} - -@test "summarize: parses the raw bats --timing stream (in Nms)" { - real_tests_dir - run summarize --log "$FIXTURES/bats-raw-timing.tap" --wall-seconds 10 - assert_success - assert_output --partial 'Tests reported | 6 (2 passed, 2 failed, 2 skipped)' - assert_output --partial 'Summed test time | 1.1s' - assert_output --partial '| 1 | 1.1s | 60-real.bats | slow one |' - assert_output --partial '| 60-real.bats | 6 |' - refute_output --partial 'No per-test timings' - refute_output --partial '(unmapped)' -} - -@test "summarize: parses the bats-format-tap stream (# in N ms, # timeout after N s)" { - real_tests_dir - run summarize --log "$FIXTURES/bats-formatter-tap-timing.tap" --wall-seconds 10 - assert_success - assert_output --partial 'Tests reported | 6 (2 passed, 2 failed, 2 skipped)' - assert_output --partial 'Summed test time | 1.1s' - assert_output --partial '| 1 | 1.0s | 60-real.bats | slow one |' - refute_output --partial 'No per-test timings' - refute_output --partial '(unmapped)' -} - -@test "summarize: a test name containing 'in 5ms' keeps its full name in both formats" { - real_tests_dir - printf '1..1\nok 1 name with in 5ms inside in 19ms\n' > "$W/a.tap" - printf '1..1\nok 1 name with in 5ms inside # in 28 ms\n' > "$W/b.tap" - printf '1..1\nok 1 name with in 5ms inside\n' > "$W/c.tap" - run summarize --log "$W/a.tap" --json "$W/a.json" - assert_output --partial '| name with in 5ms inside |' - run summarize --log "$W/b.tap" - assert_output --partial '| name with in 5ms inside |' - assert_output --partial '| 1 | 28ms | 60-real.bats | name with in 5ms inside |' - run summarize --log "$W/c.tap" - assert_output --partial 'No per-test timings' -} - -# Run the pinned bats from a clean environment: this file already runs inside -# bats, whose BATS_* variables would otherwise leak into the inner run. -inner_bats() { - env -i PATH="$PATH" HOME="$W" TMPDIR="$W" "$@" -} - -make_tiny_suite() { - local t='@test' - mkdir -p "$W/tiny" - printf '%s "tiny pass in 5ms" { sleep 0.01; }\n%s "tiny skip" { skip "why"; }\n%s "tiny fail" { false; }\n' \ - "$t" "$t" "$t" > "$W/tiny/tiny.bats" -} - -@test "summarize: live pinned bats --timing output (raw and formatter) is understood" { - make_tiny_suite - local bats="$REPO_ROOT/test/vendor/bats-core/bin/bats" - inner_bats "$bats" --timing "$W/tiny/tiny.bats" > "$W/live-raw.tap" 2>&1 || true - inner_bats "$bats" --timing --tap --report-formatter tap -o "$W" "$W/tiny/tiny.bats" > "$W/live-fmt.tap" 2>&1 || true - local f - for f in live-raw live-fmt; do - run summarize --log "$W/$f.tap" --tests-dir "$W/tiny" --json "$W/$f.json" - assert_success - assert_output --partial 'Tests reported | 3 (1 passed, 1 failed, 1 skipped)' - refute_output --partial 'No per-test timings' - refute_output --partial '(unmapped)' - run python3 -c 'import json,sys; d=json.load(open(sys.argv[1])); sys.exit(0 if d["timed"] >= 2 and d["sum_ms"] > 0 else 1)' "$W/$f.json" - assert_success - done -} - -@test "summarize: live scripts/test-acq-bats output (explicit file and whole-suite runner) is understood" { - make_tiny_suite - local root="$W/runner" - mkdir -p "$root/scripts" "$root/test/vendor" "$root/test/bats" - cp "$REPO_ROOT/scripts/test-acq-bats" "$root/scripts/test-acq-bats" - ln -s "$REPO_ROOT/test/vendor/bats-core" "$root/test/vendor/bats-core" - cp "$W/tiny/tiny.bats" "$root/test/bats/a-tiny.bats" - sed 's/tiny/other/g' "$W/tiny/tiny.bats" > "$root/test/bats/b-other.bats" - inner_bats ACQ_BATS_TIMING=1 bash "$root/scripts/test-acq-bats" "$root/test/bats/a-tiny.bats" > "$W/run-file.log" 2>&1 || true - inner_bats ACQ_BATS_TIMING=1 ACQ_BATS_JOBS=2 bash "$root/scripts/test-acq-bats" > "$W/run-suite.log" 2>&1 || true - run summarize --log "$W/run-file.log" --tests-dir "$root/test/bats" - assert_success - assert_output --partial 'Tests reported | 3 (1 passed, 1 failed, 1 skipped)' - refute_output --partial 'No per-test timings' - run summarize --log "$W/run-suite.log" --tests-dir "$root/test/bats" --wall-seconds 5 - assert_success - assert_output --partial 'Tests reported | 6 (2 passed, 2 failed, 2 skipped)' - assert_output --partial '(2 workers)' - refute_output --partial 'No per-test timings' - refute_output --partial '(unmapped)' -} diff --git a/test/bats/156-summarize-bats-timing-real.bats b/test/bats/156-summarize-bats-timing-real.bats new file mode 100644 index 00000000..04bafe5c --- /dev/null +++ b/test/bats/156-summarize-bats-timing-real.bats @@ -0,0 +1,142 @@ +#!/usr/bin/env bats +# +# 156-summarize-bats-timing-real.bats — checks scripts/summarize-bats-timing against +# what the pinned bats-core really prints with --timing: trimmed captures under +# test/bats/fixtures plus live runs of bats and scripts/test-acq-bats. The +# hand-written TAP in 155-summarize-bats-timing.bats cannot catch a parser that +# disagrees with the real formatter, so this file exists to make that impossible. +# +# shellcheck shell=bats + +load 'helper' + +setup() { + command -v python3 >/dev/null 2>&1 || skip "python3 unavailable" + SUMMARIZE="$REPO_ROOT/scripts/summarize-bats-timing" + W="$BATS_TEST_TMPDIR" + TESTS="$W/tests" + mkdir -p "$TESTS" +} + +summarize() { python3 "$SUMMARIZE" --tests-dir "$TESTS" "$@"; } + +# The fixtures under test/bats/fixtures are trimmed captures from the pinned +# bats-core (test/vendor/bats-core) so the parser is checked against what bats +# really prints, not against syntax this file invented. The live tests below +# re-capture the same streams so a bats bump cannot silently break the parser. + +FIXTURES="$BATS_TEST_DIRNAME/fixtures" + +real_tests_dir() { + local t='@test' + printf '%s "fast one" { true; }\n%s "name with in 5ms inside" { true; }\n' "$t" "$t" > "$TESTS/60-real.bats" + printf '%s "skipped one" { true; }\n%s "bare skip" { true; }\n%s "fails" { true; }\n%s "slow one" { true; }\n' "$t" "$t" "$t" "$t" >> "$TESTS/60-real.bats" +} + +@test "summarize: parses the raw bats --timing stream (in Nms)" { + real_tests_dir + run summarize --log "$FIXTURES/bats-raw-timing.tap" --wall-seconds 10 + assert_success + assert_output --partial 'Tests reported | 6 (2 passed, 2 failed, 2 skipped)' + assert_output --partial 'Summed test time | 1.1s' + assert_output --partial '| 1 | 1.1s | 60-real.bats | slow one |' + assert_output --partial '| 60-real.bats | 6 |' + refute_output --partial 'No per-test timings' + refute_output --partial '(unmapped)' +} + +@test "summarize: parses the bats-format-tap stream (# in N ms, # timeout after N s)" { + real_tests_dir + run summarize --log "$FIXTURES/bats-formatter-tap-timing.tap" --wall-seconds 10 + assert_success + assert_output --partial 'Tests reported | 6 (2 passed, 2 failed, 2 skipped)' + assert_output --partial 'Summed test time | 1.1s' + assert_output --partial '| 1 | 1.0s | 60-real.bats | slow one |' + refute_output --partial 'No per-test timings' + refute_output --partial '(unmapped)' +} + +@test "summarize: a test name containing 'in 5ms' keeps its full name in both formats" { + real_tests_dir + printf '1..1\nok 1 name with in 5ms inside in 19ms\n' > "$W/a.tap" + printf '1..1\nok 1 name with in 5ms inside # in 28 ms\n' > "$W/b.tap" + printf '1..1\nok 1 name with in 5ms inside\n' > "$W/c.tap" + run summarize --log "$W/a.tap" + assert_output --partial '| name with in 5ms inside |' + run summarize --log "$W/b.tap" + assert_output --partial '| name with in 5ms inside |' + assert_output --partial '| 1 | 28ms | 60-real.bats | name with in 5ms inside |' + run summarize --log "$W/c.tap" + assert_output --partial 'No per-test timings' +} + +# Run the pinned bats from a clean environment: this file already runs inside +# bats, whose BATS_* variables would otherwise leak into the inner run. +inner_bats() { + env -i PATH="$PATH" HOME="$W" TMPDIR="$W" "$@" +} + +make_tiny_suite() { + local t='@test' + mkdir -p "$W/tiny" + printf '%s "tiny pass in 5ms" { sleep 0.01; }\n%s "tiny skip" { skip "why"; }\n%s "tiny fail" { false; }\n' \ + "$t" "$t" "$t" > "$W/tiny/tiny.bats" +} + +@test "summarize: live pinned bats --timing output (raw and formatter) is understood" { + make_tiny_suite + local bats="$REPO_ROOT/test/vendor/bats-core/bin/bats" + inner_bats "$bats" --timing "$W/tiny/tiny.bats" > "$W/live-raw.tap" 2>&1 || true + inner_bats "$bats" --timing --tap --report-formatter tap -o "$W" "$W/tiny/tiny.bats" > "$W/live-fmt.tap" 2>&1 || true + local f + for f in live-raw live-fmt; do + run summarize --log "$W/$f.tap" --tests-dir "$W/tiny" --json "$W/$f.json" + assert_success + assert_output --partial 'Tests reported | 3 (1 passed, 1 failed, 1 skipped)' + refute_output --partial 'No per-test timings' + refute_output --partial '(unmapped)' + run python3 -c 'import json,sys; d=json.load(open(sys.argv[1])); sys.exit(0 if d["timed"] >= 2 else 1)' "$W/$f.json" + assert_success + done +} + +@test "summarize: live scripts/test-acq-bats output (explicit file and whole-suite runner) is understood" { + make_tiny_suite + local root="$W/runner" + mkdir -p "$root/scripts" "$root/test/vendor" "$root/test/bats" + cp "$REPO_ROOT/scripts/test-acq-bats" "$root/scripts/test-acq-bats" + ln -s "$REPO_ROOT/test/vendor/bats-core" "$root/test/vendor/bats-core" + cp "$W/tiny/tiny.bats" "$root/test/bats/a-tiny.bats" + sed 's/tiny/other/g' "$W/tiny/tiny.bats" > "$root/test/bats/b-other.bats" + inner_bats ACQ_BATS_TIMING=1 bash "$root/scripts/test-acq-bats" "$root/test/bats/a-tiny.bats" > "$W/run-file.log" 2>&1 || true + inner_bats ACQ_BATS_TIMING=1 ACQ_BATS_JOBS=2 bash "$root/scripts/test-acq-bats" > "$W/run-suite.log" 2>&1 || true + run summarize --log "$W/run-file.log" --tests-dir "$root/test/bats" + assert_success + assert_output --partial 'Tests reported | 3 (1 passed, 1 failed, 1 skipped)' + refute_output --partial 'No per-test timings' + run summarize --log "$W/run-suite.log" --tests-dir "$root/test/bats" --wall-seconds 5 + assert_success + assert_output --partial 'Tests reported | 6 (2 passed, 2 failed, 2 skipped)' + assert_output --partial '(2 workers)' + refute_output --partial 'No per-test timings' + refute_output --partial '(unmapped)' +} + +@test "summarize: near-miss duration suffixes are part of the name, never a timing" { + local variant + for variant in 'x in 5 ms' 'x # in 5 ms ' 'x in 5ms ' 'x in -5ms'; do + printf '1..1\nok 1 %s\n' "$variant" > "$W/nm.tap" + run summarize --log "$W/nm.tap" + assert_success + assert_output --partial 'No per-test timings' + done +} + +@test "summarize: a broken install (missing sibling modules) still exits 0 with a note" { + mkdir -p "$W/lonely" + cp "$SUMMARIZE" "$W/lonely/summarize-bats-timing" + printf '1..1\nok 1 x in 5ms\n' > "$W/l.tap" + run python3 "$W/lonely/summarize-bats-timing" --log "$W/l.tap" + assert_success + assert_output --partial 'could not be produced' +}