diff --git a/.pre-commit-config.yaml b/.pre-commit-config.yaml index 580ddfa7..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)|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 c2e35518..62242802 100644 --- a/CONTRIBUTING.md +++ b/CONTRIBUTING.md @@ -205,6 +205,20 @@ 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`. + 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 remote transports fail locally. This covers direct provider-input discovery as 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..c6fea490 --- /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` or `# in N ms` 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 new file mode 100755 index 00000000..ca136ad7 --- /dev/null +++ b/scripts/summarize-bats-timing @@ -0,0 +1,175 @@ +#!/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` 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. + +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 json +import math +import os +import sys + +sys.dont_write_bytecode = True # keep __pycache__ out of scripts/ +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): + 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' +} 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' +} 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