Check that log strings tests match on are still ones the daemon emits

A test that greps the daemon's log for a message the daemon stopped emitting
does not fail. It stops observing, and an assertion built on it — especially
one expecting a count of zero — then passes because nothing can be seen
rather than because nothing happened. Several findings have come from that
one class, so it is now checked mechanically.

testing/check-log-strings.py extracts the strings test code matches against
daemon log text and requires each to exist in src/. It reads four shapes:
python `"..." in line` tests, the first argument of the shell log helpers,
bash associative-array pattern tables, and greps whose input is daemon log
output. Patterns carry regex syntax, so each is reduced to the longest
literal run of every alternation branch, with escaping resolved in the same
pass — `\.` is a literal dot and `.` is a wildcard, and conflating them would
let a pattern match text that is not there.

Scoping is by what a grep READS, not by what its file mentions. A suite greps
its own analyzer output, fipsctl JSON, Tor's log and ping output, and none of
those have to correspond to a string in src/; scoping on the file produced 34
false positives. Strings that legitimately do not come from src/ are named in
ALLOWED with a reason, so the exceptions are reviewable rather than invisible.

It found six dead strings, three of which were not previously known: a second
copy of "Excessive decrypt failures" in the interop pattern table, a dead
"Handshake error" branch inside an alternation whose other branches still
matched, and "bootstrap failed" in the NAT suite. All six are corrected to
what the daemon emits, or dropped where the surviving branch already covers
the case. Verified by breaking it two ways and confirming it reports.

Also here, since it is the same failure shape one layer down: the shared log
library returned an empty string for a container whose logs it could not
read, so analysing a missing container reported no panics, no errors and no
sessions, and exited 0 — indistinguishable from a clean run. It now reports
which containers could not be read and raises, matching the fix already
landed in the chaos copy.

.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

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())

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

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

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
 
 

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

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" \