diff --git a/.github/workflows/ci.yml b/.github/workflows/ci.yml index b84e3f3..321b09b 100644 --- a/.github/workflows/ci.yml +++ b/.github/workflows/ci.yml @@ -61,6 +61,8 @@ jobs: run: pip3 install --quiet pyyaml - name: Check local and GitHub runners cover the same work run: bash testing/check-ci-parity.sh + - name: Check test log matchers against the strings src/ emits + run: python3 testing/check-log-strings.py fmt: name: Format check diff --git a/testing/check-log-strings.py b/testing/check-log-strings.py new file mode 100755 index 0000000..7a597f9 --- /dev/null +++ b/testing/check-log-strings.py @@ -0,0 +1,252 @@ +#!/usr/bin/env python3 +"""Verify that every daemon log string a test matches on still exists in src/. + +A test that greps the daemon's log for a message the daemon no longer emits +does not fail — it quietly stops observing anything, and an assertion built on +it (especially one expecting a count of zero) passes for the wrong reason. +That class has produced several findings, so it is checked mechanically here +rather than re-discovered by reading. + +The check extracts the string literals that test code matches against daemon +log lines, reduces each to its longest literal run (patterns carry regex +syntax), and requires that run to appear somewhere under src/. Anything that +legitimately does not originate in src/ — runtime panic text, tracing's own +level tokens — must be named in ALLOWED with a reason, so the exceptions are +reviewable instead of invisible. + +Usage: testing/check-log-strings.py [--verbose] +Exit: 0 all matched strings are live, 1 otherwise. +""" + +from __future__ import annotations + +import re +import sys +from pathlib import Path + +REPO = Path(__file__).resolve().parent.parent +SRC = REPO / "src" +TESTING = REPO / "testing" + +# Strings matched against log text that do not come from src/, each with the +# reason it is legitimately absent. Anything here is exempt from the src/ +# existence requirement — keep the list short and the reasons specific. +ALLOWED = { + "panicked": "emitted by the Rust runtime's panic hook, not by our code", + "PANIC": "panic-adjacent marker matched defensively alongside 'panicked'", + "ERROR": "tracing's own level token, produced by the subscriber's formatter", + " ERROR ": "tracing's own level token, produced by the subscriber's formatter", + " WARN ": "tracing's own level token, produced by the subscriber's formatter", + "Bootstrapped 100%": ( + "read from the tor-daemon container's log, not the fips daemon's — " + "Tor's own bootstrap progress line" + ), + "panicked at": "the Rust runtime's panic hook writes this, not our code", + "RUST_BACKTRACE": "the runtime's backtrace hint, printed alongside a panic", + "fatal runtime error": "emitted by the Rust runtime on an abort", +} + +# Shell helpers whose first argument is a pattern matched against daemon logs. +SHELL_HELPERS = ("count_log_pattern", "assert_zero_count") + +# A literal run shorter than this is too weak to search for meaningfully. +MIN_ANCHOR = 8 + + +META = set("[](){}?*+.^$") + + +def literal_anchors(pattern: str) -> list[str]: + """Longest literal run of each alternation branch of a grep pattern. + + Walks the pattern rather than substituting, because escaping has to be + resolved in the same pass as the split: `\\.` is a literal dot and ends + nothing, while a bare `.` is a wildcard and ends the run. Unescaping first + and splitting after would conflate the two and treat `directory.mode` as + though it were literal text. + """ + branches, current, i = [], [], 0 + while i < len(pattern): + ch = pattern[i] + if ch == "\\" and i + 1 < len(pattern): + nxt = pattern[i + 1] + if nxt == "|": # BRE alternation + branches.append("".join(current)) + current = [] + elif nxt in "wsdbWSDB": # a character class, not a literal + current.append("\0") + else: + current.append(nxt) + i += 2 + continue + if ch == "|": # ERE alternation + branches.append("".join(current)) + current = [] + elif ch in META: + current.append("\0") + else: + current.append(ch) + i += 1 + branches.append("".join(current)) + + anchors = [] + for branch in branches: + runs = [r.strip() for r in branch.split("\0")] + runs = [r for r in runs if r] + if runs: + anchors.append(max(runs, key=len)) + return anchors + + +def python_candidates() -> list[tuple[Path, int, str]]: + """`"literal" in line` tests in testing/ python.""" + found = [] + for path in sorted(TESTING.rglob("*.py")): + for n, line in enumerate(path.read_text(encoding="utf-8").splitlines(), 1): + for m in re.finditer(r'"([^"]+)"\s+in\s+line\b', line): + found.append((path, n, m.group(1))) + return found + + +def shell_candidates() -> list[tuple[Path, int, str]]: + """Literal first argument to a log-matching shell helper.""" + helpers = "|".join(SHELL_HELPERS) + # Quoted literal only; a variable argument is resolved elsewhere and is + # reported as unscannable rather than silently skipped. + literal = re.compile(rf"\b(?:{helpers})\s+(\"[^\"$]+\"|'[^']+')") + variable = re.compile(rf"\b(?:{helpers})\s+[\"']?\$") + found = [] + for path in sorted(TESTING.rglob("*.sh")): + for n, line in enumerate(path.read_text(encoding="utf-8").splitlines(), 1): + if line.lstrip().startswith("#"): + continue + for m in literal.finditer(line): + found.append((path, n, m.group(1)[1:-1])) + if variable.search(line): + found.append((path, n, None)) + return found + + +def pattern_table_candidates() -> list[tuple[Path, int, str]]: + """Bash associative-array keys used as log patterns. + + A suite that iterates a table of patterns into a log-matching helper hides + every string behind a variable, so the helper rule above sees only + `count_log_pattern "$pat"` and reports it unscannable. The keys are the + patterns; read them where they are written. + """ + key = re.compile(r'^\s*\[\s*"([^"$]+)"\s*\]=') + found = [] + for path in sorted(TESTING.rglob("*.sh")): + text = path.read_text(encoding="utf-8") + if not any(h in text for h in SHELL_HELPERS): + continue + for n, line in enumerate(text.splitlines(), 1): + if line.lstrip().startswith("#"): + continue + m = key.match(line) + if m: + found.append((path, n, m.group(1))) + return found + + +def grep_candidates() -> list[tuple[Path, int, str]]: + """Literal grep patterns whose input is daemon log text. + + Scoped by what the grep READS, not by what the file mentions. A suite + greps several unrelated sources — its own analyzer output, fipsctl JSON, + Tor's log, ping output — and only the daemon's log has to correspond to a + string in src/. Two shapes qualify: a grep piped directly from + `docker logs`, and a grep fed a variable that was assigned from it. + """ + grep_lit = r"\bgrep\b[^|;]*?\s(\"[^\"$]+\"|'[^'$]+')" + assign = re.compile(r"(\w+)=\"?\$\(\s*docker logs\b") + found = [] + for path in sorted(TESTING.rglob("*.sh")): + text = path.read_text(encoding="utf-8") + if "docker logs" not in text: + continue + log_vars = set(assign.findall(text)) + # A grep reading one of those variables, by herestring or by pipe. + var_alt = "|".join(re.escape(v) for v in log_vars) or r"\0" + reads_var = re.compile(rf"[\"']?\$\{{?(?:{var_alt})\b") + for n, line in enumerate(text.splitlines(), 1): + if line.lstrip().startswith("#"): + continue + if "docker logs" not in line and not reads_var.search(line): + continue + for m in re.finditer(grep_lit, line): + found.append((path, n, m.group(1)[1:-1])) + return found + + +def main() -> int: + verbose = "--verbose" in sys.argv + src_text = "\n".join( + p.read_text(encoding="utf-8", errors="replace") + for p in SRC.rglob("*.rs") + ) + + candidates = ( + python_candidates() + + shell_candidates() + + pattern_table_candidates() + + grep_candidates() + ) + dead, checked, exempt, unscannable = [], 0, 0, 0 + + for path, lineno, raw in candidates: + rel = path.relative_to(REPO) + if raw is None: + unscannable += 1 + if verbose: + print(f" skip {rel}:{lineno}: pattern comes from a variable") + continue + if raw in ALLOWED: + exempt += 1 + if verbose: + print(f" allow {rel}:{lineno}: {raw!r} ({ALLOWED[raw]})") + continue + anchors = literal_anchors(raw) + # An alternation may mix daemon strings with runtime ones, so the + # allowlist applies per branch and not only to the whole pattern. + if any(a in ALLOWED for a in anchors): + exempt += 1 + if verbose: + print(f" allow {rel}:{lineno}: {raw!r} (branch in ALLOWED)") + anchors = [a for a in anchors if a not in ALLOWED] + usable = [a for a in anchors if len(a) >= MIN_ANCHOR] + if not usable: + unscannable += 1 + if verbose: + print(f" skip {rel}:{lineno}: {raw!r} has no literal run >= {MIN_ANCHOR}") + continue + checked += 1 + # Every alternation branch must be live: one dead branch is a matcher + # that has silently narrowed. + for anchor in usable: + if anchor not in src_text: + dead.append((rel, lineno, raw, anchor)) + elif verbose: + print(f" ok {rel}:{lineno}: {anchor!r}") + + print( + f"log-string check: {checked} matched, {exempt} allowed, " + f"{unscannable} unscannable, {len(dead)} dead" + ) + if dead: + print("\nStrings matched against daemon logs that src/ never emits:\n") + for rel, lineno, raw, anchor in dead: + print(f" {rel}:{lineno}") + print(f" pattern: {raw!r}") + print(f" missing: {anchor!r}") + print( + "\nEither correct the string to what the daemon emits, or add it to " + "ALLOWED\nin this script with the reason it does not come from src/." + ) + return 1 + return 0 + + +if __name__ == "__main__": + sys.exit(main()) diff --git a/testing/ci-local.sh b/testing/ci-local.sh index 5410a34..cee312c 100755 --- a/testing/ci-local.sh +++ b/testing/ci-local.sh @@ -1059,6 +1059,16 @@ run_ci_parity() { record "ci-parity" $rc } +# Every daemon log string a test matches on must still be emitted by src/. +# A stale one does not fail — it stops observing, and an expect-zero assertion +# built on it then passes for the wrong reason. +run_log_strings() { + local rc=0 + info "[log-strings] Checking test log matchers against the strings src/ emits" + python3 "$SCRIPT_DIR/check-log-strings.py" || rc=$? + record "log-strings" $rc +} + # ── Main ─────────────────────────────────────────────────────────────────── main() { @@ -1071,6 +1081,7 @@ main() { # --build-only are gated too: a divergence invalidates any claim that a # local run means what a GitHub run means, whichever subset was asked for. run_ci_parity + run_log_strings if [[ "$TEST_ONLY" == true ]]; then run_tests diff --git a/testing/interop/interop-test.sh b/testing/interop/interop-test.sh index b2e0866..f240daf 100755 --- a/testing/interop/interop-test.sh +++ b/testing/interop/interop-test.sh @@ -846,10 +846,10 @@ declare -A GLOBAL_PATTERNS=( ["ERROR"]="error-level log lines" ["unknown FMP version|Unknown FMP version"]="unknown-FMP-version drops" ["MMP link teardown"]="MMP link teardowns" - ["Excessive decrypt failures"]="excessive-decrypt-failure removals" + ["Excessive decryption failures"]="excessive-decryption-failure removals" ["Session AEAD decryption failed"]="FSP AEAD decrypt failures" ["Rekey msg2 processing failed"]="rekey msg2 failures" - ["Handshake failed|handshake failed|Handshake error"]="handshake failures" + ["Handshake failed|handshake failed"]="handshake failures" ) for pat in "${!GLOBAL_PATTERNS[@]}"; do diff --git a/testing/lib/log_analysis.py b/testing/lib/log_analysis.py index ffa33bb..7de162f 100644 --- a/testing/lib/log_analysis.py +++ b/testing/lib/log_analysis.py @@ -149,7 +149,7 @@ def _analyze_lines(result: AnalysisResult, source: str, log_text: str): if "Session established" in line: result.sessions_established.append((source, line)) # Peer promotion - if "Inbound peer promoted" in line or "Outbound handshake completed" in line: + if "Peer promoted to active" in line or "Outbound handshake completed" in line: result.peers_promoted.append((source, line)) # Peer removal if "Peer removed" in line: @@ -174,7 +174,7 @@ def _analyze_lines(result: AnalysisResult, source: str, log_text: str): if "Rekey cutover complete" in line or "FSP rekey cutover complete" in line: result.rekey_cutovers.append((source, line)) # Discovery - if "Initiating LookupRequest" in line or "Discovery lookup initiated" in line: + if "Discovery lookup initiated" in line: result.discovery_initiated.append((source, line)) if "proof verified, route cached" in line: result.discovery_succeeded.append((source, line)) @@ -197,8 +197,18 @@ def _analyze_lines(result: AnalysisResult, source: str, log_text: str): def collect_docker_logs(containers: list[str]) -> dict[str, str]: - """Collect logs from Docker containers, stripping ANSI codes.""" + """Collect logs from Docker containers, stripping ANSI codes. + + Raises RuntimeError if any container's log could not be read. `docker + logs` reports a missing container on stderr and exits non-zero, so + without the returncode check that reply was stored as though it were the + node's own log and analysed as a mesh with no panics, no errors and no + sessions — which reads exactly like a clean run. Substituting "" on the + exception path has the same effect. Mirrors the fix already landed in + chaos/sim/logs.py's collect_logs. + """ logs = {} + failed = [] for name in containers: try: result = subprocess.run( @@ -207,10 +217,26 @@ def collect_docker_logs(containers: list[str]) -> dict[str, str]: text=True, timeout=30, ) - raw = result.stdout + result.stderr - logs[name] = strip_ansi(raw) - except (subprocess.TimeoutExpired, Exception): - logs[name] = "" + except Exception as e: + print(f"failed to collect logs from {name}: {e}", file=sys.stderr) + failed.append(name) + continue + + if result.returncode != 0: + print( + f"docker logs {name} exited {result.returncode}: " + f"{result.stderr.strip()}", + file=sys.stderr, + ) + failed.append(name) + continue + + # A container's own stderr arrives on our stderr, so on the success + # path both streams are log content. + logs[name] = strip_ansi(result.stdout + result.stderr) + + if failed: + raise RuntimeError("could not read logs from: " + ", ".join(failed)) return logs diff --git a/testing/nat/scripts/nat-test.sh b/testing/nat/scripts/nat-test.sh index 2ae48a0..3628e87 100755 --- a/testing/nat/scripts/nat-test.sh +++ b/testing/nat/scripts/nat-test.sh @@ -316,7 +316,7 @@ require_bootstrap_activity() { local container="$1" local logs logs="$(docker logs "$container" 2>&1 || true)" - if ! grep -Eq "bootstrap failed|Started Nostr( UDP)? NAT traversal attempt" <<<"$logs"; then + if ! grep -Eq "Started Nostr( UDP)? NAT traversal attempt" <<<"$logs"; then echo "Expected bootstrap activity in ${container} logs" >&2 return 1 fi diff --git a/testing/static/scripts/rekey-test.sh b/testing/static/scripts/rekey-test.sh index 0c7a72b..eab2b2a 100755 --- a/testing/static/scripts/rekey-test.sh +++ b/testing/static/scripts/rekey-test.sh @@ -491,7 +491,7 @@ assert_min_count "Peer FSP new-epoch frame authenticated" 1 \ assert_zero_count "PANIC\|panicked" "Panics" assert_zero_count "ERROR" "Errors" assert_zero_count "MMP link teardown" "Spurious link teardowns" -assert_zero_count "Excessive decrypt failures" \ +assert_zero_count "Excessive decryption failures" \ "Excessive decrypt failure removals" assert_zero_count "Rekey msg2 processing failed" "Rekey msg2 failures" assert_zero_count "Session AEAD decryption failed" \