From 39d087bdaa92cfc01875c8a0ef097a6edda69c0d Mon Sep 17 00:00:00 2001 From: Claude Date: Tue, 13 Oct 2026 17:03:22 +0000 Subject: [PATCH 01/10] Phase 1 (in progress): pin the pillars, fix the relative IDENTITY_DIR quickstart, add 22 missing tests - pyproject.toml: the six pillars pinned to the same commits listing-assistants pins (they installed from branch tips). - tests/test_day3.py, demo/run_p11_demo.py: IDENTITY_DIR made absolute before the P11 test changes directory. The README's command (IDENTITY_DIR=../listing-assistants) failed one test; it now passes (164 passed). - tests/test_phase1_coverage.py (22 tests): the envelope's required fields and provenance.source, a misspelled audience label holding as counterparty, the escalation.confidence_underflow queue, Hub.arm_signer_registry(), and the WhatsApp notifier. Not yet done: the re-run of the three mutants these tests are meant to kill (stopped by the owner before it ran), Phase 1.1 (notification truth), 1.2 (torn last line), 1.6 (CI), the full mutation sweep, and the listing-assistants sync. This branch is not merged to main; listing- assistants is unchanged. Push-log row goes in listing-assistants with the sync commit. Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_01CRunDQmfmnZdtJiP78e8WR --- demo/run_p11_demo.py | 4 +- pyproject.toml | 15 ++- tests/test_day3.py | 6 +- tests/test_phase1_coverage.py | 199 ++++++++++++++++++++++++++++++++++ 4 files changed, 215 insertions(+), 9 deletions(-) create mode 100644 tests/test_phase1_coverage.py diff --git a/demo/run_p11_demo.py b/demo/run_p11_demo.py index ad8ed90..60db456 100644 --- a/demo/run_p11_demo.py +++ b/demo/run_p11_demo.py @@ -40,9 +40,9 @@ def stub_model_a(prompt: str) -> dict: def stub_model_b(prompt: str) -> dict: return {"model": "stub-b", "response": "Fine.", "thinking": ""} -IDENTITY = os.environ.get( +IDENTITY = os.path.abspath(os.environ.get( "IDENTITY_DIR", - os.path.join(os.path.dirname(os.path.abspath(__file__)), "..", "..", "listing-assistants")) + os.path.join(os.path.dirname(os.path.abspath(__file__)), "..", "..", "listing-assistants"))) def signal(ctx, payload): diff --git a/pyproject.toml b/pyproject.toml index e980acd..9765066 100644 --- a/pyproject.toml +++ b/pyproject.toml @@ -21,14 +21,17 @@ requires-python = ">=3.10" # signing and verifying authority envelopes needs [crypto]. # dispatcher.pillars and dispatcher.analysis import the six pillars from # source (never vendored). Install them with: pip install -e ".[pillars]" +# Pinned to exact commits (2026-10-13), the same six listing-assistants pins +# in its requirements.txt: what CI tested is what you install. To move a +# pillar forward: change its hash here and there, run both suites, commit. # This is what the test suite and the P11 demo require. pillars = [ - "before-turn @ git+https://github.com/QuietFireAI/before-turn", - "open-mind @ git+https://github.com/QuietFireAI/open-mind", - "agent-open-mind @ git+https://github.com/QuietFireAI/agent-open-mind", - "sleep-marks @ git+https://github.com/QuietFireAI/sleep-marks", - "pre-response-selfcheck @ git+https://github.com/QuietFireAI/pre-response-selfcheck", - "splitvantage @ git+https://github.com/QuietFireAI/splitvantage", + "before-turn @ git+https://github.com/QuietFireAI/before-turn.git@0b18252a319a48cb540acf90e9d1508d0b2874ad", + "open-mind @ git+https://github.com/QuietFireAI/open-mind.git@570e1b8e4c2f141dbcd2cb3b0b9eb1f7fac63ea6", + "agent-open-mind @ git+https://github.com/QuietFireAI/agent-open-mind.git@9b0dc89ce923c3b767e3e4436f6966d8ede99b2a", + "sleep-marks @ git+https://github.com/QuietFireAI/sleep-marks.git@8aa298b98b229cbdd76f3caa917298087888f0e8", + "pre-response-selfcheck @ git+https://github.com/QuietFireAI/pre-response-selfcheck.git@94d6a30cdb41fd8934391114a1979b0071f9e9a0", + "splitvantage @ git+https://github.com/QuietFireAI/splitvantage.git@0a202d5dbbb593be5908f66ffc95ea4c6f7380d4", ] # Ed25519 authority signatures (the only signing tier since 2026-10-12). crypto = ["cryptography>=42"] diff --git a/tests/test_day3.py b/tests/test_day3.py index 13face9..bd66b6f 100644 --- a/tests/test_day3.py +++ b/tests/test_day3.py @@ -12,7 +12,10 @@ FIX = os.path.join(os.path.dirname(__file__), "routes_fixture.json") PKG = os.path.join(os.path.dirname(__file__), "..", "dispatcher") -LISTING = os.environ.get("IDENTITY_DIR", os.path.join(os.path.dirname(__file__), "..", "..", "listing-assistants")) # real identity when present as a sibling clone; identity-gated tests skip cleanly otherwise +# Absolute from the start (2026-10-13): the P11 test changes directory before +# the demo reads IDENTITY_DIR, so the README's relative form +# (IDENTITY_DIR=../listing-assistants) used to fail that one test. +LISTING = os.path.abspath(os.environ.get("IDENTITY_DIR", os.path.join(os.path.dirname(__file__), "..", "..", "listing-assistants"))) # real identity when present as a sibling clone; identity-gated tests skip cleanly otherwise def make_hub(tmp_path, verifier=None): @@ -226,6 +229,7 @@ def test_agent_dir_without_skill_is_violation_not_skip(tmp_path): def test_p11_demo_end_to_end(tmp_path, monkeypatch): if os.path.isdir(LISTING) and load_identity(LISTING).vertical != "real-estate-listing-agent": pytest.skip("P11 demo is listing-pinned; generic contract test covers other identities") + monkeypatch.setenv("IDENTITY_DIR", LISTING) # absolute, before the chdir monkeypatch.chdir(tmp_path) sys.path.insert(0, os.path.join(os.path.dirname(__file__), "..", "demo")) import run_p11_demo diff --git a/tests/test_phase1_coverage.py b/tests/test_phase1_coverage.py new file mode 100644 index 0000000..8a810ab --- /dev/null +++ b/tests/test_phase1_coverage.py @@ -0,0 +1,199 @@ +"""Tests the 2026-10-13 snapshot found missing (repair plan, Phase 1). + +1.4 - three checks whose removal left the whole suite green (targeted + mutants that survived): the envelope's required fields, the + required provenance.source, and an outbound route with a misspelled + audience label failing closed to "counterparty" (held). +1.7 - three additions made in the core for listing-assistants and tested + only there: the escalation.confidence_underflow queue, + Hub.arm_signer_registry(), and the WhatsApp notifier. +""" +import io +import json +import os +import sys +import urllib.error +import urllib.parse + +import pytest + +sys.path.insert(0, os.path.join(os.path.dirname(__file__), "..")) + +from dispatcher.core import AuditLog, Envelope, Routes # noqa: E402 +from dispatcher.hub import Hub # noqa: E402 + +FIXTURE = os.path.join(os.path.dirname(__file__), "routes_fixture.json") + + +def hub_on(tmp_path, routes_path=FIXTURE, **kw): + return Hub(Routes(routes_path), AuditLog(str(tmp_path / "a.jsonl")), **kw) + + +def good(**kw): + base = dict(from_agent="01", to_agent="02", intent="lead.captured", + client_context_id="c1", payload={}, provenance={"source": "test"}) + base.update(kw) + return Envelope(**base) + + +# ------------------------------------------------------------ 1.4 schema +@pytest.mark.parametrize("field", ["from_agent", "to_agent", "intent", "client_context_id"]) +def test_an_envelope_missing_a_required_field_is_rejected_and_logged(tmp_path, field): + hub = hub_on(tmp_path) + env = good(**{field: ""}) + r = hub.send(env) + assert r["status"] == "reject" + assert f"missing field: {field}" in r["reason"] + rejects = [e for e in hub.audit.read() if e["kind"] == "reject"] + assert rejects and f"missing field: {field}" in rejects[-1]["reason"] + assert not any(e["kind"] == "envelope.persisted" for e in hub.audit.read()) + + +@pytest.mark.parametrize("prov", [{}, {"captured_at": "x"}, "source", None]) +def test_an_envelope_without_provenance_source_is_rejected(tmp_path, prov): + hub = hub_on(tmp_path) + r = hub.send(good(provenance=prov)) + assert r["status"] == "reject" and "provenance.source required" in r["reason"] + assert not any(e["kind"] == "envelope.persisted" for e in hub.audit.read()) + + +def test_the_well_formed_envelope_in_these_tests_does_route(tmp_path): + # control: the rejections above are the field, not the fixture + hub = hub_on(tmp_path) + hub.register("02", lambda env: None) + assert hub.send(good())["status"] == "ack" + + +# ------------------------------------------------- 1.4 audience fail-closed +def routes_file(tmp_path, audience): + p = tmp_path / "routes.json" + p.write_text(json.dumps({"version": "t", "routes": [ + {"intent": "offer.share", "senders": ["11"], "receivers": ["external"], + "audience": audience}]}), encoding="utf-8") + return str(p) + + +@pytest.mark.parametrize("label", ["publik", "Principal", "", "client", 7]) +def test_a_misspelled_audience_label_holds_like_counterparty(tmp_path, label): + routes = Routes(routes_file(tmp_path, label)) + assert routes.audience_for("offer.share") == "counterparty" + hub = Hub(routes, AuditLog(str(tmp_path / "a.jsonl"))) + r = hub.send(good(from_agent="11", to_agent="external", intent="offer.share")) + assert r["status"] == "held" and r["reason"] == "absolute_signal" + assert r["audience"] == "counterparty" + kinds = [e["kind"] for e in hub.audit.read()] + assert "absolute_signal.hold" in kinds and "envelope.persisted" not in kinds + + +def test_a_correct_principal_label_passes_the_gate(tmp_path): + # control: the label is what decides, so "principal" spelled right passes + hub = Hub(Routes(routes_file(tmp_path, "principal")), AuditLog(str(tmp_path / "a.jsonl"))) + r = hub.send(good(from_agent="11", to_agent="external", intent="offer.share")) + assert r["status"] != "held" + + +# ------------------------------------------- 1.7 confidence_underflow queue +def test_confidence_underflow_is_an_escalation_queue(tmp_path): + seen = [] + hub = hub_on(tmp_path, human_notifier=lambda q, r: seen.append(q) or {"status": "sent"}) + out = hub.escalate("escalation.confidence_underflow", + {"client_context_id": "c9", "agent": "02", "reason": "under floor"}) + assert out == {"status": "escalated", "queue": "escalation.confidence_underflow"} + assert hub.queues["escalation.confidence_underflow"][-1]["client_context_id"] == "c9" + assert seen == ["escalation.confidence_underflow"] + raised = [e for e in hub.audit.read() if e["kind"] == "escalation.raised"] + assert raised[-1]["queue"] == "escalation.confidence_underflow" + with pytest.raises(KeyError): + hub.escalate("escalation.no_such_queue", {}) + + +# ----------------------------------------------- 1.7 arm_signer_registry +def identity_root(tmp_path, status="RATIFIED 2026-10-13 test owner"): + root = tmp_path / "ident" + (root / "config").mkdir(parents=True) + (root / "config" / "authority_signers.json").write_text(json.dumps({ + "_status": status, + "entries": [{"intent": "config.update", "signer_login": "owner@example.test", + "idp": "test", "mfa_required": True, + "effective": "2026-01-01", "revoked": None}]}), encoding="utf-8") + return str(root) + + +def test_arm_signer_registry_arms_from_an_identity_and_logs_it(tmp_path): + hub = hub_on(tmp_path) + reg = hub.arm_signer_registry(identity_root(tmp_path)) + assert hub.signer_registry is reg + armed = [e for e in hub.audit.read() if e["kind"] == "signer.armed"] + assert armed and armed[-1]["intents"] == ["config.update"] + assert armed[-1]["identity_root"].endswith("ident") + + +def test_arm_signer_registry_refuses_an_unratified_registry(tmp_path): + hub = hub_on(tmp_path) + with pytest.raises(ValueError, match="UNRATIFIED"): + hub.arm_signer_registry(identity_root(tmp_path, status="UNRATIFIED TEMPLATE")) + assert hub.signer_registry is None + assert not any(e["kind"] == "signer.armed" for e in hub.audit.read()) + + +def test_arm_signer_registry_default_root_names_the_missing_file_in_the_core(tmp_path): + # The default root is the repo holding dispatcher/ - an identity repo in + # practice. The core repo itself carries no config/, so it must refuse + # by name rather than arm on nothing. + hub = hub_on(tmp_path) + with pytest.raises(FileNotFoundError, match="authority_signers.json absent"): + hub.arm_signer_registry() + assert hub.signer_registry is None + + +# -------------------------------------------------- 1.7 WhatsApp notifier +class _Resp: + status = 201 + + def __enter__(self): + return self + + def __exit__(self, *a): + return False + + +def test_whatsapp_sends_with_the_channel_prefix(monkeypatch): + import dispatcher.notifier as n + sent = [] + + def fake_urlopen(req, timeout=5.0): + sent.append(urllib.parse.parse_qs(req.data.decode())) + return _Resp() + monkeypatch.setattr(n.urllib.request, "urlopen", fake_urlopen) + out = n.send_whatsapp_via_twilio("hello", to_number="+15550000002", from_number="whatsapp:+15550000001") + assert out == {"status": "sent", "http_status": 201, "channel": "whatsapp"} + assert sent[0]["To"] == ["whatsapp:+15550000002"] + assert sent[0]["From"] == ["whatsapp:+15550000001"] + assert sent[0]["Body"] == ["hello"] + + +def test_whatsapp_failures_are_reported_not_raised(monkeypatch): + import dispatcher.notifier as n + + def http_error(req, timeout=5.0): + raise urllib.error.HTTPError(req.full_url, 401, "Unauthorized", {}, io.BytesIO(b"bad creds")) + monkeypatch.setattr(n.urllib.request, "urlopen", http_error) + out = n.send_whatsapp_via_twilio("x") + assert out["status"] == "failed" and out["http_status"] == 401 and out["channel"] == "whatsapp" + + def down(req, timeout=5.0): + raise OSError("network down") + monkeypatch.setattr(n.urllib.request, "urlopen", down) + out = n.send_whatsapp_via_twilio("x") + assert out["status"] == "failed" and "network down" in out["error"] + + +def test_whatsapp_human_notifier_formats_and_sends(monkeypatch): + import dispatcher.notifier as n + bodies = [] + monkeypatch.setattr(n, "send_whatsapp_via_twilio", + lambda body, **kw: bodies.append(body) or {"status": "sent", "channel": "whatsapp"}) + out = n.whatsapp_human_notifier("escalation.hot_lead", {"client_context_id": "c1", "agent": "02"}) + assert out["status"] == "sent" + assert bodies == [n.format_notification_text("escalation.hot_lead", + {"client_context_id": "c1", "agent": "02"})] From d761a57227493702d7ae76c06eeaae6a116afd49 Mon Sep 17 00:00:00 2001 From: Claude Date: Tue, 13 Oct 2026 17:14:10 +0000 Subject: [PATCH 02/10] Phase 1.1 + 1.2: notifications say only what was delivered; a cut-off audit line is named and repairable 1.1 Notification truth (owner decision D3) - hub._notify records human.notified only when the notifier reports sent/delivered/shown. A failed status or a raised exception records human.notify_failed (status, http_status, channel, error - never the body). A notifier that reports nothing is recorded as transport "not reported". - escalate() and queue_and_notify() both go through _notify. - kpi escalation_transport counts confirmed / not_reported / notify_failed. - after_action prints "NOTIFICATION FAILED ... no person was reached". - tests/test_notification_truth.py: 16 tests. 7 targeted mutants, 7 killed. 1.2 Damaged or cut-off audit log (owner decision D4) - AuditLog refuses to open a log with an unreadable line: AuditLogDamaged names the line, says nothing was written, and says whether it is a cut-off last write (repairable) or damage to investigate. - verify_chain / check_file name the first bad line instead of raising. - AuditLog.repair_torn_tail + tools/audit_repair.py (run by a person): moves the partial bytes to .torn--, cuts back to the last complete entry, records audit.tail_quarantined on the chain. Refuses, changing nothing, if anything before the last line is damaged or the chain breaks. - A complete last entry missing only its newline opens; the next append writes the newline first. CRLF logs check and repair. - tests/test_audit_log_damage.py: 18 tests. 8 targeted mutants, 8 killed (the truncation-length mutant is killed by the interrupted-repair test). Suite: 198 passed. Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_01CRunDQmfmnZdtJiP78e8WR --- dispatcher/after_action.py | 13 +- dispatcher/core.py | 191 ++++++++++++++++++++++---- dispatcher/hub.py | 52 +++++++- dispatcher/kpi.py | 41 ++++-- dispatcher/notifier.py | 9 +- tests/test_audit_log_damage.py | 222 +++++++++++++++++++++++++++++++ tests/test_notification_truth.py | 143 ++++++++++++++++++++ tools/audit_repair.py | 58 ++++++++ 8 files changed, 680 insertions(+), 49 deletions(-) create mode 100644 tests/test_audit_log_damage.py create mode 100644 tests/test_notification_truth.py create mode 100644 tools/audit_repair.py diff --git a/dispatcher/after_action.py b/dispatcher/after_action.py index 377c511..04e0640 100644 --- a/dispatcher/after_action.py +++ b/dispatcher/after_action.py @@ -4,8 +4,9 @@ agent memory, never self-reported. One markdown report per run. Schema fields the runtime cannot yet populate are DECLARED, not faked: -- manners re-injections: no manners events exist in the runtime yet - human response time: notification is instrumented, response is not +(Corrected 2026-10-13: this list also named manners re-injections, which the +report below does read from the log.) An unreported deviation is a fabricated report (schema's own words), so deviations are computed mechanically: any audited reject, hold, dead-letter, taint, or siding event inside the run window is a deviation, verbatim. @@ -37,7 +38,8 @@ def generate_report(events: list[dict], playbook: str, run_id: str, run_events = [e for e in events if e.get("client_context_id") == client_context_id or e.get("envelope_id") in {s.get("envelope_id") for s in steps} - or e["kind"] in ("escalation.raised", "human.notified")] + or e["kind"] in ("escalation.raised", "human.notified", + "human.notify_failed")] if not run_events: raise ValueError(f"no audited events for run {run_id!r} - a report " f"without log evidence would be fabricated") @@ -91,12 +93,19 @@ def generate_report(events: list[dict], playbook: str, run_id: str, lines += ["", "## escalations"] notif = {e.get("queue"): e["ts"] for e in run_events if e["kind"] == "human.notified"} + failed = {e.get("queue"): e for e in run_events + if e["kind"] == "human.notify_failed"} if esc: for e in esc: q = e.get("queue") if q in notif and notif[q] >= e["ts"]: lines.append(f"- {q}: transport {notif[q]-e['ts']:.4f}s; " f"human response time: NOT INSTRUMENTED") + elif q in failed and failed[q]["ts"] >= e["ts"]: + f = failed[q] + why = f.get("notifier_status") or f.get("error") or "unknown" + lines.append(f"- {q}: raised, NOTIFICATION FAILED ({why}) - " + f"no person was reached") else: lines.append(f"- {q}: raised, NO human.notified on log - " f"transport unproven") diff --git a/dispatcher/core.py b/dispatcher/core.py index 03e7448..8b747a9 100644 --- a/dispatcher/core.py +++ b/dispatcher/core.py @@ -128,6 +128,55 @@ def tuple_legal(self, frm: str, intent: str, to: str) -> bool: return False +class AuditLogDamaged(Exception): + """The audit log has a line that is not a readable entry (added + 2026-10-13, repair plan 1.2; owner decision D4: refuse, name the line, + and say how to recover - never clean up silently). + + torn_tail is True when the unreadable line is the LAST one and the file + does not end with a newline: the signature of a write cut off part-way + (a crash or power loss during append). Only that case has a recovery + path, AuditLog.repair_torn_tail(path), which a person runs. Any other + unreadable line is damage or tampering and has no automatic repair.""" + + def __init__(self, path: str, line: int, reason: str, torn_tail: bool): + self.path, self.line, self.reason, self.torn_tail = path, line, reason, torn_tail + if torn_tail: + how = ("this looks like a write that was cut off (for example by a " + "power loss). To recover, a person runs " + "AuditLog.repair_torn_tail(path) (tools/audit_repair.py in " + "dispatcher-agents): it moves that partial line to a side " + "file, keeps every complete entry, and records the repair " + "on the chain") + else: + how = ("this is not a cut-off last write; nothing repairs it " + "automatically. Keep the file as it is and investigate") + super().__init__(f"audit log {path} is damaged at line {line}: {reason}. " + f"Nothing was written. {how}.") + + +def _log_lines(path: str): + """The file's lines as (line_number, bytes), 1-based, blank lines + skipped, read as bytes so a cut-off multi-byte character cannot stop the + read. Also returns whether the file ends with a newline.""" + with open(path, "rb") as f: + data = f.read() + out = [] + for i, raw in enumerate(data.split(b"\n"), 1): + if raw.strip(): + out.append((i, raw.rstrip(b"\r"))) + return out, data.endswith(b"\n") or not data + + +def _parse(raw: bytes): + """One log line as a dict, or None if it is not a readable entry.""" + try: + e = json.loads(raw.decode("utf-8")) + except (UnicodeDecodeError, ValueError): + return None + return e if isinstance(e, dict) else None + + class AuditLog: """Append-only, HASH-CHAINED JSONL. Persist happens BEFORE delivery; the log is the single source of truth for KPIs - no self-reported metrics @@ -149,16 +198,90 @@ def __init__(self, path: str): self._prev = self._recover_tip() def _recover_tip(self) -> str: - """Resume the chain across process restarts: tip = last entry_hash.""" + """Resume the chain across process restarts: tip = last entry_hash. + An unreadable line raises AuditLogDamaged naming it (2026-10-13; it + used to raise a bare JSONDecodeError). A complete last entry that + only lost its newline is kept, and the next append starts a new line.""" + self._needs_newline = False if not os.path.exists(self.path): return self.GENESIS + lines, ends_nl = _log_lines(self.path) tip = self.GENESIS - with open(self.path, encoding="utf-8") as f: - for line in f: - if line.strip(): - tip = json.loads(line).get("entry_hash", tip) + for n, (i, raw) in enumerate(lines): + e = _parse(raw) + if e is None: + last = n == len(lines) - 1 + raise AuditLogDamaged(self.path, i, "not a readable entry", + torn_tail=last and not ends_nl) + tip = e.get("entry_hash", tip) + self._needs_newline = bool(lines) and not ends_nl return tip + @classmethod + def check_file(cls, path: str) -> dict: + """verify_chain() for a log that may be too damaged to open for + writing (AuditLog(path) refuses a damaged file). Reads only.""" + o = cls.__new__(cls) + o.path = path + return o.verify_chain() + + @classmethod + def repair_torn_tail(cls, path: str) -> dict: + """Recovery for a write cut off part-way - run by a person, never + automatically (owner decision D4, 2026-10-13). Refuses (raises + AuditLogDamaged or ValueError, changing nothing) unless ALL of: + - the bytes after the last newline are not a readable entry, and + - every line before them is readable and the chain over them verifies. + Then: the partial bytes are written to a new side file + .torn-- (flushed to disk first), the log is cut + back to its last complete entry, and an audit.tail_quarantined entry + (line, byte count, sha256 of the partial bytes, side file) is + appended, so the repair itself is on the chain. Returns that record.""" + if not os.path.exists(path): + raise ValueError(f"{path}: no such audit log") + with open(path, "rb") as f: + data = f.read() + cut = data.rfind(b"\n") + 1 # start of the bytes after the last newline + tail = data[cut:] + if not tail.strip(): + raise ValueError(f"{path}: the file ends with a complete line - " + f"there is no cut-off write to repair") + if _parse(tail.rstrip(b"\r")) is not None: + raise ValueError(f"{path}: the last line is a complete entry that only " + f"lacks its newline - nothing to repair; the log opens as is") + prefix = data[:cut] + prev, n = cls.GENESIS, 0 + for i, raw in enumerate(prefix.split(b"\n"), 1): + if not raw.strip(): + continue + e = _parse(raw.rstrip(b"\r")) + if e is None: + raise AuditLogDamaged(path, i, "not a readable entry (before the " + "last line)", torn_tail=False) + body = {k: v for k, v in e.items() if k not in ("prev_hash", "entry_hash")} + if e.get("prev_hash") != prev or e.get("entry_hash") != cls._entry_hash(body, prev): + raise ValueError(f"{path}: the chain breaks at line {i}, before the " + f"cut-off line - this is not only a cut-off write; " + f"nothing was changed") + prev, n = e["entry_hash"], i + torn_line = prefix.count(b"\n") + 1 + digest = hashlib.sha256(tail).hexdigest() + stamp = time.strftime("%Y%m%dT%H%M%SZ", time.gmtime()) + side = f"{path}.torn-{stamp}-{digest[:12]}" + with open(side, "xb") as f: # never overwrite an earlier side file + f.write(tail) + f.flush() + os.fsync(f.fileno()) + with open(path, "r+b") as f: + f.truncate(len(prefix)) + f.flush() + os.fsync(f.fileno()) + rec = {"line": torn_line, "bytes": len(tail), "sha256": digest, + "side_file": os.path.basename(side), + "complete_entries": sum(1 for r in prefix.split(b"\n") if r.strip())} + cls(path).append("audit.tail_quarantined", rec) + return rec + RESERVED = ("ts", "kind", "prev_hash", "entry_hash") # framing fields the log owns, never the caller @staticmethod @@ -178,9 +301,12 @@ def append(self, kind: str, record: dict) -> None: eh = self._entry_hash(body, self._prev) line = json.dumps({**body, "prev_hash": self._prev, "entry_hash": eh}) with open(self.path, "a", encoding="utf-8") as f: + if self._needs_newline: # last entry lost only its newline + f.write("\n") f.write(line + "\n") f.flush() os.fsync(f.fileno()) + self._needs_newline = False self._prev = eh def anchor(self) -> dict: @@ -192,10 +318,7 @@ def anchor(self) -> dict: in a handoff) closes that: a regenerated log cannot reproduce the anchored head hash at the anchored position. Gap named in the 2026-07-17 review, closed 2026-07-18.""" - n = 0 - if os.path.exists(self.path): - with open(self.path, encoding="utf-8") as f: - n = sum(1 for line in f if line.strip()) + n = len(_log_lines(self.path)[0]) if os.path.exists(self.path) else 0 return {"entries": n, "head_hash": self._prev} def verify_anchor(self, anchor: dict) -> dict: @@ -221,13 +344,13 @@ def verify_anchor(self, anchor: dict) -> dict: return {"ok": False, "reason": f"anchor names {n} entries; log file absent - " f"wholesale deletion"} - with open(self.path, encoding="utf-8") as f: - lines = [l for l in f if l.strip()] + lines = [raw for _, raw in _log_lines(self.path)[0]] if len(lines) < n: return {"ok": False, "reason": f"anchor names {n} entries; log has only " f"{len(lines)} - the anchored history is gone"} - actual = json.loads(lines[n - 1]).get("entry_hash") + e = _parse(lines[n - 1]) + actual = e.get("entry_hash") if e else None if actual != head: return {"ok": False, "reason": f"entry {n} hash mismatch - the log was " @@ -236,24 +359,42 @@ def verify_anchor(self, anchor: dict) -> dict: def verify_chain(self) -> dict: """Walk the file and recompute every link. Returns - {ok, entries, break_at} - break_at names the first bad line (1-based).""" + {ok, entries, break_at} - break_at names the first bad line (1-based). + On a break it also returns "reason" and "torn_tail". Since 2026-10-13 + an unreadable line (a cut-off write, damage) is a named break, never + an exception.""" prev, n = self.GENESIS, 0 if not os.path.exists(self.path): return {"ok": True, "entries": 0, "break_at": None} - with open(self.path, encoding="utf-8") as f: - for i, line in enumerate(f, 1): - if not line.strip(): - continue - e = json.loads(line) - body = {k: v for k, v in e.items() - if k not in ("prev_hash", "entry_hash")} - if e.get("prev_hash") != prev or \ - e.get("entry_hash") != self._entry_hash(body, prev): - return {"ok": False, "entries": i, "break_at": i} - prev = e["entry_hash"]; n = i + lines, ends_nl = _log_lines(self.path) + for k, (i, raw) in enumerate(lines): + e = _parse(raw) + if e is None: + return {"ok": False, "entries": i, "break_at": i, + "reason": "not a readable entry", + "torn_tail": k == len(lines) - 1 and not ends_nl} + body = {key: v for key, v in e.items() + if key not in ("prev_hash", "entry_hash")} + if e.get("prev_hash") != prev or \ + e.get("entry_hash") != self._entry_hash(body, prev): + return {"ok": False, "entries": i, "break_at": i, + "reason": "does not link to the entry before it " + "(edited, deleted or reordered)", + "torn_tail": False} + prev = e["entry_hash"]; n = i return {"ok": True, "entries": n, "break_at": None} def read(self) -> list[dict]: + """Every entry. An unreadable line raises AuditLogDamaged naming it + (2026-10-13; it used to raise a bare JSONDecodeError).""" if not os.path.exists(self.path): return [] - return [json.loads(l) for l in open(self.path, encoding="utf-8") if l.strip()] + lines, ends_nl = _log_lines(self.path) + out = [] + for k, (i, raw) in enumerate(lines): + e = _parse(raw) + if e is None: + raise AuditLogDamaged(self.path, i, "not a readable entry", + torn_tail=k == len(lines) - 1 and not ends_nl) + out.append(e) + return out diff --git a/dispatcher/hub.py b/dispatcher/hub.py index 479194e..9f11d7c 100644 --- a/dispatcher/hub.py +++ b/dispatcher/hub.py @@ -39,6 +39,14 @@ AUTHORITY_INTENTS = {"listing.change.authorized", "config.update"} +# A notifier result whose status is one of these means a person was reached +# (a page was accepted for delivery, or the alert was put on a screen). +# Anything else - a failure, an exception, an unknown status - is recorded as +# human.notify_failed. Added 2026-10-13 (repair plan 1.1): the hub used to +# write human.notified after every notifier call, so a Twilio 401 with the +# placeholder account was recorded as a person notified. +NOTIFY_DELIVERED = {"sent", "delivered", "shown"} + def is_authority(intent: str) -> bool: """Authority classification for the enforcement gate. Identity modules @@ -249,9 +257,7 @@ def escalate(self, queue: str, record: dict) -> dict: # untrusted record FIRST so the framing queue wins (a spoke must not be # able to redirect its escalation's audited queue). self.audit.append("escalation.raised", {**record, "queue": queue}) - if self.human_notifier is not None: - self.human_notifier(queue, record) - self.audit.append("human.notified", {**record, "queue": queue}) + self._notify(queue, record) return {"status": "escalated", "queue": queue} def register(self, agent_id: str, handler: Callable[[Envelope], None]): @@ -373,9 +379,43 @@ def queue_and_notify(self, queue_name: str, record: dict) -> None: reimplementing the pattern by hand.""" with self._lock: self.queues.setdefault(queue_name, []).append(record) - if self.human_notifier is not None: - self.human_notifier(queue_name, record) - self.audit.append("human.notified", {**record, "queue": queue_name}) + self._notify(queue_name, record) + + def _notify(self, queue: str, record: dict) -> None: + """Calls the human notifier and records what actually happened + (repair plan 1.1, 2026-10-13). The notifier's return value decides: + - a dict whose "status" is in NOTIFY_DELIVERED -> human.notified + - a dict with any other status, or an exception -> human.notify_failed + (with the status, http status, channel or error; never the body) + - no dict at all (a notifier that reports nothing) -> human.notified + with transport "not reported", so the record does not claim a + delivery the notifier never confirmed + A notifier that raises no longer aborts the send it was reporting on: + the failure is on the record and the hub carries on. The escalation + transport KPI (kpi.py) reports confirmed, unreported and failed + notifications separately.""" + if self.human_notifier is None: + return + try: + res = self.human_notifier(queue, record) + except Exception as e: # recorded, never raised past the hub + self.audit.append("human.notify_failed", + {**record, "queue": queue, "error": repr(e)[:300]}) + return + if not isinstance(res, dict): + self.audit.append("human.notified", + {**record, "queue": queue, "transport": "not reported"}) + return + status = res.get("status") + if status in NOTIFY_DELIVERED: + self.audit.append("human.notified", + {**record, "queue": queue, "transport_status": status}) + return + failed = {**record, "queue": queue, "notifier_status": status} + for k in ("http_status", "channel", "error"): + if k in res: + failed[f"notifier_{k}"] = str(res[k])[:300] if k == "error" else res[k] + self.audit.append("human.notify_failed", failed) def resume_loop_suspension(self, client_context_id: str, intent: str) -> dict: """Real gap, found 2026-07-17: once a (context, intent) pair diff --git a/dispatcher/kpi.py b/dispatcher/kpi.py index 47de3b2..a78e918 100644 --- a/dispatcher/kpi.py +++ b/dispatcher/kpi.py @@ -8,20 +8,21 @@ absent, never estimated. (Gate principle: absence of the expected artifact is reported, not papered over.) -Computable from Day 1/2 event kinds -(ack, envelope.persisted, reject, dead.letter, dedupe.hit, hold.clarification, - integrity.violation, hub.reflection, spoke.trace, turn.start, - openmind.drift, agentopenmind.tainted, agentopenmind.trace): +What it computes (docstring corrected 2026-10-13: an earlier list said the +last four were not computable; the code below computes all of them when +their events are on the log): - ack integrity rate (ack backed by prior persist of same envelope) - routing latency (persist ts -> ack ts, same envelope) - queue health (dead-letter rate, hold count, taint count) - - dedupe hits, signature/integrity rejections, sequence-gap incidents - -NOT computable yet - no emitting instrumentation exists: - - escalation transport time (no human-notification event) - - playbook completion / completion-proof coverage (no playbook events) - - heartbeat uptime (external watchdog does not exist) - - loop suspensions (no suspension event kind) + - dedupe hits, rejections, sequence-gap incidents, loop suspensions + - escalation transport time (escalation.raised -> human.notified); since + 2026-10-13 a failed notification is + human.notify_failed and never counts as a + transport, and a notifier that reported nothing + is counted apart as "not_reported" + - playbook completion (playbook.started / playbook.completed) + - heartbeat observations (needs at least two heartbeat events; gap + incidents need the Watchdog's cadence) """ from __future__ import annotations @@ -77,10 +78,15 @@ def compute_kpis(events: list[dict]) -> dict: "siding_resumes": len(by_kind["siding.resume"]), } - # escalation transport: raised -> human.notified, matched per queue+ts order + # escalation transport: raised -> human.notified, matched per queue+ts order. + # Only human.notified is a transport; human.notify_failed (2026-10-13) is + # counted as failed, and a notified entry whose notifier reported nothing + # ("transport": "not reported") is counted apart from confirmed ones. raised = by_kind["escalation.raised"] notified = by_kind["human.notified"] - if raised and notified: + esc_failed = [e for e in by_kind["human.notify_failed"] + if str(e.get("queue", "")).startswith("escalation.")] + if raised and (notified or esc_failed): n_by_q = defaultdict(list) for n in notified: n_by_q[n.get("queue")].append(n["ts"]) @@ -89,9 +95,16 @@ def compute_kpis(events: list[dict]) -> dict: cands = [t for t in n_by_q.get(r.get("queue"), []) if t >= r["ts"]] if cands: transports.append(min(cands) - r["ts"]) + esc_notified = [n for n in notified + if str(n.get("queue", "")).startswith("escalation.")] escalation_transport = {"computable": True, "n": len(transports), "unnotified": len(raised) - len(transports), - "max_s": max(transports) if transports else None} + "max_s": max(transports) if transports else None, + "confirmed": sum(1 for n in esc_notified + if n.get("transport") != "not reported"), + "not_reported": sum(1 for n in esc_notified + if n.get("transport") == "not reported"), + "notify_failed": len(esc_failed)} else: escalation_transport = {"computable": False, "missing": ["escalation.raised/human.notified pairs"]} diff --git a/dispatcher/notifier.py b/dispatcher/notifier.py index 05e8ff6..3a9ba4b 100644 --- a/dispatcher/notifier.py +++ b/dispatcher/notifier.py @@ -67,15 +67,19 @@ def send_sms_via_twilio(body: str, to_number: str | None = None, req.add_header("Authorization", f"Basic {auth}") req.add_header("Content-Type", "application/x-www-form-urlencoded") try: + # nosec B310: the URL is the fixed https://api.twilio.com address above, + # never caller-supplied, so no file:// or other scheme can reach urlopen. with urllib.request.urlopen(req, timeout=timeout) as resp: # nosec B310 return {"status": "sent", "http_status": resp.status, "is_fallback": False} except urllib.error.HTTPError as e: return {"status": "failed", "http_status": e.code, "is_fallback": True, - "fallback_reason": f"Twilio API error {e.code}: failover to local audit ledger", + "fallback_reason": f"Twilio API error {e.code}: not delivered; the hub " + f"records human.notify_failed", "body": e.read().decode(errors="replace")[:300]} except Exception as e: return {"status": "failed", "is_fallback": True, - "fallback_reason": f"Network exception: {e!r}", "error": repr(e)} + "fallback_reason": f"Network exception: {e!r}; not delivered, the hub " + f"records human.notify_failed", "error": repr(e)} def send_whatsapp_via_twilio(body: str, to_number: str | None = None, @@ -100,6 +104,7 @@ def send_whatsapp_via_twilio(body: str, to_number: str | None = None, req.add_header("Authorization", f"Basic {auth}") req.add_header("Content-Type", "application/x-www-form-urlencoded") try: + # nosec B310: fixed https://api.twilio.com URL, never caller-supplied. with urllib.request.urlopen(req, timeout=timeout) as resp: # nosec B310 return {"status": "sent", "http_status": resp.status, "channel": "whatsapp"} except urllib.error.HTTPError as e: diff --git a/tests/test_audit_log_damage.py b/tests/test_audit_log_damage.py new file mode 100644 index 0000000..dafa16c --- /dev/null +++ b/tests/test_audit_log_damage.py @@ -0,0 +1,222 @@ +"""A damaged or cut-off audit log is named, never a crash, and only a person +repairs it (repair plan 1.2, owner decision D4, 2026-10-13). + +Found in the 2026-10-13 snapshot: a partial last line (a process dying +part-way through an append) made AuditLog() itself raise a bare +JSONDecodeError, so nothing could start on that log, and verify_chain() - +which promises to name the first bad line - raised instead. +""" +import hashlib +import json +import os +import subprocess +import sys + +import pytest + +ROOT = os.path.dirname(os.path.dirname(os.path.abspath(__file__))) +sys.path.insert(0, ROOT) + +from dispatcher.core import AuditLog, AuditLogDamaged # noqa: E402 + + +def three(tmp_path, name="a.jsonl"): + p = str(tmp_path / name) + log = AuditLog(p) + for n in range(3): + log.append("x", {"n": n, "note": "café"}) + return p + + +def raw(p): + return open(p, "rb").read() + + +# ------------------------------------------------------------- refusing to open +@pytest.mark.parametrize("tail", [b'{"n": 3, "ts": 1, "ki', b'{"note": "caf\xc3', b"{", b"garbage"]) +def test_a_cut_off_last_write_is_named_not_a_crash(tmp_path, tail): + p = three(tmp_path) + open(p, "ab").write(tail) + with pytest.raises(AuditLogDamaged) as ei: + AuditLog(p) + e = ei.value + assert e.line == 4 and e.torn_tail is True and e.path == p + assert "damaged at line 4" in str(e) and "repair_torn_tail" in str(e) + assert "Nothing was written" in str(e) + c = AuditLog.check_file(p) + assert c == {"ok": False, "entries": 4, "break_at": 4, + "reason": "not a readable entry", "torn_tail": True} + + +def test_a_damaged_line_before_the_end_is_not_called_a_cut_off_write(tmp_path): + p = three(tmp_path) + lines = raw(p).split(b"\n") + lines[1] = b"{this is not json" + open(p, "wb").write(b"\n".join(lines)) + with pytest.raises(AuditLogDamaged) as ei: + AuditLog(p) + assert ei.value.line == 2 and ei.value.torn_tail is False + assert "investigate" in str(ei.value) and "repair_torn_tail(path) (" not in str(ei.value) + c = AuditLog.check_file(p) + assert c["break_at"] == 2 and c["torn_tail"] is False + + +def test_an_unreadable_last_line_that_ends_with_a_newline_is_damage_not_a_cut_off(tmp_path): + p = three(tmp_path) + open(p, "ab").write(b"not json at all\n") + with pytest.raises(AuditLogDamaged) as ei: + AuditLog(p) + assert ei.value.torn_tail is False + with pytest.raises(ValueError, match="no cut-off write to repair"): + AuditLog.repair_torn_tail(p) + + +def test_read_names_the_line_too(tmp_path): + p = three(tmp_path) + log = AuditLog(p) # opened while intact + open(p, "ab").write(b'{"half') + with pytest.raises(AuditLogDamaged) as ei: + log.read() + assert ei.value.line == 4 and ei.value.torn_tail is True + assert log.verify_chain()["break_at"] == 4 + + +def test_an_edited_line_still_reads_as_a_link_break(tmp_path): + p = three(tmp_path) + lines = raw(p).split(b"\n") + lines[0] = lines[0].replace(b'"n": 0', b'"n": 9') + open(p, "wb").write(b"\n".join(lines)) + c = AuditLog.check_file(p) + assert c["ok"] is False and c["break_at"] == 1 and c["torn_tail"] is False + assert "edited, deleted or reordered" in c["reason"] + + +# ----------------------------------------------------------------- the repair +def test_repair_moves_the_partial_line_aside_and_records_it(tmp_path): + p = three(tmp_path) + before = raw(p) + tail = b'{"n": 3, "ts": 1, "kind": "x", "prev_ha' + open(p, "ab").write(tail) + rec = AuditLog.repair_torn_tail(p) + assert rec["line"] == 4 and rec["bytes"] == len(tail) and rec["complete_entries"] == 3 + assert rec["sha256"] == hashlib.sha256(tail).hexdigest() + side = os.path.join(str(tmp_path), rec["side_file"]) + assert open(side, "rb").read() == tail + assert rec["side_file"].startswith("a.jsonl.torn-") and rec["side_file"].endswith(rec["sha256"][:12]) + after = raw(p) + assert after.startswith(before) # every complete entry kept, byte for byte + log = AuditLog(p) + entries = log.read() + assert len(entries) == 4 and entries[-1]["kind"] == "audit.tail_quarantined" + assert entries[-1]["sha256"] == rec["sha256"] + assert log.verify_chain() == {"ok": True, "entries": 4, "break_at": None} + log.append("y", {"after": True}) + assert AuditLog.check_file(p)["ok"] and len(AuditLog(p).read()) == 5 + + +@pytest.mark.parametrize("crlf", [False, True]) +def test_a_repair_interrupted_before_it_records_itself_leaves_exactly_the_complete_entries(tmp_path, monkeypatch, crlf): + # The process can die between the cut and the audit.tail_quarantined entry. + # What is left on disk must then be the complete entries byte for byte - + # a clean, newline-terminated log, not one cut a byte short. + p = three(tmp_path) + data = raw(p) + if crlf: + data = data.replace(b"\n", b"\r\n") + open(p, "wb").write(data + b'{"half') + + def died(self, *a, **k): + raise RuntimeError("process died") + monkeypatch.setattr(AuditLog, "append", died) + with pytest.raises(RuntimeError): + AuditLog.repair_torn_tail(p) + assert raw(p) == data + monkeypatch.undo() + assert AuditLog.check_file(p) == {"ok": True, "entries": 3, "break_at": None} + + +def test_repair_refuses_when_the_chain_is_broken_before_the_cut_and_changes_nothing(tmp_path): + p = three(tmp_path) + lines = raw(p).split(b"\n") + lines[0] = lines[0].replace(b'"n": 0', b'"n": 9') + open(p, "wb").write(b"\n".join(lines) + b'{"half') + before = raw(p) + with pytest.raises(ValueError, match="chain breaks at line 1"): + AuditLog.repair_torn_tail(p) + assert raw(p) == before + assert not [f for f in os.listdir(str(tmp_path)) if ".torn-" in f] + + +def test_repair_refuses_when_an_earlier_line_is_unreadable(tmp_path): + p = three(tmp_path) + lines = raw(p).split(b"\n") + lines[1] = b"{nope" + open(p, "wb").write(b"\n".join(lines) + b'{"half') + before = raw(p) + with pytest.raises(AuditLogDamaged) as ei: + AuditLog.repair_torn_tail(p) + assert ei.value.line == 2 and raw(p) == before + + +def test_repair_refuses_when_there_is_nothing_to_repair(tmp_path): + p = three(tmp_path) + before = raw(p) + with pytest.raises(ValueError, match="no cut-off write"): + AuditLog.repair_torn_tail(p) + assert raw(p) == before + + +# ------------------------------------------- a complete entry missing its newline +def test_a_complete_last_entry_without_its_newline_opens_and_appends_cleanly(tmp_path): + p = three(tmp_path) + data = raw(p) # read before opening for write + open(p, "wb").write(data.rstrip(b"\n")) + with pytest.raises(ValueError, match="only lacks its newline"): + AuditLog.repair_torn_tail(p) + log = AuditLog(p) + log.append("y", {"next": 1}) + assert log.verify_chain() == {"ok": True, "entries": 4, "break_at": None} + assert len(log.read()) == 4 + + +# ------------------------------------------------------------------- Windows +def test_windows_line_endings_check_and_repair(tmp_path): + p = three(tmp_path) + data = raw(p) # read before opening for write + open(p, "wb").write(data.replace(b"\n", b"\r\n") + b'{"half') + assert AuditLog.check_file(p)["break_at"] == 4 + rec = AuditLog.repair_torn_tail(p) + assert rec["complete_entries"] == 3 + assert AuditLog(p).verify_chain()["ok"] + + +# ------------------------------------------------------------------- anchors +def test_an_anchor_before_the_cut_still_verifies(tmp_path): + p = three(tmp_path) + log = AuditLog(p) + anchor = log.anchor() + open(p, "ab").write(b'{"half') + assert log.verify_anchor(anchor) == {"ok": True, "reason": None} + assert log.anchor()["entries"] == 4 + + +# --------------------------------------------------------------------- the CLI +def cli(*args): + return subprocess.run([sys.executable, os.path.join(ROOT, "tools", "audit_repair.py"), *args], + capture_output=True, text=True) + + +def test_the_cli_checks_repairs_and_refuses(tmp_path): + p = three(tmp_path) + r = cli(p, "--check") + assert r.returncode == 0 and json.loads(r.stdout)["ok"] is True + open(p, "ab").write(b'{"half') + r = cli(p, "--check") + assert r.returncode == 1 and json.loads(r.stdout)["torn_tail"] is True + r = cli(p) + out = json.loads(r.stdout) + assert r.returncode == 0 and out["repaired"] is True and out["chain"]["ok"] is True + r = cli(p) + assert r.returncode == 2 and json.loads(r.stdout)["repaired"] is False + r = cli(str(tmp_path / "missing.jsonl")) + assert r.returncode == 2 diff --git a/tests/test_notification_truth.py b/tests/test_notification_truth.py new file mode 100644 index 0000000..0ee9e62 --- /dev/null +++ b/tests/test_notification_truth.py @@ -0,0 +1,143 @@ +"""The record says a person was notified only when the notifier confirms it +(repair plan 1.1, 2026-10-13). + +Found in the 2026-10-13 snapshot: Hub.escalate and Hub.queue_and_notify +wrote human.notified after every notifier call and ignored its result, so a +Twilio 401 with the placeholder account went on the hash chain as a person +notified, and the escalation transport KPI was computed from it. +""" +import io +import os +import sys +import urllib.error + +import pytest + +sys.path.insert(0, os.path.join(os.path.dirname(__file__), "..")) + +from dispatcher.after_action import generate_report # noqa: E402 +from dispatcher.core import AuditLog, Envelope, Routes # noqa: E402 +from dispatcher.hub import Hub, NOTIFY_DELIVERED # noqa: E402 +from dispatcher.kpi import compute_kpis # noqa: E402 + +FIXTURE = os.path.join(os.path.dirname(__file__), "routes_fixture.json") + + +def hub_with(tmp_path, notifier): + return Hub(Routes(FIXTURE), AuditLog(str(tmp_path / "a.jsonl")), human_notifier=notifier) + + +def kinds(hub): + return [e["kind"] for e in hub.audit.read()] + + +def last(hub, kind): + return [e for e in hub.audit.read() if e["kind"] == kind][-1] + + +def test_a_failed_send_is_recorded_as_failed_not_notified(tmp_path): + hub = hub_with(tmp_path, lambda q, r: {"status": "failed", "http_status": 401, + "body": "secret-ish twilio body"}) + out = hub.escalate("escalation.hot_lead", {"client_context_id": "C1", "reason": "call now"}) + assert out == {"status": "escalated", "queue": "escalation.hot_lead"} + assert "human.notified" not in kinds(hub) + f = last(hub, "human.notify_failed") + assert f["queue"] == "escalation.hot_lead" and f["notifier_status"] == "failed" + assert f["notifier_http_status"] == 401 and f["client_context_id"] == "C1" + assert "body" not in f and "secret-ish" not in str(f) + k = compute_kpis(hub.audit.read())["escalation_transport_time"] + assert k["n"] == 0 and k["unnotified"] == 1 and k["notify_failed"] == 1 and k["confirmed"] == 0 + + +@pytest.mark.parametrize("status", sorted(NOTIFY_DELIVERED)) +def test_a_confirmed_send_is_recorded_as_notified(tmp_path, status): + hub = hub_with(tmp_path, lambda q, r: {"status": status}) + hub.escalate("escalation.complaint", {"client_context_id": "C2"}) + n = last(hub, "human.notified") + assert n["transport_status"] == status and n["queue"] == "escalation.complaint" + assert "human.notify_failed" not in kinds(hub) + k = compute_kpis(hub.audit.read())["escalation_transport_time"] + assert k["n"] == 1 and k["confirmed"] == 1 and k["not_reported"] == 0 and k["notify_failed"] == 0 + + +@pytest.mark.parametrize("status", ["queued", "failed", "", None, "SENT", "ok"]) +def test_any_other_status_is_a_failure(tmp_path, status): + hub = hub_with(tmp_path, lambda q, r: {"status": status}) + hub.escalate("escalation.legal_line", {"client_context_id": "C3"}) + assert "human.notified" not in kinds(hub) + assert last(hub, "human.notify_failed")["notifier_status"] == status + + +def test_a_notifier_that_reports_nothing_is_kept_apart(tmp_path): + hub = hub_with(tmp_path, lambda q, r: None) + hub.escalate("escalation.hot_lead", {"client_context_id": "C4"}) + n = last(hub, "human.notified") + assert n["transport"] == "not reported" and "transport_status" not in n + k = compute_kpis(hub.audit.read())["escalation_transport_time"] + assert k["n"] == 1 and k["not_reported"] == 1 and k["confirmed"] == 0 + + +def test_a_notifier_that_raises_is_recorded_and_the_hub_carries_on(tmp_path): + def boom(q, r): + raise ConnectionError("network down") + hub = hub_with(tmp_path, boom) + out = hub.escalate("escalation.hot_lead", {"client_context_id": "C5"}) + assert out["status"] == "escalated" + assert hub.queues["escalation.hot_lead"][-1]["client_context_id"] == "C5" + f = last(hub, "human.notify_failed") + assert "network down" in f["error"] and "human.notified" not in kinds(hub) + + +def test_a_raising_notifier_does_not_abort_a_send(tmp_path): + # unknown intent -> clarification hold -> queue_and_notify; and a crashing + # handler -> escalation.system_error. Both used to raise out of send(). + def boom(q, r): + raise RuntimeError("pager crashed") + hub = hub_with(tmp_path, boom) + held = hub.send(Envelope(from_agent="01", to_agent="02", intent="no.such.intent", + client_context_id="C6", payload={}, provenance={"source": "t"})) + assert held["status"] == "held" + + def crash(env): + raise ValueError("handler bug") + hub.register("02", crash) + dead = hub.send(Envelope(from_agent="01", to_agent="02", intent="lead.captured", + client_context_id="C6", payload={}, provenance={"source": "t"})) + assert dead["status"] == "dead.letter" + assert kinds(hub).count("human.notify_failed") == 2 + + +def test_the_record_cannot_overwrite_the_framing(tmp_path): + hub = hub_with(tmp_path, lambda q, r: {"status": "failed"}) + hub.escalate("escalation.hot_lead", {"client_context_id": "C7", "queue": "fake", + "notifier_status": "sent"}) + f = last(hub, "human.notify_failed") + assert f["queue"] == "escalation.hot_lead" and f["notifier_status"] == "failed" + hub2 = Hub(Routes(FIXTURE), AuditLog(str(tmp_path / "b.jsonl")), + human_notifier=lambda q, r: {"status": "sent"}) + hub2.escalate("escalation.hot_lead", {"client_context_id": "C7", "transport_status": "x"}) + assert last(hub2, "human.notified")["transport_status"] == "sent" + + +def test_the_shipped_sms_notifier_with_a_401_is_a_failure(tmp_path, monkeypatch): + import dispatcher.notifier as n + + def reject(req, timeout=5.0): + raise urllib.error.HTTPError(req.full_url, 401, "Unauthorized", {}, + io.BytesIO(b'{"code":20003,"message":"Authenticate"}')) + monkeypatch.setattr(n.urllib.request, "urlopen", reject) + hub = hub_with(tmp_path, n.sms_human_notifier) + hub.escalate("escalation.hot_lead", {"client_context_id": "C8", "reason": "hot"}) + f = last(hub, "human.notify_failed") + assert f["notifier_status"] == "failed" and f["notifier_http_status"] == 401 + assert "human.notified" not in kinds(hub) + assert "20003" not in str(f) # the provider's response body stays off the chain + + +def test_the_after_action_report_says_the_notification_failed(tmp_path): + hub = hub_with(tmp_path, lambda q, r: {"status": "failed", "http_status": 401}) + hub.escalate("escalation.hot_lead", {"client_context_id": "C9"}) + report = generate_report(hub.audit.read(), "P11", "r1", "C9", steps=[]) + assert "NOTIFICATION FAILED (failed) - no person was reached" in report + assert "transport" not in report.split("## escalations")[1].split("##")[0].replace( + "NOTIFICATION FAILED", "") diff --git a/tools/audit_repair.py b/tools/audit_repair.py new file mode 100644 index 0000000..4b33a0e --- /dev/null +++ b/tools/audit_repair.py @@ -0,0 +1,58 @@ +"""audit_repair - check an audit log, and recover from a write that was cut off. + +Added 2026-10-13 (repair plan 1.2, owner decision D4). A process that dies +part-way through writing an audit line leaves a partial last line. The hub +then refuses to open the log (AuditLogDamaged names the line) rather than +guess. This tool is the person's way back: + + python3 tools/audit_repair.py --check + Reads only. Prints the chain check as JSON: ok, entries, break_at, + and on a break the reason and whether it is a cut-off last write. + Exit 0 when the chain is intact, 1 when it is not. + + python3 tools/audit_repair.py + Repairs a cut-off last write ONLY: the partial line is moved to a + side file next to the log (.torn--), every + complete entry is kept, and an audit.tail_quarantined entry records + the repair on the chain. Anything else - a damaged or edited line + before the last one, a broken chain - is refused and nothing changes. + Exit 0 when repaired, 2 when refused. + +Stop whatever process writes to the log (a console session, a desk) first. +""" +from __future__ import annotations + +import argparse +import json +import os +import sys + +sys.path.insert(0, os.path.join(os.path.dirname(os.path.abspath(__file__)), "..")) + +from dispatcher.core import AuditLog, AuditLogDamaged # noqa: E402 + + +def main(argv=None) -> int: + ap = argparse.ArgumentParser(description=__doc__.split("\n\n")[0]) + ap.add_argument("log", help="path to the audit log (.jsonl)") + ap.add_argument("--check", action="store_true", help="check only; change nothing") + args = ap.parse_args(argv) + if not os.path.exists(args.log): + print(json.dumps({"error": f"{args.log}: no such file"})) + return 2 + if args.check: + r = AuditLog.check_file(args.log) + print(json.dumps(r)) + return 0 if r["ok"] else 1 + try: + rec = AuditLog.repair_torn_tail(args.log) + except (AuditLogDamaged, ValueError) as e: + print(json.dumps({"repaired": False, "refused": str(e)})) + return 2 + print(json.dumps({"repaired": True, **rec, + "chain": AuditLog.check_file(args.log)})) + return 0 + + +if __name__ == "__main__": + sys.exit(main()) From fb7a04f52243e00d8b84985b0e703eaba3a37de6 Mon Sep 17 00:00:00 2001 From: Claude Date: Tue, 13 Oct 2026 17:14:54 +0000 Subject: [PATCH 03/10] Phase 1.6: core CI runs the identity tests for real, on Python 3.10/3.12/3.13 and Windows Until now every core CI run skipped the 5 identity-pinned tests in tests/test_day3.py (no listing identity next to the clone), so green said nothing about them. New job with-identity clones listing-assistants at main, sets IDENTITY_DIR, and fails on any skip. Matrix: ubuntu 3.10 (the declared floor), 3.12, 3.13; windows 3.12 with PYTHONUTF8=0. The original job stays as the clone-alone path and now prints its skips (-rs). Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_01CRunDQmfmnZdtJiP78e8WR --- .github/workflows/ci.yml | 44 +++++++++++++++++++++++++++++++++++++++- 1 file changed, 43 insertions(+), 1 deletion(-) diff --git a/.github/workflows/ci.yml b/.github/workflows/ci.yml index 60194a8..5053100 100644 --- a/.github/workflows/ci.yml +++ b/.github/workflows/ci.yml @@ -2,6 +2,9 @@ name: ci on: [push, pull_request] jobs: suite: + # The repo alone, as a buyer first clones it: no listing identity next + # to it, so the 5 identity-pinned tests in tests/test_day3.py skip. + # They are run for real, with zero skips allowed, in with-identity below. runs-on: ubuntu-latest steps: - uses: actions/checkout@v4 @@ -11,4 +14,43 @@ jobs: # CI run installed bare pytest and died on collection because # analysis.py imports the pillar packages at module level. - run: pip install -e ".[pillars,crypto,dev]" - - run: python -m pytest -q + - run: python -m pytest -q -rs + + with-identity: + # Added 2026-10-13 (repair plan 1.6). Until then every CI run skipped the + # 5 identity tests, so a green badge said nothing about them. Here the + # real listing-assistants identity is cloned and ANY skip fails the job. + # Python 3.10 is the floor pyproject.toml declares; Windows runs because + # the listing product ships a Windows desk on this core. + strategy: + fail-fast: false + matrix: + include: + - {os: ubuntu-latest, python: "3.10"} + - {os: ubuntu-latest, python: "3.12"} + - {os: ubuntu-latest, python: "3.13"} + - {os: windows-latest, python: "3.12"} + runs-on: ${{ matrix.os }} + timeout-minutes: 30 + defaults: + run: + shell: bash + steps: + - uses: actions/checkout@v4 + - uses: actions/setup-python@v5 + with: {python-version: "${{ matrix.python }}"} + - run: pip install -e ".[pillars,crypto,dev]" + - name: clone the listing identity at main + run: git clone --depth 1 https://github.com/QuietFireAI/listing-assistants.git "$RUNNER_TEMP/listing-assistants" + - name: full suite, no skips allowed + env: + # Keep Windows on its real default text encoding (cp1252), so a + # missing encoding="utf-8" fails here and not on a buyer's machine. + PYTHONUTF8: "0" + run: | + export IDENTITY_DIR="$RUNNER_TEMP/listing-assistants" + python -m pytest -q -rs | tee out.txt + if grep -qi "skipped" out.txt; then + echo "::error::identity tests skipped - the identity was not found or not loaded" + exit 1 + fi From 04e80ffa82d43b6e171275366581051336a16161 Mon Sep 17 00:00:00 2001 From: Claude Date: Tue, 13 Oct 2026 17:17:42 +0000 Subject: [PATCH 04/10] Watchdog test: exact timestamps instead of real sleeps (failed on Windows CI) Core CI run 38437120185, windows-latest 3.12: gap_incidents 2, expected 1. The test slept 0.01 s then 0.06 s against a 0.01 s cadence (incident above 0.02 s); the Windows 15.6 ms timer tick plus a slow fsync pushed the first gap over too. A test fault, not a Watchdog fault. heartbeat() is still checked on a real hub; the gap logic now gets fixed timestamps, including a gap of exactly 2x cadence (not an incident) and fewer than 2 beats. Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_01CRunDQmfmnZdtJiP78e8WR --- tests/test_day3.py | 19 +++++++++++++++---- 1 file changed, 15 insertions(+), 4 deletions(-) diff --git a/tests/test_day3.py b/tests/test_day3.py index bd66b6f..a6ed313 100644 --- a/tests/test_day3.py +++ b/tests/test_day3.py @@ -414,12 +414,23 @@ def test_consent_gate_holds_without_recorded_consent(tmp_path): # ----------------------------------------------------- heartbeat + playbook KPI def test_watchdog_names_gap_incidents_never_percentages(tmp_path): from dispatcher.runs import heartbeat, Watchdog - import time as _t hub = make_hub(tmp_path) - heartbeat(hub); _t.sleep(0.01); heartbeat(hub); _t.sleep(0.06); heartbeat(hub) - obs = Watchdog(cadence_s=0.01).observe(hub.audit.read()) - assert obs["computable"] and obs["beats"] == 3 and obs["gap_incidents"] == 1 + heartbeat(hub); heartbeat(hub); heartbeat(hub) + beats = [e for e in hub.audit.read() if e["kind"] == "heartbeat"] + assert len(beats) == 3 and all(e["source"] == "hub" for e in beats) + # The gap logic gets exact timestamps. It used to get real sleeps + # (0.01 s, then 0.06 s, cadence 0.01 s), and on Windows the 15.6 ms + # timer tick plus a slow fsync pushed the FIRST gap past 2x cadence too + # (core CI run 38437120185: gap_incidents 2, not 1). + events = [{"kind": "heartbeat", "ts": t} for t in (100.0, 101.0, 103.0, 105.5)] + events.append({"kind": "other", "ts": 200.0}) # not a beat + obs = Watchdog(cadence_s=1.0).observe(events) + # gaps 1.0, 2.0, 2.5: only a gap MORE than twice the cadence is an incident + assert obs["computable"] and obs["beats"] == 4 and obs["gap_incidents"] == 1 + assert obs["max_gap_s"] == 2.5 and obs["span_s"] == 5.5 assert "uptime" not in obs # no invented % + assert Watchdog(cadence_s=1.0).observe(events[:1])["computable"] is False + assert Watchdog(cadence_s=1.0).observe(hub.audit.read())["beats"] == 3 def test_playbook_completion_counted_from_log_only(tmp_path): From 87aa5fffbe20dd8ed45c7705d6714c494f07ea3d Mon Sep 17 00:00:00 2001 From: Claude Date: Tue, 13 Oct 2026 17:32:30 +0000 Subject: [PATCH 05/10] Docs: test counts as they are now, splitvantage's own suite is 14 - README quickstart: 198 tests with the listing identity (was 137). - PILLAR_TESTING_MANUAL: 193 passed + 5 skipped alone, 198 with the identity (was 132 / 137); says CI runs both. splitvantage's own suite at the pinned commit is 14 tests (was stated 12) - each pinned pillar's suite was run 2026-10-13: 9, 6, 11, 27, 20, 14. - SKILL.md: 193 + 5 / 198 (was "89 doctrine tests"). README-BUILD.md's counts are a dated build log and stay as written. Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_01CRunDQmfmnZdtJiP78e8WR --- PILLAR_TESTING_MANUAL.md | 10 ++++++---- README.md | 2 +- SKILL.md | 2 +- 3 files changed, 8 insertions(+), 6 deletions(-) diff --git a/PILLAR_TESTING_MANUAL.md b/PILLAR_TESTING_MANUAL.md index d8181ab..9be0b4f 100644 --- a/PILLAR_TESTING_MANUAL.md +++ b/PILLAR_TESTING_MANUAL.md @@ -28,15 +28,17 @@ EXPECTED: seven installs, no errors. (PEP 668 systems: add Run every pillar's OWN suite from its own clone: `python3 -m pytest -q` EXPECTED, exactly: open-mind 9 | before-turn 6 | pre-response-selfcheck 11 | -agent-open-mind 27 | sleep-marks 20 | splitvantage 12. Any other number = +agent-open-mind 27 | sleep-marks 20 | splitvantage 14 (at the commits pinned +in pyproject.toml; checked 2026-10-13). Any other number = that pillar regressed; stop, report the raw failure. Do not proceed to integration on a broken pillar - the set cannot be validated on a bad part. Then the dispatcher's suite from its clone: `python3 -m pytest tests/ -q` -EXPECTED: 132 passed, 5 skipped. (The 5 identity-dependent tests activate +EXPECTED: 193 passed, 5 skipped. (The 5 identity-dependent tests activate when IDENTITY_DIR points at a listing-assistants clone, or when one sits at -the conventional sibling path `../listing-assistants` - then 137 passed, as -of 2026-10-12.) +the conventional sibling path `../listing-assistants` - then 198 passed, as +of 2026-10-13. CI runs both: the clone alone, and with the listing identity +on Linux 3.10/3.12/3.13 and Windows, where any skip fails the job.) ## PHASE 2 - Six pillars together on the bare dispatcher diff --git a/README.md b/README.md index 3a1d20c..5f6621e 100644 --- a/README.md +++ b/README.md @@ -65,7 +65,7 @@ git clone https://github.com/QuietFireAI/dispatcher-agents cd dispatcher-agents pip install -e ".[pillars,crypto,dev]" # routing core is zero-dep; signing needs crypto (Ed25519) git clone https://github.com/QuietFireAI/listing-assistants ../listing-assistants -IDENTITY_DIR=../listing-assistants python3 -m pytest tests/ # 137 tests vs the real 52-route track +IDENTITY_DIR=../listing-assistants python3 -m pytest tests/ # 198 tests vs the real 52-route track IDENTITY_DIR=../listing-assistants python3 demo/run_p11_demo.py # real spokes chain 11 envelopes from 2 signals # Identity-gated tests target the repo bundled at IDENTITY_DIR (default: a fixture track); point IDENTITY_DIR at listing-assistants for the real 52-route run. diff --git a/SKILL.md b/SKILL.md index a28e761..e7dee4d 100644 --- a/SKILL.md +++ b/SKILL.md @@ -73,7 +73,7 @@ pip install -e ".[pillars,crypto,dev]" # pillars pulled from source, never ven ### Verify before claiming anything works ```bash -python -m pytest tests/ # 89 doctrine tests (identity-gated tests activate with IDENTITY_DIR) +python -m pytest tests/ # 193 passed + 5 skipped; 198 passed with IDENTITY_DIR at a listing-assistants clone python demo/baseline_run.py # must print all six pillar events nonzero python tools/kpi_gate.py baseline-out/audit-.jsonl \ --taints-expected 1 --selfcheck-bait-expected 1 From ccbfb21f8bd0ac249689bce249a7600450ca8bc9 Mon Sep 17 00:00:00 2001 From: Claude Date: Tue, 13 Oct 2026 18:19:12 +0000 Subject: [PATCH 06/10] Phase 1.4: full mutation sweep of the 16 core files - 804 of 808 killed, 4 equivalent with evidence Method (tools/mutation_sweep.py, now in the repo): one AST-span mutant at a time (comparison, and/or, not, constants, negated tests, return None, raise -> pass, call -> pass), the full suite with the listing identity against each, in a copy of the repo, baseline checked first. First sweep (fb7a04f): 807 mutants, 593 killed, 214 survived. They clustered where the core had no direct tests: the after-action report, hub integrity-violation and dead-letter records, the unconfirmed-audience marker, wildcard and sender/receiver route limits, anchors, the hash format, disk flushes, module audit records. 90 new tests (tests/test_sweep_*_2026_10_13.py). Code changes: - loader.py: the routes check was an assert (stripped under python -O, an empty track would load); now an explicit check. - core.py: a dead variable in repair_torn_tail removed. Final sweep with the packaged tool on this commit: 808 mutants, 804 killed, 4 survived, 0 timeouts. The 4 are equivalent, each with run evidence in findings/MUTATION_SWEEP_2026-10-13.md (chunk size of a streamed hash; a route clause subsumed by the line's first test; a flush on a handle that only truncates; Exception args set before __init__). One unexplained single failure in run 2 is recorded there; it did not recur in 25 reruns. EVIDENCE.md: rows for decline, notification truth, a cut-off record, pinned pillars, the identity CI job, the sweep. Counts: 283 passed + 5 skipped alone, 288 with the listing identity. Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_01CRunDQmfmnZdtJiP78e8WR --- EVIDENCE.md | 6 + PILLAR_TESTING_MANUAL.md | 4 +- README.md | 2 +- SKILL.md | 2 +- dispatcher/core.py | 4 +- dispatcher/loader.py | 6 +- findings/MUTATION_SWEEP_2026-10-13.md | 105 ++++++ tests/test_sweep_core_hub_2026_10_13.py | 467 ++++++++++++++++++++++++ tests/test_sweep_modules_2026_10_13.py | 403 ++++++++++++++++++++ tests/test_sweep_reports_2026_10_13.py | 184 ++++++++++ tools/mutation_sweep.py | 180 +++++++++ 11 files changed, 1356 insertions(+), 7 deletions(-) create mode 100644 findings/MUTATION_SWEEP_2026-10-13.md create mode 100644 tests/test_sweep_core_hub_2026_10_13.py create mode 100644 tests/test_sweep_modules_2026_10_13.py create mode 100644 tests/test_sweep_reports_2026_10_13.py create mode 100644 tools/mutation_sweep.py diff --git a/EVIDENCE.md b/EVIDENCE.md index e3ba291..f68eed4 100644 --- a/EVIDENCE.md +++ b/EVIDENCE.md @@ -133,5 +133,11 @@ Any new claim added to any README in this stack must be added to this ledger fir | Loop protection suspends per (context,intent) at threshold; retries never inflate the count | **MEASURED** | test_day3.py; threshold 20 RATIFIED (owner, 2026-07-17) as a deliberate placeholder, revisit when after-action data exists | | Manners re-injection triggers instrumented (constants + backstop), fade-trackable per run | **MEASURED** | audit events + KPI + after-action section; conduct efficacy itself is UNTESTED | | Ed25519 authority: verifier cannot forge; tamper/forge reject; boot manifest signable incl. MANNERS.md hash | **MEASURED** | test_day3.py; asymmetric tier, optional cryptography dep | +| A held outbound message can be declined by the same signed key that releases it; a decline drops it unsent and is on the chain; a release-signed key cannot decline and a decline-signed key cannot release (2026-10-12) | **MEASURED** | tests/test_absolute_signal.py decline tests; tests/test_sweep_core_hub_2026_10_13.py (unsigned and registry-refused answers are integrity violations; reason kept to 500 characters) | +| The record says a person was notified only when the notifier reports the message delivered (sent / delivered / shown); a failed or raising notifier is recorded as human.notify_failed, and the escalation KPI counts confirmed, unreported and failed apart (2026-10-13) | **MEASURED** | tests/test_notification_truth.py (16); before this, a Twilio 401 went on the chain as human.notified | +| A cut-off or unreadable audit line is named (line, reason, cut-off or not) and nothing opens on that log; a person repairs a cut-off last write with tools/audit_repair.py, which keeps every complete entry byte for byte and records the repair; any other damage is refused unchanged (2026-10-13) | **MEASURED** | tests/test_audit_log_damage.py (18), including Windows line endings and a repair interrupted before it records itself | +| The six pillar packages are pinned to exact commits; their own suites pass at those commits (9, 6, 11, 27, 20, 14) | **MEASURED** | pyproject.toml; each pinned pillar's suite run 2026-10-13 | +| The core suite runs the listing identity tests on every push, on Linux (Python 3.10, 3.12, 3.13) and Windows, and fails on any skip | **MEASURED** | .github/workflows/ci.yml job with-identity; first green run 38437495999 | +| Every mutant the 2026-10-13 sweep put into the 16 core files is killed by the core suite, except 4 argued equivalent with evidence | **MEASURED** | findings/MUTATION_SWEEP_2026-10-13.md; tools/mutation_sweep.py reproduces it. Mutation testing shows the tests notice these changes; it does not prove the code correct | Not claimed for the runtime: production readiness; real-spoke latency; conduct-level efficacy of manners; licensed legal review of vertical content. diff --git a/PILLAR_TESTING_MANUAL.md b/PILLAR_TESTING_MANUAL.md index 9be0b4f..0659a6a 100644 --- a/PILLAR_TESTING_MANUAL.md +++ b/PILLAR_TESTING_MANUAL.md @@ -34,9 +34,9 @@ that pillar regressed; stop, report the raw failure. Do not proceed to integration on a broken pillar - the set cannot be validated on a bad part. Then the dispatcher's suite from its clone: `python3 -m pytest tests/ -q` -EXPECTED: 193 passed, 5 skipped. (The 5 identity-dependent tests activate +EXPECTED: 283 passed, 5 skipped. (The 5 identity-dependent tests activate when IDENTITY_DIR points at a listing-assistants clone, or when one sits at -the conventional sibling path `../listing-assistants` - then 198 passed, as +the conventional sibling path `../listing-assistants` - then 288 passed, as of 2026-10-13. CI runs both: the clone alone, and with the listing identity on Linux 3.10/3.12/3.13 and Windows, where any skip fails the job.) diff --git a/README.md b/README.md index 5f6621e..80cc426 100644 --- a/README.md +++ b/README.md @@ -65,7 +65,7 @@ git clone https://github.com/QuietFireAI/dispatcher-agents cd dispatcher-agents pip install -e ".[pillars,crypto,dev]" # routing core is zero-dep; signing needs crypto (Ed25519) git clone https://github.com/QuietFireAI/listing-assistants ../listing-assistants -IDENTITY_DIR=../listing-assistants python3 -m pytest tests/ # 198 tests vs the real 52-route track +IDENTITY_DIR=../listing-assistants python3 -m pytest tests/ # 288 tests vs the real 52-route track IDENTITY_DIR=../listing-assistants python3 demo/run_p11_demo.py # real spokes chain 11 envelopes from 2 signals # Identity-gated tests target the repo bundled at IDENTITY_DIR (default: a fixture track); point IDENTITY_DIR at listing-assistants for the real 52-route run. diff --git a/SKILL.md b/SKILL.md index e7dee4d..7d9071e 100644 --- a/SKILL.md +++ b/SKILL.md @@ -73,7 +73,7 @@ pip install -e ".[pillars,crypto,dev]" # pillars pulled from source, never ven ### Verify before claiming anything works ```bash -python -m pytest tests/ # 193 passed + 5 skipped; 198 passed with IDENTITY_DIR at a listing-assistants clone +python -m pytest tests/ # 283 passed + 5 skipped; 288 passed with IDENTITY_DIR at a listing-assistants clone python demo/baseline_run.py # must print all six pillar events nonzero python tools/kpi_gate.py baseline-out/audit-.jsonl \ --taints-expected 1 --selfcheck-bait-expected 1 diff --git a/dispatcher/core.py b/dispatcher/core.py index 8b747a9..8f63664 100644 --- a/dispatcher/core.py +++ b/dispatcher/core.py @@ -250,7 +250,7 @@ def repair_torn_tail(cls, path: str) -> dict: raise ValueError(f"{path}: the last line is a complete entry that only " f"lacks its newline - nothing to repair; the log opens as is") prefix = data[:cut] - prev, n = cls.GENESIS, 0 + prev = cls.GENESIS for i, raw in enumerate(prefix.split(b"\n"), 1): if not raw.strip(): continue @@ -263,7 +263,7 @@ def repair_torn_tail(cls, path: str) -> dict: raise ValueError(f"{path}: the chain breaks at line {i}, before the " f"cut-off line - this is not only a cut-off write; " f"nothing was changed") - prev, n = e["entry_hash"], i + prev = e["entry_hash"] torn_line = prefix.count(b"\n") + 1 digest = hashlib.sha256(tail).hexdigest() stamp = time.strftime("%Y%m%dT%H%M%SZ", time.gmtime()) diff --git a/dispatcher/loader.py b/dispatcher/loader.py index d6ab2bf..71454ac 100644 --- a/dispatcher/loader.py +++ b/dispatcher/loader.py @@ -46,7 +46,11 @@ def load_identity(root: str) -> Identity: try: routes_doc = json.load(open(routes_path, encoding="utf-8")) routes = routes_doc["routes"] - assert isinstance(routes, list) and routes + # an explicit check, not assert: python -O strips asserts, and an + # empty or non-list track would then load (found by the 2026-10-13 + # mutation sweep) + if not (isinstance(routes, list) and routes): + raise ValueError("'routes' must be a non-empty list") except Exception as e: raise ValueError(f"routes.json present but invalid: {e!r}") diff --git a/findings/MUTATION_SWEEP_2026-10-13.md b/findings/MUTATION_SWEEP_2026-10-13.md new file mode 100644 index 0000000..e3c60e7 --- /dev/null +++ b/findings/MUTATION_SWEEP_2026-10-13.md @@ -0,0 +1,105 @@ +# Mutation sweep of the core, 2026-10-13 + +Repair plan step 1.4. Every one of the 16 core files that listing-assistants +vendors was mutated, one change at a time, and the whole core suite was run +against each change. A change the suite does not notice (a *surviving +mutant*) marks behaviour no test holds. + +## Method + +- **Files:** the 16 in `tools/sync_core.py`'s list on the listing side + (`__init__.py` yields no mutants). +- **Operators:** comparison flipped; `and`/`or` swapped; `not` dropped; + `True`/`False` swapped and integers raised by one (docstrings skipped); an + `if`/`while`/ternary/`assert` test negated; `return ` made + `return None`; `raise` made `pass`; a bare call statement made `pass`. + Each is an exact replacement of a span of source found through the AST; + every mutant compiles. +- **Run:** the full core suite (`pytest -x`) with `IDENTITY_DIR` at a + listing-assistants clone, so the identity tests run too. Killed = the + suite fails; survived = it passes; timeout after 180 s. Each job first + runs the unmutated suite and refuses to start if it fails. +- **Isolation:** mutants are written into a copy of the repository, never + the working tree. +- **Reproduce:** `IDENTITY_DIR=../listing-assistants python tools/mutation_sweep.py --out sweep.jsonl --jobs 2` + +## Results + +| Run | Code / tests | Mutants | Killed | Survived | +|---|---|---|---|---| +| 1. First sweep | fb7a04f, 198 tests | 807 | 593 (73.5%) | 214 | +| 2. Survivors again | 87aa5ff (watchdog test rewritten), 198 tests | 214 | 7 | 207 | +| 3. Survivors after the new tests | working tree, 286 tests | 207 | 200 | 7 (one of the 207 was a duplicate, see 218 below) | +| 4. The last 7 | working tree, 288 tests | 7 | 3 | 4 | +| 5. Whole sweep again, packaged tool | this commit, 288 tests | 808 | 804 | 4 - the 4 below, 0 timeouts | + +Run 5 is the confirmation: the full sweep from scratch with +`tools/mutation_sweep.py` on the code and tests of this commit. + +## What the survivors showed + +The first sweep's 214 survivors were not spread evenly; they clustered where +the core had few or no direct tests: + +- **after_action.py** (32 of 52 survived): the report had one test. Its + steps, gates, deviations, escalations, errors and manners sections were + unchecked. Now checked line by line from a fixed log. +- **hub.py** (40): an unsigned or registry-refused disclosure answer + leaving no integrity violation, dead letters missing from their queue, + the "audience label not yet confirmed" marker on a hold, the unarmed + declarations, escalate accepting a non-escalation queue - all unheld. +- **core.py** (48): wildcard routes (`lead.*` must not cover + `leadership.x`), sender and receiver limits on a route, the anchor + checks, the hash format, the disk flushes. +- **kpi.py** (17), **notifier.py** (13), **territory.py** (12), + **loader.py** (12), **runs.py** (10), **priority.py** (7) and the rest: + the records each module leaves on the audit log, and its refusals. + +New tests: `tests/test_sweep_core_hub_2026_10_13.py`, +`tests/test_sweep_reports_2026_10_13.py`, +`tests/test_sweep_modules_2026_10_13.py` (90 tests). + +## Code changed because of the sweep + +1. **`loader.py`**: the routes check was an `assert`. Python run with `-O` + strips asserts, and an empty or non-list track would then load. It is + an explicit check now; its three new mutants are killed. +2. **`core.py` `repair_torn_tail`**: a variable `n` was assigned and never + read. Removed. Mutant 218 changed only that variable; it no longer + exists. + +## The 4 equivalent mutants + +Each changes no behaviour. Evidence was run, not assumed. + +| Mutant | Why nothing changes | Evidence | +|---|---|---| +| `attestation.py:26` read chunk 65536 -> 65537 | A streamed SHA-256 does not depend on the chunk size | 300,000 random bytes hashed with both chunk sizes and in one call: identical | +| `core.py:125` `to in SPECIAL and to in r` -> `to not in SPECIAL and to in r` | The whole clause implies `to in r`, which is already the first test on that line, so the clause can never change the answer | Exhaustive: all 32 receiver sets over {02, human, external, queue, any} x 6 destinations give the same result with the clause, with the mutant, and with no clause at all | +| `core.py:277` `f.flush()` -> `pass` after `truncate` | Nothing is written through that handle; truncate goes straight to the file | Size on disk read right after `truncate(3)`, before any flush: 3 | +| `hub.py:64` `super().__init__(reason)` -> `pass` in `Reject` | Python's exception constructor stores the arguments before `__init__` runs, so `args` and `str()` are the same | `Reject`-shaped class with and without the call: same `args` and `str` | + +## Redundant clauses found on the way (no behaviour change, reported) + +In `Routes.tuple_legal`, two clauses can never change the answer: +`(frm == "human" and "human" in s)` is covered by `frm in s`, and +`(to in SPECIAL and to in r)` is covered by `to in r`. They were left in +place: they are harmless, and changing route code was not needed to finish +this step. They read as if `human` or the special destinations were treated +differently; they are not. + +## One unexplained test failure + +In run 2, mutant 283 (one of the equivalents above) was reported killed +with 1 failure after 143 passing tests. With it in place, 3 full runs, 6 +runs with `-x` while the other job was busy, and 16 unmutated runs of both +copies side by side all passed. The runner then kept only the summary line, +not the failing test's name, so the test is not known. Counted as survived. +The runner now records failing test names. No failure has recurred. + +## What this does and does not show + +It shows the core suite notices each of these kinds of change to the core, +except the 4 above. It does not prove the code correct, it does not cover +listing-assistants' own code (its spokes, desk, console), and operators +outside the list above (for example, swapping arithmetic) were not run. diff --git a/tests/test_sweep_core_hub_2026_10_13.py b/tests/test_sweep_core_hub_2026_10_13.py new file mode 100644 index 0000000..cd509ac --- /dev/null +++ b/tests/test_sweep_core_hub_2026_10_13.py @@ -0,0 +1,467 @@ +"""Tests written from the 2026-10-13 full mutation sweep (repair plan 1.4): +core.py and hub.py. + +The sweep put 807 mutants into the 16 core files, one at a time, and ran the +whole core suite against each. These tests are for mutants that survived and +changed behavior the core promises - who may send on a route, wildcard +routes, the unverified-audience marker, what an unsigned disclosure leaves +on the record, dead letters, the anchor checks, the hash format, disk +flushes. Each test names the promise it holds, not the mutant. +""" +import hashlib +import json +import os +import sys + +import pytest + +sys.path.insert(0, os.path.join(os.path.dirname(__file__), "..")) + +from dispatcher import core # noqa: E402 +from dispatcher.core import AuditLog, AuditLogDamaged, Envelope, Routes # noqa: E402 +from dispatcher.hub import Hub, Reject # noqa: E402 +from dispatcher.signatures import Ed25519Signer # noqa: E402 +from dispatcher.signer_registry import SignerRegistry # noqa: E402 + + +def routes_file(tmp_path, routes): + p = str(tmp_path / "routes.json") + json.dump({"version": "t", "routes": routes}, open(p, "w", encoding="utf-8")) + return Routes(p) + + +def env(frm, to, intent, ctx="c1", payload=None): + return Envelope(from_agent=frm, to_agent=to, intent=intent, client_context_id=ctx, + payload=payload or {}, provenance={"source": "test"}) + + +def kinds(hub): + return [e["kind"] for e in hub.audit.read()] + + +def entries(hub, kind): + return [e for e in hub.audit.read() if e["kind"] == kind] + + +# =============================================================== the envelope +def test_an_envelope_is_not_escalated_unless_the_sender_says_so(): + e = env("01", "02", "x") + assert e.escalation_flag is False and e.in_reply_to is None and e.confidence == "unknown" + + +# ================================================================== the routes +WILD = [ + {"intent": "lead.*", "senders": ["01"], "receivers": ["02"]}, + {"intent": "vendor.*", "senders": ["09"], "receivers": ["external"], + "audience": "public", "audience_verified": True}, + {"intent": "client.*", "senders": ["11"], "receivers": ["external"], + "audience": "counterparty"}, + {"intent": "vendor.book", "senders": ["09"], "receivers": ["external"], + "audience": "counterparty", "audience_verified": False}, +] + + +def test_a_wildcard_route_covers_its_own_family_and_nothing_else(tmp_path): + r = routes_file(tmp_path, WILD) + assert r.tuple_legal("01", "lead.new", "02") is True + assert r.tuple_legal("01", "lead.", "02") is True + # "lead.*" is the family "lead." - not every intent that starts with "lead" + assert r.tuple_legal("01", "leadership.x", "02") is False + assert r.tuple_legal("01", "other.intent", "02") is False + assert list(r.matches("leadx")) == [] + + +def test_audience_lookups_follow_the_same_wildcard_rule(tmp_path): + r = routes_file(tmp_path, WILD) + assert r.audience_for("vendor.schedule") == "public" + assert r.audience_for("vendorx") is None + assert r.audience_for("lead.new") is None # not an external route + assert r.audience_is_verified("vendor.schedule") is True + assert r.audience_is_verified("client.message") is False # label never confirmed + assert r.audience_is_verified("vendorx") is False + assert r.audience_is_verified("unknown.intent") is False # no route: never verified + + +def test_an_exact_route_is_found_by_its_own_name(tmp_path): + r = routes_file(tmp_path, [ + {"intent": "vendor.book", "senders": ["09"], "receivers": ["external"], + "audience": "public", "audience_verified": True}, + {"intent": "vendor.cancel", "senders": ["09"], "receivers": ["external"], + "audience": "counterparty", "audience_verified": False}]) + assert r.audience_is_verified("vendor.cancel") is False + assert r.audience_is_verified("vendor.book") is True + assert r.audience_for("vendor.cancel") == "counterparty" + + +def test_only_the_named_senders_may_use_a_route(tmp_path): + r = routes_file(tmp_path, [ + {"intent": "config.update", "senders": ["human"], "receivers": ["05"]}, + {"intent": "listing.draft", "senders": ["04"], "receivers": ["05"]}]) + assert r.tuple_legal("human", "config.update", "05") is True + assert r.tuple_legal("04", "config.update", "05") is False # a human-only lane + assert r.tuple_legal("human", "listing.draft", "05") is False # not a human lane + + +def test_only_the_named_receivers_may_get_a_route(tmp_path): + r = routes_file(tmp_path, [ + {"intent": "listing.draft", "senders": ["04"], "receivers": ["05"]}, + {"intent": "vendor.schedule", "senders": ["09"], "receivers": ["external"]}]) + for special in ("external", "human", "queue"): + assert r.tuple_legal("04", "listing.draft", special) is False, special + assert r.tuple_legal("09", "vendor.schedule", "external") is True + assert r.tuple_legal("09", "vendor.schedule", "human") is False + + +# =============================================================== the audit log +def test_the_entry_hash_is_sha256_over_the_canonical_json(tmp_path): + # The hash format is a promise to anyone verifying the log with their own + # tools: sha256(previous hash + JSON of the entry without its two hash + # fields, keys sorted, no spaces). + log = AuditLog(str(tmp_path / "a.jsonl")) + log.append("x", {"zeta": 1, "alpha": {"b": 2, "a": 1}}) + e = log.read()[0] + body = {k: v for k, v in e.items() if k not in ("prev_hash", "entry_hash")} + canon = json.dumps(body, sort_keys=True, separators=(",", ":")) + assert e["entry_hash"] == hashlib.sha256((AuditLog.GENESIS + canon).encode()).hexdigest() + + +def test_a_caller_cannot_supply_the_chain_fields(tmp_path): + log = AuditLog(str(tmp_path / "a.jsonl")) + log.append("x", {"n": 1}) + log.append("y", {"n": 2, "prev_hash": "forged", "entry_hash": "forged"}) + e = log.read() + assert e[1]["prev_hash"] == e[0]["entry_hash"] and e[1]["entry_hash"] != "forged" + assert log.verify_chain() == {"ok": True, "entries": 2, "break_at": None} + + +def test_every_append_reaches_the_disk_before_it_returns(tmp_path, monkeypatch): + p = str(tmp_path / "a.jsonl") + log = AuditLog(p) + sizes = [] + real = os.fsync + + def fsync(fd): + sizes.append(os.fstat(fd).st_size) # what is in the file at that moment + return real(fd) + monkeypatch.setattr(core.os, "fsync", fsync) + log.append("x", {"n": 1}) + assert sizes == [os.path.getsize(p)] # flushed, then synced, the whole line + + +def test_a_repair_syncs_the_side_file_and_the_cut_before_recording(tmp_path, monkeypatch): + p = str(tmp_path / "a.jsonl") + log = AuditLog(p) + for n in range(2): + log.append("x", {"n": n}) + complete = os.path.getsize(p) + open(p, "ab").write(b'{"half') + seen = [] + real = os.fsync + + def fsync(fd): + seen.append(os.fstat(fd).st_size) + return real(fd) + monkeypatch.setattr(core.os, "fsync", fsync) + AuditLog.repair_torn_tail(p) + # side file (6 bytes, flushed), the cut log, then the repair's own entry + assert seen[:2] == [6, complete] and len(seen) == 3 + + +def test_repair_of_a_missing_file_is_refused(tmp_path): + with pytest.raises(ValueError, match="no such audit log"): + AuditLog.repair_torn_tail(str(tmp_path / "missing.jsonl")) + + +def test_repair_names_earlier_damage_as_damage_not_a_cut_off(tmp_path): + p = str(tmp_path / "a.jsonl") + log = AuditLog(p) + for n in range(3): + log.append("x", {"n": n}) + lines = open(p, "rb").read().split(b"\n") + lines[1] = b"{nope" + open(p, "wb").write(b"\n".join(lines) + b'{"half') + with pytest.raises(AuditLogDamaged) as ei: + AuditLog.repair_torn_tail(p) + assert ei.value.line == 2 and ei.value.torn_tail is False + + +def test_damage_mid_file_is_not_a_cut_off_even_when_the_file_lacks_a_final_newline(tmp_path): + p = str(tmp_path / "a.jsonl") + log = AuditLog(p) + for n in range(3): + log.append("x", {"n": n}) + lines = open(p, "rb").read().rstrip(b"\n").split(b"\n") + lines[1] = b"{nope" + open(p, "wb").write(b"\n".join(lines)) # last entry complete, no newline + c = AuditLog.check_file(p) + assert c["break_at"] == 2 and c["torn_tail"] is False + with pytest.raises(AuditLogDamaged) as ei: + AuditLog(p) + assert ei.value.torn_tail is False + reader = AuditLog.__new__(AuditLog) + reader.path = p + with pytest.raises(AuditLogDamaged) as ei: + reader.read() + assert ei.value.line == 2 and ei.value.torn_tail is False + + +def test_an_absent_or_empty_log_reads_as_empty_and_intact(tmp_path): + p = str(tmp_path / "a.jsonl") + log = AuditLog(p) + assert log.read() == [] + assert log.verify_chain() == {"ok": True, "entries": 0, "break_at": None} + assert log.anchor() == {"entries": 0, "head_hash": AuditLog.GENESIS} + open(p, "w").close() # exists, empty + assert log.verify_chain() == {"ok": True, "entries": 0, "break_at": None} + assert AuditLog.check_file(p)["entries"] == 0 + + +# ------------------------------------------------------------------- anchors +def test_an_empty_log_anchor_verifies_only_with_genesis(tmp_path): + log = AuditLog(str(tmp_path / "a.jsonl")) + assert log.verify_anchor({"entries": 0, "head_hash": AuditLog.GENESIS}) == \ + {"ok": True, "reason": None} + assert log.verify_anchor({"entries": 0, "head_hash": "f" * 64}) == \ + {"ok": False, "reason": "empty-log anchor must carry GENESIS"} + + +def test_an_anchor_fails_when_the_chain_breaks_before_it(tmp_path): + p = str(tmp_path / "a.jsonl") + log = AuditLog(p) + for n in range(3): + log.append("x", {"n": n}) + a = log.anchor() + lines = open(p, "rb").read().split(b"\n") + lines[0] = lines[0].replace(b'"n": 0', b'"n": 7') + open(p, "wb").write(b"\n".join(lines)) + r = log.verify_anchor(a) + assert r["ok"] is False and r["reason"] == "chain breaks at line 1, before the anchored position 3" + + +def test_an_anchor_still_holds_when_entries_were_added_after_it(tmp_path): + p = str(tmp_path / "a.jsonl") + log = AuditLog(p) + log.append("x", {"n": 0}) + a = log.anchor() + log.append("x", {"n": 1}) + assert log.verify_anchor(a) == {"ok": True, "reason": None} + + +def test_an_anchor_names_a_deleted_log(tmp_path): + p = str(tmp_path / "a.jsonl") + log = AuditLog(p) + log.append("x", {"n": 0}) + a = log.anchor() + os.remove(p) + r = log.verify_anchor(a) + assert r["ok"] is False and r["reason"].endswith("log file absent - wholesale deletion") + + +# ======================================================================= hub +def plain_hub(tmp_path, routes=None, **kw): + r = routes_file(tmp_path, routes or [ + {"intent": "work.do", "senders": ["01"], "receivers": ["02"]}, + {"intent": "work.park", "senders": ["01"], "receivers": ["queue"]}]) + return Hub(r, AuditLog(str(tmp_path / "audit.jsonl")), **kw) + + +def test_a_reject_carries_its_reason_as_its_message(): + e = Reject("schema: bad") + assert e.reason == "schema: bad" and str(e) == "schema: bad" and e.args == ("schema: bad",) + + +def test_the_default_loop_threshold_is_twenty(tmp_path): + hub = plain_hub(tmp_path) + hub.register("02", lambda e: None) + out = [hub.send(env("01", "02", "work.do"))["status"] for _ in range(21)] + assert out[:20] == ["ack"] * 20 and out[20] == "suspended" + + +def test_boot_declares_each_reviewer_that_is_off_and_only_those(tmp_path): + hub = plain_hub(tmp_path) + assert {"selfcheck.unarmed", "splitvantage.unarmed"} <= set(kinds(hub)) + armed = Hub(routes_file(tmp_path, [{"intent": "a", "senders": ["01"], "receivers": ["02"]}]), + AuditLog(str(tmp_path / "armed.jsonl")), + selfcheck_model=lambda *a, **k: "PASS", crosspol_models=(lambda *a: "x", lambda *a: "y")) + k = kinds(armed) + assert "selfcheck.unarmed" not in k and "splitvantage.unarmed" not in k + + +def test_turn_start_reads_the_last_five_events_and_says_so(tmp_path): + hub = plain_hub(tmp_path) + for n in range(8): + hub.audit.append("x", {"n": n}) + state = hub.on_turn_start() + assert [e.get("n") for e in state["last_events"]] == [3, 4, 5, 6, 7] + t = entries(hub, "turn.start")[-1] + assert t["read_prior_state"] is True + + +def test_without_the_taint_pillar_traces_are_kept_and_its_absence_declared_once(tmp_path, monkeypatch): + monkeypatch.setitem(sys.modules, "agent_open_mind", None) # import now fails + hub = plain_hub(tmp_path) + hub.ingest_spoke_trace("02", "e1", "thinking", "done") + hub.ingest_spoke_trace("02", "e2", "thinking more", "done") + assert kinds(hub).count("agentopenmind.unarmed") == 1 + traces = entries(hub, "spoke.trace") + assert [t["envelope_id"] for t in traces] == ["e1", "e2"] + assert [t["envelope_id"] for t in hub.spoke_traces] == ["e1", "e2"] + + +def test_escalate_takes_only_escalation_queues(tmp_path): + hub = plain_hub(tmp_path) + before = list(hub.queues["integrity.violation"]) + with pytest.raises(KeyError): + hub.escalate("integrity.violation", {"client_context_id": "c1"}) + with pytest.raises(KeyError): + hub.escalate("escalation.no_such_queue", {"client_context_id": "c1"}) + assert hub.queues["integrity.violation"] == before + assert "escalation.raised" not in kinds(hub) + + +def test_a_duplicate_is_reported_as_not_processed(tmp_path): + hub = plain_hub(tmp_path) + hub.register("02", lambda e: None) + e = env("01", "02", "work.do") + hub.send(e) + assert hub.send(e) == {"status": "duplicate", "processed": False, "envelope_id": e.envelope_id} + + +def test_an_unknown_route_is_held_with_its_reason_on_the_record(tmp_path): + hub = plain_hub(tmp_path) + r = hub.send(env("01", "02", "never.heard.of")) + assert r["status"] == "held" + refl = entries(hub, "hub.reflection")[-1] + assert "not on any track" in refl["thought"] and refl["response"] == "held in clarification.request" + + +def test_a_message_to_the_queue_is_recorded_as_held(tmp_path): + hub = plain_hub(tmp_path) + e = env("01", "queue", "work.park") + assert hub.send(e)["status"] == "held" + h = entries(hub, "hold.queued")[-1] + assert h["envelope_id"] == e.envelope_id and h["intent"] == "work.park" + + +def test_no_handler_is_a_dead_letter_on_the_queue_and_the_record(tmp_path): + hub = plain_hub(tmp_path) + e = env("01", "02", "work.do") + assert hub.send(e)["status"] == "dead.letter" + assert [d["envelope_id"] for d in hub.queues["dead.letter"]] == [e.envelope_id] + d = entries(hub, "dead.letter")[-1] + assert d["envelope_id"] == e.envelope_id and d["reason"] == "no handler for 02" + + +def test_a_crashing_handler_is_a_dead_letter_on_the_queue_too(tmp_path): + hub = plain_hub(tmp_path) + + def boom(e): + raise RuntimeError("handler bug") + hub.register("02", boom) + e = env("01", "02", "work.do") + hub.send(e) + assert [d["envelope_id"] for d in hub.queues["dead.letter"]] == [e.envelope_id] + assert "handler bug" in entries(hub, "dead.letter")[-1]["reason"] + + +def test_an_unsigned_authority_message_is_named_on_the_record(tmp_path): + hub = plain_hub(tmp_path, routes=[{"intent": "config.update", "senders": ["human"], + "receivers": ["05"]}]) + e = env("human", "05", "config.update") + assert hub.send(e)["status"] == "reject" + v = entries(hub, "integrity.violation")[-1] + assert v["envelope_id"] == e.envelope_id + assert v["reason"] == "authority intent without verified signature" + + +# --------------------------------------------- the outbound gate and disclosure +GATED = [ + {"intent": "vendor.schedule", "senders": ["09"], "receivers": ["external"], + "audience": "counterparty", "audience_verified": True}, + {"intent": "client.update", "senders": ["11"], "receivers": ["external"], + "audience": "counterparty"}, + {"intent": "disclosure.authority", "senders": ["human"], "receivers": ["09"]}, +] + + +def signed_hub(tmp_path, registry=None): + s = Ed25519Signer() + hub = Hub(routes_file(tmp_path, GATED), AuditLog(str(tmp_path / "audit.jsonl")), + signature_verifier=s.verifier(), signer_registry=registry) + hub.register("09", lambda e: None) + return hub, s + + +def test_a_hold_on_an_unconfirmed_audience_label_says_the_label_is_provisional(tmp_path): + hub, _ = signed_hub(tmp_path) + hub.send(env("11", "external", "client.update")) + hub.send(env("09", "external", "vendor.schedule")) + q = hub.queues["clarification.request"] + assert [r["intent"] for r in q] == ["client.update", "vendor.schedule"] + assert q[0]["absolute_signal"]["audience_provisional"] is True + assert "audience_provisional" not in q[1]["absolute_signal"] + assert q[1]["absolute_signal"]["signal"] == "ABSOLUTE_SIGNAL" + refl = [r for r in entries(hub, "hub.reflection") if r["response"] == "held: absolute_signal"] + assert len(refl) == 2 and "carries position risk" in refl[0]["thought"] + + +def auth(held_id, signer, decision=None, reason=None, sign=True): + payload = {"held_envelope_id": held_id} + if decision: + payload["decision"] = decision + if reason is not None: + payload["reason"] = reason + a = env("human", "09", "disclosure.authority", payload=payload) + if sign: + a.signature = signer.sign(a) + return a + + +@pytest.mark.parametrize("verb", ["release", "decline"]) +def test_an_unsigned_disclosure_answer_is_an_integrity_violation(tmp_path, verb): + hub, s = signed_hub(tmp_path) + held = env("09", "external", "vendor.schedule") + hub.send(held) + a = auth(held.envelope_id, s, decision=None if verb == "release" else "decline", sign=False) + r = (hub.release_disclosure if verb == "release" else hub.decline_disclosure)(a) + assert r["status"] == "reject" and r["reason"] == f"unverified signature on disclosure {verb}" + assert [v["envelope_id"] for v in hub.queues["integrity.violation"]] == [a.envelope_id] + v = entries(hub, "integrity.violation")[-1] + assert v["reason"] == "disclosure.authority without verified signature" + + +def test_a_disclosure_answer_the_registry_refuses_is_an_integrity_violation(tmp_path): + reg = SignerRegistry([{"intent": "disclosure.authority", "signer_login": "jeff", + "idp": "okta", "mfa_required": True, "effective": "2026-07-11", + "revoked": None}]) + hub, s = signed_hub(tmp_path, registry=reg) + held = env("09", "external", "vendor.schedule") + hub.send(held) + a = auth(held.envelope_id, s) # signed, but no signer stamp + r = hub.release_disclosure(a) + assert r["status"] == "reject" and r["reason"].startswith("signer registry: ") + assert [v["envelope_id"] for v in hub.queues["integrity.violation"]] == [a.envelope_id] + assert entries(hub, "integrity.violation")[-1]["reason"].startswith("signer registry: ") + + +def test_a_decline_reason_is_kept_to_500_characters(tmp_path): + hub, s = signed_hub(tmp_path) + held = env("09", "external", "vendor.schedule") + hub.send(held) + r = hub.decline_disclosure(auth(held.envelope_id, s, decision="decline", reason="r" * 900)) + assert r["status"] == "declined" + assert entries(hub, "disclosure.declined")[-1]["reason"] == "r" * 500 + + +# -------------------------------------------------------------- notification +def test_notifier_errors_are_kept_to_300_characters(tmp_path): + def raises(q, r): + raise RuntimeError("x" * 900) + hub = plain_hub(tmp_path, human_notifier=raises) + hub.escalate("escalation.hot_lead", {"client_context_id": "c1"}) + assert len(entries(hub, "human.notify_failed")[-1]["error"]) == 300 + hub2 = Hub(routes_file(tmp_path, [{"intent": "a", "senders": ["01"], "receivers": ["02"]}]), + AuditLog(str(tmp_path / "b.jsonl")), + human_notifier=lambda q, r: {"status": "failed", "error": "y" * 900}) + hub2.escalate("escalation.hot_lead", {"client_context_id": "c1"}) + assert entries(hub2, "human.notify_failed")[-1]["notifier_error"] == "y" * 300 diff --git a/tests/test_sweep_modules_2026_10_13.py b/tests/test_sweep_modules_2026_10_13.py new file mode 100644 index 0000000..096cae9 --- /dev/null +++ b/tests/test_sweep_modules_2026_10_13.py @@ -0,0 +1,403 @@ +"""Tests written from the 2026-10-13 full mutation sweep (repair plan 1.4): +the loader, the scheduler, territories, attestation, signatures, the signer +registry, the pillar seams, analysis, the shipped notifier and runs. + +Each test holds a promise the module makes that the sweep showed no test +held: the record a scheduler or a transfer leaves, what a loader refuses, +what a transfer carries, the exact request the notifier sends. +""" +import base64 +import hashlib +import io +import json +import os +import sys +import urllib.error + +import pytest + +sys.path.insert(0, os.path.join(os.path.dirname(__file__), "..")) + +from dispatcher.core import AuditLog, Envelope, Routes # noqa: E402 +from dispatcher.hub import Hub # noqa: E402 +from dispatcher.signatures import Ed25519Signer, Ed25519Verifier # noqa: E402 + +FIX = os.path.join(os.path.dirname(__file__), "routes_fixture.json") + + +class Rec: + """An audit stand-in that keeps (kind, record) pairs in order.""" + + def __init__(self): + self.events = [] + + def append(self, kind, record): + self.events.append((kind, record)) + + def kinds(self): + return [k for k, _ in self.events] + + +def hub_at(tmp_path, name="audit.jsonl", **kw): + return Hub(Routes(FIX), AuditLog(str(tmp_path / name)), **kw) + + +def kinds(hub): + return [e["kind"] for e in hub.audit.read()] + + +def entries(hub, kind): + return [e for e in hub.audit.read() if e["kind"] == kind] + + +# ===================================================================== loader +def identity(tmp_path, routes=None, classes=None, status="RATIFIED 2026-10-13", manners=True): + root = tmp_path / "ident" + root.mkdir() + (root / "routes.json").write_text(json.dumps( + {"routes": routes if routes is not None else + [{"intent": "a", "senders": ["01"], "receivers": ["02"]}]}), encoding="utf-8") + (root / "01-agent").mkdir() + (root / "01-agent" / "SKILL.md").write_text("skill", encoding="utf-8") + (root / "priority.json").write_text(json.dumps( + {"_status": status, "classes": classes if classes is not None else {"P01": 2}}), + encoding="utf-8") + if manners: + (root / "MANNERS.md").write_text("manners", encoding="utf-8") + return str(root) + + +@pytest.mark.parametrize("routes", [[], {"intent": "a"}, "routes"]) +def test_a_track_that_is_not_a_non_empty_list_refuses_to_load(tmp_path, routes): + from dispatcher.loader import load_identity + with pytest.raises(ValueError, match="routes.json present but invalid"): + load_identity(identity(tmp_path, routes=routes)) + + +@pytest.mark.parametrize("classes", [{"P01": 0}, {"P01": 5}, {"P01": "2"}, {"P01": 2.0}]) +def test_priority_classes_must_be_whole_numbers_one_to_four(tmp_path, classes): + from dispatcher.loader import load_identity + with pytest.raises(ValueError, match="must be int 1..4"): + load_identity(identity(tmp_path, classes=classes)) + + +def test_priority_classes_one_and_four_are_accepted(tmp_path): + from dispatcher.loader import load_identity + ident = load_identity(identity(tmp_path, classes={"P01": 1, "P02": 4})) + assert ident.priority_classes == {"P01": 1, "P02": 4} and ident.warnings == [] + + +@pytest.mark.parametrize("status,warned", [("DRAFT - not ratified", True), ("pending owner", True), + ("RATIFIED 2026-10-13", False)]) +def test_a_draft_or_pending_priority_table_loads_with_a_warning(tmp_path, status, warned): + from dispatcher.loader import load_identity + ident = load_identity(identity(tmp_path, status=status)) + assert ident.priority_status == status + assert (f"priority table is {status}" in ident.warnings) is warned + + +def test_an_identity_without_manners_says_so(tmp_path): + from dispatcher.loader import load_identity + ident = load_identity(identity(tmp_path, manners=False)) + assert ident.manners_path is None + assert any(w.startswith("MANNERS.md absent") for w in ident.warnings) + + +# ================================================================== scheduler +def test_the_scheduler_records_every_grant_siding_and_release(): + from dispatcher.priority import SidingScheduler + a = Rec() + s = SidingScheduler(a, {"low": 3, "high": 1}) + assert s.request_segment("r-low", "low", "07")["granted"] is True + assert s.request_segment("r-high", "high", "07")["sided"] == "r-low" + assert s.request_segment("r-low2", "low", "07")["granted"] is False + assert s.release_segment("r-high", "07") == {"resumed": "r-low", "spoke": "07"} + assert a.kinds() == ["segment.grant", "siding.hold", "segment.grant", "siding.hold", + "segment.release", "siding.resume", "segment.grant"] + assert a.events[0][1] == {"run": "r-low", "spoke": "07", "class": 3} + assert a.events[2][1] == {"run": "r-high", "spoke": "07", "class": 1} + assert a.events[4][1] == {"run": "r-high", "spoke": "07"} + assert a.events[6][1] == {"run": "r-low", "spoke": "07", "class": 3} + + +def test_only_the_holder_can_release_a_segment(): + from dispatcher.priority import SidingScheduler + s = SidingScheduler(Rec(), {"p": 2}) + with pytest.raises(ValueError, match="does not hold segment"): + s.release_segment("r1", "07") # nobody holds it + s.request_segment("r1", "p", "07") + with pytest.raises(ValueError, match="does not hold segment"): + s.release_segment("r2", "07") # somebody else holds it + assert s.holding["07"] == ("r1", 2) + + +# ================================================================ territories +def test_a_transfer_carries_only_its_contexts_and_the_receiver_adopts_their_open_items(tmp_path): + from dispatcher.territory import build_transfer, confirm_release, receive_transfer + signer = Ed25519Signer() + a = hub_at(tmp_path, "a.jsonl") + a.queues["clarification.request"] += [{"client_context_id": "c1", "x": 1}, + {"client_context_id": "c2", "x": 2}, "not-a-dict"] + rec = build_transfer(a, ["c1", "c-new"], signer, manifest={"core.py": "abc"}) + assert rec["contexts"] == {"c1": {"sequence_hwm": 0}, "c-new": {"sequence_hwm": 0}} + assert rec["open_items"] == {"clarification.request": [{"client_context_id": "c1", "x": 1}]} + assert rec["attested_manifest"] == {"core.py": "abc"} + sent = entries(a, "territory.transfer.sent")[-1] + assert sent["contexts"] == ["c1", "c-new"] and sent["signed"] is True + # a transport may re-serialise the record with its keys in another order + moved = json.loads(json.dumps(rec, sort_keys=True)) + b = hub_at(tmp_path, "b.jsonl") + ack = receive_transfer(b, moved, Ed25519Verifier(signer.public_key_bytes())) + assert ack == {"status": "ack", "contexts": ["c-new", "c1"]} + assert b.queues["clarification.request"] == [{"client_context_id": "c1", "x": 1}] + got = entries(b, "territory.transfer.received")[-1] + assert got["open_item_queues"] == ["clarification.request"] + assert entries(b, "territory.transfer.ack")[-1]["contexts"] == ["c-new", "c1"] + confirm_release(a, ["c1", "c-new"], ack) + assert entries(a, "territory.transfer.released")[-1]["contexts"] == ["c1", "c-new"] + + +def test_a_refused_transfer_is_on_the_record(tmp_path): + from dispatcher.territory import build_transfer, receive_transfer + rec = build_transfer(hub_at(tmp_path, "a.jsonl"), ["c1"], Ed25519Signer()) + b = hub_at(tmp_path, "b.jsonl") + res = receive_transfer(b, rec, Ed25519Verifier(Ed25519Signer().public_key_bytes())) + assert res["status"] == "refused" + r = entries(b, "territory.transfer.refused")[-1] + assert r["contexts"] == ["c1"] and r["reason"].startswith("territory transfer signature") + + +# ================================================================ attestation +def test_the_manifest_covers_the_track_and_names_what_is_missing(tmp_path): + from dispatcher.attestation import build_manifest, verify_manifest + pkg = tmp_path / "pkg" + pkg.mkdir() + (pkg / "a.py").write_text("x = 1\n", encoding="utf-8") + routes = tmp_path / "routes.json" + routes.write_text("{}", encoding="utf-8") + m = build_manifest(str(pkg), str(routes)) + assert set(m) == {"a.py", "routes.json"} + assert m["routes.json"] == hashlib.sha256(b"{}").hexdigest() + gone = dict(m, **{"b.py": "0" * 64}) + assert verify_manifest(gone, str(pkg), str(routes)) == ["b.py: in manifest, absent on disk"] + changed = dict(m, **{"a.py": "f" * 64}) + assert verify_manifest(changed, str(pkg), str(routes)) == [ + f"a.py: hash mismatch (attested {'f' * 12}…, running {m['a.py'][:12]}…)"] + + +def test_a_signer_without_sign_bytes_gives_an_unsigned_attestation(tmp_path): + from dispatcher.attestation import attest_boot + pkg = tmp_path / "pkg" + pkg.mkdir() + routes = tmp_path / "routes.json" + routes.write_text("{}", encoding="utf-8") + hub = hub_at(tmp_path) + attest_boot(hub, str(pkg), str(routes), signer=object()) + rec = entries(hub, "boot.attestation")[-1] + assert rec["signed"] is False and "manifest_signature" not in rec + + +# ================================================================= signatures +def test_a_signature_survives_the_payload_keys_arriving_in_another_order(): + s = Ed25519Signer() + e = Envelope(from_agent="human", to_agent="05", intent="config.update", client_context_id="c", + payload={"b": 1, "a": {"y": 2, "x": 3}}, provenance={"source": "t"}) + s.sign(e) + e.payload = {"a": {"x": 3, "y": 2}, "b": 1} + assert Ed25519Verifier(s.public_key_bytes()).verify(e) is True + + +def test_a_key_saved_and_loaded_is_the_same_key(): + s = Ed25519Signer() + again = Ed25519Signer(private_key_bytes=s.private_key_bytes()) + assert len(s.private_key_bytes()) == 32 + assert again.public_key_bytes() == s.public_key_bytes() + + +def test_verification_answers_false_never_none(): + s = Ed25519Signer() + v = Ed25519Verifier(s.public_key_bytes()) + e = Envelope(from_agent="human", to_agent="05", intent="x", client_context_id="c", + payload={}, provenance={}) + assert v.verify(e) is False # no signature + assert v.verify_bytes(b"data", "zz") is False # not hex + assert v.verify_bytes(b"data", s.sign_bytes(b"other")) is False + + +# ============================================================ signer registry +@pytest.mark.parametrize("entry", [{"intent": "x"}, {"signer_login": "jeff"}]) +def test_a_signer_entry_without_intent_or_login_refuses_to_arm(entry): + from dispatcher.signer_registry import SignerRegistry + with pytest.raises(ValueError, match="missing intent or signer_login"): + SignerRegistry([{"mfa_required": True, **entry}]) + + +def test_a_stamp_without_a_login_is_refused_by_name(): + from dispatcher.signer_registry import SignerRegistry + reg = SignerRegistry([{"intent": "config.update", "signer_login": "jeff", "idp": "okta", + "mfa_required": True, "effective": "2026-01-01", "revoked": None}]) + e = Envelope(from_agent="human", to_agent="05", intent="config.update", client_context_id="c", + payload={}, provenance={"signer": {"mfa": True}}) + v = reg.check(e) + assert v.ok is False and v.reason == "signer stamp missing signer_login" + + +# ================================================================ pillar seams +def test_before_turn_reviews_the_last_three_thoughts_and_returns_its_record(tmp_path): + from dispatcher.pillars import before_turn_check + hub = hub_at(tmp_path) + for n in range(5): + hub._reflect(f"e{n}", f"thought {n}", "done") + rec = before_turn_check(hub) + assert rec["thoughts_reviewed"] == 3 + assert rec["recent_thoughts"] == ["thought 2", "thought 3", "thought 4"] + assert entries(hub, "beforeturn.check")[-1]["thoughts_reviewed"] == 3 + + +def test_the_exit_gate_without_a_reviewer_says_it_is_off(tmp_path): + from dispatcher.pillars import exit_gate + hub = hub_at(tmp_path) + e = Envelope(from_agent="11", to_agent="external", intent="x", client_context_id="c", + payload={"text": "hi"}, provenance={"source": "t"}) + assert exit_gate(hub, e) == {"armed": False, "passed": None} + off = entries(hub, "selfcheck.unarmed")[-1] + assert off["envelope_id"] == e.envelope_id + + +def test_a_sleepmark_carries_the_last_five_thoughts_and_restore_returns_it(tmp_path): + from dispatcher.pillars import capture_sleepmark, restore_sleepmark + hub = hub_at(tmp_path) + for n in range(7): + hub._reflect(f"e{n}", f"t{n}", "done") + out = capture_sleepmark(hub, "handover") + assert out["traces"] == 5 + assert [t["thinking"] for t in out["mark"]["reasoning_traces"]] == ["t2", "t3", "t4", "t5", "t6"] + assert restore_sleepmark(hub, out["mark"]) is out["mark"] + + +# =================================================================== analysis +def test_drift_is_flagged_at_or_above_the_threshold(tmp_path): + from dispatcher.analysis import analyze_reflections + hub = hub_at(tmp_path) # no reviewer pair: no second opinion + hub._reflect("e1", "route the lead to 02", "routed the lead to 02") + assert [r["flagged"] for r in analyze_reflections(hub, drift_threshold=0.0)] == [True] + assert [r["flagged"] for r in analyze_reflections(hub, drift_threshold=1.01)] == [False] + assert "splitvantage.review" not in kinds(hub) + + +def test_a_trace_without_thought_found_only_at_analysis_is_flagged_there(tmp_path): + from dispatcher.analysis import score_spoke_traces + hub = hub_at(tmp_path) + hub.spoke_traces.append({"agent": "03", "envelope_id": "e7", "thought": "", "result": "sent"}) + out = score_spoke_traces(hub) + assert out[0]["tainted"] is True + t = entries(hub, "agentopenmind.tainted")[-1] + assert t["envelope_id"] == "e7" and t["agent"] == "03" + assert [i["envelope_id"] for i in hub.queues["integrity.violation"]] == ["e7"] + + +# ============================================================ absolute signal +def test_the_signal_hash_is_sha256_of_its_text(): + from dispatcher.absolute_signal import SIGNAL_TEXT, signal_sha256 + assert signal_sha256() == hashlib.sha256(SIGNAL_TEXT.encode("utf-8")).hexdigest() + + +# ===================================================================== runs +def test_a_watchdog_needs_a_positive_cadence(): + from dispatcher.runs import Watchdog + for bad in (0, -1): + with pytest.raises(ValueError, match="cadence must be positive"): + Watchdog(cadence_s=bad) + + +def test_every_playbook_step_is_on_the_record(tmp_path): + from dispatcher.runs import PlaybookRun + hub = hub_at(tmp_path) + run = PlaybookRun(hub, "P11", "r1", "c1") + run.step(1, "env-1", "lead in") + run.complete() + s = entries(hub, "playbook.step") + assert [(x["step"], x["envelope_id"], x["note"]) for x in s] == [(1, "env-1", "lead in")] + + +# =================================================================== notifier +class Captured: + def __init__(self, status=201): + self.req = None + self.status = status + + def __call__(self, req, timeout=5.0): + self.req = req + status = self.status + + class R: + def __enter__(s): + s.status = status + return s + + def __exit__(s, *a): + return False + return R() + + +def test_the_sms_request_is_the_one_twilio_expects(monkeypatch): + import dispatcher.notifier as n + cap = Captured() + monkeypatch.setattr(n.urllib.request, "urlopen", cap) + out = n.send_sms_via_twilio("hello") + assert out == {"status": "sent", "http_status": 201, "is_fallback": False} + auth = base64.b64encode(f"{n.TWILIO_ACCOUNT_SID}:{n.TWILIO_AUTH_TOKEN}".encode()).decode() + assert cap.req.get_header("Authorization") == f"Basic {auth}" + assert cap.req.get_header("Content-type") == "application/x-www-form-urlencoded" + assert f"To={n.TWILIO_TO_NUMBER.replace('+', '%2B')}" in cap.req.data.decode() + n.send_sms_via_twilio("hello", to_number="+15550001111") + assert "To=%2B15550001111" in cap.req.data.decode() + + +def test_the_whatsapp_request_is_the_one_twilio_expects(monkeypatch): + import dispatcher.notifier as n + cap = Captured() + monkeypatch.setattr(n.urllib.request, "urlopen", cap) + assert n.send_whatsapp_via_twilio("hi", to_number="+15550001111") == \ + {"status": "sent", "http_status": 201, "channel": "whatsapp"} + assert cap.req.get_header("Authorization").startswith("Basic ") + assert cap.req.get_header("Content-type") == "application/x-www-form-urlencoded" + assert "To=whatsapp%3A%2B15550001111" in cap.req.data.decode() + + +def test_a_refused_page_keeps_at_most_300_characters_of_the_answer(monkeypatch): + import dispatcher.notifier as n + + def refuse(req, timeout=5.0): + raise urllib.error.HTTPError(req.full_url, 401, "no", {}, io.BytesIO(b"z" * 900)) + monkeypatch.setattr(n.urllib.request, "urlopen", refuse) + sms = n.send_sms_via_twilio("x") + assert sms["status"] == "failed" and sms["is_fallback"] is True and sms["body"] == "z" * 300 + wa = n.send_whatsapp_via_twilio("x") + assert wa["status"] == "failed" and wa["body"] == "z" * 300 + + +def test_a_wait_id_is_named_in_the_page_only_when_there_is_one(): + from dispatcher.notifier import format_notification_text + assert "wait_id=w-9" in format_notification_text("q", {"wait_id": "w-9"}) + assert "wait_id" not in format_notification_text("q", {}) + + +def test_a_page_that_never_reaches_twilio_is_a_failure_with_the_error(monkeypatch): + import dispatcher.notifier as n + + def offline(req, timeout=5.0): + raise OSError("network unreachable") + monkeypatch.setattr(n.urllib.request, "urlopen", offline) + out = n.send_sms_via_twilio("x") + assert out["status"] == "failed" and out["is_fallback"] is True + assert out["error"] == "OSError('network unreachable')" + assert "not delivered" in out["fallback_reason"] + + +def test_two_beats_are_enough_for_the_watchdog(): + from dispatcher.runs import Watchdog + obs = Watchdog(cadence_s=1.0).observe([{"kind": "heartbeat", "ts": 5.0}, + {"kind": "heartbeat", "ts": 8.0}]) + assert obs == {"computable": True, "beats": 2, "span_s": 3.0, "max_gap_s": 3.0, + "gap_incidents": 1, "cadence_s": 1.0} diff --git a/tests/test_sweep_reports_2026_10_13.py b/tests/test_sweep_reports_2026_10_13.py new file mode 100644 index 0000000..11943d3 --- /dev/null +++ b/tests/test_sweep_reports_2026_10_13.py @@ -0,0 +1,184 @@ +"""Tests written from the 2026-10-13 full mutation sweep (repair plan 1.4): +the after-action report, the KPIs, the watchdog and the playbook record. + +Before these, the after-action report had one test in the core (the failed +notification line); 32 of its 52 mutants survived. The report is built only +from the audit log, so each test feeds a fixed log and checks the exact +lines a reader gets. +""" +import datetime +import os +import sys + +import pytest + +sys.path.insert(0, os.path.join(os.path.dirname(__file__), "..")) + +from dispatcher.after_action import generate_report # noqa: E402 +from dispatcher.kpi import compute_kpis # noqa: E402 + + +def iso(ts): + return datetime.datetime.fromtimestamp(ts, tz=datetime.timezone.utc).isoformat() + + +C = "ctx-A" +LOG = [ + {"kind": "envelope.persisted", "ts": 100.0, "envelope_id": "e1", "client_context_id": C}, + {"kind": "ack", "ts": 100.25, "envelope_id": "e1"}, # no context on acks + {"kind": "envelope.persisted", "ts": 101.0, "envelope_id": "e2", "client_context_id": C}, + {"kind": "reject", "ts": 102.0, "envelope_id": "e3", "reason": "tuple illegal: x"}, # step's id, no ctx + {"kind": "reject", "ts": 102.5, "envelope_id": "zz", "client_context_id": "ctx-OTHER", + "reason": "someone else's run"}, + {"kind": "human.notify_failed", "ts": 102.8, "queue": "escalation.complaint", + "notifier_status": "failed"}, # stale: before its escalation + {"kind": "escalation.raised", "ts": 103.0, "queue": "escalation.hot_lead", "client_context_id": C}, + {"kind": "human.notified", "ts": 103.5, "queue": "escalation.hot_lead"}, + {"kind": "escalation.raised", "ts": 104.0, "queue": "escalation.legal_line", "client_context_id": C}, + {"kind": "human.notify_failed", "ts": 104.1, "queue": "escalation.legal_line", "error": "RuntimeError('x')"}, + {"kind": "escalation.raised", "ts": 105.0, "queue": "escalation.complaint", "client_context_id": C}, + {"kind": "agentopenmind.tainted", "ts": 105.5, "agent": "03", "client_context_id": C}, + {"kind": "dead.letter", "ts": 106.0, "envelope_id": "e2", "reason": "no handler for 09"}, + {"kind": "manners.reinjection", "ts": 107.0, "trigger": "long_thread", "position": 12, + "client_context_id": C}, + {"kind": "manners.reinjection", "ts": 108.0, "trigger": "new_party", "client_context_id": C}, +] +STEPS = [{"step": 1, "agent": "01", "intent": "lead.inbound", "envelope_id": "e1"}, + {"step": 2, "agent": "02", "intent": "lead.score", "envelope_id": "e2"}, + {"step": 3, "agent": "05", "intent": "listing.x", "envelope_id": "e3"}] + + +def report(**kw): + return generate_report(LOG, "P11", "run-1", C, STEPS, **kw).splitlines() + + +def section(lines, name): + i = lines.index(f"## {name}") + out = [] + for l in lines[i + 1:]: + if l.startswith("## "): + break + if l: + out.append(l) + return out + + +def test_the_run_window_is_the_first_and_last_event_of_this_run(): + r = report() + assert f"- started: {iso(100.0)}" in r and f"- ended: {iso(108.0)}" in r + + +def test_steps_are_proven_by_their_ack_with_the_latency_from_the_log(): + assert section(report(), "steps") == [ + "- step 1 [01] lead.inbound: executed=yes, proof=ack on e1 (audit), latency=0.2500s", + "- step 2 [02] lead.score: executed=NO ACK ON LOG (envelope e2) - unproven, not counted done", + "- step 3 [05] listing.x: executed=NO ACK ON LOG (envelope e3) - unproven, not counted done"] + + +def test_the_outcome_carries_an_abort_reason_verbatim_only_when_there_is_one(): + assert section(report(), "outcome") == ["- completed"] + assert section(report(outcome="aborted", abort_reason="seller withdrew"), "outcome") == \ + ["- aborted - verbatim reason: seller withdrew"] + + +def test_the_gates_count_escalations_and_taints(): + assert section(report(), "gates") == [ + "- hot-lead escalation gate: TRIGGERED x3 (evidence: escalation.raised on log)", + "- absent-thought taint gate: TRIGGERED x1 (evidence: agentopenmind.tainted)"] + + +def test_deviations_are_this_runs_and_only_this_runs(): + devs = section(report(), "deviations") + assert [d.split(":")[0] for d in devs] == ["- reject", "- agentopenmind.tainted", "- dead.letter"] + assert not any("someone else's run" in d for d in devs) + + +def test_each_escalation_says_whether_a_person_was_reached(): + assert section(report(), "escalations") == [ + "- escalation.hot_lead: transport 0.5000s; human response time: NOT INSTRUMENTED", + "- escalation.legal_line: raised, NOTIFICATION FAILED (RuntimeError('x')) - no person was reached", + # the failure on record is from BEFORE this escalation - it proves nothing about it + "- escalation.complaint: raised, NO human.notified on log - transport unproven"] + + +def test_errors_list_rejects_and_dead_letters_with_their_reasons(): + assert section(report(), "errors") == ["- reject: tuple illegal: x", "- dead.letter: no handler for 09"] + + +def test_manners_reinjections_are_counted_and_listed(): + assert section(report(), "manners re-injections") == [ + "- count: 2", "- long_thread @ 12", "- new_party @ unstated"] + + +def test_a_quiet_run_says_none_in_each_section(): + log = [{"kind": "envelope.persisted", "ts": 1.0, "envelope_id": "q1", "client_context_id": "Q"}, + {"kind": "ack", "ts": 1.5, "envelope_id": "q1"}] + r = generate_report(log, "P1", "r", "Q", [{"step": 1, "agent": "01", "intent": "i", + "envelope_id": "q1"}]).splitlines() + assert section(r, "gates") == ["- hot-lead escalation gate: not triggered this run", + "- absent-thought taint gate: cleared - all traces present"] + assert section(r, "deviations") == ["- none on log"] + assert section(r, "escalations") == ["- none"] + assert section(r, "errors") == ["- none on log"] + assert section(r, "manners re-injections") == ["- none on log this run (instrumented; zero fired)"] + + +def test_a_run_with_no_events_on_the_log_is_refused(): + with pytest.raises(ValueError, match="without log evidence would be fabricated"): + generate_report([{"kind": "x", "ts": 1.0, "client_context_id": "other"}], + "P1", "r", "Q", []) + + +# ======================================================================= KPIs +def test_an_ack_counts_only_when_its_envelope_was_persisted_first(): + k = compute_kpis([ + {"kind": "envelope.persisted", "ts": 10.0, "envelope_id": "a"}, + {"kind": "ack", "ts": 10.5, "envelope_id": "a"}, + {"kind": "ack", "ts": 11.0, "envelope_id": "b"}, # never persisted + {"kind": "ack", "ts": 11.5, "envelope_id": "c"}, # acked before persisted + {"kind": "envelope.persisted", "ts": 12.0, "envelope_id": "c"}])["ack_integrity"] + assert k == {"acks": 3, "acks_backed_by_persist": 1, "rate": 1 / 3, "integrity_incidents": 2} + + +def test_routing_latency_p50_is_the_middle_of_the_sorted_latencies(): + ev = [] + for i, lat in enumerate([0.4, 0.1, 0.3, 0.2]): + ev += [{"kind": "envelope.persisted", "ts": 100.0 + i, "envelope_id": f"e{i}"}, + {"kind": "ack", "ts": 100.0 + i + lat, "envelope_id": f"e{i}"}] + r = compute_kpis(ev)["routing_latency"] + assert r["n"] == 4 and r["p50_s"] == pytest.approx(0.3) and r["max_s"] == pytest.approx(0.4) + + +def test_sequence_gaps_are_counted_per_context_from_one(): + ev = [{"kind": "envelope.persisted", "ts": 1, "envelope_id": f"a{s}", "client_context_id": "A", + "sequence": s} for s in (1, 2, 4)] # 4 is out of place + ev += [{"kind": "envelope.persisted", "ts": 1, "envelope_id": f"b{s}", "client_context_id": "B", + "sequence": s} for s in (1, 2)] + ev += [{"kind": "envelope.persisted", "ts": 1, "envelope_id": "n1", "client_context_id": "A", + "sequence": None}, # not stamped: ignored + {"kind": "envelope.persisted", "ts": 1, "envelope_id": "n2", "sequence": 9}] # no context + assert compute_kpis(ev)["sequence_gap_incidents"] == 1 + + +def test_escalation_transport_needs_an_escalation_to_measure(): + k = compute_kpis([{"kind": "human.notified", "ts": 1.0, "queue": "escalation.hot_lead"}]) + assert k["escalation_transport_time"]["computable"] is False + + +def test_heartbeat_from_two_beats_with_exact_span_and_gap(): + k = compute_kpis([{"kind": "heartbeat", "ts": t} for t in (10.0, 11.0, 14.0)])["heartbeat"] + assert k == {"computable": True, "beats": 3, "span_s": 4.0, "max_gap_s": 3.0} + two = compute_kpis([{"kind": "heartbeat", "ts": t} for t in (10.0, 12.5)])["heartbeat"] + assert two == {"computable": True, "beats": 2, "span_s": 2.5, "max_gap_s": 2.5} + + +def test_manners_and_drift_counts_are_exact(): + ev = [{"kind": "manners.reinjection", "ts": 1, "trigger": t} + for t in ("phase_gate", "phase_gate", "turn_backstop", "other")] + ev += [{"kind": "openmind.drift", "ts": 1, "flagged": f} for f in (True, False, True)] + ev += [{"kind": "agentopenmind.trace", "ts": 1, "flagged": f} for f in (False, True)] + k = compute_kpis(ev) + assert k["manners_reinjections"] == {"count": 4, "by_trigger": { + "phase_gate": 2, "post_compaction": 0, "turn_backstop": 1}} + assert k["drift"] == {"hub_reflections_analyzed": 3, "hub_reflections_flagged": 2, + "spoke_traces_scored": 2, "spoke_traces_flagged": 1} diff --git a/tools/mutation_sweep.py b/tools/mutation_sweep.py new file mode 100644 index 0000000..802f669 --- /dev/null +++ b/tools/mutation_sweep.py @@ -0,0 +1,180 @@ +"""mutation_sweep - one mutant at a time over the core files, the full suite +against each (repair plan 1.4, 2026-10-13). + + python tools/mutation_sweep.py --out sweep.jsonl [--jobs 2] [--files core.py hub.py] + +Your checkout is never touched: the repo is copied to a temporary folder per +job and mutants are written there. Set IDENTITY_DIR to a listing-assistants +clone so the identity tests run too (the 2026-10-13 sweep did). + +Operators (exact source-span replacement from the AST; every mutant compiles): + CMP flip one comparison (== !=, < >=, <= >, in / not in, is / is not) + BOOL and <-> or + NOT drop a `not` + CONST True <-> False; int n -> n+1 (docstrings skipped) + IF negate an if / while / ternary / assert test + RET return -> return None + RAISE raise ... -> pass + CALL a bare call statement -> pass + +A mutant is KILLED when the suite fails with it in place (pytest -x: the first +failure is enough), SURVIVED when the suite passes, TIMEOUT after 180 s. Each +job first runs the unmutated suite and refuses to start if it fails - a +failing baseline would make every mutant look killed. One JSON line per +mutant goes to --out, with the failing test's name when there is one. +""" +from __future__ import annotations + +import argparse +import ast +import json +import os +import shutil +import subprocess +import sys +import tempfile +import threading +import time + +ROOT = os.path.dirname(os.path.dirname(os.path.abspath(__file__))) +CORE_FILES = ["__init__.py", "absolute_signal.py", "after_action.py", "analysis.py", + "attestation.py", "core.py", "hub.py", "kpi.py", "loader.py", "notifier.py", + "pillars.py", "priority.py", "runs.py", "signatures.py", + "signer_registry.py", "territory.py"] +FLIP = {ast.Eq: "!=", ast.NotEq: "==", ast.Lt: ">=", ast.GtE: "<", ast.Gt: "<=", + ast.LtE: ">", ast.In: "not in", ast.NotIn: "in", ast.Is: "is not", ast.IsNot: "is"} + + +def mutants(files): + out = [] + for f in files: + src = open(os.path.join(ROOT, "dispatcher", f), "rb").read() # AST offsets are bytes + tree = ast.parse(src) + starts, pos = [0], 0 + for line in src.split(b"\n"): + pos += len(line) + 1 + starts.append(pos) + + def span(n): + return (starts[n.lineno - 1] + n.col_offset, + starts[n.end_lineno - 1] + n.end_col_offset) + + def seg(n): + a, b = span(n) + return src[a:b].decode("utf-8") + + docs = {id(n.body[0].value) for n in ast.walk(tree) + if isinstance(n, (ast.Module, ast.FunctionDef, ast.AsyncFunctionDef, ast.ClassDef)) + and n.body and isinstance(n.body[0], ast.Expr) + and isinstance(n.body[0].value, ast.Constant)} + + def add(n, op, rep): + a, b = span(n) + out.append({"file": f, "line": n.lineno, "op": op, "start": a, "end": b, + "rep": rep, "orig": src[a:b].decode("utf-8")}) + + for n in ast.walk(tree): + if isinstance(n, ast.Compare) and len(n.ops) == 1 and type(n.ops[0]) in FLIP: + add(n, "CMP", f"({seg(n.left)}) {FLIP[type(n.ops[0])]} ({seg(n.comparators[0])})") + elif isinstance(n, ast.BoolOp): + j = " or " if isinstance(n.op, ast.And) else " and " + add(n, "BOOL", "(" + j.join(f"({seg(v)})" for v in n.values) + ")") + elif isinstance(n, ast.UnaryOp) and isinstance(n.op, ast.Not): + add(n, "NOT", f"({seg(n.operand)})") + elif isinstance(n, ast.Constant) and id(n) not in docs: + if n.value is True: + add(n, "CONST", "False") + elif n.value is False: + add(n, "CONST", "True") + elif type(n.value) is int: + add(n, "CONST", str(n.value + 1)) + if isinstance(n, (ast.If, ast.While, ast.IfExp, ast.Assert)): + add(n.test, "IF", f"(not ({seg(n.test)}))") + elif isinstance(n, ast.Return) and n.value is not None and not ( + isinstance(n.value, ast.Constant) and n.value.value is None): + add(n, "RET", "return None") + elif isinstance(n, ast.Raise): + add(n, "RAISE", "pass") + elif isinstance(n, ast.Expr) and isinstance(n.value, ast.Call): + add(n, "CALL", "pass") + seen, res = set(), [] + for m in out: + k = (m["file"], m["start"], m["end"], m["rep"]) + if k not in seen: + seen.add(k) + res.append({"id": len(res), **m}) + return res + + +def run_suite(wt, env): + try: + r = subprocess.run([sys.executable, "-m", "pytest", "-x", "-q", "-p", "no:cacheprovider", + "tests/"], cwd=wt, env=env, capture_output=True, text=True, timeout=180) + except subprocess.TimeoutExpired: + return "timeout", "timeout after 180s", [] + lines = r.stdout.strip().splitlines() + failed = [l for l in lines if l.startswith(("FAILED", "ERROR"))][:3] + return r.returncode, (lines[-1] if lines else r.stderr[-200:]), failed + + +def main(argv=None) -> int: + ap = argparse.ArgumentParser(description=__doc__.split("\n\n")[0]) + ap.add_argument("--out", required=True) + ap.add_argument("--jobs", type=int, default=1) + ap.add_argument("--files", nargs="*", default=CORE_FILES) + args = ap.parse_args(argv) + ms = mutants(args.files) + print(json.dumps({"mutants": len(ms), "files": len(args.files), "jobs": args.jobs}), flush=True) + lock = threading.Lock() + out = open(args.out, "w", encoding="utf-8") + errors = [] + + def worker(k): + tmp = tempfile.mkdtemp(prefix=f"mutsweep{k}-") + wt = os.path.join(tmp, "repo") + shutil.copytree(ROOT, wt, ignore=shutil.ignore_patterns( + ".git", "__pycache__", "*.egg-info", "baseline-out", "after-action")) + env = dict(os.environ, PYTHONPATH=wt, PYTHONDONTWRITEBYTECODE="1") + try: + rc, tail, _ = run_suite(wt, env) + if rc != 0: + errors.append(f"job {k}: baseline failed: {tail}") + return + for m in ms: + if m["id"] % args.jobs != k: + continue + p = os.path.join(wt, "dispatcher", m["file"]) + src = open(p, "rb").read() + t0 = time.time() + try: + open(p, "wb").write(src[:m["start"]] + m["rep"].encode("utf-8") + src[m["end"]:]) + rc, tail, failed = run_suite(wt, env) + finally: + open(p, "wb").write(src) + status = "survived" if rc == 0 else ("timeout" if rc == "timeout" else "killed") + with lock: + out.write(json.dumps({**{x: m[x] for x in ("id", "file", "line", "op")}, + "orig": m["orig"][:200], "rep": m["rep"][:200], + "status": status, "tail": tail, "failed": failed, + "secs": round(time.time() - t0, 1)}) + "\n") + out.flush() + finally: + shutil.rmtree(tmp, ignore_errors=True) + + threads = [threading.Thread(target=worker, args=(k,)) for k in range(args.jobs)] + for t in threads: + t.start() + for t in threads: + t.join() + out.close() + if errors: + print(json.dumps({"error": errors})) + return 2 + res = [json.loads(l) for l in open(args.out, encoding="utf-8")] + counts = {s: sum(1 for r in res if r["status"] == s) for s in ("killed", "survived", "timeout")} + print(json.dumps({"done": len(res), **counts})) + return 0 if len(res) == len(ms) else 1 + + +if __name__ == "__main__": + sys.exit(main()) From 7ded6a6859bd084840e02de608186bb97f1f8fc0 Mon Sep 17 00:00:00 2001 From: Claude Date: Tue, 13 Oct 2026 19:51:11 +0000 Subject: [PATCH 07/10] Cold review fixes: a writer refuses a log changed under it, one-step repair, each escalation paired with its own notification A separate agent reviewed Phase 1 cold. Its findings, reproduced, fixed: - A writer that opened an intact log kept appending after the file was damaged under it (the running desk did). AuditLog now remembers the file's size after its own write; if it differs at the next append it re-verifies: damaged, cut back, replaced or deleted -> AuditLogDamaged, nothing written; another writer's valid entries -> continue from them (no fork). - The repair cut the log and then appended its record: a crash between left a cut log with no record. It now writes the repaired log to a new file and swaps it in with os.replace (folder synced on POSIX). - KPI and after-action matched notifications by queue and time, so a later delivery on the same queue covered an earlier failure. kpi.pair_escalations pairs each escalation with its own outcome; the report no longer gives a transport time to a notifier that reported nothing. - An odd notifier answer (list status, object values) raised out of the hub after escalation.raised was written. Now recorded as notify_failed. - Hub.notify(queue, record): notify without queueing, outcome recorded (listing's decision alerts called the notifier around the hub). - tools/kpi_gate.py checks the chain first (it crashed on a damaged log and passed an edited one). - CI with-identity uses the listing branch of the same name when it exists. - A test of mine passed for the wrong reason (its "cut back" case emptied the file); fixed, and the same read-after-truncate bug in a new test. Not fixed (owner decision pending): two processes appending in the very same instant - only an OS file lock stops that. Sweep on this commit (tools/mutation_sweep.py): 859 mutants, 855 killed, 1 timeout, 3 equivalent (findings/MUTATION_SWEEP_2026-10-13.md). 309 passed + 5 skipped alone; 314 with the listing identity. Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_01CRunDQmfmnZdtJiP78e8WR --- .github/workflows/ci.yml | 11 +- EVIDENCE.md | 6 +- PILLAR_TESTING_MANUAL.md | 4 +- README.md | 2 +- SKILL.md | 2 +- dispatcher/after_action.py | 28 ++-- dispatcher/core.py | 112 ++++++++++++--- dispatcher/hub.py | 39 +++-- dispatcher/kpi.py | 63 +++++--- findings/MUTATION_SWEEP_2026-10-13.md | 35 ++++- tests/test_audit_log_damage.py | 183 ++++++++++++++++++++++-- tests/test_day3.py | 10 +- tests/test_notification_truth.py | 84 +++++++++++ tests/test_sweep_core_hub_2026_10_13.py | 8 +- tools/kpi_gate.py | 12 +- 15 files changed, 510 insertions(+), 89 deletions(-) diff --git a/.github/workflows/ci.yml b/.github/workflows/ci.yml index 5053100..818cf2e 100644 --- a/.github/workflows/ci.yml +++ b/.github/workflows/ci.yml @@ -40,8 +40,15 @@ jobs: - uses: actions/setup-python@v5 with: {python-version: "${{ matrix.python }}"} - run: pip install -e ".[pillars,crypto,dev]" - - name: clone the listing identity at main - run: git clone --depth 1 https://github.com/QuietFireAI/listing-assistants.git "$RUNNER_TEMP/listing-assistants" + - name: clone the listing identity (same branch name if it exists, else main) + run: | + BR="${GITHUB_HEAD_REF:-$GITHUB_REF_NAME}" + if git clone --depth 1 -b "$BR" https://github.com/QuietFireAI/listing-assistants.git "$RUNNER_TEMP/listing-assistants" 2>/dev/null; then + echo "listing identity: branch $BR" + else + git clone --depth 1 https://github.com/QuietFireAI/listing-assistants.git "$RUNNER_TEMP/listing-assistants" + echo "listing identity: main (no branch named $BR)" + fi - name: full suite, no skips allowed env: # Keep Windows on its real default text encoding (cp1252), so a diff --git a/EVIDENCE.md b/EVIDENCE.md index f68eed4..78a9514 100644 --- a/EVIDENCE.md +++ b/EVIDENCE.md @@ -134,10 +134,10 @@ Any new claim added to any README in this stack must be added to this ledger fir | Manners re-injection triggers instrumented (constants + backstop), fade-trackable per run | **MEASURED** | audit events + KPI + after-action section; conduct efficacy itself is UNTESTED | | Ed25519 authority: verifier cannot forge; tamper/forge reject; boot manifest signable incl. MANNERS.md hash | **MEASURED** | test_day3.py; asymmetric tier, optional cryptography dep | | A held outbound message can be declined by the same signed key that releases it; a decline drops it unsent and is on the chain; a release-signed key cannot decline and a decline-signed key cannot release (2026-10-12) | **MEASURED** | tests/test_absolute_signal.py decline tests; tests/test_sweep_core_hub_2026_10_13.py (unsigned and registry-refused answers are integrity violations; reason kept to 500 characters) | -| The record says a person was notified only when the notifier reports the message delivered (sent / delivered / shown); a failed or raising notifier is recorded as human.notify_failed, and the escalation KPI counts confirmed, unreported and failed apart (2026-10-13) | **MEASURED** | tests/test_notification_truth.py (16); before this, a Twilio 401 went on the chain as human.notified | -| A cut-off or unreadable audit line is named (line, reason, cut-off or not) and nothing opens on that log; a person repairs a cut-off last write with tools/audit_repair.py, which keeps every complete entry byte for byte and records the repair; any other damage is refused unchanged (2026-10-13) | **MEASURED** | tests/test_audit_log_damage.py (18), including Windows line endings and a repair interrupted before it records itself | +| The record says a person was notified only when the notifier reports the message delivered (sent / delivered / shown); a failed or raising notifier, or one that answers with anything odd, is recorded as human.notify_failed; the escalation KPI and the after-action report pair each escalation with its own outcome, so one escalation's delivery never covers another's failure, and an unreported delivery gets no transport time (2026-10-13) | **MEASURED** | tests/test_notification_truth.py (29); before this, a Twilio 401 went on the chain as human.notified | +| A cut-off or unreadable audit line is named (line, reason, cut-off or not) and nothing opens on that log; a writer that finds the file damaged, cut back or replaced since its own last write refuses to append, and one that finds another writer's valid entries continues from them; a person repairs a cut-off last write with tools/audit_repair.py, which replaces the log in one step with every complete entry byte for byte plus the record of the repair; any other damage is refused unchanged (2026-10-13) | **MEASURED** | tests/test_audit_log_damage.py (31), including Windows line endings and a repair that dies before its swap. Not covered: two processes appending in the very same instant (no OS file lock) | | The six pillar packages are pinned to exact commits; their own suites pass at those commits (9, 6, 11, 27, 20, 14) | **MEASURED** | pyproject.toml; each pinned pillar's suite run 2026-10-13 | | The core suite runs the listing identity tests on every push, on Linux (Python 3.10, 3.12, 3.13) and Windows, and fails on any skip | **MEASURED** | .github/workflows/ci.yml job with-identity; first green run 38437495999 | -| Every mutant the 2026-10-13 sweep put into the 16 core files is killed by the core suite, except 4 argued equivalent with evidence | **MEASURED** | findings/MUTATION_SWEEP_2026-10-13.md; tools/mutation_sweep.py reproduces it. Mutation testing shows the tests notice these changes; it does not prove the code correct | +| Every mutant the 2026-10-13 sweep puts into the 16 core files is caught by the core suite (859: 855 killed, 1 timeout), except 3 argued equivalent with evidence | **MEASURED** | findings/MUTATION_SWEEP_2026-10-13.md; tools/mutation_sweep.py reproduces it. Mutation testing shows the tests notice these changes; it does not prove the code correct | Not claimed for the runtime: production readiness; real-spoke latency; conduct-level efficacy of manners; licensed legal review of vertical content. diff --git a/PILLAR_TESTING_MANUAL.md b/PILLAR_TESTING_MANUAL.md index 0659a6a..c779aa2 100644 --- a/PILLAR_TESTING_MANUAL.md +++ b/PILLAR_TESTING_MANUAL.md @@ -34,9 +34,9 @@ that pillar regressed; stop, report the raw failure. Do not proceed to integration on a broken pillar - the set cannot be validated on a bad part. Then the dispatcher's suite from its clone: `python3 -m pytest tests/ -q` -EXPECTED: 283 passed, 5 skipped. (The 5 identity-dependent tests activate +EXPECTED: 309 passed, 5 skipped. (The 5 identity-dependent tests activate when IDENTITY_DIR points at a listing-assistants clone, or when one sits at -the conventional sibling path `../listing-assistants` - then 288 passed, as +the conventional sibling path `../listing-assistants` - then 314 passed, as of 2026-10-13. CI runs both: the clone alone, and with the listing identity on Linux 3.10/3.12/3.13 and Windows, where any skip fails the job.) diff --git a/README.md b/README.md index 80cc426..32e1544 100644 --- a/README.md +++ b/README.md @@ -65,7 +65,7 @@ git clone https://github.com/QuietFireAI/dispatcher-agents cd dispatcher-agents pip install -e ".[pillars,crypto,dev]" # routing core is zero-dep; signing needs crypto (Ed25519) git clone https://github.com/QuietFireAI/listing-assistants ../listing-assistants -IDENTITY_DIR=../listing-assistants python3 -m pytest tests/ # 288 tests vs the real 52-route track +IDENTITY_DIR=../listing-assistants python3 -m pytest tests/ # 314 tests vs the real 52-route track IDENTITY_DIR=../listing-assistants python3 demo/run_p11_demo.py # real spokes chain 11 envelopes from 2 signals # Identity-gated tests target the repo bundled at IDENTITY_DIR (default: a fixture track); point IDENTITY_DIR at listing-assistants for the real 52-route run. diff --git a/SKILL.md b/SKILL.md index 7d9071e..287ba50 100644 --- a/SKILL.md +++ b/SKILL.md @@ -73,7 +73,7 @@ pip install -e ".[pillars,crypto,dev]" # pillars pulled from source, never ven ### Verify before claiming anything works ```bash -python -m pytest tests/ # 283 passed + 5 skipped; 288 passed with IDENTITY_DIR at a listing-assistants clone +python -m pytest tests/ # 309 passed + 5 skipped with no listing-assistants clone beside this repo; 314 passed with one (found at ../listing-assistants, or set IDENTITY_DIR) python demo/baseline_run.py # must print all six pillar events nonzero python tools/kpi_gate.py baseline-out/audit-.jsonl \ --taints-expected 1 --selfcheck-bait-expected 1 diff --git a/dispatcher/after_action.py b/dispatcher/after_action.py index 04e0640..d800858 100644 --- a/dispatcher/after_action.py +++ b/dispatcher/after_action.py @@ -15,7 +15,7 @@ import datetime -from .kpi import compute_kpis +from .kpi import compute_kpis, pair_escalations def _iso(ts: float) -> str: @@ -91,24 +91,26 @@ def generate_report(events: list[dict], playbook: str, run_id: str, lines.append("- none on log") lines += ["", "## escalations"] - notif = {e.get("queue"): e["ts"] for e in run_events - if e["kind"] == "human.notified"} - failed = {e.get("queue"): e for e in run_events - if e["kind"] == "human.notify_failed"} + # each escalation's own outcome (kpi.pair_escalations), paired over the + # whole log so another escalation's notification never stands in + outcome = {id(r): o for r, o in pair_escalations(events)} if esc: for e in esc: q = e.get("queue") - if q in notif and notif[q] >= e["ts"]: - lines.append(f"- {q}: transport {notif[q]-e['ts']:.4f}s; " - f"human response time: NOT INSTRUMENTED") - elif q in failed and failed[q]["ts"] >= e["ts"]: - f = failed[q] - why = f.get("notifier_status") or f.get("error") or "unknown" + o = outcome.get(id(e)) + if o is None: + lines.append(f"- {q}: raised, NO human.notified on log - " + f"transport unproven") + elif o["kind"] == "human.notify_failed": + why = o.get("notifier_status") or o.get("error") or "unknown" lines.append(f"- {q}: raised, NOTIFICATION FAILED ({why}) - " f"no person was reached") + elif o.get("transport") == "not reported": + lines.append(f"- {q}: raised, the notifier reported nothing - " + f"delivery unconfirmed, no transport time") else: - lines.append(f"- {q}: raised, NO human.notified on log - " - f"transport unproven") + lines.append(f"- {q}: transport {o['ts'] - e['ts']:.4f}s; " + f"human response time: NOT INSTRUMENTED") else: lines.append("- none") diff --git a/dispatcher/core.py b/dispatcher/core.py index 8f63664..036825d 100644 --- a/dispatcher/core.py +++ b/dispatcher/core.py @@ -139,19 +139,21 @@ class AuditLogDamaged(Exception): path, AuditLog.repair_torn_tail(path), which a person runs. Any other unreadable line is damage or tampering and has no automatic repair.""" - def __init__(self, path: str, line: int, reason: str, torn_tail: bool): + def __init__(self, path: str, line, reason: str, torn_tail: bool): self.path, self.line, self.reason, self.torn_tail = path, line, reason, torn_tail if torn_tail: how = ("this looks like a write that was cut off (for example by a " - "power loss). To recover, a person runs " - "AuditLog.repair_torn_tail(path) (tools/audit_repair.py in " - "dispatcher-agents): it moves that partial line to a side " - "file, keeps every complete entry, and records the repair " - "on the chain") + "power loss). To recover, stop every process using the log; " + "then a person runs AuditLog.repair_torn_tail(path) " + "(dispatcher-agents: tools/audit_repair.py; a product built " + "on this core may give it its own command): it moves " + "that partial line to a side file, keeps every complete " + "entry, and records the repair on the chain") else: how = ("this is not a cut-off last write; nothing repairs it " "automatically. Keep the file as it is and investigate") - super().__init__(f"audit log {path} is damaged at line {line}: {reason}. " + where = f"at line {line}" if line else "(no single line)" + super().__init__(f"audit log {path} is damaged {where}: {reason}. " f"Nothing was written. {how}.") @@ -168,6 +170,18 @@ def _log_lines(path: str): return out, data.endswith(b"\n") or not data +def _fsync_dir(d: str) -> None: + """Make a rename in folder d durable. POSIX only: Windows cannot open a + folder to sync it, and its rename is already ordered with the data.""" + if os.name == "nt": + return + fd = os.open(d, os.O_RDONLY) + try: + os.fsync(fd) + finally: + os.close(fd) + + def _parse(raw: bytes): """One log line as a dict, or None if it is not a readable entry.""" try: @@ -196,6 +210,40 @@ def __init__(self, path: str): os.makedirs(os.path.dirname(path) or ".", exist_ok=True) self._lock = threading.Lock() self._prev = self._recover_tip() + self._size = self._file_size() + + def _file_size(self): + try: + return os.path.getsize(self.path) + except FileNotFoundError: + return None + + def _resync(self) -> None: + """The file is not the size this process left it: someone else wrote, + cut or replaced it (found by the 2026-10-13 cold review: a desk kept + appending to a log damaged under it, and a second writer forked the + chain). Append again only if the whole chain verifies AND still holds + this process's last entry; then continue from the file's real tip. + Otherwise raise AuditLogDamaged and write nothing. + + This catches every change that alters the file's size between two + appends. It does not stop two processes appending in the very same + instant; only an operating-system file lock does that.""" + chain = self.verify_chain() + if not chain["ok"]: + raise AuditLogDamaged( + self.path, chain["break_at"], + f"{chain['reason']} (the file changed since this process last wrote it)", + torn_tail=chain["torn_tail"]) + if self._prev != self.GENESIS and ( + not os.path.exists(self.path) + or self._prev not in {(_parse(r) or {}).get("entry_hash") + for _, r in _log_lines(self.path)[0]}): + raise AuditLogDamaged( + self.path, None, "entries this process wrote are no longer in the " + "file - it was cut back, replaced or deleted while in use", + torn_tail=False) + self._prev = self._recover_tip() def _recover_tip(self) -> str: """Resume the chain across process restarts: tip = last entry_hash. @@ -233,10 +281,17 @@ def repair_torn_tail(cls, path: str) -> dict: - the bytes after the last newline are not a readable entry, and - every line before them is readable and the chain over them verifies. Then: the partial bytes are written to a new side file - .torn-- (flushed to disk first), the log is cut - back to its last complete entry, and an audit.tail_quarantined entry - (line, byte count, sha256 of the partial bytes, side file) is - appended, so the repair itself is on the chain. Returns that record.""" + .torn-- (flushed to disk first), and the log is + replaced in one step (os.replace) by every complete entry, byte for + byte, followed by an audit.tail_quarantined entry (line, byte count, + sha256 of the partial bytes, side file), so the repair itself is on + the chain. Returns that record. + + Every process writing the log must be stopped first. A process still + holding it would find the file changed at its next append and refuse + to write (AuditLog._resync). The repair cannot tell a crash from + someone cutting the log back and adding a partial line: an anchor + saved earlier (anchor() / verify_anchor()) is what shows that.""" if not os.path.exists(path): raise ValueError(f"{path}: no such audit log") with open(path, "rb") as f: @@ -268,18 +323,38 @@ def repair_torn_tail(cls, path: str) -> dict: digest = hashlib.sha256(tail).hexdigest() stamp = time.strftime("%Y%m%dT%H%M%SZ", time.gmtime()) side = f"{path}.torn-{stamp}-{digest[:12]}" - with open(side, "xb") as f: # never overwrite an earlier side file + k = 1 + while os.path.exists(side): # never overwrite an earlier side file + k += 1 + side = f"{path}.torn-{stamp}-{digest[:12]}-{k}" + with open(side, "xb") as f: f.write(tail) f.flush() os.fsync(f.fileno()) - with open(path, "r+b") as f: - f.truncate(len(prefix)) - f.flush() - os.fsync(f.fileno()) rec = {"line": torn_line, "bytes": len(tail), "sha256": digest, "side_file": os.path.basename(side), "complete_entries": sum(1 for r in prefix.split(b"\n") if r.strip())} - cls(path).append("audit.tail_quarantined", rec) + # One step (2026-10-13 cold review): the repaired log - every complete + # entry byte for byte, then the entry recording this repair - is + # written to a new file and swapped in with os.replace. A crash leaves + # either the old log or the repaired one, never a cut log without the + # record of why it was cut. + body = {**rec, "ts": time.time(), "kind": "audit.tail_quarantined"} + entry = json.dumps({**body, "prev_hash": prev, + "entry_hash": cls._entry_hash(body, prev)}) + nl = b"\r\n" if prefix.endswith(b"\r\n") else b"\n" + tmp = f"{path}.repair-{stamp}-{digest[:12]}" + try: + with open(tmp, "wb") as f: + f.write(prefix + entry.encode("utf-8") + nl) + f.flush() + os.fsync(f.fileno()) + os.replace(tmp, path) + except BaseException: + if os.path.exists(tmp): + os.remove(tmp) + raise + _fsync_dir(os.path.dirname(os.path.abspath(path))) return rec RESERVED = ("ts", "kind", "prev_hash", "entry_hash") # framing fields the log owns, never the caller @@ -295,6 +370,8 @@ def append(self, kind: str, record: dict) -> None: # Hub.escalate) could forge or erase an event kind - the audit log is # the single source of truth, so its framing is not caller-writable. with self._lock: + if self._file_size() != self._size: + self._resync() body = {**record, "ts": time.time(), "kind": kind} for k in ("prev_hash", "entry_hash"): body.pop(k, None) @@ -306,6 +383,7 @@ def append(self, kind: str, record: dict) -> None: f.write(line + "\n") f.flush() os.fsync(f.fileno()) + self._size = os.fstat(f.fileno()).st_size self._needs_newline = False self._prev = eh diff --git a/dispatcher/hub.py b/dispatcher/hub.py index 9f11d7c..e3020ea 100644 --- a/dispatcher/hub.py +++ b/dispatcher/hub.py @@ -58,6 +58,14 @@ def is_authority(intent: str) -> bool: return intent.endswith(".authority") or intent in AUTHORITY_INTENTS +def _plain(v): + """A notifier's value as the record can hold it: str, number, bool or + None as is, anything else as its repr, cut to 300 characters.""" + if v is None or isinstance(v, (str, int, float, bool)): + return v + return repr(v)[:300] + + class Reject(Exception): def __init__(self, reason: str): self.reason = reason @@ -381,7 +389,17 @@ def queue_and_notify(self, queue_name: str, record: dict) -> None: self.queues.setdefault(queue_name, []).append(record) self._notify(queue_name, record) - def _notify(self, queue: str, record: dict) -> None: + def notify(self, queue: str, record: dict) -> str: + """Tell a person about something without putting it on a queue (for + example an alert that a decision is waiting), with the outcome + recorded exactly as for a queue landing. Returns "notified", + "not reported", "notify_failed" or "no notifier" (2026-10-13 cold + review: a caller that invoked human_notifier directly left no + outcome on the record).""" + with self._lock: + return self._notify(queue, record) + + def _notify(self, queue: str, record: dict) -> str: """Calls the human notifier and records what actually happened (repair plan 1.1, 2026-10-13). The notifier's return value decides: - a dict whose "status" is in NOTIFY_DELIVERED -> human.notified @@ -395,27 +413,32 @@ def _notify(self, queue: str, record: dict) -> None: transport KPI (kpi.py) reports confirmed, unreported and failed notifications separately.""" if self.human_notifier is None: - return + return "no notifier" try: res = self.human_notifier(queue, record) except Exception as e: # recorded, never raised past the hub self.audit.append("human.notify_failed", {**record, "queue": queue, "error": repr(e)[:300]}) - return + return "notify_failed" if not isinstance(res, dict): self.audit.append("human.notified", {**record, "queue": queue, "transport": "not reported"}) - return + return "not reported" status = res.get("status") - if status in NOTIFY_DELIVERED: + # only a plain string status can claim delivery; anything else a + # notifier returns is reported as it is, never raised past the hub + # (2026-10-13 cold review: a list status or an object in http_status + # raised out of escalate after escalation.raised was written) + if isinstance(status, str) and status in NOTIFY_DELIVERED: self.audit.append("human.notified", {**record, "queue": queue, "transport_status": status}) - return - failed = {**record, "queue": queue, "notifier_status": status} + return "notified" + failed = {**record, "queue": queue, "notifier_status": _plain(status)} for k in ("http_status", "channel", "error"): if k in res: - failed[f"notifier_{k}"] = str(res[k])[:300] if k == "error" else res[k] + failed[f"notifier_{k}"] = str(res[k])[:300] if k == "error" else _plain(res[k]) self.audit.append("human.notify_failed", failed) + return "notify_failed" def resume_loop_suspension(self, client_context_id: str, intent: str) -> dict: """Real gap, found 2026-07-17: once a (context, intent) pair diff --git a/dispatcher/kpi.py b/dispatcher/kpi.py index a78e918..2213c13 100644 --- a/dispatcher/kpi.py +++ b/dispatcher/kpi.py @@ -29,6 +29,31 @@ from collections import defaultdict +NOTIFY_OUTCOMES = ("human.notified", "human.notify_failed") + + +def pair_escalations(events: list[dict]) -> list[tuple[dict, dict | None]]: + """Each escalation.raised with the notification outcome written for it, + in log order. Hub.escalate writes escalation.raised and then, under the + same lock, that escalation's outcome (human.notified or + human.notify_failed) on the same queue - so an escalation's outcome is + the first outcome on its queue after it and before the next escalation + on that queue. An outcome is never shared: one escalation's delivery + cannot stand in for another's failure (2026-10-13 cold review: matching + by queue and time alone let a later page on the same queue cover an + earlier failed one).""" + pairs: list[list] = [] + waiting: dict = {} + for e in events: + k = e.get("kind") + if k == "escalation.raised": + waiting[e.get("queue")] = len(pairs) + pairs.append([e, None]) + elif k in NOTIFY_OUTCOMES and e.get("queue") in waiting: + pairs[waiting.pop(e.get("queue"))][1] = e + return [(r, o) for r, o in pairs] + + def compute_kpis(events: list[dict]) -> dict: by_kind: dict[str, list[dict]] = defaultdict(list) for e in events: @@ -78,33 +103,25 @@ def compute_kpis(events: list[dict]) -> dict: "siding_resumes": len(by_kind["siding.resume"]), } - # escalation transport: raised -> human.notified, matched per queue+ts order. - # Only human.notified is a transport; human.notify_failed (2026-10-13) is - # counted as failed, and a notified entry whose notifier reported nothing - # ("transport": "not reported") is counted apart from confirmed ones. + # escalation transport: each escalation paired with its own outcome + # (pair_escalations). Only human.notified is a transport; + # human.notify_failed is counted as failed, and a notified entry whose + # notifier reported nothing ("transport": "not reported") is counted + # apart from confirmed ones. raised = by_kind["escalation.raised"] - notified = by_kind["human.notified"] - esc_failed = [e for e in by_kind["human.notify_failed"] - if str(e.get("queue", "")).startswith("escalation.")] - if raised and (notified or esc_failed): - n_by_q = defaultdict(list) - for n in notified: - n_by_q[n.get("queue")].append(n["ts"]) - transports = [] - for r in raised: - cands = [t for t in n_by_q.get(r.get("queue"), []) if t >= r["ts"]] - if cands: - transports.append(min(cands) - r["ts"]) - esc_notified = [n for n in notified - if str(n.get("queue", "")).startswith("escalation.")] + pairs = pair_escalations(events) + if raised and any(o for _, o in pairs): + notified = [(r, o) for r, o in pairs if o and o["kind"] == "human.notified"] + transports = [o["ts"] - r["ts"] for r, o in notified] escalation_transport = {"computable": True, "n": len(transports), "unnotified": len(raised) - len(transports), "max_s": max(transports) if transports else None, - "confirmed": sum(1 for n in esc_notified - if n.get("transport") != "not reported"), - "not_reported": sum(1 for n in esc_notified - if n.get("transport") == "not reported"), - "notify_failed": len(esc_failed)} + "confirmed": sum(1 for _, o in notified + if o.get("transport") != "not reported"), + "not_reported": sum(1 for _, o in notified + if o.get("transport") == "not reported"), + "notify_failed": sum(1 for _, o in pairs + if o and o["kind"] == "human.notify_failed")} else: escalation_transport = {"computable": False, "missing": ["escalation.raised/human.notified pairs"]} diff --git a/findings/MUTATION_SWEEP_2026-10-13.md b/findings/MUTATION_SWEEP_2026-10-13.md index e3c60e7..7827906 100644 --- a/findings/MUTATION_SWEEP_2026-10-13.md +++ b/findings/MUTATION_SWEEP_2026-10-13.md @@ -33,8 +33,17 @@ mutant*) marks behaviour no test holds. | 4. The last 7 | working tree, 288 tests | 7 | 3 | 4 | | 5. Whole sweep again, packaged tool | this commit, 288 tests | 808 | 804 | 4 - the 4 below, 0 timeouts | -Run 5 is the confirmation: the full sweep from scratch with -`tools/mutation_sweep.py` on the code and tests of this commit. +Run 5 confirmed commit ccbfb21. A cold review by a separate agent then +found defects in the 1.1/1.2 code (below); fixing them added code, so the +sweep was run again on the fixed tree: + +| Run | Code / tests | Mutants | Killed | Survived | +|---|---|---|---|---| +| 6. After the review fixes | working tree, 306 tests | 860 | 845 + 1 timeout (an infinite-loop mutant: caught) | 14: the 4 below and 10 in the new code | +| 7. Those 14 again | working tree, 314 tests | 14 | 11 | 3 - the 3 equivalents still in the code | +| 8. Whole sweep, final | this commit, 314 tests | 859 | 855 + 1 timeout (the same infinite-loop mutant: caught) | 3 - the 3 equivalents | + +Run 8 is the confirmation for this commit. ## What the survivors showed @@ -68,15 +77,17 @@ New tests: `tests/test_sweep_core_hub_2026_10_13.py`, read. Removed. Mutant 218 changed only that variable; it no longer exists. -## The 4 equivalent mutants +## The equivalent mutants -Each changes no behaviour. Evidence was run, not assumed. +Each changes no behaviour. Evidence was run, not assumed. The third row's +code no longer exists: the repair now writes a new file and swaps it in +instead of truncating, so 3 remain. | Mutant | Why nothing changes | Evidence | |---|---|---| | `attestation.py:26` read chunk 65536 -> 65537 | A streamed SHA-256 does not depend on the chunk size | 300,000 random bytes hashed with both chunk sizes and in one call: identical | | `core.py:125` `to in SPECIAL and to in r` -> `to not in SPECIAL and to in r` | The whole clause implies `to in r`, which is already the first test on that line, so the clause can never change the answer | Exhaustive: all 32 receiver sets over {02, human, external, queue, any} x 6 destinations give the same result with the clause, with the mutant, and with no clause at all | -| `core.py:277` `f.flush()` -> `pass` after `truncate` | Nothing is written through that handle; truncate goes straight to the file | Size on disk read right after `truncate(3)`, before any flush: 3 | +| (removed with the truncate) `core.py:277` `f.flush()` -> `pass` after `truncate` | Nothing is written through that handle; truncate goes straight to the file | Size on disk read right after `truncate(3)`, before any flush: 3 | | `hub.py:64` `super().__init__(reason)` -> `pass` in `Reject` | Python's exception constructor stores the arguments before `__init__` runs, so `args` and `str()` are the same | `Reject`-shaped class with and without the call: same `args` and `str` | ## Redundant clauses found on the way (no behaviour change, reported) @@ -97,6 +108,20 @@ copies side by side all passed. The runner then kept only the summary line, not the failing test's name, so the test is not known. Counted as survived. The runner now records failing test names. No failure has recurred. +## What the cold review found that the sweep could not + +Mutation testing only asks whether the tests notice a change to code that +exists. The review found behaviour that was missing or wrong under every +test: a running desk kept writing to a log damaged under it; a later page +on the same queue covered an earlier failed one in the KPI and the report; +the report gave a transport time to a notifier that reported nothing; an +odd notifier answer raised out of the hub; a decision alert in +listing-assistants called the notifier around the hub; two writers could +fork the chain. All fixed with tests on 2026-10-13. One test it prompted me +to recheck was passing for the wrong reason (its "cut back" case emptied +the file); fixed. Not fixed: two processes appending in the very same +instant - only an operating-system file lock stops that. + ## What this does and does not show It shows the core suite notices each of these kinds of change to the core, diff --git a/tests/test_audit_log_damage.py b/tests/test_audit_log_damage.py index dafa16c..a27845f 100644 --- a/tests/test_audit_log_damage.py +++ b/tests/test_audit_log_damage.py @@ -115,24 +115,99 @@ def test_repair_moves_the_partial_line_aside_and_records_it(tmp_path): @pytest.mark.parametrize("crlf", [False, True]) -def test_a_repair_interrupted_before_it_records_itself_leaves_exactly_the_complete_entries(tmp_path, monkeypatch, crlf): - # The process can die between the cut and the audit.tail_quarantined entry. - # What is left on disk must then be the complete entries byte for byte - - # a clean, newline-terminated log, not one cut a byte short. +def test_a_repair_that_dies_before_the_swap_leaves_the_log_as_it_was(tmp_path, monkeypatch, crlf): + # The repaired log is written to a new file and swapped in with one + # os.replace (2026-10-13 cold review: the earlier repair cut the log and + # then appended, so a crash between the two left a cut log with no record + # of why). Dying before the swap must leave the original untouched, no + # temporary file behind, and the repair still possible. + from dispatcher import core p = three(tmp_path) data = raw(p) if crlf: data = data.replace(b"\n", b"\r\n") open(p, "wb").write(data + b'{"half') - def died(self, *a, **k): + def died(a, b): raise RuntimeError("process died") - monkeypatch.setattr(AuditLog, "append", died) + monkeypatch.setattr(core.os, "replace", died) with pytest.raises(RuntimeError): AuditLog.repair_torn_tail(p) - assert raw(p) == data + assert raw(p) == data + b'{"half' + assert not [f for f in os.listdir(str(tmp_path)) if ".repair-" in f] monkeypatch.undo() - assert AuditLog.check_file(p) == {"ok": True, "entries": 3, "break_at": None} + rec = AuditLog.repair_torn_tail(p) # runs again, new side file name + assert raw(p).startswith(data) and AuditLog.check_file(p)["ok"] + assert len([f for f in os.listdir(str(tmp_path)) if ".torn-" in f]) == 2 + assert rec["complete_entries"] == 3 + + +# ------------------------------------------- the file changed under a writer +# Found by the 2026-10-13 cold review: AuditLog checked the file only when it +# was opened, so a running desk kept appending to a log damaged under it, +# and two writers on one file forked the chain. +def test_a_writer_refuses_to_append_after_the_file_was_damaged_under_it(tmp_path): + p = three(tmp_path) + log = AuditLog(p) + lines = raw(p).split(b"\n") + lines[1] = b'{"garbage' + open(p, "wb").write(b"\n".join(lines)) + before = raw(p) + with pytest.raises(AuditLogDamaged) as ei: + log.append("y", {"after": "damage"}) + assert ei.value.line == 2 and "changed since this process last wrote" in str(ei.value) + assert raw(p) == before + + +def test_a_writer_does_not_write_after_another_writers_cut_off_line(tmp_path): + p = three(tmp_path) + a = AuditLog(p) + open(p, "ab").write(b'{"half') # another writer died mid-line + before = raw(p) + with pytest.raises(AuditLogDamaged) as ei: + a.append("y", {}) + assert ei.value.torn_tail is True and raw(p) == before + AuditLog.repair_torn_tail(p) # still repairable + assert AuditLog.check_file(p)["ok"] + + +def test_two_writers_on_one_file_continue_one_chain(tmp_path): + p = three(tmp_path) + a, b = AuditLog(p), AuditLog(p) + a.append("from-a", {}) + b.append("from-b", {}) # b sees a's entry and follows it + a.append("from-a", {}) + assert AuditLog.check_file(p) == {"ok": True, "entries": 6, "break_at": None} + + +def test_a_writer_open_during_a_repair_follows_the_repaired_chain(tmp_path): + p = three(tmp_path) + w = AuditLog(p) + open(p, "ab").write(b'{"half') + AuditLog.repair_torn_tail(p) + w.append("after-repair", {}) + assert AuditLog.check_file(p)["ok"] + assert [e["kind"] for e in AuditLog(p).read()][-2:] == ["audit.tail_quarantined", "after-repair"] + + +@pytest.mark.parametrize("how", ["deleted", "cut back", "replaced"]) +def test_a_writer_whose_entries_are_gone_refuses(tmp_path, how): + p = three(tmp_path) + w = AuditLog(p) + if how == "deleted": + os.remove(p) + elif how == "cut back": + first = raw(p).split(b"\n")[0] + b"\n" # read before opening for write + open(p, "wb").write(first) + assert AuditLog.check_file(p) == {"ok": True, "entries": 1, "break_at": None} + else: + os.remove(p) + other = AuditLog(p) + other.append("x", {"n": "new history"}) + before = raw(p) if os.path.exists(p) else None + with pytest.raises(AuditLogDamaged, match="no longer in the file"): + w.append("y", {}) + assert (raw(p) if os.path.exists(p) else None) == before def test_repair_refuses_when_the_chain_is_broken_before_the_cut_and_changes_nothing(tmp_path): @@ -220,3 +295,95 @@ def test_the_cli_checks_repairs_and_refuses(tmp_path): assert r.returncode == 2 and json.loads(r.stdout)["repaired"] is False r = cli(str(tmp_path / "missing.jsonl")) assert r.returncode == 2 + + +# --------------------------------------------------------------- the KPI gate +def gate(*args): + return subprocess.run([sys.executable, os.path.join(ROOT, "tools", "kpi_gate.py"), *args], + capture_output=True, text=True) + + +def test_the_kpi_gate_fails_a_damaged_or_edited_log_by_name(tmp_path): + p = three(tmp_path) + r = gate(p) + assert r.returncode == 0 and "KPI GATE PASS" in r.stdout + open(p, "ab").write(b'{"half') + r = gate(p) + assert r.returncode == 1 and "Traceback" not in r.stderr + assert "FAIL audit chain broken at line 4: not a readable entry (a write cut off at the end)" in r.stdout + q = three(tmp_path, "b.jsonl") + lines = raw(q).split(b"\n") + lines[0] = lines[0].replace(b'"n": 0', b'"n": 5') + open(q, "wb").write(b"\n".join(lines)) + r = gate(q) + assert r.returncode == 1 and "FAIL audit chain broken at line 1: does not link" in r.stdout + + +# --------------------------------- details the 2026-10-13 re-sweep asked about +def test_a_second_repair_in_the_same_second_gets_its_own_side_file(tmp_path, monkeypatch): + from dispatcher import core + monkeypatch.setattr(core.time, "strftime", lambda *a: "20261013T000000Z") + p = three(tmp_path) + open(p, "ab").write(b'{"half') + first = AuditLog.repair_torn_tail(p) + open(p, "ab").write(b'{"half') # the same bytes, cut again + second = AuditLog.repair_torn_tail(p) + sha12 = first["sha256"][:12] + assert first["side_file"] == f"a.jsonl.torn-20261013T000000Z-{sha12}" + assert second["side_file"] == f"a.jsonl.torn-20261013T000000Z-{sha12}-2" + + +def test_the_repaired_log_keeps_the_files_own_line_endings(tmp_path): + p = three(tmp_path) + open(p, "ab").write(b'{"half') + AuditLog.repair_torn_tail(p) + assert b"\r" not in raw(p) + q = three(tmp_path, "b.jsonl") + data = raw(q) # read before opening for write + open(q, "wb").write(data.replace(b"\n", b"\r\n") + b'{"half') + AuditLog.repair_torn_tail(q) + assert raw(q).endswith(b"}\r\n") and raw(q).count(b"\r\n") == 4 + + +def test_the_repair_swaps_in_a_temporary_file_named_for_the_cut(tmp_path, monkeypatch): + from dispatcher import core + p = three(tmp_path) + open(p, "ab").write(b'{"half') + seen = [] + real = os.replace + monkeypatch.setattr(core.os, "replace", lambda a, b: (seen.append((a, b)), real(a, b))) + rec = AuditLog.repair_torn_tail(p) + stamp = rec["side_file"].split(".torn-")[1].split("-")[0] + assert seen == [(f"{p}.repair-{stamp}-{rec['sha256'][:12]}", p)] + + +def test_the_repair_closes_every_file_handle_it_opens(tmp_path, monkeypatch): + from dispatcher import core + p = three(tmp_path) + open(p, "ab").write(b'{"half') + opened, closed = [], [] + real_open, real_close = os.open, os.close + + def track_open(*a, **k): + fd = real_open(*a, **k) + opened.append(fd) + return fd + + def track_close(fd): + closed.append(fd) + return real_close(fd) + monkeypatch.setattr(core.os, "open", track_open) + monkeypatch.setattr(core.os, "close", track_close) + AuditLog.repair_torn_tail(p) + assert sorted(opened) == sorted(closed) + assert len(opened) == (0 if os.name == "nt" else 1) # the folder, to sync the swap + + +def test_a_writer_whose_entries_are_gone_is_not_told_it_was_a_cut_off_write(tmp_path): + p = three(tmp_path) + w = AuditLog(p) + os.remove(p) + with pytest.raises(AuditLogDamaged) as ei: + w.append("y", {}) + assert ei.value.torn_tail is False and ei.value.line is None + assert "damaged (no single line)" in str(ei.value) diff --git a/tests/test_day3.py b/tests/test_day3.py index a6ed313..b7150ce 100644 --- a/tests/test_day3.py +++ b/tests/test_day3.py @@ -250,8 +250,14 @@ def test_p11_demo_end_to_end(tmp_path, monkeypatch): "## kpis", "## manners re-injections"): assert section in report # full AFTER_ACTION schema assert "TRIGGERED" in report # both gates fired - assert "NOT INSTRUMENTED" in report # declared, not faked - assert "'computable': True" in report # escalation transport real + # the demo's notifier appends to a list and reports nothing, so the + # report says delivery is unconfirmed - no transport time is claimed + # (2026-10-13: it used to print a transport time for it) + esc = report.split("## escalations")[1].split("##")[0] + assert "the notifier reported nothing - delivery unconfirmed" in esc + assert "transport 0" not in esc and "NOT INSTRUMENTED" not in esc + assert "'computable': True" in report # outcome paired from the log + assert "'not_reported': 1" in report # --------------------------------------------- loop protection + manners (Day 5) diff --git a/tests/test_notification_truth.py b/tests/test_notification_truth.py index 0ee9e62..7843fc0 100644 --- a/tests/test_notification_truth.py +++ b/tests/test_notification_truth.py @@ -141,3 +141,87 @@ def test_the_after_action_report_says_the_notification_failed(tmp_path): assert "NOTIFICATION FAILED (failed) - no person was reached" in report assert "transport" not in report.split("## escalations")[1].split("##")[0].replace( "NOTIFICATION FAILED", "") + + +# ------------------------------------------- found by the 2026-10-13 cold review +def test_a_later_delivery_on_the_same_queue_does_not_cover_an_earlier_failure(tmp_path): + outcomes = iter([{"status": "failed", "http_status": 401}, {"status": "sent"}]) + hub = hub_with(tmp_path, lambda q, r: next(outcomes)) + hub.escalate("escalation.hot_lead", {"client_context_id": "A"}) + hub.escalate("escalation.hot_lead", {"client_context_id": "B"}) + k = compute_kpis(hub.audit.read())["escalation_transport_time"] + assert (k["n"], k["unnotified"], k["confirmed"], k["notify_failed"]) == (1, 1, 1, 1) + report = generate_report(hub.audit.read(), "P11", "r", "A", steps=[]) + esc = report.split("## escalations")[1].split("##")[0].strip().splitlines() + assert esc[0] == "- escalation.hot_lead: raised, NOTIFICATION FAILED (failed) - no person was reached" + assert esc[1].startswith("- escalation.hot_lead: transport ") + + +def test_an_escalation_with_no_outcome_is_not_covered_by_the_next_ones(tmp_path): + hub = hub_with(tmp_path, None) # nobody to notify + hub.escalate("escalation.hot_lead", {"client_context_id": "A"}) + hub.human_notifier = lambda q, r: {"status": "sent"} + hub.escalate("escalation.hot_lead", {"client_context_id": "B"}) + k = compute_kpis(hub.audit.read())["escalation_transport_time"] + assert (k["n"], k["unnotified"]) == (1, 1) + + +def test_the_report_does_not_give_a_transport_time_to_a_notifier_that_reported_nothing(tmp_path): + hub = hub_with(tmp_path, lambda q, r: None) + hub.escalate("escalation.hot_lead", {"client_context_id": "C"}) + report = generate_report(hub.audit.read(), "P11", "r", "C", steps=[]) + assert ("- escalation.hot_lead: raised, the notifier reported nothing - delivery " + "unconfirmed, no transport time") in report + assert "transport 0" not in report.split("## escalations")[1].split("##")[0] + + +@pytest.mark.parametrize("res,status", [({"status": ["sent"]}, "['sent']"), + ({"status": "SENT"}, "SENT"), + ({"status": "failed", "http_status": object()}, "failed")]) +def test_an_odd_notifier_answer_is_recorded_never_raised(tmp_path, res, status): + hub = hub_with(tmp_path, lambda q, r: res) + assert hub.escalate("escalation.hot_lead", {"client_context_id": "D"})["status"] == "escalated" + f = last(hub, "human.notify_failed") + assert f["notifier_status"] == status and "human.notified" not in kinds(hub) + if "http_status" in res: + assert f["notifier_http_status"].startswith(" complete + assert len(seen) == (2 if os.name == "nt" else 3) def test_repair_of_a_missing_file_is_refused(tmp_path): diff --git a/tools/kpi_gate.py b/tools/kpi_gate.py index 48ef971..99ae324 100644 --- a/tools/kpi_gate.py +++ b/tools/kpi_gate.py @@ -68,7 +68,17 @@ def main(argv=None) -> int: ap.add_argument("--taints-expected", type=int, default=0) ap.add_argument("--selfcheck-bait-expected", type=int, default=0) a = ap.parse_args(argv) - events = [json.loads(l) for l in open(a.audit_log, encoding="utf-8") if l.strip()] + # the chain first (2026-10-13 cold review: a damaged log crashed this + # gate with a raw JSONDecodeError, and a log with an edited line passed) + from dispatcher.core import AuditLog + chain = AuditLog.check_file(a.audit_log) + if not chain["ok"]: + print(f"FAIL audit chain broken at line {chain['break_at']}: {chain['reason']}" + + (" (a write cut off at the end)" if chain.get("torn_tail") else "")) + return 1 + reader = AuditLog.__new__(AuditLog) + reader.path = a.audit_log + events = reader.read() v = gate(events, a.taints_expected, a.selfcheck_bait_expected) k = compute_kpis(events) print("delta-class (recorded, not thresholded):", From 008fb8a2298646ab548b019f6fb9e07035dca741 Mon Sep 17 00:00:00 2001 From: Claude Date: Tue, 13 Oct 2026 21:40:43 +0000 Subject: [PATCH 08/10] Second review fixes and the OS lock: writers take turns, a stopped desk saves nothing unrecorded, outcomes name their escalation Owner decision (2026-10-13): an operating-system lock on .lock (flock on POSIX, msvcrt.locking on Windows). Every AuditLog read and write takes it, re-entrant within a process; a writer waits up to LOCK_WAIT_S (30 s) and then raises AuditLogBusy, writing nothing. The repair takes it too. Shown by three processes appending 450 entries at once (fails without the lock). Second review (same agent re-checking its findings), fixed: - the change check compared size only; now size and modification time - AuditLog.ensure_intact(): callers check before writing anything else (listing's swarm saved a snapshot the log could not record) - each notification outcome carries raised_entry = the escalation's entry_hash; pairing is exact across processes (older logs by order) - Windows CI red: a test assumed LF; now built byte for byte - the repair keeps the log's permissions and owner where allowed, and a failed swap removes its side file; tools/audit_repair.py reports a busy lock or failed swap instead of a traceback - AuditLog.reader(path): read-only view (replaces __new__ hacks) - the repair's docstring said a holder would refuse; it follows the chain Sweep on this commit: 921 mutants, 908 killed, 1 timeout, 12 survived: 3 equivalent, 1 that only changes CPU use (the lock's retry sleep), 8 on Windows-only lines a Linux sweep cannot run (findings document). 325 passed + 5 skipped alone; 330 with the listing identity. Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_01CRunDQmfmnZdtJiP78e8WR --- EVIDENCE.md | 6 +- PILLAR_TESTING_MANUAL.md | 4 +- README.md | 2 +- SKILL.md | 2 +- dispatcher/core.py | 188 +++++++++++++++++---- dispatcher/hub.py | 21 ++- dispatcher/kpi.py | 31 +++- findings/MUTATION_SWEEP_2026-10-13.md | 53 +++++- tests/test_audit_log_damage.py | 214 +++++++++++++++++++++++- tests/test_notification_truth.py | 46 +++++ tests/test_sweep_core_hub_2026_10_13.py | 4 +- tools/audit_repair.py | 12 +- tools/kpi_gate.py | 4 +- 13 files changed, 515 insertions(+), 72 deletions(-) diff --git a/EVIDENCE.md b/EVIDENCE.md index 78a9514..bce8ee1 100644 --- a/EVIDENCE.md +++ b/EVIDENCE.md @@ -134,10 +134,10 @@ Any new claim added to any README in this stack must be added to this ledger fir | Manners re-injection triggers instrumented (constants + backstop), fade-trackable per run | **MEASURED** | audit events + KPI + after-action section; conduct efficacy itself is UNTESTED | | Ed25519 authority: verifier cannot forge; tamper/forge reject; boot manifest signable incl. MANNERS.md hash | **MEASURED** | test_day3.py; asymmetric tier, optional cryptography dep | | A held outbound message can be declined by the same signed key that releases it; a decline drops it unsent and is on the chain; a release-signed key cannot decline and a decline-signed key cannot release (2026-10-12) | **MEASURED** | tests/test_absolute_signal.py decline tests; tests/test_sweep_core_hub_2026_10_13.py (unsigned and registry-refused answers are integrity violations; reason kept to 500 characters) | -| The record says a person was notified only when the notifier reports the message delivered (sent / delivered / shown); a failed or raising notifier, or one that answers with anything odd, is recorded as human.notify_failed; the escalation KPI and the after-action report pair each escalation with its own outcome, so one escalation's delivery never covers another's failure, and an unreported delivery gets no transport time (2026-10-13) | **MEASURED** | tests/test_notification_truth.py (29); before this, a Twilio 401 went on the chain as human.notified | -| A cut-off or unreadable audit line is named (line, reason, cut-off or not) and nothing opens on that log; a writer that finds the file damaged, cut back or replaced since its own last write refuses to append, and one that finds another writer's valid entries continues from them; a person repairs a cut-off last write with tools/audit_repair.py, which replaces the log in one step with every complete entry byte for byte plus the record of the repair; any other damage is refused unchanged (2026-10-13) | **MEASURED** | tests/test_audit_log_damage.py (31), including Windows line endings and a repair that dies before its swap. Not covered: two processes appending in the very same instant (no OS file lock) | +| The record says a person was notified only when the notifier reports the message delivered (sent / delivered / shown); a failed or raising notifier, or one that answers with anything odd, is recorded as human.notify_failed; the escalation KPI and the after-action report pair each escalation with its own outcome - the outcome names the escalation entry's hash - so one escalation's delivery never covers another's failure, even when two processes raise on one queue, and an unreported delivery gets no transport time (2026-10-13) | **MEASURED** | tests/test_notification_truth.py (33); before this, a Twilio 401 went on the chain as human.notified | +| A cut-off or unreadable audit line is named (line, reason, cut-off or not) and nothing opens on that log; writers take turns through an OS lock on .lock, so two processes never append at once; a writer that finds the file's size or time changed since its own last write re-checks the chain and refuses to append if it is damaged, cut back, edited or replaced, and continues from another writer's valid entries; a person repairs a cut-off last write with tools/audit_repair.py, which under the lock replaces the log in one step with every complete entry byte for byte plus the record of the repair, keeping the file's permissions; any other damage, or a swap that fails, changes nothing (2026-10-13) | **MEASURED** | tests/test_audit_log_damage.py (43), including three processes appending 450 entries at once, Windows line endings, a lock held by another process, and a repair that dies before its swap. Not seen at append time: an edit that keeps both size and modification time (verify_chain still finds it) | | The six pillar packages are pinned to exact commits; their own suites pass at those commits (9, 6, 11, 27, 20, 14) | **MEASURED** | pyproject.toml; each pinned pillar's suite run 2026-10-13 | | The core suite runs the listing identity tests on every push, on Linux (Python 3.10, 3.12, 3.13) and Windows, and fails on any skip | **MEASURED** | .github/workflows/ci.yml job with-identity; first green run 38437495999 | -| Every mutant the 2026-10-13 sweep puts into the 16 core files is caught by the core suite (859: 855 killed, 1 timeout), except 3 argued equivalent with evidence | **MEASURED** | findings/MUTATION_SWEEP_2026-10-13.md; tools/mutation_sweep.py reproduces it. Mutation testing shows the tests notice these changes; it does not prove the code correct | +| Every mutant the 2026-10-13 sweep puts into the 16 core files is caught by the core suite (921: 908 killed, 1 timeout), except 3 argued equivalent with evidence, 1 that only changes CPU use while waiting for the lock, and 8 on Windows-only lines a Linux sweep cannot run | **MEASURED** | findings/MUTATION_SWEEP_2026-10-13.md; tools/mutation_sweep.py reproduces it. Mutation testing shows the tests notice these changes; it does not prove the code correct | Not claimed for the runtime: production readiness; real-spoke latency; conduct-level efficacy of manners; licensed legal review of vertical content. diff --git a/PILLAR_TESTING_MANUAL.md b/PILLAR_TESTING_MANUAL.md index c779aa2..35b0bd9 100644 --- a/PILLAR_TESTING_MANUAL.md +++ b/PILLAR_TESTING_MANUAL.md @@ -34,9 +34,9 @@ that pillar regressed; stop, report the raw failure. Do not proceed to integration on a broken pillar - the set cannot be validated on a bad part. Then the dispatcher's suite from its clone: `python3 -m pytest tests/ -q` -EXPECTED: 309 passed, 5 skipped. (The 5 identity-dependent tests activate +EXPECTED: 325 passed, 5 skipped. (The 5 identity-dependent tests activate when IDENTITY_DIR points at a listing-assistants clone, or when one sits at -the conventional sibling path `../listing-assistants` - then 314 passed, as +the conventional sibling path `../listing-assistants` - then 330 passed, as of 2026-10-13. CI runs both: the clone alone, and with the listing identity on Linux 3.10/3.12/3.13 and Windows, where any skip fails the job.) diff --git a/README.md b/README.md index 32e1544..301bf4d 100644 --- a/README.md +++ b/README.md @@ -65,7 +65,7 @@ git clone https://github.com/QuietFireAI/dispatcher-agents cd dispatcher-agents pip install -e ".[pillars,crypto,dev]" # routing core is zero-dep; signing needs crypto (Ed25519) git clone https://github.com/QuietFireAI/listing-assistants ../listing-assistants -IDENTITY_DIR=../listing-assistants python3 -m pytest tests/ # 314 tests vs the real 52-route track +IDENTITY_DIR=../listing-assistants python3 -m pytest tests/ # 330 tests vs the real 52-route track IDENTITY_DIR=../listing-assistants python3 demo/run_p11_demo.py # real spokes chain 11 envelopes from 2 signals # Identity-gated tests target the repo bundled at IDENTITY_DIR (default: a fixture track); point IDENTITY_DIR at listing-assistants for the real 52-route run. diff --git a/SKILL.md b/SKILL.md index 287ba50..0ede387 100644 --- a/SKILL.md +++ b/SKILL.md @@ -73,7 +73,7 @@ pip install -e ".[pillars,crypto,dev]" # pillars pulled from source, never ven ### Verify before claiming anything works ```bash -python -m pytest tests/ # 309 passed + 5 skipped with no listing-assistants clone beside this repo; 314 passed with one (found at ../listing-assistants, or set IDENTITY_DIR) +python -m pytest tests/ # 325 passed + 5 skipped with no listing-assistants clone beside this repo; 330 passed with one (found at ../listing-assistants, or set IDENTITY_DIR) python demo/baseline_run.py # must print all six pillar events nonzero python tools/kpi_gate.py baseline-out/audit-.jsonl \ --taints-expected 1 --selfcheck-bait-expected 1 diff --git a/dispatcher/core.py b/dispatcher/core.py index 036825d..b1f8b89 100644 --- a/dispatcher/core.py +++ b/dispatcher/core.py @@ -10,6 +10,7 @@ Spec sources: DISPATCHER_CORE.md, 00-dispatcher/SKILL.md, SWARM.md v0.16. """ from __future__ import annotations +import contextlib import hashlib import json, os, threading, time, uuid from dataclasses import dataclass, field @@ -191,6 +192,58 @@ def _parse(raw: bytes): return e if isinstance(e, dict) else None +class AuditLogBusy(RuntimeError): + """Another process held the log's lock for longer than the wait allows.""" + + +class _FileLock: + """An operating-system lock on .lock, so processes write (and read) + the log one at a time (owner decision 2026-10-13, after the cold review: + two processes appending at the same instant forked the chain). POSIX: + flock; Windows: msvcrt.locking on the first byte. The lock file is + never removed. A second process waits up to `timeout` seconds, then + AuditLogBusy is raised and nothing is written.""" + + def __init__(self, path: str, timeout: float = 30.0): + self.path, self.timeout, self.f = path + ".lock", timeout, None + + def __enter__(self): + if not os.path.isdir(os.path.dirname(os.path.abspath(self.path))): + return # no folder: nothing to read or write yet + self.f = open(self.path, "a+b") + deadline = time.monotonic() + self.timeout + while True: + try: + if os.name == "nt": + import msvcrt + self.f.seek(0) + msvcrt.locking(self.f.fileno(), msvcrt.LK_NBLCK, 1) + else: + import fcntl + fcntl.flock(self.f.fileno(), fcntl.LOCK_EX | fcntl.LOCK_NB) + return + except OSError: + if time.monotonic() > deadline: + self.f.close() + self.f = None + raise AuditLogBusy(f"{self.path}: held by another process for more " + f"than {self.timeout:.0f} s - nothing was written") + time.sleep(0.02) + + def __exit__(self, *exc): + if self.f is None: + return + try: + if os.name == "nt": # Windows: unlock before closing + import msvcrt + self.f.seek(0) + msvcrt.locking(self.f.fileno(), msvcrt.LK_UNLCK, 1) + # POSIX: closing the file releases its flock + finally: + self.f.close() + self.f = None + + class AuditLog: """Append-only, HASH-CHAINED JSONL. Persist happens BEFORE delivery; the log is the single source of truth for KPIs - no self-reported metrics @@ -204,31 +257,76 @@ class AuditLog: from trust in the file.""" GENESIS = "GENESIS" + LOCK_WAIT_S = 30.0 # how long a writer waits for another process's lock def __init__(self, path: str): self.path = path os.makedirs(os.path.dirname(path) or ".", exist_ok=True) - self._lock = threading.Lock() - self._prev = self._recover_tip() - self._size = self._file_size() + self._lock = threading.RLock() + self._held = False + with self._guard(): + self._prev = self._recover_tip() + self._stamp = self._file_stamp() - def _file_size(self): + @classmethod + def reader(cls, path: str) -> "AuditLog": + """A read-only view of a log: read(), verify_chain(), anchor checks. + Opens nothing for writing and works on a damaged log (the + constructor refuses one).""" + o = cls.__new__(cls) + o.path = path + o._lock, o._held = threading.RLock(), False + o._prev, o._stamp, o._read_only = cls.GENESIS, None, True + return o + + @contextlib.contextmanager + def _guard(self): + """This process's threads one at a time, and other processes one at + a time through the OS lock. Re-entrant within a process: a call made + while this instance already holds the OS lock does not take it again + (a second flock from the same process would wait on itself).""" + with self._lock: + if self._held: + yield + return + with _FileLock(self.path, self.LOCK_WAIT_S): + self._held = True + try: + yield + finally: + self._held = False + + def _file_stamp(self): + """(size, modification time) of the file, or None if it is absent.""" try: - return os.path.getsize(self.path) + st = os.stat(self.path) except FileNotFoundError: return None + return (st.st_size, st.st_mtime_ns) + + def ensure_intact(self) -> None: + """Raise AuditLogDamaged now, writing nothing, if the next append + would refuse. For a caller about to write something ELSE (a state + store) that the log must then record: check first, so the other + write never happens without its record (2026-10-13 cold review: a + desk stopped after damage saved a snapshot the log never recorded).""" + with self._guard(): + if self._file_stamp() != self._stamp: + self._resync() + self._stamp = self._file_stamp() def _resync(self) -> None: - """The file is not the size this process left it: someone else wrote, - cut or replaced it (found by the 2026-10-13 cold review: a desk kept - appending to a log damaged under it, and a second writer forked the - chain). Append again only if the whole chain verifies AND still holds - this process's last entry; then continue from the file's real tip. - Otherwise raise AuditLogDamaged and write nothing. - - This catches every change that alters the file's size between two - appends. It does not stop two processes appending in the very same - instant; only an operating-system file lock does that.""" + """The file's size or modification time is not what this process + left: someone else wrote, cut, edited or replaced it (found by the + 2026-10-13 cold review: a desk kept appending to a log damaged under + it, and a second writer forked the chain). Append again only if the + whole chain verifies AND still holds this process's last entry; then + continue from the file's real tip. Otherwise raise AuditLogDamaged + and write nothing. + + Writers that use this class take the OS lock, so they never append + at the same instant. An edit that keeps both the size and the + modification time is not seen here; verify_chain() still finds it.""" chain = self.verify_chain() if not chain["ok"]: raise AuditLogDamaged( @@ -269,9 +367,7 @@ def _recover_tip(self) -> str: def check_file(cls, path: str) -> dict: """verify_chain() for a log that may be too damaged to open for writing (AuditLog(path) refuses a damaged file). Reads only.""" - o = cls.__new__(cls) - o.path = path - return o.verify_chain() + return cls.reader(path).verify_chain() @classmethod def repair_torn_tail(cls, path: str) -> dict: @@ -287,13 +383,23 @@ def repair_torn_tail(cls, path: str) -> dict: sha256 of the partial bytes, side file), so the repair itself is on the chain. Returns that record. - Every process writing the log must be stopped first. A process still - holding it would find the file changed at its next append and refuse - to write (AuditLog._resync). The repair cannot tell a crash from + Stop every process using the log first. The repair takes the log's + OS lock, so it never runs during another process's write; a process + that still holds the log open sees the file changed at its next + append, finds the chain intact with its own entries in it, and + continues after the repair entry (AuditLog._resync). The repaired + file keeps the old one's permissions, and its owner where this + process may set it. If the swap fails, the log is unchanged and the + side file is removed again. The repair cannot tell a crash from someone cutting the log back and adding a partial line: an anchor saved earlier (anchor() / verify_anchor()) is what shows that.""" if not os.path.exists(path): raise ValueError(f"{path}: no such audit log") + with _FileLock(path, cls.LOCK_WAIT_S): + return cls._repair_torn_tail(path) + + @classmethod + def _repair_torn_tail(cls, path: str) -> dict: with open(path, "rb") as f: data = f.read() cut = data.rfind(b"\n") + 1 # start of the bytes after the last newline @@ -349,10 +455,18 @@ def repair_torn_tail(cls, path: str) -> dict: f.write(prefix + entry.encode("utf-8") + nl) f.flush() os.fsync(f.fileno()) + st = os.stat(path) + os.chmod(tmp, st.st_mode & 0o7777) + if hasattr(os, "chown"): + try: + os.chown(tmp, st.st_uid, st.st_gid) + except PermissionError: + pass # not allowed to give it away: kept as ours os.replace(tmp, path) except BaseException: - if os.path.exists(tmp): - os.remove(tmp) + for leftover in (tmp, side): # nothing changed: leave nothing behind + if os.path.exists(leftover): + os.remove(leftover) raise _fsync_dir(os.path.dirname(os.path.abspath(path))) return rec @@ -364,13 +478,15 @@ def _entry_hash(body: dict, prev: str) -> str: canon = json.dumps(body, sort_keys=True, separators=(",", ":")) return hashlib.sha256((prev + canon).encode()).hexdigest() - def append(self, kind: str, record: dict) -> None: + def append(self, kind: str, record: dict) -> str: # Framing wins: a caller-supplied record can never shadow the log's own # ts/kind/chain fields. Without this, any splatted untrusted dict (see # Hub.escalate) could forge or erase an event kind - the audit log is # the single source of truth, so its framing is not caller-writable. - with self._lock: - if self._file_size() != self._size: + if getattr(self, "_read_only", False): + raise TypeError("AuditLog.reader() is read-only; open the log with AuditLog(path) to append") + with self._guard(): + if self._file_stamp() != self._stamp: self._resync() body = {**record, "ts": time.time(), "kind": kind} for k in ("prev_hash", "entry_hash"): @@ -383,9 +499,10 @@ def append(self, kind: str, record: dict) -> None: f.write(line + "\n") f.flush() os.fsync(f.fileno()) - self._size = os.fstat(f.fileno()).st_size + self._stamp = self._file_stamp() # after close: the final size and time self._needs_newline = False self._prev = eh + return eh def anchor(self) -> dict: """Export an external anchor: {entries, head_hash}. verify_chain @@ -396,10 +513,15 @@ def anchor(self) -> dict: in a handoff) closes that: a regenerated log cannot reproduce the anchored head hash at the anchored position. Gap named in the 2026-07-17 review, closed 2026-07-18.""" - n = len(_log_lines(self.path)[0]) if os.path.exists(self.path) else 0 - return {"entries": n, "head_hash": self._prev} + with self._guard(): + n = len(_log_lines(self.path)[0]) if os.path.exists(self.path) else 0 + return {"entries": n, "head_hash": self._prev} def verify_anchor(self, anchor: dict) -> dict: + with self._guard(): + return self._verify_anchor(anchor) + + def _verify_anchor(self, anchor: dict) -> dict: """Verify a previously exported anchor against the current file. The entry at the anchored position must carry exactly the anchored hash, and the chain up to it must verify. Returns @@ -436,6 +558,10 @@ def verify_anchor(self, anchor: dict) -> dict: return {"ok": True, "reason": None} def verify_chain(self) -> dict: + with self._guard(): + return self._verify_chain() + + def _verify_chain(self) -> dict: """Walk the file and recompute every link. Returns {ok, entries, break_at} - break_at names the first bad line (1-based). On a break it also returns "reason" and "torn_tail". Since 2026-10-13 @@ -463,6 +589,10 @@ def verify_chain(self) -> dict: return {"ok": True, "entries": n, "break_at": None} def read(self) -> list[dict]: + with self._guard(): + return self._read() + + def _read(self) -> list[dict]: """Every entry. An unreadable line raises AuditLogDamaged naming it (2026-10-13; it used to raise a bare JSONDecodeError).""" if not os.path.exists(self.path): diff --git a/dispatcher/hub.py b/dispatcher/hub.py index e3020ea..e8ee2d6 100644 --- a/dispatcher/hub.py +++ b/dispatcher/hub.py @@ -264,8 +264,11 @@ def escalate(self, queue: str, record: dict) -> dict: # queue is dispatcher-assigned routing, not caller-writable: splat the # untrusted record FIRST so the framing queue wins (a spoke must not be # able to redirect its escalation's audited queue). - self.audit.append("escalation.raised", {**record, "queue": queue}) - self._notify(queue, record) + raised = self.audit.append("escalation.raised", {**record, "queue": queue}) + # the outcome names this entry, so it can never be paired with + # another escalation - not even one another process raised on the + # same queue while this notifier ran (2026-10-13 second review) + self._notify(queue, record, raised_entry=raised if isinstance(raised, str) else None) return {"status": "escalated", "queue": queue} def register(self, agent_id: str, handler: Callable[[Envelope], None]): @@ -399,7 +402,7 @@ def notify(self, queue: str, record: dict) -> str: with self._lock: return self._notify(queue, record) - def _notify(self, queue: str, record: dict) -> str: + def _notify(self, queue: str, record: dict, raised_entry: str | None = None) -> str: """Calls the human notifier and records what actually happened (repair plan 1.1, 2026-10-13). The notifier's return value decides: - a dict whose "status" is in NOTIFY_DELIVERED -> human.notified @@ -418,11 +421,13 @@ def _notify(self, queue: str, record: dict) -> str: res = self.human_notifier(queue, record) except Exception as e: # recorded, never raised past the hub self.audit.append("human.notify_failed", - {**record, "queue": queue, "error": repr(e)[:300]}) + {**record, "queue": queue, "raised_entry": raised_entry, + "error": repr(e)[:300]}) return "notify_failed" if not isinstance(res, dict): self.audit.append("human.notified", - {**record, "queue": queue, "transport": "not reported"}) + {**record, "queue": queue, "raised_entry": raised_entry, + "transport": "not reported"}) return "not reported" status = res.get("status") # only a plain string status can claim delivery; anything else a @@ -431,9 +436,11 @@ def _notify(self, queue: str, record: dict) -> str: # raised out of escalate after escalation.raised was written) if isinstance(status, str) and status in NOTIFY_DELIVERED: self.audit.append("human.notified", - {**record, "queue": queue, "transport_status": status}) + {**record, "queue": queue, "raised_entry": raised_entry, + "transport_status": status}) return "notified" - failed = {**record, "queue": queue, "notifier_status": _plain(status)} + failed = {**record, "queue": queue, "raised_entry": raised_entry, + "notifier_status": _plain(status)} for k in ("http_status", "channel", "error"): if k in res: failed[f"notifier_{k}"] = str(res[k])[:300] if k == "error" else _plain(res[k]) diff --git a/dispatcher/kpi.py b/dispatcher/kpi.py index 2213c13..960a353 100644 --- a/dispatcher/kpi.py +++ b/dispatcher/kpi.py @@ -34,23 +34,36 @@ def pair_escalations(events: list[dict]) -> list[tuple[dict, dict | None]]: """Each escalation.raised with the notification outcome written for it, - in log order. Hub.escalate writes escalation.raised and then, under the - same lock, that escalation's outcome (human.notified or - human.notify_failed) on the same queue - so an escalation's outcome is - the first outcome on its queue after it and before the next escalation - on that queue. An outcome is never shared: one escalation's delivery - cannot stand in for another's failure (2026-10-13 cold review: matching - by queue and time alone let a later page on the same queue cover an - earlier failed one).""" + in log order. Since the second 2026-10-13 review every outcome carries + "raised_entry": the entry_hash of the escalation.raised it answers (or + None), and pairing is exact. Logs written before that are paired by + order: the first outcome on the escalation's queue after it and before + the next escalation on that queue. An outcome is never shared: one + escalation's delivery cannot stand in for another's failure (first + review: matching by queue and time alone let a later page cover an + earlier failed one; second review: two processes raising on one queue + could still interleave).""" pairs: list[list] = [] waiting: dict = {} + by_entry: dict = {} for e in events: k = e.get("kind") if k == "escalation.raised": + if e.get("entry_hash"): + by_entry[e["entry_hash"]] = len(pairs) waiting[e.get("queue")] = len(pairs) pairs.append([e, None]) + elif k in NOTIFY_OUTCOMES and "raised_entry" in e: + # written since the second review: the outcome names its + # escalation's entry_hash, or None when it answers no escalation + # (a queue landing, Hub.notify). Exact; log order does not matter. + i = by_entry.get(e["raised_entry"]) if e["raised_entry"] else None + if i is not None and pairs[i][1] is None: + pairs[i][1] = e + if waiting.get(e.get("queue")) == i: + waiting.pop(e.get("queue")) elif k in NOTIFY_OUTCOMES and e.get("queue") in waiting: - pairs[waiting.pop(e.get("queue"))][1] = e + pairs[waiting.pop(e.get("queue"))][1] = e # older logs: queue order return [(r, o) for r, o in pairs] diff --git a/findings/MUTATION_SWEEP_2026-10-13.md b/findings/MUTATION_SWEEP_2026-10-13.md index 7827906..6629b54 100644 --- a/findings/MUTATION_SWEEP_2026-10-13.md +++ b/findings/MUTATION_SWEEP_2026-10-13.md @@ -31,7 +31,7 @@ mutant*) marks behaviour no test holds. | 2. Survivors again | 87aa5ff (watchdog test rewritten), 198 tests | 214 | 7 | 207 | | 3. Survivors after the new tests | working tree, 286 tests | 207 | 200 | 7 (one of the 207 was a duplicate, see 218 below) | | 4. The last 7 | working tree, 288 tests | 7 | 3 | 4 | -| 5. Whole sweep again, packaged tool | this commit, 288 tests | 808 | 804 | 4 - the 4 below, 0 timeouts | +| 5. Whole sweep again, packaged tool | ccbfb21, 288 tests | 808 | 804 | 4 - the 4 below, 0 timeouts | Run 5 confirmed commit ccbfb21. A cold review by a separate agent then found defects in the 1.1/1.2 code (below); fixing them added code, so the @@ -41,9 +41,18 @@ sweep was run again on the fixed tree: |---|---|---|---|---| | 6. After the review fixes | working tree, 306 tests | 860 | 845 + 1 timeout (an infinite-loop mutant: caught) | 14: the 4 below and 10 in the new code | | 7. Those 14 again | working tree, 314 tests | 14 | 11 | 3 - the 3 equivalents still in the code | -| 8. Whole sweep, final | this commit, 314 tests | 859 | 855 + 1 timeout (the same infinite-loop mutant: caught) | 3 - the 3 equivalents | +| 8. Whole sweep | 7ded6a6, 314 tests | 859 | 855 + 1 timeout (the same infinite-loop mutant: caught) | 3 - the 3 equivalents | -Run 8 is the confirmation for this commit. +Run 8 confirmed commit 7ded6a6. The same reviewer then checked its +findings against the fixes and found more (below). The owner chose an +operating-system lock for the log. After those changes: + +| Run | Code / tests | Mutants | Killed | Survived | +|---|---|---|---|---| +| 9. Whole sweep | lock added, 324 tests | 930 | 896 + 1 timeout | 33: the 3 equivalents and 30 in the new lock code | +| 10. Whole sweep, final | this commit, 330 tests | 921 | 908 + 1 timeout | 12: 3 equivalent, 1 that only changes CPU use, 8 on Windows-only lines | + +Run 9 found 30 survivors in the lock code: the reader not tested to wait for the lock, the file handle not tested to be closed, the owner kept on repair, mixed old and new pairing, a nesting counter that the outer reset made meaningless (now a flag), redundant return values and a redundant POSIX unlock (removed). Windows-only lines cannot run on Linux; see below. Run 10 is the confirmation for this commit. ## What the survivors showed @@ -86,10 +95,21 @@ instead of truncating, so 3 remain. | Mutant | Why nothing changes | Evidence | |---|---|---| | `attestation.py:26` read chunk 65536 -> 65537 | A streamed SHA-256 does not depend on the chunk size | 300,000 random bytes hashed with both chunk sizes and in one call: identical | -| `core.py:125` `to in SPECIAL and to in r` -> `to not in SPECIAL and to in r` | The whole clause implies `to in r`, which is already the first test on that line, so the clause can never change the answer | Exhaustive: all 32 receiver sets over {02, human, external, queue, any} x 6 destinations give the same result with the clause, with the mutant, and with no clause at all | +| `core.py` `tuple_legal`: `to in SPECIAL and to in r` -> `to not in SPECIAL and to in r` | The whole clause implies `to in r`, which is already the first test on that line, so the clause can never change the answer | Exhaustive: all 32 receiver sets over {02, human, external, queue, any} x 6 destinations give the same result with the clause, with the mutant, and with no clause at all | | (removed with the truncate) `core.py:277` `f.flush()` -> `pass` after `truncate` | Nothing is written through that handle; truncate goes straight to the file | Size on disk read right after `truncate(3)`, before any flush: 3 | +| `core.py` `_FileLock.__enter__` `time.sleep(0.02)` -> `pass` | Only the CPU use while waiting for another process's lock changes: the loop spins instead of sleeping, and still waits for the same deadline | The lock-wait tests pass with it; no result depends on how often the lock is retried | | `hub.py:64` `super().__init__(reason)` -> `pass` in `Reject` | Python's exception constructor stores the arguments before `__init__` runs, so `args` and `str()` are the same | `Reject`-shaped class with and without the call: same `args` and `str` | +## Lines that a Linux sweep cannot run + +8 surviving mutants are on the Windows branch of `_FileLock` +(`msvcrt.locking` and the `seek(0)` before it, lock and unlock). On Linux +that branch never runs, so no Linux test can notice a change to it. The +unmutated Windows branch is exercised by core CI on windows-latest, where +`test_two_processes_appending_at_once_keep_one_chain` (three processes, 450 +entries), the lock-wait and the closed-handle tests run. No mutation run +was made on Windows. + ## Redundant clauses found on the way (no behaviour change, reported) In `Routes.tuple_legal`, two clauses can never change the answer: @@ -119,8 +139,29 @@ odd notifier answer raised out of the hub; a decision alert in listing-assistants called the notifier around the hub; two writers could fork the chain. All fixed with tests on 2026-10-13. One test it prompted me to recheck was passing for the wrong reason (its "cut back" case emptied -the file); fixed. Not fixed: two processes appending in the very same -instant - only an operating-system file lock stops that. +the file); fixed. + +## What the second review found + +- Stopping a desk after the record broke saved a state snapshot the record + never logged, so after the documented repair the desk refused to start. + The swarm now checks the log can take the record before it writes the + store (`AuditLog.ensure_intact`). +- The change check compared sizes only; it now compares size and + modification time. An edit that keeps both is still not seen at append + time; `verify_chain` finds it. +- With two processes writing one log cleanly, escalations from both on one + queue could be paired with each other's page. Each outcome now names the + entry hash of the escalation it answers. +- Core CI was red on Windows: a test of mine assumed LF line endings. +- The repair reset the log's permissions and owner; it keeps them now. A + failed swap left a side file and gave a traceback; now nothing is left + and the reason is printed. +- A test assertion that could not fail (the decision-alert test) is fixed. +- Owner decision: writers take an OS lock on `.lock` (flock on + POSIX, msvcrt.locking on Windows), so two processes no longer append at + the same instant. Shown by three processes appending 450 entries at + once; the test fails without the lock. ## What this does and does not show diff --git a/tests/test_audit_log_damage.py b/tests/test_audit_log_damage.py index a27845f..d8fd30c 100644 --- a/tests/test_audit_log_damage.py +++ b/tests/test_audit_log_damage.py @@ -120,7 +120,7 @@ def test_a_repair_that_dies_before_the_swap_leaves_the_log_as_it_was(tmp_path, m # os.replace (2026-10-13 cold review: the earlier repair cut the log and # then appended, so a crash between the two left a cut log with no record # of why). Dying before the swap must leave the original untouched, no - # temporary file behind, and the repair still possible. + # temporary or side file behind, and the repair still possible. from dispatcher import core p = three(tmp_path) data = raw(p) @@ -134,11 +134,11 @@ def died(a, b): with pytest.raises(RuntimeError): AuditLog.repair_torn_tail(p) assert raw(p) == data + b'{"half' - assert not [f for f in os.listdir(str(tmp_path)) if ".repair-" in f] + assert not [f for f in os.listdir(str(tmp_path)) if ".repair-" in f or ".torn-" in f] monkeypatch.undo() - rec = AuditLog.repair_torn_tail(p) # runs again, new side file name + rec = AuditLog.repair_torn_tail(p) # runs again assert raw(p).startswith(data) and AuditLog.check_file(p)["ok"] - assert len([f for f in os.listdir(str(tmp_path)) if ".torn-" in f]) == 2 + assert len([f for f in os.listdir(str(tmp_path)) if ".torn-" in f]) == 1 assert rec["complete_entries"] == 3 @@ -334,12 +334,15 @@ def test_a_second_repair_in_the_same_second_gets_its_own_side_file(tmp_path, mon def test_the_repaired_log_keeps_the_files_own_line_endings(tmp_path): + # LF and CRLF files built byte for byte, so the test means the same on + # Windows, where text-mode appends write CRLF (core CI run 38458144436) p = three(tmp_path) - open(p, "ab").write(b'{"half') + data = raw(p).replace(b"\r\n", b"\n") + open(p, "wb").write(data + b'{"half') AuditLog.repair_torn_tail(p) assert b"\r" not in raw(p) q = three(tmp_path, "b.jsonl") - data = raw(q) # read before opening for write + data = raw(q).replace(b"\r\n", b"\n") # read before opening for write open(q, "wb").write(data.replace(b"\n", b"\r\n") + b'{"half') AuditLog.repair_torn_tail(q) assert raw(q).endswith(b"}\r\n") and raw(q).count(b"\r\n") == 4 @@ -387,3 +390,202 @@ def test_a_writer_whose_entries_are_gone_is_not_told_it_was_a_cut_off_write(tmp_ w.append("y", {}) assert ei.value.torn_tail is False and ei.value.line is None assert "damaged (no single line)" in str(ei.value) + + + +# ------------------- the OS lock and the stamp (owner decision 2026-10-13, second review) +WRITER = """ +import sys +sys.path.insert(0, sys.argv[1]) +from dispatcher.core import AuditLog +log = AuditLog(sys.argv[2]) +for n in range(int(sys.argv[4])): + log.append("w", {"who": sys.argv[3], "n": n}) +""" + + +def test_two_processes_appending_at_once_keep_one_chain(tmp_path): + p = str(tmp_path / "a.jsonl") + script = tmp_path / "writer.py" + script.write_text(WRITER, encoding="utf-8") + procs = [subprocess.Popen([sys.executable, str(script), ROOT, p, who, "150"]) + for who in ("A", "B", "C")] + assert [pr.wait(timeout=120) for pr in procs] == [0, 0, 0] + assert AuditLog.check_file(p) == {"ok": True, "entries": 450, "break_at": None} + got = [(e["who"], e["n"]) for e in AuditLog.reader(p).read()] + assert sorted(got) == sorted((w, n) for w in "ABC" for n in range(150)) + + +def test_a_writer_that_cannot_get_the_lock_writes_nothing(tmp_path, monkeypatch): + from dispatcher import core + p = three(tmp_path) + log = AuditLog(p) + before = raw(p) + monkeypatch.setattr(AuditLog, "LOCK_WAIT_S", 0.2) + holder = subprocess.Popen([sys.executable, "-c", ( + "import sys, time; sys.path.insert(0, sys.argv[1]);" + "from dispatcher.core import _FileLock;" + "l = _FileLock(sys.argv[2]); l.__enter__(); print('held', flush=True); time.sleep(5)"), + ROOT, p], stdout=subprocess.PIPE, text=True) + try: + assert holder.stdout.readline().strip() == "held" + with pytest.raises(core.AuditLogBusy, match="nothing was written"): + log.append("x", {}) + finally: + holder.kill() + holder.wait() + assert raw(p) == before + log.append("x", {}) # free again + assert AuditLog.check_file(p)["ok"] + + +def test_an_edit_that_keeps_the_size_is_still_refused(tmp_path): + p = three(tmp_path) + log = AuditLog(p) + st = os.stat(p) + data = raw(p) + open(p, "wb").write(data.replace(b'"n": 1', b'"n": 7')) # same size + os.utime(p, ns=(st.st_atime_ns, st.st_mtime_ns + 1_000_000_000)) + assert os.path.getsize(p) == st.st_size + with pytest.raises(AuditLogDamaged) as ei: + log.append("y", {}) + assert ei.value.line == 2 and "does not link" in ei.value.reason + + +def test_ensure_intact_checks_without_writing(tmp_path): + p = three(tmp_path) + log = AuditLog(p) + log.ensure_intact() # nothing changed: fine + other = AuditLog(p) + other.append("x", {}) + log.ensure_intact() # another writer's valid entry: fine + before = raw(p) + open(p, "ab").write(b'{"half') + with pytest.raises(AuditLogDamaged): + log.ensure_intact() + assert raw(p) == before + b'{"half' + + +def test_a_reader_reads_a_damaged_log_without_opening_it_for_writing(tmp_path): + p = three(tmp_path) + open(p, "ab").write(b'{"half') + r = AuditLog.reader(p) + assert r.verify_chain()["torn_tail"] is True + with pytest.raises(AuditLogDamaged): + r.read() + + +def test_the_repair_keeps_the_logs_permissions(tmp_path): + p = three(tmp_path) + open(p, "ab").write(b'{"half') + os.chmod(p, 0o640) + before = os.stat(p).st_mode + AuditLog.repair_torn_tail(p) + assert os.stat(p).st_mode == before + + +def test_the_cli_reports_a_failed_swap_and_changes_nothing(tmp_path): + p = three(tmp_path) + open(p, "ab").write(b'{"half') + before = raw(p) + script = tmp_path / "fail_replace.py" + script.write_text( + "import os, runpy, sys\n" + "def no(a, b):\n raise PermissionError(13, 'in use by another program')\n" + "os.replace = no\n" + "sys.argv = [sys.argv[1], sys.argv[2]]\n" + "runpy.run_path(sys.argv[0], run_name='__main__')\n", encoding="utf-8") + r = subprocess.run([sys.executable, str(script), os.path.join(ROOT, "tools", "audit_repair.py"), p], + capture_output=True, text=True) + assert r.returncode == 2 and "Traceback" not in r.stderr, r.stderr + out = json.loads(r.stdout) + assert out["repaired"] is False and out["changed"] == "nothing" and "in use" in out["refused"] + assert raw(p) == before + assert not [f for f in os.listdir(str(tmp_path)) if ".torn-" in f or ".repair-" in f] + + +# ----------------------------------------- the lock, as the third sweep asked +HOLD = ("import sys, time; sys.path.insert(0, sys.argv[1]);" + "from dispatcher.core import _FileLock;" + "l = _FileLock(sys.argv[2]); l.__enter__(); print('held', flush=True); time.sleep(5)") + + +def held_by_another_process(p): + pr = subprocess.Popen([sys.executable, "-c", HOLD, ROOT, p], stdout=subprocess.PIPE, text=True) + assert pr.stdout.readline().strip() == "held" + return pr + + +def test_a_reader_waits_for_a_writer_in_another_process(tmp_path, monkeypatch): + from dispatcher import core + p = three(tmp_path) + monkeypatch.setattr(AuditLog, "LOCK_WAIT_S", 0.2) + pr = held_by_another_process(p) + try: + with pytest.raises(core.AuditLogBusy): + AuditLog.reader(p).read() + with pytest.raises(core.AuditLogBusy): + AuditLog.check_file(p) + finally: + pr.kill() + pr.wait() + assert len(AuditLog.reader(p).read()) == 3 + + +def test_a_reader_cannot_append(tmp_path): + p = three(tmp_path) + with pytest.raises(TypeError, match="read-only"): + AuditLog.reader(p).append("x", {}) + + +def test_a_nested_check_does_not_wait_on_its_own_lock_and_releases_it(tmp_path, monkeypatch): + p = three(tmp_path) + monkeypatch.setattr(AuditLog, "LOCK_WAIT_S", 0.5) + a, b = AuditLog(p), AuditLog(p) + b.append("x", {}) + a.append("y", {}) # a's file changed: _resync -> verify_chain inside the lock + assert a._held is False + pr = subprocess.run([sys.executable, "-c", + "import sys; sys.path.insert(0, sys.argv[1]);" + "from dispatcher.core import _FileLock;" + "l = _FileLock(sys.argv[2], 0.5); l.__enter__(); print('got it')", + ROOT, p], capture_output=True, text=True, timeout=30) + assert pr.stdout.strip() == "got it" + + +def test_the_lock_closes_its_file_every_time(tmp_path, monkeypatch): + import gc + import warnings + from dispatcher import core + p = three(tmp_path) + monkeypatch.setattr(AuditLog, "LOCK_WAIT_S", 0.2) + with warnings.catch_warnings(record=True) as seen: + warnings.simplefilter("always") + AuditLog(p).append("x", {}) # lock taken and given back + pr = held_by_another_process(p) + try: + with pytest.raises(core.AuditLogBusy): + AuditLog.reader(p).read() # lock never got: file closed too + finally: + pr.kill() + pr.wait() + gc.collect() + leaks = [w for w in seen if issubclass(w.category, ResourceWarning) and ".lock" in str(w.message)] + assert leaks == [] + + +def test_the_repair_gives_the_new_file_the_old_owner_where_it_can(tmp_path, monkeypatch): + from dispatcher import core + p = three(tmp_path) + open(p, "ab").write(b'{"half') + st = os.stat(p) + calls = [] + if hasattr(os, "chown"): + real = os.chown + monkeypatch.setattr(core.os, "chown", lambda f, u, g: (calls.append((f, u, g)), real(f, u, g))) + AuditLog.repair_torn_tail(p) + if hasattr(os, "chown"): + assert len(calls) == 1 and calls[0][0].startswith(p + ".repair-") + assert calls[0][1:] == (st.st_uid, st.st_gid) + else: + assert calls == [] diff --git a/tests/test_notification_truth.py b/tests/test_notification_truth.py index 7843fc0..12340f2 100644 --- a/tests/test_notification_truth.py +++ b/tests/test_notification_truth.py @@ -225,3 +225,49 @@ def test_an_escalation_nobody_was_notified_about_has_no_transport_kpi(tmp_path): hub.escalate("escalation.hot_lead", {"client_context_id": "H"}) k = compute_kpis(hub.audit.read())["escalation_transport_time"] assert k["computable"] is False + + + +# ------------------------------------------- second review: pairing by link +def test_two_hubs_on_one_log_never_pair_one_escalation_with_the_others_page(tmp_path): + log = str(tmp_path / "shared.jsonl") + b = Hub(Routes(FIXTURE), AuditLog(log), human_notifier=lambda q, r: {"status": "failed"}) + + def a_notifier(q, r): # while A's page is on its way, B raises on the same queue + b.escalate("escalation.hot_lead", {"client_context_id": "B"}) + return {"status": "sent"} + a = Hub(Routes(FIXTURE), AuditLog(log), human_notifier=a_notifier) + a.escalate("escalation.hot_lead", {"client_context_id": "A"}) + ev = AuditLog.reader(log).read() + order = [(e["kind"], e.get("client_context_id")) for e in ev if e["kind"].startswith(("escal", "human"))] + assert order == [("escalation.raised", "A"), ("escalation.raised", "B"), + ("human.notify_failed", "B"), ("human.notified", "A")] + from dispatcher.kpi import pair_escalations + pairs = {r["client_context_id"]: (o["kind"], o["client_context_id"]) for r, o in pair_escalations(ev)} + assert pairs == {"A": ("human.notified", "A"), "B": ("human.notify_failed", "B")} + report = generate_report(ev, "P", "r", "B", steps=[]) + assert "NOTIFICATION FAILED" in report.split("## escalations")[1].split("##")[0] + + +def test_a_notification_that_answers_no_escalation_is_never_paired_with_one(tmp_path): + hub = hub_with(tmp_path, None) + hub.escalate("escalation.hot_lead", {"client_context_id": "C"}) # nobody to tell + hub.human_notifier = lambda q, r: {"status": "sent"} + hub.notify("escalation.hot_lead", {"client_context_id": "D"}) + from dispatcher.kpi import pair_escalations + assert [o for _, o in pair_escalations(hub.audit.read())] == [None] + + +def test_an_older_log_without_links_is_still_paired_by_order(): + from dispatcher.kpi import pair_escalations + ev = [{"kind": "escalation.raised", "ts": 1, "queue": "escalation.x", "entry_hash": "h1"}, + {"kind": "human.notified", "ts": 2, "queue": "escalation.x"}] + assert pair_escalations(ev)[0][1] is ev[1] + + +def test_an_answered_escalation_is_not_answered_again_by_an_older_style_outcome(): + from dispatcher.kpi import pair_escalations + ev = [{"kind": "escalation.raised", "ts": 1, "queue": "escalation.x", "entry_hash": "h1"}, + {"kind": "human.notify_failed", "ts": 2, "queue": "escalation.x", "raised_entry": "h1"}, + {"kind": "human.notified", "ts": 3, "queue": "escalation.x"}] # no link: older style + assert pair_escalations(ev)[0][1] is ev[1] diff --git a/tests/test_sweep_core_hub_2026_10_13.py b/tests/test_sweep_core_hub_2026_10_13.py index 77daada..eba1390 100644 --- a/tests/test_sweep_core_hub_2026_10_13.py +++ b/tests/test_sweep_core_hub_2026_10_13.py @@ -200,10 +200,8 @@ def test_damage_mid_file_is_not_a_cut_off_even_when_the_file_lacks_a_final_newli with pytest.raises(AuditLogDamaged) as ei: AuditLog(p) assert ei.value.torn_tail is False - reader = AuditLog.__new__(AuditLog) - reader.path = p with pytest.raises(AuditLogDamaged) as ei: - reader.read() + AuditLog.reader(p).read() assert ei.value.line == 2 and ei.value.torn_tail is False diff --git a/tools/audit_repair.py b/tools/audit_repair.py index 4b33a0e..c36c408 100644 --- a/tools/audit_repair.py +++ b/tools/audit_repair.py @@ -19,6 +19,9 @@ Exit 0 when repaired, 2 when refused. Stop whatever process writes to the log (a console session, a desk) first. +The repair takes the log's lock (.lock), so it never runs in the +middle of another process's write; if the old log cannot be replaced +(Windows, another program holding it open) nothing changes. """ from __future__ import annotations @@ -29,7 +32,7 @@ sys.path.insert(0, os.path.join(os.path.dirname(os.path.abspath(__file__)), "..")) -from dispatcher.core import AuditLog, AuditLogDamaged # noqa: E402 +from dispatcher.core import AuditLog, AuditLogBusy, AuditLogDamaged # noqa: E402 def main(argv=None) -> int: @@ -46,9 +49,14 @@ def main(argv=None) -> int: return 0 if r["ok"] else 1 try: rec = AuditLog.repair_torn_tail(args.log) - except (AuditLogDamaged, ValueError) as e: + except (AuditLogDamaged, AuditLogBusy, ValueError) as e: print(json.dumps({"repaired": False, "refused": str(e)})) return 2 + except OSError as e: # e.g. Windows: another program holds the log open + print(json.dumps({"repaired": False, "changed": "nothing", + "refused": f"the repaired log could not replace the old one: {e!r}; " + f"stop every program using it and run this again"})) + return 2 print(json.dumps({"repaired": True, **rec, "chain": AuditLog.check_file(args.log)})) return 0 diff --git a/tools/kpi_gate.py b/tools/kpi_gate.py index 99ae324..4c8eea4 100644 --- a/tools/kpi_gate.py +++ b/tools/kpi_gate.py @@ -76,9 +76,7 @@ def main(argv=None) -> int: print(f"FAIL audit chain broken at line {chain['break_at']}: {chain['reason']}" + (" (a write cut off at the end)" if chain.get("torn_tail") else "")) return 1 - reader = AuditLog.__new__(AuditLog) - reader.path = a.audit_log - events = reader.read() + events = AuditLog.reader(a.audit_log).read() v = gate(events, a.taints_expected, a.selfcheck_bait_expected) k = compute_kpis(events) print("delta-class (recorded, not thresholded):", From a0006ac69456a7f861015a069667aaa55665849b Mon Sep 17 00:00:00 2001 From: Claude Date: Tue, 13 Oct 2026 23:12:51 +0000 Subject: [PATCH 09/10] Third review fixes: reads need no write access, one lock state per file per process, holding() - Reads take the lock shared on POSIX (readers no longer block each other) and need no write access: if .lock cannot be opened for writing a read opens it read-only, and if it cannot be opened at all (absent in a read-only folder) the read goes ahead unlocked. Before this, checking a log on read-only media crashed (third review, L1). - One lock state per file per process (_PROCESS_HELD), shared by every AuditLog instance on that file: two instances in one process never wait on each other (L3); threads take turns. A write inside a held read upgrades the lock to exclusive. - AuditLog.holding(): hold the lock across several steps (listing's state save: check, write the store, record it). The repair goes through the same per-process state. - Tests: read-only folder (lock file present / absent), a read through a read-only lock file still waits for a writer, two instances and two threads in one process, readers sharing across processes, the upgrade seen from another process, no leaked lock file handles, a repair from inside a held lock. Sweep: run 11 on this code, 942 mutants: 924 killed, 1 timeout, 17 survived; the 5 new ones killed by tests added after (run 12). Result: 929 killed, 1 timeout, 12 survived - 3 equivalent, 1 CPU-only, 8 on Windows-only lines. 334 passed + 5 skipped alone; 339 with the identity. Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_01CRunDQmfmnZdtJiP78e8WR --- EVIDENCE.md | 4 +- PILLAR_TESTING_MANUAL.md | 4 +- README.md | 2 +- SKILL.md | 2 +- dispatcher/core.py | 113 +++++++++++++++------ findings/MUTATION_SWEEP_2026-10-13.md | 6 +- tests/test_audit_log_damage.py | 136 +++++++++++++++++++++++++- 7 files changed, 228 insertions(+), 39 deletions(-) diff --git a/EVIDENCE.md b/EVIDENCE.md index bce8ee1..6c959df 100644 --- a/EVIDENCE.md +++ b/EVIDENCE.md @@ -135,9 +135,9 @@ Any new claim added to any README in this stack must be added to this ledger fir | Ed25519 authority: verifier cannot forge; tamper/forge reject; boot manifest signable incl. MANNERS.md hash | **MEASURED** | test_day3.py; asymmetric tier, optional cryptography dep | | A held outbound message can be declined by the same signed key that releases it; a decline drops it unsent and is on the chain; a release-signed key cannot decline and a decline-signed key cannot release (2026-10-12) | **MEASURED** | tests/test_absolute_signal.py decline tests; tests/test_sweep_core_hub_2026_10_13.py (unsigned and registry-refused answers are integrity violations; reason kept to 500 characters) | | The record says a person was notified only when the notifier reports the message delivered (sent / delivered / shown); a failed or raising notifier, or one that answers with anything odd, is recorded as human.notify_failed; the escalation KPI and the after-action report pair each escalation with its own outcome - the outcome names the escalation entry's hash - so one escalation's delivery never covers another's failure, even when two processes raise on one queue, and an unreported delivery gets no transport time (2026-10-13) | **MEASURED** | tests/test_notification_truth.py (33); before this, a Twilio 401 went on the chain as human.notified | -| A cut-off or unreadable audit line is named (line, reason, cut-off or not) and nothing opens on that log; writers take turns through an OS lock on .lock, so two processes never append at once; a writer that finds the file's size or time changed since its own last write re-checks the chain and refuses to append if it is damaged, cut back, edited or replaced, and continues from another writer's valid entries; a person repairs a cut-off last write with tools/audit_repair.py, which under the lock replaces the log in one step with every complete entry byte for byte plus the record of the repair, keeping the file's permissions; any other damage, or a swap that fails, changes nothing (2026-10-13) | **MEASURED** | tests/test_audit_log_damage.py (43), including three processes appending 450 entries at once, Windows line endings, a lock held by another process, and a repair that dies before its swap. Not seen at append time: an edit that keeps both size and modification time (verify_chain still finds it) | +| A cut-off or unreadable audit line is named (line, reason, cut-off or not) and nothing opens on that log; writers take turns through an OS lock on .lock (on POSIX readers share it; reading needs no write access to the folder), so two processes never append at once and one process never waits on itself; a writer that finds the file's size or time changed since its own last write re-checks the chain and refuses to append if it is damaged, cut back, edited or replaced, and continues from another writer's valid entries; a person repairs a cut-off last write with tools/audit_repair.py, which under the lock replaces the log in one step with every complete entry byte for byte plus the record of the repair, keeping the file's permissions; any other damage, or a swap that fails, changes nothing (2026-10-13) | **MEASURED** | tests/test_audit_log_damage.py (52), including three processes appending 450 entries at once, Windows line endings, a lock held by another process, a read-only folder, and a repair that dies before its swap. Not seen at append time: an edit that keeps both size and modification time, and a deletion or replacement made before this writer ever wrote or saw an entry (verify_chain or a saved anchor finds those) | | The six pillar packages are pinned to exact commits; their own suites pass at those commits (9, 6, 11, 27, 20, 14) | **MEASURED** | pyproject.toml; each pinned pillar's suite run 2026-10-13 | | The core suite runs the listing identity tests on every push, on Linux (Python 3.10, 3.12, 3.13) and Windows, and fails on any skip | **MEASURED** | .github/workflows/ci.yml job with-identity; first green run 38437495999 | -| Every mutant the 2026-10-13 sweep puts into the 16 core files is caught by the core suite (921: 908 killed, 1 timeout), except 3 argued equivalent with evidence, 1 that only changes CPU use while waiting for the lock, and 8 on Windows-only lines a Linux sweep cannot run | **MEASURED** | findings/MUTATION_SWEEP_2026-10-13.md; tools/mutation_sweep.py reproduces it. Mutation testing shows the tests notice these changes; it does not prove the code correct | +| Every mutant the 2026-10-13 sweep puts into the 16 core files is caught by the core suite (942: 929 killed, 1 timeout), except 3 argued equivalent with evidence, 1 that only changes CPU use while waiting for the lock, and 8 on Windows-only lines a Linux sweep cannot run | **MEASURED** | findings/MUTATION_SWEEP_2026-10-13.md; tools/mutation_sweep.py reproduces it. Mutation testing shows the tests notice these changes; it does not prove the code correct | Not claimed for the runtime: production readiness; real-spoke latency; conduct-level efficacy of manners; licensed legal review of vertical content. diff --git a/PILLAR_TESTING_MANUAL.md b/PILLAR_TESTING_MANUAL.md index 35b0bd9..08f7855 100644 --- a/PILLAR_TESTING_MANUAL.md +++ b/PILLAR_TESTING_MANUAL.md @@ -34,9 +34,9 @@ that pillar regressed; stop, report the raw failure. Do not proceed to integration on a broken pillar - the set cannot be validated on a bad part. Then the dispatcher's suite from its clone: `python3 -m pytest tests/ -q` -EXPECTED: 325 passed, 5 skipped. (The 5 identity-dependent tests activate +EXPECTED: 334 passed, 5 skipped. (The 5 identity-dependent tests activate when IDENTITY_DIR points at a listing-assistants clone, or when one sits at -the conventional sibling path `../listing-assistants` - then 330 passed, as +the conventional sibling path `../listing-assistants` - then 339 passed, as of 2026-10-13. CI runs both: the clone alone, and with the listing identity on Linux 3.10/3.12/3.13 and Windows, where any skip fails the job.) diff --git a/README.md b/README.md index 301bf4d..b7e24cb 100644 --- a/README.md +++ b/README.md @@ -65,7 +65,7 @@ git clone https://github.com/QuietFireAI/dispatcher-agents cd dispatcher-agents pip install -e ".[pillars,crypto,dev]" # routing core is zero-dep; signing needs crypto (Ed25519) git clone https://github.com/QuietFireAI/listing-assistants ../listing-assistants -IDENTITY_DIR=../listing-assistants python3 -m pytest tests/ # 330 tests vs the real 52-route track +IDENTITY_DIR=../listing-assistants python3 -m pytest tests/ # 339 tests vs the real 52-route track IDENTITY_DIR=../listing-assistants python3 demo/run_p11_demo.py # real spokes chain 11 envelopes from 2 signals # Identity-gated tests target the repo bundled at IDENTITY_DIR (default: a fixture track); point IDENTITY_DIR at listing-assistants for the real 52-route run. diff --git a/SKILL.md b/SKILL.md index 0ede387..351f6c0 100644 --- a/SKILL.md +++ b/SKILL.md @@ -73,7 +73,7 @@ pip install -e ".[pillars,crypto,dev]" # pillars pulled from source, never ven ### Verify before claiming anything works ```bash -python -m pytest tests/ # 325 passed + 5 skipped with no listing-assistants clone beside this repo; 330 passed with one (found at ../listing-assistants, or set IDENTITY_DIR) +python -m pytest tests/ # 334 passed + 5 skipped with no listing-assistants clone beside this repo; 339 passed with one (found at ../listing-assistants, or set IDENTITY_DIR) python demo/baseline_run.py # must print all six pillar events nonzero python tools/kpi_gate.py baseline-out/audit-.jsonl \ --taints-expected 1 --selfcheck-bait-expected 1 diff --git a/dispatcher/core.py b/dispatcher/core.py index b1f8b89..d1d4c97 100644 --- a/dispatcher/core.py +++ b/dispatcher/core.py @@ -197,20 +197,38 @@ class AuditLogBusy(RuntimeError): class _FileLock: - """An operating-system lock on .lock, so processes write (and read) - the log one at a time (owner decision 2026-10-13, after the cold review: - two processes appending at the same instant forked the chain). POSIX: - flock; Windows: msvcrt.locking on the first byte. The lock file is - never removed. A second process waits up to `timeout` seconds, then - AuditLogBusy is raised and nothing is written.""" - - def __init__(self, path: str, timeout: float = 30.0): - self.path, self.timeout, self.f = path + ".lock", timeout, None + """An operating-system lock on .lock, so processes take turns with + the log (owner decision 2026-10-13, after the cold review: two processes + appending at the same instant forked the chain). POSIX: flock, shared + for reads and exclusive for writes; Windows: msvcrt.locking on the first + byte, exclusive for both. The lock file is never removed. A process + waits up to `timeout` seconds, then AuditLogBusy is raised and nothing + is written. + + Reading needs no write access (third review): if the lock file cannot be + opened for writing, a read opens it read-only, and if it cannot be + opened at all (absent in a read-only folder) the read goes ahead + unlocked - nothing can be writing to a log there through this class.""" + + def __init__(self, path: str, timeout: float = 30.0, shared: bool = False): + self.path, self.timeout, self.shared = path + ".lock", timeout, shared + self.f, self.exclusive = None, False def __enter__(self): if not os.path.isdir(os.path.dirname(os.path.abspath(self.path))): return # no folder: nothing to read or write yet - self.f = open(self.path, "a+b") + try: + self.f = open(self.path, "a+b") + except OSError: + if not self.shared: + raise + try: + self.f = open(self.path, "rb") + except OSError: + return # unlockable, read-only: read without a lock + self._acquire(exclusive=os.name == "nt" or not self.shared) + + def _acquire(self, exclusive: bool) -> None: deadline = time.monotonic() + self.timeout while True: try: @@ -220,16 +238,27 @@ def __enter__(self): msvcrt.locking(self.f.fileno(), msvcrt.LK_NBLCK, 1) else: import fcntl - fcntl.flock(self.f.fileno(), fcntl.LOCK_EX | fcntl.LOCK_NB) + fcntl.flock(self.f.fileno(), + (fcntl.LOCK_EX if exclusive else fcntl.LOCK_SH) | fcntl.LOCK_NB) + self.exclusive = exclusive return except OSError: if time.monotonic() > deadline: self.f.close() self.f = None - raise AuditLogBusy(f"{self.path}: held by another process for more " + raise AuditLogBusy(f"{self.path}: held by another program for more " f"than {self.timeout:.0f} s - nothing was written") time.sleep(0.02) + def upgrade(self) -> None: + """A write inside a read this process already holds: make the lock + exclusive (POSIX converts the flock; Windows already holds it so).""" + if self.exclusive: + return + if self.f is None: + self.f = open(self.path, "a+b") + self._acquire(exclusive=True) + def __exit__(self, *exc): if self.f is None: return @@ -244,6 +273,20 @@ def __exit__(self, *exc): self.f = None +class _Held: + """What this process holds on one log file: shared by every AuditLog + instance on that file, so two instances in one process never wait on + each other (third review), and threads take turns through the RLock.""" + + def __init__(self): + self.rlock = threading.RLock() + self.flock = None + + +_PROCESS_HELD: dict = {} +_PROCESS_HELD_LOCK = threading.Lock() + + class AuditLog: """Append-only, HASH-CHAINED JSONL. Persist happens BEFORE delivery; the log is the single source of truth for KPIs - no self-reported metrics @@ -262,8 +305,6 @@ class AuditLog: def __init__(self, path: str): self.path = path os.makedirs(os.path.dirname(path) or ".", exist_ok=True) - self._lock = threading.RLock() - self._held = False with self._guard(): self._prev = self._recover_tip() self._stamp = self._file_stamp() @@ -275,26 +316,38 @@ def reader(cls, path: str) -> "AuditLog": constructor refuses one).""" o = cls.__new__(cls) o.path = path - o._lock, o._held = threading.RLock(), False o._prev, o._stamp, o._read_only = cls.GENESIS, None, True return o @contextlib.contextmanager - def _guard(self): - """This process's threads one at a time, and other processes one at - a time through the OS lock. Re-entrant within a process: a call made - while this instance already holds the OS lock does not take it again - (a second flock from the same process would wait on itself).""" - with self._lock: - if self._held: + def _guard(self, shared: bool = False): + """Threads of this process one at a time, other processes through the + OS lock (shared for reads, exclusive for writes). Re-entrant: a call + made while this process already holds the lock on this file - from + any AuditLog instance on it - does not take it again, and a write + inside a read upgrades it.""" + key = os.path.realpath(self.path) + with _PROCESS_HELD_LOCK: + h = _PROCESS_HELD.setdefault(key, _Held()) + with h.rlock: + if h.flock is not None: + if not shared: + h.flock.upgrade() yield return - with _FileLock(self.path, self.LOCK_WAIT_S): - self._held = True + fl = _FileLock(self.path, self.LOCK_WAIT_S, shared=shared) + with fl: + h.flock = fl try: yield finally: - self._held = False + h.flock = None + + def holding(self): + """Hold the log's lock across several steps, e.g. check it, write a + state store, then record that on the log - so no other process can + change the log in between (third review).""" + return self._guard() def _file_stamp(self): """(size, modification time) of the file, or None if it is absent.""" @@ -395,7 +448,7 @@ def repair_torn_tail(cls, path: str) -> dict: saved earlier (anchor() / verify_anchor()) is what shows that.""" if not os.path.exists(path): raise ValueError(f"{path}: no such audit log") - with _FileLock(path, cls.LOCK_WAIT_S): + with cls.reader(path)._guard(): # exclusive, shared with this process's holders return cls._repair_torn_tail(path) @classmethod @@ -513,12 +566,12 @@ def anchor(self) -> dict: in a handoff) closes that: a regenerated log cannot reproduce the anchored head hash at the anchored position. Gap named in the 2026-07-17 review, closed 2026-07-18.""" - with self._guard(): + with self._guard(shared=True): n = len(_log_lines(self.path)[0]) if os.path.exists(self.path) else 0 return {"entries": n, "head_hash": self._prev} def verify_anchor(self, anchor: dict) -> dict: - with self._guard(): + with self._guard(shared=True): return self._verify_anchor(anchor) def _verify_anchor(self, anchor: dict) -> dict: @@ -558,7 +611,7 @@ def _verify_anchor(self, anchor: dict) -> dict: return {"ok": True, "reason": None} def verify_chain(self) -> dict: - with self._guard(): + with self._guard(shared=True): return self._verify_chain() def _verify_chain(self) -> dict: @@ -589,7 +642,7 @@ def _verify_chain(self) -> dict: return {"ok": True, "entries": n, "break_at": None} def read(self) -> list[dict]: - with self._guard(): + with self._guard(shared=True): return self._read() def _read(self) -> list[dict]: diff --git a/findings/MUTATION_SWEEP_2026-10-13.md b/findings/MUTATION_SWEEP_2026-10-13.md index 6629b54..6fcd2cb 100644 --- a/findings/MUTATION_SWEEP_2026-10-13.md +++ b/findings/MUTATION_SWEEP_2026-10-13.md @@ -50,9 +50,11 @@ operating-system lock for the log. After those changes: | Run | Code / tests | Mutants | Killed | Survived | |---|---|---|---|---| | 9. Whole sweep | lock added, 324 tests | 930 | 896 + 1 timeout | 33: the 3 equivalents and 30 in the new lock code | -| 10. Whole sweep, final | this commit, 330 tests | 921 | 908 + 1 timeout | 12: 3 equivalent, 1 that only changes CPU use, 8 on Windows-only lines | +| 10. Whole sweep | 008fb8a, 330 tests | 921 | 908 + 1 timeout | 12: 3 equivalent, 1 that only changes CPU use, 8 on Windows-only lines | +| 11. Whole sweep | after the third review, 338 tests | 942 | 924 + 1 timeout | 17: the 12 above and 5 in the new lock code | +| 12. Those 17 again | this commit, 339 tests (tests added, no core code changed since run 11) | 17 | 5 | 12: 3 equivalent, 1 CPU-only, 8 on Windows-only lines | -Run 9 found 30 survivors in the lock code: the reader not tested to wait for the lock, the file handle not tested to be closed, the owner kept on repair, mixed old and new pairing, a nesting counter that the outer reset made meaningless (now a flag), redundant return values and a redundant POSIX unlock (removed). Windows-only lines cannot run on Linux; see below. Run 10 is the confirmation for this commit. +Run 9 found 30 survivors in the lock code: the reader not tested to wait for the lock, the file handle not tested to be closed, the owner kept on repair, mixed old and new pairing, a nesting counter that the outer reset made meaningless (now a flag), redundant return values and a redundant POSIX unlock (removed). Windows-only lines cannot run on Linux; see below. Run 10 confirmed 008fb8a. A third review found that reads needed write access to the log's folder (now: shared lock for reads, read-only fallback), that a busy lock was not handled in listing-assistants, and that two AuditLog instances in one process could wait on each other (now one lock state per file per process). Runs 11 and 12 are the confirmation for this commit: 942 mutants, 929 killed, 1 timeout, 12 survived. ## What the survivors showed diff --git a/tests/test_audit_log_damage.py b/tests/test_audit_log_damage.py index d8fd30c..02457a3 100644 --- a/tests/test_audit_log_damage.py +++ b/tests/test_audit_log_damage.py @@ -544,7 +544,8 @@ def test_a_nested_check_does_not_wait_on_its_own_lock_and_releases_it(tmp_path, a, b = AuditLog(p), AuditLog(p) b.append("x", {}) a.append("y", {}) # a's file changed: _resync -> verify_chain inside the lock - assert a._held is False + from dispatcher import core + assert core._PROCESS_HELD[os.path.realpath(p)].flock is None # released pr = subprocess.run([sys.executable, "-c", "import sys; sys.path.insert(0, sys.argv[1]);" "from dispatcher.core import _FileLock;" @@ -589,3 +590,136 @@ def test_the_repair_gives_the_new_file_the_old_owner_where_it_can(tmp_path, monk assert calls[0][1:] == (st.st_uid, st.st_gid) else: assert calls == [] + + +# ------------------------------------------- the lock, third review +def _no_write_open(real_open, writable_lock_exists): + """open() as in a folder this process may not write to.""" + def fake(f, mode="r", *a, **k): + if str(f).endswith(".lock") and ("a" in mode or "w" in mode): + raise PermissionError(13, "read-only folder", str(f)) + if str(f).endswith(".lock") and not writable_lock_exists: + raise FileNotFoundError(2, "no lock file", str(f)) + return real_open(f, mode, *a, **k) + return fake + + +@pytest.mark.parametrize("lock_file_there", [True, False]) +def test_a_log_in_a_folder_you_cannot_write_can_still_be_checked_and_read(tmp_path, monkeypatch, lock_file_there): + import builtins + from dispatcher import core + p = three(tmp_path) + monkeypatch.setattr(core, "open", _no_write_open(builtins.open, lock_file_there), raising=False) + assert AuditLog.check_file(p) == {"ok": True, "entries": 3, "break_at": None} + assert len(AuditLog.reader(p).read()) == 3 + with pytest.raises(PermissionError): # writing there still needs the lock + AuditLog(p).append("x", {}) + + +def test_two_instances_in_one_process_never_wait_on_each_other(tmp_path, monkeypatch): + p = three(tmp_path) + monkeypatch.setattr(AuditLog, "LOCK_WAIT_S", 0.5) + a, b = AuditLog(p), AuditLog(p) + with a.holding(): + b.append("inside", {}) # same thread, other instance + assert AuditLog.check_file(p)["ok"] + assert AuditLog.check_file(p) == {"ok": True, "entries": 4, "break_at": None} + + +def test_another_thread_waits_for_the_holder_in_this_process(tmp_path): + import threading + p = three(tmp_path) + a, b = AuditLog(p), AuditLog(p) + order = [] + with a.holding(): + t = threading.Thread(target=lambda: (b.append("t", {}), order.append("thread wrote"))) + t.start() + t.join(0.3) + order.append("holder done") + t.join(10) + assert order == ["holder done", "thread wrote"] + + +SHARED = ("import sys, time; sys.path.insert(0, sys.argv[1]);" + "from dispatcher.core import _FileLock;" + "l = _FileLock(sys.argv[2], shared=True); l.__enter__(); print('held', flush=True); time.sleep(5)") + + +def test_readers_share_the_lock_and_a_writer_waits_for_them(tmp_path, monkeypatch): + from dispatcher import core + p = three(tmp_path) + monkeypatch.setattr(AuditLog, "LOCK_WAIT_S", 0.3) + pr = subprocess.Popen([sys.executable, "-c", SHARED, ROOT, p], stdout=subprocess.PIPE, text=True) + try: + assert pr.stdout.readline().strip() == "held" + if os.name == "nt": # Windows has no shared lock: readers wait too + with pytest.raises(core.AuditLogBusy): + AuditLog.reader(p).read() + else: + r = AuditLog.reader(p) # other readers: no wait + assert len(r.read()) == 3 and r.verify_chain()["ok"] + assert r.anchor()["entries"] == 3 + assert r.verify_anchor({"entries": 0, "head_hash": AuditLog.GENESIS})["ok"] + with pytest.raises(core.AuditLogBusy): # a writer waits for the reader + AuditLog(p) + finally: + pr.kill() + pr.wait() + + +def test_a_write_inside_a_read_this_process_holds_takes_the_lock_for_writing(tmp_path): + p = three(tmp_path) + log = AuditLog(p) + probe = ("import sys; sys.path.insert(0, sys.argv[1]);" + "from dispatcher.core import _FileLock, AuditLogBusy;" + "l = _FileLock(sys.argv[2], 0.3, shared=True)\n" + "try:\n l.__enter__(); print('read allowed')\nexcept AuditLogBusy:\n print('kept out')") + import gc + import warnings + with warnings.catch_warnings(record=True) as seen: + warnings.simplefilter("always") + with log._guard(shared=True): + log.append("inside a read", {}) + r = subprocess.run([sys.executable, "-c", probe, ROOT, p], capture_output=True, text=True, + timeout=30) + assert r.stdout.strip() == "kept out" # exclusive now: no reader while writing + gc.collect() + assert [w for w in seen if issubclass(w.category, ResourceWarning) and ".lock" in str(w.message)] == [] + assert AuditLog.check_file(p) == {"ok": True, "entries": 4, "break_at": None} + + +def test_a_write_inside_an_unlocked_read_in_a_read_only_folder_is_refused(tmp_path, monkeypatch): + import builtins + from dispatcher import core + p = three(tmp_path) + log = AuditLog(p) + os.remove(p + ".lock") + monkeypatch.setattr(core, "open", _no_write_open(builtins.open, False), raising=False) + with log._guard(shared=True): # read: no lock file, none can be made + with pytest.raises(PermissionError): + log.append("x", {}) # a write needs the lock + + +def test_a_read_through_a_read_only_lock_file_still_waits_for_a_writer(tmp_path, monkeypatch): + import builtins + from dispatcher import core + p = three(tmp_path) + monkeypatch.setattr(AuditLog, "LOCK_WAIT_S", 0.3) + pr = held_by_another_process(p) # a writer elsewhere holds it + try: + monkeypatch.setattr(core, "open", _no_write_open(builtins.open, True), raising=False) + with pytest.raises(core.AuditLogBusy): + AuditLog.reader(p).read() + finally: + pr.kill() + pr.wait() + + +def test_a_repair_from_inside_this_processs_lock_does_not_wait_on_itself(tmp_path, monkeypatch): + p = three(tmp_path) + monkeypatch.setattr(AuditLog, "LOCK_WAIT_S", 0.5) + log = AuditLog(p) + open(p, "ab").write(b'{"half') + with log.holding(): + rec = AuditLog.repair_torn_tail(p) + assert rec["complete_entries"] == 3 and AuditLog.check_file(p)["ok"] From b3cd1475f6b7da1de2c1993acbd5c6728f76bebe Mon Sep 17 00:00:00 2001 From: Claude Date: Wed, 14 Oct 2026 00:12:21 +0000 Subject: [PATCH 10/10] Recheck before merge: name the first break, report only the run's own escalations, count entries, drop dead route clauses - Opening a log edited at line 2 and cut off at its end said "cut off, run the repair"; the repair then refused because of line 2. AuditLog now reports the FIRST break in the file (AuditLog._first_problem), so the repair is suggested only when it will accept the file. - after_action: the run filter added every escalation and notification on the log regardless of context, so a report listed other runs' escalations as its own (the P11 demo's warm-lead report claimed the hot lead's escalation). Now only the run's own; pairing still uses the whole log. - verify_chain()["entries"] counts entries, not line numbers (blank lines). - Routes.tuple_legal: two clauses that could never change the answer removed (proved over every receiver set; one equivalent mutant gone). - Tests for each, shown to fail on the previous code. Sweep: run 13 on this code, 931 mutants: 917 killed, 1 timeout, 13 survived; the 2 new ones killed by tests added after (run 14). Result: 919 killed, 1 timeout, 11 survived - 2 equivalent, 1 CPU-only, 8 on Windows-only lines. 339 passed + 5 skipped alone; 344 with the identity. Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_01CRunDQmfmnZdtJiP78e8WR --- EVIDENCE.md | 4 +-- PILLAR_TESTING_MANUAL.md | 4 +-- README.md | 2 +- SKILL.md | 2 +- dispatcher/after_action.py | 10 ++++-- dispatcher/core.py | 34 ++++++++++++------- findings/MUTATION_SWEEP_2026-10-13.md | 20 ++++++------ tests/test_audit_log_damage.py | 45 ++++++++++++++++++++++++++ tests/test_day3.py | 23 +++++++++---- tests/test_notification_truth.py | 10 +++--- tests/test_sweep_reports_2026_10_13.py | 10 ++++++ 11 files changed, 125 insertions(+), 39 deletions(-) diff --git a/EVIDENCE.md b/EVIDENCE.md index 6c959df..7c78699 100644 --- a/EVIDENCE.md +++ b/EVIDENCE.md @@ -135,9 +135,9 @@ Any new claim added to any README in this stack must be added to this ledger fir | Ed25519 authority: verifier cannot forge; tamper/forge reject; boot manifest signable incl. MANNERS.md hash | **MEASURED** | test_day3.py; asymmetric tier, optional cryptography dep | | A held outbound message can be declined by the same signed key that releases it; a decline drops it unsent and is on the chain; a release-signed key cannot decline and a decline-signed key cannot release (2026-10-12) | **MEASURED** | tests/test_absolute_signal.py decline tests; tests/test_sweep_core_hub_2026_10_13.py (unsigned and registry-refused answers are integrity violations; reason kept to 500 characters) | | The record says a person was notified only when the notifier reports the message delivered (sent / delivered / shown); a failed or raising notifier, or one that answers with anything odd, is recorded as human.notify_failed; the escalation KPI and the after-action report pair each escalation with its own outcome - the outcome names the escalation entry's hash - so one escalation's delivery never covers another's failure, even when two processes raise on one queue, and an unreported delivery gets no transport time (2026-10-13) | **MEASURED** | tests/test_notification_truth.py (33); before this, a Twilio 401 went on the chain as human.notified | -| A cut-off or unreadable audit line is named (line, reason, cut-off or not) and nothing opens on that log; writers take turns through an OS lock on .lock (on POSIX readers share it; reading needs no write access to the folder), so two processes never append at once and one process never waits on itself; a writer that finds the file's size or time changed since its own last write re-checks the chain and refuses to append if it is damaged, cut back, edited or replaced, and continues from another writer's valid entries; a person repairs a cut-off last write with tools/audit_repair.py, which under the lock replaces the log in one step with every complete entry byte for byte plus the record of the repair, keeping the file's permissions; any other damage, or a swap that fails, changes nothing (2026-10-13) | **MEASURED** | tests/test_audit_log_damage.py (52), including three processes appending 450 entries at once, Windows line endings, a lock held by another process, a read-only folder, and a repair that dies before its swap. Not seen at append time: an edit that keeps both size and modification time, and a deletion or replacement made before this writer ever wrote or saw an entry (verify_chain or a saved anchor finds those) | +| A log with an unreadable line does not open, and the error names the first break in the file (line, reason, cut-off last write or not) - an edited line before a cut-off end is named first, so the repair is only suggested when it will accept the file; writers take turns through an OS lock on .lock (on POSIX readers share it; reading needs no write access to the folder), so two processes never append at once and one process never waits on itself; a writer that finds the file's size or time changed since its own last write re-checks the chain and refuses to append if it is damaged, cut back, edited or replaced, and continues from another writer's valid entries; a person repairs a cut-off last write with tools/audit_repair.py, which under the lock replaces the log in one step with every complete entry byte for byte plus the record of the repair, keeping the file's permissions; any other damage, or a swap that fails, changes nothing (2026-10-13) | **MEASURED** | tests/test_audit_log_damage.py (56), including three processes appending 450 entries at once, Windows line endings, a lock held by another process, a read-only folder, and a repair that dies before its swap. Not seen at append time: an edit that keeps both size and modification time, and a deletion or replacement made before this writer ever wrote or saw an entry (verify_chain or a saved anchor finds those) | | The six pillar packages are pinned to exact commits; their own suites pass at those commits (9, 6, 11, 27, 20, 14) | **MEASURED** | pyproject.toml; each pinned pillar's suite run 2026-10-13 | | The core suite runs the listing identity tests on every push, on Linux (Python 3.10, 3.12, 3.13) and Windows, and fails on any skip | **MEASURED** | .github/workflows/ci.yml job with-identity; first green run 38437495999 | -| Every mutant the 2026-10-13 sweep puts into the 16 core files is caught by the core suite (942: 929 killed, 1 timeout), except 3 argued equivalent with evidence, 1 that only changes CPU use while waiting for the lock, and 8 on Windows-only lines a Linux sweep cannot run | **MEASURED** | findings/MUTATION_SWEEP_2026-10-13.md; tools/mutation_sweep.py reproduces it. Mutation testing shows the tests notice these changes; it does not prove the code correct | +| Every mutant the 2026-10-13 sweep puts into the 16 core files is caught by the core suite (931: 919 killed, 1 timeout), except 2 argued equivalent with evidence, 1 that only changes CPU use while waiting for the lock, and 8 on Windows-only lines a Linux sweep cannot run | **MEASURED** | findings/MUTATION_SWEEP_2026-10-13.md; tools/mutation_sweep.py reproduces it. Mutation testing shows the tests notice these changes; it does not prove the code correct | Not claimed for the runtime: production readiness; real-spoke latency; conduct-level efficacy of manners; licensed legal review of vertical content. diff --git a/PILLAR_TESTING_MANUAL.md b/PILLAR_TESTING_MANUAL.md index 08f7855..2cdec4e 100644 --- a/PILLAR_TESTING_MANUAL.md +++ b/PILLAR_TESTING_MANUAL.md @@ -34,9 +34,9 @@ that pillar regressed; stop, report the raw failure. Do not proceed to integration on a broken pillar - the set cannot be validated on a bad part. Then the dispatcher's suite from its clone: `python3 -m pytest tests/ -q` -EXPECTED: 334 passed, 5 skipped. (The 5 identity-dependent tests activate +EXPECTED: 339 passed, 5 skipped. (The 5 identity-dependent tests activate when IDENTITY_DIR points at a listing-assistants clone, or when one sits at -the conventional sibling path `../listing-assistants` - then 339 passed, as +the conventional sibling path `../listing-assistants` - then 344 passed, as of 2026-10-13. CI runs both: the clone alone, and with the listing identity on Linux 3.10/3.12/3.13 and Windows, where any skip fails the job.) diff --git a/README.md b/README.md index b7e24cb..6477753 100644 --- a/README.md +++ b/README.md @@ -65,7 +65,7 @@ git clone https://github.com/QuietFireAI/dispatcher-agents cd dispatcher-agents pip install -e ".[pillars,crypto,dev]" # routing core is zero-dep; signing needs crypto (Ed25519) git clone https://github.com/QuietFireAI/listing-assistants ../listing-assistants -IDENTITY_DIR=../listing-assistants python3 -m pytest tests/ # 339 tests vs the real 52-route track +IDENTITY_DIR=../listing-assistants python3 -m pytest tests/ # 344 tests vs the real 52-route track IDENTITY_DIR=../listing-assistants python3 demo/run_p11_demo.py # real spokes chain 11 envelopes from 2 signals # Identity-gated tests target the repo bundled at IDENTITY_DIR (default: a fixture track); point IDENTITY_DIR at listing-assistants for the real 52-route run. diff --git a/SKILL.md b/SKILL.md index 351f6c0..10bfd17 100644 --- a/SKILL.md +++ b/SKILL.md @@ -73,7 +73,7 @@ pip install -e ".[pillars,crypto,dev]" # pillars pulled from source, never ven ### Verify before claiming anything works ```bash -python -m pytest tests/ # 334 passed + 5 skipped with no listing-assistants clone beside this repo; 339 passed with one (found at ../listing-assistants, or set IDENTITY_DIR) +python -m pytest tests/ # 339 passed + 5 skipped with no listing-assistants clone beside this repo; 344 passed with one (found at ../listing-assistants, or set IDENTITY_DIR) python demo/baseline_run.py # must print all six pillar events nonzero python tools/kpi_gate.py baseline-out/audit-.jsonl \ --taints-expected 1 --selfcheck-bait-expected 1 diff --git a/dispatcher/after_action.py b/dispatcher/after_action.py index d800858..a64698b 100644 --- a/dispatcher/after_action.py +++ b/dispatcher/after_action.py @@ -35,11 +35,15 @@ def generate_report(events: list[dict], playbook: str, run_id: str, """events: full audit log. steps: the playbook's step list as executed, each {step, agent, intent, envelope_id} - proof and latency are looked up in the log, never taken from the caller's word.""" + # this run's events only: its client context, or an envelope of its + # steps. (Until 2026-10-13 every escalation.raised and notification on + # the log was added regardless of context, so a report listed other + # runs' escalations as its own.) Notifications are still paired with + # escalations over the whole log (kpi.pair_escalations), so an outcome + # recorded without this context still answers this run's escalation. run_events = [e for e in events if e.get("client_context_id") == client_context_id - or e.get("envelope_id") in {s.get("envelope_id") for s in steps} - or e["kind"] in ("escalation.raised", "human.notified", - "human.notify_failed")] + or e.get("envelope_id") in {s.get("envelope_id") for s in steps}] if not run_events: raise ValueError(f"no audited events for run {run_id!r} - a report " f"without log evidence would be fabricated") diff --git a/dispatcher/core.py b/dispatcher/core.py index d1d4c97..266b9fc 100644 --- a/dispatcher/core.py +++ b/dispatcher/core.py @@ -121,9 +121,12 @@ def matches(self, intent: str): def tuple_legal(self, frm: str, intent: str, to: str) -> bool: for s, r in self.matches(intent): - frm_ok = frm in s or "any" in s or (frm == "human" and "human" in s) - to_ok = (to in r or "any" in r - or (to in SPECIAL and to in r)) + # 2026-10-13: two further clauses, (frm == "human" and "human" in s) + # and (to in SPECIAL and to in r), were removed: each implied the + # membership test before it, so neither could change the answer + # (checked over every receiver set; findings/MUTATION_SWEEP_2026-10-13.md) + frm_ok = frm in s or "any" in s + to_ok = to in r or "any" in r if frm_ok and to_ok: return True return False @@ -409,13 +412,22 @@ def _recover_tip(self) -> str: for n, (i, raw) in enumerate(lines): e = _parse(raw) if e is None: - last = n == len(lines) - 1 - raise AuditLogDamaged(self.path, i, "not a readable entry", - torn_tail=last and not ends_nl) + raise self._first_problem() tip = e.get("entry_hash", tip) self._needs_newline = bool(lines) and not ends_nl return tip + def _first_problem(self) -> "AuditLogDamaged": + """The error for the FIRST break in the file, not merely the first + unreadable line (recheck before merge, 2026-10-13: a log edited at + line 2 and cut off at its end was reported as "cut off, run the + repair", and the repair then refused because of line 2). A cut-off + last write is reported as one only when every line before it + verifies - exactly when the repair will accept it.""" + chain = self._verify_chain() + return AuditLogDamaged(self.path, chain["break_at"], chain["reason"], + torn_tail=chain["torn_tail"]) + @classmethod def check_file(cls, path: str) -> dict: """verify_chain() for a log that may be too damaged to open for @@ -627,18 +639,19 @@ def _verify_chain(self) -> dict: for k, (i, raw) in enumerate(lines): e = _parse(raw) if e is None: - return {"ok": False, "entries": i, "break_at": i, + return {"ok": False, "entries": k + 1, "break_at": i, "reason": "not a readable entry", "torn_tail": k == len(lines) - 1 and not ends_nl} body = {key: v for key, v in e.items() if key not in ("prev_hash", "entry_hash")} if e.get("prev_hash") != prev or \ e.get("entry_hash") != self._entry_hash(body, prev): - return {"ok": False, "entries": i, "break_at": i, + return {"ok": False, "entries": k + 1, "break_at": i, "reason": "does not link to the entry before it " "(edited, deleted or reordered)", "torn_tail": False} - prev = e["entry_hash"]; n = i + prev = e["entry_hash"] + n = k + 1 # entries, not line numbers: blank lines are skipped return {"ok": True, "entries": n, "break_at": None} def read(self) -> list[dict]: @@ -655,7 +668,6 @@ def _read(self) -> list[dict]: for k, (i, raw) in enumerate(lines): e = _parse(raw) if e is None: - raise AuditLogDamaged(self.path, i, "not a readable entry", - torn_tail=k == len(lines) - 1 and not ends_nl) + raise self._first_problem() out.append(e) return out diff --git a/findings/MUTATION_SWEEP_2026-10-13.md b/findings/MUTATION_SWEEP_2026-10-13.md index 6fcd2cb..4a723b1 100644 --- a/findings/MUTATION_SWEEP_2026-10-13.md +++ b/findings/MUTATION_SWEEP_2026-10-13.md @@ -52,9 +52,11 @@ operating-system lock for the log. After those changes: | 9. Whole sweep | lock added, 324 tests | 930 | 896 + 1 timeout | 33: the 3 equivalents and 30 in the new lock code | | 10. Whole sweep | 008fb8a, 330 tests | 921 | 908 + 1 timeout | 12: 3 equivalent, 1 that only changes CPU use, 8 on Windows-only lines | | 11. Whole sweep | after the third review, 338 tests | 942 | 924 + 1 timeout | 17: the 12 above and 5 in the new lock code | -| 12. Those 17 again | this commit, 339 tests (tests added, no core code changed since run 11) | 17 | 5 | 12: 3 equivalent, 1 CPU-only, 8 on Windows-only lines | +| 12. Those 17 again | a0006ac, 339 tests (tests added, no core code changed since run 11) | 17 | 5 | 12: 3 equivalent, 1 CPU-only, 8 on Windows-only lines | +| 13. Whole sweep | after the recheck before merge, 341 tests | 931 | 917 + 1 timeout | 13: the 11 below and 2 in the new code | +| 14. Those 13 again | this commit, 344 tests (tests added, no core code changed since run 13) | 13 | 2 | 11: 2 equivalent, 1 CPU-only, 8 on Windows-only lines | -Run 9 found 30 survivors in the lock code: the reader not tested to wait for the lock, the file handle not tested to be closed, the owner kept on repair, mixed old and new pairing, a nesting counter that the outer reset made meaningless (now a flag), redundant return values and a redundant POSIX unlock (removed). Windows-only lines cannot run on Linux; see below. Run 10 confirmed 008fb8a. A third review found that reads needed write access to the log's folder (now: shared lock for reads, read-only fallback), that a busy lock was not handled in listing-assistants, and that two AuditLog instances in one process could wait on each other (now one lock state per file per process). Runs 11 and 12 are the confirmation for this commit: 942 mutants, 929 killed, 1 timeout, 12 survived. +Run 9 found 30 survivors in the lock code: the reader not tested to wait for the lock, the file handle not tested to be closed, the owner kept on repair, mixed old and new pairing, a nesting counter that the outer reset made meaningless (now a flag), redundant return values and a redundant POSIX unlock (removed). Windows-only lines cannot run on Linux; see below. Run 10 confirmed 008fb8a. A third review found that reads needed write access to the log's folder (now: shared lock for reads, read-only fallback), that a busy lock was not handled in listing-assistants, and that two AuditLog instances in one process could wait on each other (now one lock state per file per process). Runs 11 and 12 confirmed a0006ac. A recheck before merging found that opening a log edited at line 2 and cut off at its end advised the repair, which then refused; the error now names the first break. The owner also asked for the four items left open at the gate to be fixed: the after-action report's run filter, the redundant tuple_legal clauses (removed, which removed one equivalent mutant), entry counts with blank lines, and the desk feed's style for a repair. Runs 13 and 14 are the confirmation for this commit: 931 mutants, 919 killed, 1 timeout, 11 survived. ## What the survivors showed @@ -97,7 +99,7 @@ instead of truncating, so 3 remain. | Mutant | Why nothing changes | Evidence | |---|---|---| | `attestation.py:26` read chunk 65536 -> 65537 | A streamed SHA-256 does not depend on the chunk size | 300,000 random bytes hashed with both chunk sizes and in one call: identical | -| `core.py` `tuple_legal`: `to in SPECIAL and to in r` -> `to not in SPECIAL and to in r` | The whole clause implies `to in r`, which is already the first test on that line, so the clause can never change the answer | Exhaustive: all 32 receiver sets over {02, human, external, queue, any} x 6 destinations give the same result with the clause, with the mutant, and with no clause at all | +| (clause removed before merge) `core.py` `tuple_legal`: `to in SPECIAL and to in r` -> `to not in SPECIAL and to in r` | The whole clause implies `to in r`, which is already the first test on that line, so the clause can never change the answer | Exhaustive: all 32 receiver sets over {02, human, external, queue, any} x 6 destinations give the same result with the clause, with the mutant, and with no clause at all | | (removed with the truncate) `core.py:277` `f.flush()` -> `pass` after `truncate` | Nothing is written through that handle; truncate goes straight to the file | Size on disk read right after `truncate(3)`, before any flush: 3 | | `core.py` `_FileLock.__enter__` `time.sleep(0.02)` -> `pass` | Only the CPU use while waiting for another process's lock changes: the loop spins instead of sleeping, and still waits for the same deadline | The lock-wait tests pass with it; no result depends on how often the lock is retried | | `hub.py:64` `super().__init__(reason)` -> `pass` in `Reject` | Python's exception constructor stores the arguments before `__init__` runs, so `args` and `str()` are the same | `Reject`-shaped class with and without the call: same `args` and `str` | @@ -112,14 +114,14 @@ unmutated Windows branch is exercised by core CI on windows-latest, where entries), the lock-wait and the closed-handle tests run. No mutation run was made on Windows. -## Redundant clauses found on the way (no behaviour change, reported) +## Redundant clauses found on the way (removed before merge) -In `Routes.tuple_legal`, two clauses can never change the answer: +In `Routes.tuple_legal`, two clauses could never change the answer: `(frm == "human" and "human" in s)` is covered by `frm in s`, and -`(to in SPECIAL and to in r)` is covered by `to in r`. They were left in -place: they are harmless, and changing route code was not needed to finish -this step. They read as if `human` or the special destinations were treated -differently; they are not. +`(to in SPECIAL and to in r)` is covered by `to in r`. They read as if +`human` or the special destinations were treated differently; they were +not. Removed on the owner's request before the merge; the route tests and +the exhaustive check above show the answers are unchanged. ## One unexplained test failure diff --git a/tests/test_audit_log_damage.py b/tests/test_audit_log_damage.py index 02457a3..66a961b 100644 --- a/tests/test_audit_log_damage.py +++ b/tests/test_audit_log_damage.py @@ -723,3 +723,48 @@ def test_a_repair_from_inside_this_processs_lock_does_not_wait_on_itself(tmp_pat with log.holding(): rec = AuditLog.repair_torn_tail(p) assert rec["complete_entries"] == 3 and AuditLog.check_file(p)["ok"] + + +# ---------------------------------------------- recheck before merge, 2026-10-13 +def test_an_earlier_break_is_named_before_a_cut_off_end(tmp_path): + # edited at line 2 AND cut off at the end: the first problem is line 2, + # and the error must not send a person to a repair that will refuse + p = three(tmp_path) + lines = raw(p).split(b"\n") + lines[1] = lines[1].replace(b'"n": 1', b'"n": 8') + open(p, "wb").write(b"\n".join(lines) + b'{"half') + for opener in (lambda: AuditLog(p), lambda: AuditLog.reader(p).read()): + with pytest.raises(AuditLogDamaged) as ei: + opener() + assert ei.value.line == 2 and ei.value.torn_tail is False + assert "does not link" in ei.value.reason and "repair_torn_tail" not in str(ei.value) + with pytest.raises(ValueError, match="chain breaks at line 2"): + AuditLog.repair_torn_tail(p) + + +def test_entries_are_counted_not_numbered_when_the_file_has_blank_lines(tmp_path): + p = three(tmp_path) + data = raw(p) # read before opening for write + open(p, "wb").write(b"\n\n" + data.replace(b"\n", b"\n\n")) + log = AuditLog.reader(p) + assert log.verify_chain() == {"ok": True, "entries": 3, "break_at": None} + assert log.anchor()["entries"] == 3 + open(p, "ab").write(b'{"half') + c = AuditLog.check_file(p) + assert c["entries"] == 4 and c["break_at"] == raw(p).count(b"\n") + 1 + + +def test_a_link_break_counts_the_entries_up_to_it(tmp_path): + p = three(tmp_path) + lines = raw(p).split(b"\n") + lines[1] = lines[1].replace(b'"n": 1', b'"n": 6') + open(p, "wb").write(b"\n\n".join(lines)) # blank lines between, too + c = AuditLog.check_file(p) + assert c["entries"] == 2 and c["break_at"] == 3 and "does not link" in c["reason"] + + +def test_reopening_a_clean_log_adds_no_blank_lines(tmp_path): + p = three(tmp_path) + for _ in range(3): + AuditLog(p).append("again", {}) + assert b"\n\n" not in raw(p) and raw(p).count(b"\n") == 6 diff --git a/tests/test_day3.py b/tests/test_day3.py index b7150ce..4b13458 100644 --- a/tests/test_day3.py +++ b/tests/test_day3.py @@ -250,14 +250,25 @@ def test_p11_demo_end_to_end(tmp_path, monkeypatch): "## kpis", "## manners re-injections"): assert section in report # full AFTER_ACTION schema assert "TRIGGERED" in report # both gates fired - # the demo's notifier appends to a list and reports nothing, so the - # report says delivery is unconfirmed - no transport time is claimed - # (2026-10-13: it used to print a transport time for it) + # This report is the warm lead's run (lead-w). The hot-lead escalation + # belongs to lead-h, so it is not in this report (2026-10-13: the report + # used to list every escalation on the log as its own). esc = report.split("## escalations")[1].split("##")[0] - assert "the notifier reported nothing - delivery unconfirmed" in esc - assert "transport 0" not in esc and "NOT INSTRUMENTED" not in esc - assert "'computable': True" in report # outcome paired from the log + assert esc.strip() == "- none" + assert "'computable': True" in report # the full-log KPI still sees it assert "'not_reported': 1" in report + # lead-h's own report has it; the demo's notifier appends to a list and + # reports nothing, so delivery is unconfirmed and no transport time is claimed + import glob + from dispatcher.after_action import generate_report + from dispatcher.core import AuditLog + [audit] = [f for f in glob.glob(str(tmp_path / "aa" / "demo-audit-*.jsonl")) if "-b-" not in f] + hot = generate_report(AuditLog.reader(audit).read(), "P11", "hot", "lead-h", steps=[]) + hot_esc = hot.split("## escalations")[1].split("##")[0] + assert ("- escalation.hot_lead: raised, the notifier reported nothing - delivery " + "unconfirmed, no transport time") in hot_esc + assert "transport 0" not in hot_esc + # --------------------------------------------- loop protection + manners (Day 5) diff --git a/tests/test_notification_truth.py b/tests/test_notification_truth.py index 12340f2..3e1bbfb 100644 --- a/tests/test_notification_truth.py +++ b/tests/test_notification_truth.py @@ -151,10 +151,12 @@ def test_a_later_delivery_on_the_same_queue_does_not_cover_an_earlier_failure(tm hub.escalate("escalation.hot_lead", {"client_context_id": "B"}) k = compute_kpis(hub.audit.read())["escalation_transport_time"] assert (k["n"], k["unnotified"], k["confirmed"], k["notify_failed"]) == (1, 1, 1, 1) - report = generate_report(hub.audit.read(), "P11", "r", "A", steps=[]) - esc = report.split("## escalations")[1].split("##")[0].strip().splitlines() - assert esc[0] == "- escalation.hot_lead: raised, NOTIFICATION FAILED (failed) - no person was reached" - assert esc[1].startswith("- escalation.hot_lead: transport ") + def esc(ctx): + r = generate_report(hub.audit.read(), "P11", "r", ctx, steps=[]) + return r.split("## escalations")[1].split("##")[0].strip().splitlines() + assert esc("A") == ["- escalation.hot_lead: raised, NOTIFICATION FAILED (failed) - no person was reached"] + [b] = esc("B") # each report: its own escalation only + assert b.startswith("- escalation.hot_lead: transport ") def test_an_escalation_with_no_outcome_is_not_covered_by_the_next_ones(tmp_path): diff --git a/tests/test_sweep_reports_2026_10_13.py b/tests/test_sweep_reports_2026_10_13.py index 11943d3..163fddd 100644 --- a/tests/test_sweep_reports_2026_10_13.py +++ b/tests/test_sweep_reports_2026_10_13.py @@ -182,3 +182,13 @@ def test_manners_and_drift_counts_are_exact(): "phase_gate": 2, "post_compaction": 0, "turn_backstop": 1}} assert k["drift"] == {"hub_reflections_analyzed": 3, "hub_reflections_flagged": 2, "spoke_traces_scored": 2, "spoke_traces_flagged": 1} + + +def test_another_runs_escalation_is_not_in_this_report(): + log = LOG + [{"kind": "escalation.raised", "ts": 109.0, "queue": "escalation.hot_lead", + "client_context_id": "ctx-OTHER"}, + {"kind": "human.notified", "ts": 109.5, "queue": "escalation.hot_lead", + "client_context_id": "ctx-OTHER"}] + r = generate_report(log, "P11", "run-1", C, STEPS).splitlines() + assert len(section(r, "escalations")) == 3 # this run's three only + assert section(r, "gates")[0] == "- hot-lead escalation gate: TRIGGERED x3 (evidence: escalation.raised on log)"