From 55331a80b5488fdff06c7b134d98c33eb395f2d0 Mon Sep 17 00:00:00 2001 From: Johnathan Corgan Date: Thu, 23 Jul 2026 14:09:04 +0000 Subject: [PATCH] Gate on shell functions whose exit status is a log call's MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit A bash function returns its last command's status, so one ending in a log call returns 0 whatever it did, and a caller written as `if func` or `func || fail` has a gate that cannot fire. This tree found two in one day: run_chaos ended in record, making every chaos row unconditionally green since 2026-03-09, and build_fips_for_e2e ended in log, letting five end-to-end legs test the previous commit's binary and report green. Both were repaired one at a time. This is the rule that catches the next one. What it enforces is a contract, not a bug hunt: a function whose status a caller tests must end in an explicit return rather than leaving its success value to whatever the last log call produced. That distinction is deliberate and worth stating, because all three instances found in the tree were benign — each failure path already returned early, so the trailing echo reported a real success. Reading the function is the only way to know that, and the next edit that puts an unguarded command before the final log converts the benign shape into the defect with nothing to notice. An explicit return costs a line and makes the class unreachable. The three are given one here. Scoped on the call sites rather than the definitions, the same way check-log-strings.py scopes on what a grep reads rather than what its file mentions: 315 functions scanned, 42 end in a log call, and only the ones whose status something consumes are reported. A function that ends by reporting and is called for its output is idiomatic and is left alone. Without that scoping the finding list would be 42 long and would stop being read. Validated by construction rather than by a green run: injecting a copy of build_fips_for_e2e's exact shape — unguarded docker cp, then a log as the last statement, with a `|| { ...; return 1; }` caller — makes the checker report it and exit 1. Wired into both runners beside the parity and log-string checks. --- .github/workflows/ci.yml | 2 + testing/check-trailing-log.py | 199 ++++++++++++++++++++++++ testing/ci-local.sh | 14 ++ testing/nat/scripts/nostr-relay-test.sh | 1 + testing/nat/scripts/stun-faults-test.sh | 2 + 5 files changed, 218 insertions(+) create mode 100755 testing/check-trailing-log.py diff --git a/.github/workflows/ci.yml b/.github/workflows/ci.yml index 43e78dc..bbc5f87 100644 --- a/.github/workflows/ci.yml +++ b/.github/workflows/ci.yml @@ -63,6 +63,8 @@ jobs: run: bash testing/check-ci-parity.sh - name: Check test log matchers against the strings src/ emits run: python3 testing/check-log-strings.py + - name: Check no tested function's exit status is a log call's + run: python3 testing/check-trailing-log.py # Hermetic: synthetic ping functions, no containers, ~45s. Lives beside # the other two so both runners gate on it identically — putting it in # only one would create exactly the drift check-ci-parity.sh exists to diff --git a/testing/check-trailing-log.py b/testing/check-trailing-log.py new file mode 100755 index 0000000..eb8a5c8 --- /dev/null +++ b/testing/check-trailing-log.py @@ -0,0 +1,199 @@ +#!/usr/bin/env python3 +"""Find shell functions that end in a logging call and whose status a caller tests. + +A bash function's exit status is the status of its last command. A function +whose last statement is `echo`/`log`/`info`/... therefore returns 0 on every +path that reaches the end, and any caller written as `if func`, `func || fail` +or `func && ...` has a gate that cannot fire. + +This is not hypothetical and not a style rule. Two instances were found in one +day in this tree: + + * `run_chaos` ended in `record`, whose own last statement is an `echo`, so + every chaos row was unconditionally green from 2026-03-09. + * `build_fips_for_e2e` ended in `log`, so a failed binary extraction left the + previous run's cache in place and five end-to-end legs tested the previous + commit's code and reported green — a green run certifying software that was + never built. + +Both were repaired individually. This exists so the next one is caught by a +gate rather than by a reader. + +WHAT IT ENFORCES, stated precisely, because it is a convention and not a bug +hunt: a function whose exit status a caller tests must END WITH AN EXPLICIT +`return`. It must not leave its success value to be whatever the last logging +call happened to produce. + +That is deliberately stricter than "has a bug". Every instance in the tree when +this check was written was in fact benign -- each failure path already returned +early, so the trailing `echo` reported a genuine success. The point is that +reading the function is the only way to know that, and the next edit that adds +an unguarded command before the final log turns a benign shape into the exact +defect above with nothing to notice it. An explicit terminal `return` costs one +line and makes the class unreachable. + +WHAT IT DELIBERATELY DOES NOT FLAG: a function ending in a logging call whose +status nobody consumes. That is idiomatic and harmless — a reporting helper is +supposed to end by reporting. The defect needs both halves, and scoping on the +call sites rather than on the definitions is what keeps the finding list short +enough to stay read. Same reasoning as check-log-strings.py scoping on what a +grep reads rather than on what its file mentions. + +Exit codes: + 0 — no function has both the shape and a status-testing caller + 1 — at least one does + 2 — the checker could not run (bad tree, unreadable file) +""" + +from __future__ import annotations + +import re +import sys +from pathlib import Path + +TESTING = Path(__file__).resolve().parent + +# Commands whose exit status is always 0 in practice and which exist to print. +# `record` and `skip` are project helpers that end in `echo` themselves, so a +# function ending in one of those inherits the same problem transitively. +LOG_COMMANDS = { + "echo", "printf", "log", "info", "warn", "warning", "note", "stage", + "pass", "ok", "record", "skip", "report", "summary", "header", +} + +# Functions allowed to end in a logging call even though a caller tests them, +# each with the reason. Keep this list short: a long one means the check has +# been miscalibrated rather than satisfied. +ALLOWED: dict[str, str] = {} + +FUNC_RE = re.compile(r"^\s*(?:function\s+)?([A-Za-z_][A-Za-z0-9_]*)\s*\(\)\s*\{") + + +def function_bodies(lines: list[str]) -> list[tuple[str, int, list[str]]]: + """Yield (name, start_line, body_lines) for each top-level function. + + Brace counting rather than a real parser. Good enough because the tree's + functions are conventionally formatted, and a miscount fails safe: it + produces a body that ends somewhere odd, which at worst misreads the last + statement of one function rather than silently skipping every function. + """ + out = [] + i = 0 + while i < len(lines): + m = FUNC_RE.match(lines[i]) + if not m: + i += 1 + continue + name = m.group(1) + depth = lines[i].count("{") - lines[i].count("}") + body_start = i + j = i + 1 + body: list[str] = [] + while j < len(lines) and depth > 0: + depth += lines[j].count("{") - lines[j].count("}") + if depth > 0: + body.append(lines[j]) + j += 1 + out.append((name, body_start + 1, body)) + i = j + return out + + +def last_statement(body: list[str]) -> str | None: + """The last executable line of a function body, or None if there is none.""" + for line in reversed(body): + stripped = line.strip() + if not stripped or stripped.startswith("#"): + continue + return stripped + return None + + +def leading_command(statement: str) -> str | None: + """The command word a statement starts with, ignoring shell decoration.""" + s = statement.strip() + # A trailing-log defect cannot hide behind these, and treating them as the + # command word would miss the real one. + for prefix in ("}", "fi", "done", "esac", "else", ";;"): + if s == prefix or s.startswith(prefix + " "): + return None + s = s.lstrip("&|;( ") + m = re.match(r"([A-Za-z_][A-Za-z0-9_\-]*)", s) + return m.group(1) if m else None + + +def status_tested(name: str, all_text: str, defining_file: Path) -> list[str]: + """Call sites that consume the function's exit status, as evidence strings.""" + patterns = [ + (rf"\bif\s+{re.escape(name)}\b", "if "), + (rf"\bif\s+!\s+{re.escape(name)}\b", "if ! "), + (rf"\bwhile\s+{re.escape(name)}\b", "while "), + (rf"^\s*{re.escape(name)}\s+[^\n|&]*\|\|", " ||"), + (rf"^\s*{re.escape(name)}\s*\|\|", " ||"), + (rf"^\s*{re.escape(name)}\s+[^\n|&]*&&", " &&"), + (rf"^\s*{re.escape(name)}\s*&&", " &&"), + (rf"\bif\s+\S*\s*{re.escape(name)}\b.*;\s*then", "if ... ; then"), + ] + hits = [] + for pat, label in patterns: + if re.search(pat, all_text, re.M): + hits.append(label) + return sorted(set(hits)) + + +def main() -> int: + sh_files = sorted( + p for p in TESTING.rglob("*.sh") + if "sim-results" not in p.parts and ".cache" not in p.parts + ) + if not sh_files: + print("trailing-log check: found no shell scripts to scan", file=sys.stderr) + return 2 + + corpus = {} + for p in sh_files: + try: + corpus[p] = p.read_text(errors="replace") + except OSError as e: + print(f"trailing-log check: cannot read {p}: {e}", file=sys.stderr) + return 2 + all_text = "\n".join(corpus.values()) + + findings = [] + scanned = 0 + shaped = 0 + for path, text in corpus.items(): + lines = text.splitlines() + for name, lineno, body in function_bodies(lines): + scanned += 1 + stmt = last_statement(body) + if stmt is None: + continue + cmd = leading_command(stmt) + if cmd is None or cmd not in LOG_COMMANDS: + continue + shaped += 1 + if name in ALLOWED: + continue + callers = status_tested(name, all_text, path) + if callers: + rel = path.relative_to(TESTING.parent) + findings.append((rel, lineno, name, cmd, callers, stmt)) + + for rel, lineno, name, cmd, callers, stmt in sorted(findings): + print(f"{rel}:{lineno}: {name}() has a caller that tests its status, " + f"but ends in `{cmd}` rather than an explicit return") + print(f" last statement: {stmt[:100]}") + print(f" status consumed by: {', '.join(callers)}") + print(f" fix: add an explicit `return 0` as the last statement. Its " + f"success value is currently whatever the log call returned, " + f"which is 0 whatever the function did.") + + print(f"trailing-log check: {scanned} function(s) scanned, " + f"{shaped} end in a logging call, {len(ALLOWED)} allowed, " + f"{len(findings)} with a status-testing caller") + return 1 if findings else 0 + + +if __name__ == "__main__": + sys.exit(main()) diff --git a/testing/ci-local.sh b/testing/ci-local.sh index fc1fae6..a6c52b7 100755 --- a/testing/ci-local.sh +++ b/testing/ci-local.sh @@ -1092,6 +1092,19 @@ run_log_strings() { record "log-strings" $rc } +# A shell function's exit status is its last command's. One ending in a log +# call returns 0 whatever it did, so a caller testing that status has a dead +# gate — the run_chaos and build_fips_for_e2e defects, one of which certified +# unbuilt code as green. This enforces an explicit terminal return wherever a +# caller consumes the status, which makes the class unreachable rather than +# repairing instances of it. +run_trailing_log() { + local rc=0 + info "[trailing-log] Checking for functions whose status is a log call's" + python3 "$SCRIPT_DIR/check-trailing-log.py" || rc=$? + record "trailing-log" $rc +} + # Unit tests for the convergence gate every static suite waits on. Hermetic — # synthetic ping functions against the same SECONDS clock, no containers — but # it drives real timeouts, so it costs about 45 seconds rather than the "few @@ -1121,6 +1134,7 @@ main() { # local run means what a GitHub run means, whichever subset was asked for. run_ci_parity run_log_strings + run_trailing_log run_wait_converge if [[ "$TEST_ONLY" == true ]]; then diff --git a/testing/nat/scripts/nostr-relay-test.sh b/testing/nat/scripts/nostr-relay-test.sh index 9fea6e3..f02531d 100755 --- a/testing/nat/scripts/nostr-relay-test.sh +++ b/testing/nat/scripts/nostr-relay-test.sh @@ -288,6 +288,7 @@ assert_process_alive() { return 1 fi echo " $container: fips daemon still alive after malformed advert" + return 0 } assert_no_panic() { diff --git a/testing/nat/scripts/stun-faults-test.sh b/testing/nat/scripts/stun-faults-test.sh index a9d5d22..51a5a13 100755 --- a/testing/nat/scripts/stun-faults-test.sh +++ b/testing/nat/scripts/stun-faults-test.sh @@ -126,6 +126,7 @@ apply_delay() { docker exec "$SHIM" tc qdisc add dev "$DEV" root netem delay 5000ms 2>/dev/null \ || { echo " delay: tc netem unavailable, skipping" >&2; return 1; } echo " delay: tc netem 5000ms applied" + return 0 } clear_delay() { @@ -139,6 +140,7 @@ assert_process_alive() { return 1 fi echo " $NODE: fips daemon alive" + return 0 } assert_no_panic() {