#!/usr/bin/env python3 """Summarise a Canary log around the in-mission freeze. [`mission-freeze-resume-spin.md`](../../docs/re/mission-freeze-resume-spin.md) found a frozen Stage 02 run whose log ends in 1 171 refused resumes of one guest thread by one guest thread. This turns that reading into a repeatable one, and answers the question that separates the two candidate mechanisms: * the target thread **never ran** — a lost resume, the same class of bug as `c1b57f93b`, and the refusals are the *cause*; * the target thread **ran and then blocked** — the refusals are the game's reaction to a worker stuck on something else, and the resume path is innocent. `XThread::Execute thid N (handle=…)` is logged on the **Kernel** channel when a thread actually begins executing, so the discriminator is simply whether that line exists for the target handle. It needs `LOG_MASK=12 LOG_LEVEL=3`: the scripts' old `log_mask=13` has Kernel DISABLED, which is why no earlier log ever held a kernel call. Usage: freeze_report.py [top_n] """ import collections import re import sys REFUSED = re.compile( r"^\S+ (\S+) XThread::Resume: host resume was refused for thread (\S+)") EXECUTE = re.compile(r"XThread::Execute thid (\d+) \(handle=([0-9A-F]{8})") CREATE = re.compile(r"XThread([0-9A-F]{8}) \(([0-9A-F]+)\) Stack: (\S+)") def main(): path = sys.argv[1] lines = open(path, errors="replace").read().splitlines() pairs = collections.Counter() first_line = {} for i, l in enumerate(lines): m = REFUSED.match(l) if m: pairs[m.groups()] += 1 first_line.setdefault(m.groups(), i + 1) print(f"# {len(lines)} log lines, {sum(pairs.values())} refused resumes, " f"{len(pairs)} distinct (caller -> target) pairs") for (caller, target), n in pairs.most_common(int(sys.argv[2]) if len(sys.argv) > 2 else 5): print(f" {caller} -> {target}: {n} (first at line {first_line[(caller, target)]})") if not pairs: print(" none — this run did not spin") return 0 (caller, target), n = pairs.most_common(1)[0] executed = {m.group(2) for l in lines for m in [EXECUTE.search(l)] if m} # Without the Kernel channel there are NO XThread::Execute lines at all, and # every thread then looks like it never ran — a false answer to exactly the # question this tool exists to settle. Refuse instead. if not executed: print("\n# NO XThread::Execute lines in this log at all.") print("# The Kernel channel was disabled, so 'did it ever run' is " "UNANSWERABLE here — re-run with LOG_MASK=12 LOG_LEVEL=3.") return 2 created = {m.group(1): m.group(0) for l in lines for m in [CREATE.search(l)] if m} print(f"\n# the dominant target, {target}:") print(f" created: {created.get(target, 'NO CREATION LINE')}") print(f" executed: {'YES' if target in executed else 'NO — it never began executing'}") print(f" caller {caller} executed: " f"{'YES' if caller in executed else 'NO'}") print(f"# threads created: {len(created)} threads that executed: {len(executed)}") never = [h for h in created if h not in executed] print(f"# created but NEVER executed ({len(never)}): {' '.join(sorted(never)[:20])}") own = [l for l in lines if l.split(" ")[1:2] == [target] and "host resume was refused" not in l] print(f"\n# last lines whose CALLER is {target} ({len(own)} total):") for l in own[-12:]: print(" " + l[:160]) print(f"\n# last non-refusal lines in the file:") for l in [x for x in lines if "host resume was refused" not in x][-12:]: print(" " + l[:160]) return 0 if __name__ == "__main__": raise SystemExit(main())