mirror of
https://github.com/jmcorgan/fips.git
synced 2026-07-30 19:46:15 +00:00
Johnathan Corgan
4315328f2b
The shared analyzer matched two strings for one event: "Peer promoted to active", emitted at info, and "Outbound handshake completed", emitted at debug. Both come from handle_msg2 on the same call path for the same outbound promotion, so any run at debug level counted every outbound promotion twice. Measured rather than argued. On the archived debug-level churn-mixed run of 2026-07-25, the node logs carry 20 of each string; the old matcher reported 40 promotions and the new one reports 20. The neighbouring counters are unmoved at 13 sessions and 33 parent switches. Info-level runs are unaffected, which was checked rather than assumed: on the tcp-mesh run of the same date the debug string occurs zero times, and the old and new matchers both report 7 against 7 raw occurrences. Three scenarios run at debug, one of them gating, so this corrects the promotion figure in their artifacts. No assertion reads the counter, so no suite's verdict changes. The earlier fix that introduced this added the live string alongside the dead one where it needed to replace it.
278 lines
11 KiB
Python
278 lines
11 KiB
Python
#!/usr/bin/env python3
|
|
"""Shared log analysis for FIPS integration tests.
|
|
|
|
Parses structured tracing output from FIPS daemons and categorizes
|
|
events (panics, errors, sessions, parent switches, etc.).
|
|
|
|
CLI usage:
|
|
python3 -m lib.log_analysis <logfile> [<logfile> ...]
|
|
python3 -m lib.log_analysis --from-docker <container> [<container> ...]
|
|
|
|
Exit codes:
|
|
0 — no panics detected
|
|
2 — panics detected
|
|
"""
|
|
|
|
from __future__ import annotations
|
|
|
|
import re
|
|
import subprocess
|
|
import sys
|
|
from dataclasses import dataclass, field
|
|
|
|
|
|
# Regex to strip ANSI escape codes from tracing output
|
|
ANSI_RE = re.compile(r"\x1b\[[0-9;]*m")
|
|
|
|
|
|
def strip_ansi(text: str) -> str:
|
|
"""Remove ANSI escape codes from text."""
|
|
return ANSI_RE.sub("", text)
|
|
|
|
|
|
@dataclass
|
|
class AnalysisResult:
|
|
"""Categorized events extracted from FIPS daemon logs."""
|
|
|
|
errors: list[tuple[str, str]] = field(default_factory=list)
|
|
warnings: list[tuple[str, str]] = field(default_factory=list)
|
|
sessions_established: list[tuple[str, str]] = field(default_factory=list)
|
|
peers_promoted: list[tuple[str, str]] = field(default_factory=list)
|
|
peer_removals: list[tuple[str, str]] = field(default_factory=list)
|
|
parent_switches: list[tuple[str, str]] = field(default_factory=list)
|
|
mmp_link_metrics: list[tuple[str, str]] = field(default_factory=list)
|
|
mmp_session_metrics: list[tuple[str, str]] = field(default_factory=list)
|
|
handshake_timeouts: list[tuple[str, str]] = field(default_factory=list)
|
|
panics: list[tuple[str, str]] = field(default_factory=list)
|
|
congestion_detected: list[tuple[str, str]] = field(default_factory=list)
|
|
kernel_drop_events: list[tuple[str, str]] = field(default_factory=list)
|
|
rekey_cutovers: list[tuple[str, str]] = field(default_factory=list)
|
|
discovery_initiated: list[tuple[str, str]] = field(default_factory=list)
|
|
discovery_succeeded: list[tuple[str, str]] = field(default_factory=list)
|
|
discovery_bloom_miss: list[tuple[str, str]] = field(default_factory=list)
|
|
discovery_backoff: list[tuple[str, str]] = field(default_factory=list)
|
|
discovery_dedup: list[tuple[str, str]] = field(default_factory=list)
|
|
discovery_timeout: list[tuple[str, str]] = field(default_factory=list)
|
|
discovery_retry: list[tuple[str, str]] = field(default_factory=list)
|
|
discovery_no_tree_peer: list[tuple[str, str]] = field(default_factory=list)
|
|
discovery_fallback: list[tuple[str, str]] = field(default_factory=list)
|
|
discovery_trigger: list[tuple[str, str]] = field(default_factory=list)
|
|
|
|
def summary(self) -> str:
|
|
"""Format a human-readable summary of the analysis."""
|
|
lines = [
|
|
"=== Log Analysis ===",
|
|
"",
|
|
f"Panics: {len(self.panics)}",
|
|
f"Errors: {len(self.errors)}",
|
|
f"Warnings: {len(self.warnings)}",
|
|
f"Sessions established: {len(self.sessions_established)}",
|
|
f"Peers promoted: {len(self.peers_promoted)}",
|
|
f"Peer removals: {len(self.peer_removals)}",
|
|
f"Parent switches: {len(self.parent_switches)}",
|
|
f"Handshake timeouts: {len(self.handshake_timeouts)}",
|
|
f"MMP link samples: {len(self.mmp_link_metrics)}",
|
|
f"MMP session samples: {len(self.mmp_session_metrics)}",
|
|
f"Congestion events: {len(self.congestion_detected)}",
|
|
f"Kernel drop events: {len(self.kernel_drop_events)}",
|
|
f"Rekey cutovers: {len(self.rekey_cutovers)}",
|
|
"",
|
|
"--- Discovery ---",
|
|
f"Triggers: {len(self.discovery_trigger)}",
|
|
f"Initiated: {len(self.discovery_initiated)}",
|
|
f"Succeeded: {len(self.discovery_succeeded)}",
|
|
f"Retries: {len(self.discovery_retry)}",
|
|
f"Bloom miss: {len(self.discovery_bloom_miss)}",
|
|
f"Backoff suppressed: {len(self.discovery_backoff)}",
|
|
f"Deduplicated: {len(self.discovery_dedup)}",
|
|
f"No tree peer: {len(self.discovery_no_tree_peer)}",
|
|
f"Non-tree fallback: {len(self.discovery_fallback)}",
|
|
f"Timed out: {len(self.discovery_timeout)}",
|
|
]
|
|
|
|
if self.panics:
|
|
lines.append("")
|
|
lines.append("--- PANICS ---")
|
|
for source, line in self.panics[:10]:
|
|
lines.append(f" [{source}] {line.strip()}")
|
|
|
|
if self.errors:
|
|
lines.append("")
|
|
lines.append("--- ERRORS (first 20) ---")
|
|
for source, line in self.errors[:20]:
|
|
lines.append(f" [{source}] {line.strip()}")
|
|
|
|
if self.handshake_timeouts:
|
|
lines.append("")
|
|
lines.append("--- HANDSHAKE TIMEOUTS (first 10) ---")
|
|
for source, line in self.handshake_timeouts[:10]:
|
|
lines.append(f" [{source}] {line.strip()}")
|
|
|
|
lines.append("")
|
|
return "\n".join(lines)
|
|
|
|
@property
|
|
def has_panics(self) -> bool:
|
|
return len(self.panics) > 0
|
|
|
|
|
|
def analyze_text(log_text: str, source: str = "") -> AnalysisResult:
|
|
"""Analyze a single log text and return categorized events."""
|
|
result = AnalysisResult()
|
|
_analyze_lines(result, source, log_text)
|
|
return result
|
|
|
|
|
|
def analyze_logs(logs: dict[str, str]) -> AnalysisResult:
|
|
"""Analyze logs from multiple sources (keyed by source name)."""
|
|
result = AnalysisResult()
|
|
for source, log_text in logs.items():
|
|
_analyze_lines(result, source, log_text)
|
|
return result
|
|
|
|
|
|
def _analyze_lines(result: AnalysisResult, source: str, log_text: str):
|
|
"""Parse log lines and append to result."""
|
|
for raw_line in log_text.splitlines():
|
|
line = strip_ansi(raw_line)
|
|
|
|
# Panics
|
|
if "panicked" in line or "PANIC" in line:
|
|
result.panics.append((source, line))
|
|
# Errors and warnings
|
|
elif " ERROR " in line:
|
|
result.errors.append((source, line))
|
|
elif " WARN " in line:
|
|
result.warnings.append((source, line))
|
|
|
|
# Session establishment
|
|
if "Session established" in line:
|
|
result.sessions_established.append((source, line))
|
|
# Peer promotion. Match only the info-level string. "Outbound handshake
|
|
# completed" is emitted from handle_msg2 on the same call path for the
|
|
# same promotion, so matching it too double-counted every outbound
|
|
# promotion in any run at debug level.
|
|
if "Peer promoted to active" in line:
|
|
result.peers_promoted.append((source, line))
|
|
# Peer removal
|
|
if "Peer removed" in line:
|
|
result.peer_removals.append((source, line))
|
|
# Parent switches
|
|
if "Parent switched" in line:
|
|
result.parent_switches.append((source, line))
|
|
# Handshake timeouts
|
|
if "timed out" in line and ("handshake" in line.lower() or "Handshake" in line):
|
|
result.handshake_timeouts.append((source, line))
|
|
# MMP metrics
|
|
if "MMP link metrics" in line:
|
|
result.mmp_link_metrics.append((source, line))
|
|
if "MMP session metrics" in line:
|
|
result.mmp_session_metrics.append((source, line))
|
|
# Congestion events
|
|
if "Congestion detected" in line:
|
|
result.congestion_detected.append((source, line))
|
|
if "Kernel recv drops first observed" in line:
|
|
result.kernel_drop_events.append((source, line))
|
|
# Rekey cutovers
|
|
if "Rekey cutover complete" in line or "FSP rekey cutover complete" in line:
|
|
result.rekey_cutovers.append((source, line))
|
|
# Discovery
|
|
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))
|
|
if "target not in any peer bloom filter" in line:
|
|
result.discovery_bloom_miss.append((source, line))
|
|
if "suppressed by backoff" in line:
|
|
result.discovery_backoff.append((source, line))
|
|
if "deduplicated, already pending" in line:
|
|
result.discovery_dedup.append((source, line))
|
|
if "lookup timed out" in line:
|
|
result.discovery_timeout.append((source, line))
|
|
if "Discovery retry sent" in line:
|
|
result.discovery_retry.append((source, line))
|
|
if "no tree peers with bloom match" in line or "No eligible peers to forward" in line:
|
|
result.discovery_no_tree_peer.append((source, line))
|
|
if "non-tree fallback" in line:
|
|
result.discovery_fallback.append((source, line))
|
|
if "Failed to initiate session, trying discovery" in line:
|
|
result.discovery_trigger.append((source, line))
|
|
|
|
|
|
def collect_docker_logs(containers: list[str]) -> dict[str, str]:
|
|
"""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(
|
|
["docker", "logs", name],
|
|
capture_output=True,
|
|
text=True,
|
|
timeout=30,
|
|
)
|
|
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
|
|
|
|
|
|
def main():
|
|
"""CLI entry point."""
|
|
if len(sys.argv) < 2:
|
|
print(f"Usage: {sys.argv[0]} [--from-docker] <source> [<source> ...]",
|
|
file=sys.stderr)
|
|
sys.exit(1)
|
|
|
|
from_docker = False
|
|
args = sys.argv[1:]
|
|
if args[0] == "--from-docker":
|
|
from_docker = True
|
|
args = args[1:]
|
|
|
|
if not args:
|
|
print("Error: no sources specified", file=sys.stderr)
|
|
sys.exit(1)
|
|
|
|
if from_docker:
|
|
logs = collect_docker_logs(args)
|
|
else:
|
|
logs = {}
|
|
for path in args:
|
|
with open(path) as f:
|
|
logs[path] = f.read()
|
|
|
|
result = analyze_logs(logs)
|
|
print(result.summary())
|
|
sys.exit(2 if result.has_panics else 0)
|
|
|
|
|
|
if __name__ == "__main__":
|
|
main()
|