From 328b123ad8ccbd002a4d21feb95a45ee62b42c65 Mon Sep 17 00:00:00 2001 From: colombod Date: Mon, 14 Sep 2026 22:06:36 +0000 Subject: [PATCH 01/14] feat(hook-context-intelligence): record per-destination delivery watermark MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Adds DeliveryWatermark: a per-session, per-destination byte-offset cursor into events.jsonl at /delivery/.json, written atomically (temp + fsync + os.replace). _append_event now returns the byte offset past its record; that offset plus the session dir travels through _persist_to_disk -> __call__ -> enqueue as a _WatermarkKey, and the dispatcher commits it on delivery. The tracker FREEZES a session's prefix the moment any record goes undelivered (overflow drop, permanent reject, hard auth failure, breaker skip). The live path's delivered set is NOT a contiguous prefix — drops happen at enqueue time, so a dropped record can sit between delivered ones. Freezing is what keeps the cursor honest and bounds the bookkeeping to queue depth. Nothing reads the watermark yet; delivery behaviour is unchanged. Monotonicity is CONDITIONAL. A truncated log rewinds the offset to 0, but a plain monotonic save re-reads the stale on-disk value and silently restores it, leaving the cursor past EOF forever and skipping every event in the log. `reset_by_guard` overrides monotonicity for exactly that case. Pinned by test_guard_reset_survives_save. Tests reaching directly into _queue.put_nowait were updated for the 3-tuple queue item; two test doubles accept the new kwarg; the enqueue hot-path AST allowlist gained _wm_freeze / setdefault / _SessionWatermarkState with justifications. Generated with Amplifier Co-Authored-By: Amplifier <240397093+microsoft-amplifier@users.noreply.github.com> --- .../handlers/delivery_watermark.py | 270 +++++++++++++ .../handlers/logging_handler.py | 202 +++++++++- .../tests/test_council_fixes.py | 20 +- .../tests/test_delivery_watermark.py | 377 ++++++++++++++++++ .../tests/test_dispatcher.py | 2 +- .../tests/test_hot_path.py | 12 + .../tests/test_logging_handler.py | 2 +- .../test_logging_handler_disk_breaker.py | 6 +- .../tests/test_worker_retry.py | 2 +- 9 files changed, 858 insertions(+), 35 deletions(-) create mode 100644 modules/hook-context-intelligence/amplifier_module_hook_context_intelligence/handlers/delivery_watermark.py create mode 100644 modules/hook-context-intelligence/tests/test_delivery_watermark.py diff --git a/modules/hook-context-intelligence/amplifier_module_hook_context_intelligence/handlers/delivery_watermark.py b/modules/hook-context-intelligence/amplifier_module_hook_context_intelligence/handlers/delivery_watermark.py new file mode 100644 index 00000000..36cc2c82 --- /dev/null +++ b/modules/hook-context-intelligence/amplifier_module_hook_context_intelligence/handlers/delivery_watermark.py @@ -0,0 +1,270 @@ +"""Per-session, per-destination delivery watermark — the resume cursor. + +Answers exactly one question: **how far through this session's ``events.jsonl`` +has destination D been accepted?** + +``events.jsonl`` is append-only, line-oriented, and never rewritten, so a byte +offset is the natural cursor: resuming is ``seek(offset)``, O(1), with no need to +parse or even read what came before. That matters at real corpus sizes — a single +observed ``events.jsonl`` on a developer workstation reached 2.47 GB. + +State lives in ``/delivery/.json``, beside the log it +indexes, rather than in a central registry. That choice buys three things: +self-cleanup (the state dies with the session directory, so there is no orphan +registry and no reaping job), natural sharding (concurrent sessions write +different session directories, so the common case has zero contention), and +locality (everything about one session is in one place). + +**Failure bias.** Every guard below resolves toward RE-SENDING, never toward +SKIPPING. Re-sending is absorbed by the server's ``MERGE`` on a deterministic +``node_id``; skipping is silent data loss. When in doubt, this module rewinds. +""" + +from __future__ import annotations + +import json +import logging +import os +import re +import tempfile +import time +from dataclasses import asdict, dataclass +from pathlib import Path +from typing import Self + +logger = logging.getLogger(__name__) + +WATERMARK_FORMAT = "context-intelligence-delivery-watermark" +WATERMARK_VERSION = "1.0.0" + +#: Destination names are operator-chosen ``settings.yaml`` dict keys, so they can +#: contain anything. Sanitize for use as a filename; the RAW name is kept inside +#: the file so a post-sanitization collision is detectable rather than silent. +_UNSAFE_NAME = re.compile(r"[^A-Za-z0-9._-]") + +#: A sweep lock older than this is assumed to belong to a dead process. Generous +#: on purpose: breaking a live lock costs only duplicate work, but breaking it +#: too eagerly defeats the point of having one. +DEFAULT_LOCK_STALE_SECONDS = 600.0 + + +def sanitize_destination(name: str) -> str: + """Map a destination name to a safe filename component.""" + return _UNSAFE_NAME.sub("_", name) or "_" + + +@dataclass +class DeliveryWatermark: + """The cursor for one (session, destination) pair.""" + + destination: str + destination_url: str = "" + offset: int = 0 + delivered_lines: int = 0 + events_file_size_at_write: int = 0 + last_delivered_at: str = "" + last_attempt_at: str = "" + last_outcome: str = "" + last_error: str | None = None + consecutive_sweeps_without_progress: int = 0 + format: str = WATERMARK_FORMAT + version: str = WATERMARK_VERSION + + #: Transient, never persisted. Set when a load-time guard rewound `offset`. + #: Monotonicity on save MUST NOT apply in that case — see `save`. + reset_by_guard: bool = False + + # -- locations ------------------------------------------------------ + + @staticmethod + def dir_for(session_dir: Path) -> Path: + return session_dir / "delivery" + + @staticmethod + def path_for(session_dir: Path, destination: str) -> Path: + return DeliveryWatermark.dir_for(session_dir) / f"{sanitize_destination(destination)}.json" + + # -- load ----------------------------------------------------------- + + @classmethod + def load( + cls, + session_dir: Path, + destination: str, + *, + destination_url: str = "", + ) -> tuple[DeliveryWatermark, list[str]]: + """Load the watermark, applying every guard. + + Returns ``(watermark, notes)``. ``notes`` names any guard that fired; + the caller owns the logging policy so this stays pure and testable. + A guard firing is never an exception — it is a rewind plus a note. + """ + notes: list[str] = [] + path = cls.path_for(session_dir, destination) + events = session_dir / "events.jsonl" + try: + size = events.stat().st_size + except OSError: + size = 0 + + if not path.exists(): + return cls(destination=destination, destination_url=destination_url), notes + + try: + raw = json.loads(path.read_text()) + if not isinstance(raw, dict): + raise TypeError("watermark is not a JSON object") + known = set(cls.__dataclass_fields__) + wm = cls(**{k: v for k, v in raw.items() if k in known}) + except (OSError, ValueError, TypeError) as exc: + # GUARD 1 — unreadable/corrupt. Bounded re-delivery beats a hard + # failure in a best-effort telemetry path. + notes.append(f"watermark unreadable ({exc}); resetting to 0") + return cls(destination=destination, destination_url=destination_url), notes + + # GUARD 2 — truncation. If the log is now SMALLER than where we believe + # we are, it was truncated or replaced and our offset is a lie. + if wm.offset > size: + notes.append( + f"events.jsonl shrank ({size} < offset {wm.offset}); truncated or replaced" + f" — resetting to 0" + ) + wm.offset = 0 + wm.delivered_lines = 0 + wm.reset_by_guard = True + + # GUARD 3 — destination identity. Same name, different URL means a + # different sink. Claiming "already delivered" against a server that + # never saw these events is the one genuinely lossy mistake available. + if destination_url and wm.destination_url and wm.destination_url != destination_url: + notes.append( + f"destination url changed ({wm.destination_url} -> {destination_url});" + f" treating as a fresh destination" + ) + wm.offset = 0 + wm.delivered_lines = 0 + wm.reset_by_guard = True + + wm.destination_url = destination_url or wm.destination_url + return wm, notes + + # -- save ----------------------------------------------------------- + + def save(self, session_dir: Path) -> None: + """Persist atomically: temp file, fsync, ``os.replace``. Never torn. + + Monotonic by default: re-reads the on-disk value and refuses to move the + offset backwards, so two racing processes can only ever advance it. + + **EXCEPT after a guard rewind**, which is the subtle part and was a real + bug caught only by executing this path. A truncated log rewinds `offset` + to 0 in memory — but the STALE ON-DISK value is still large, so plain + monotonicity reads it back and silently restores it. The watermark would + then point past the end of a truncated log forever and every event in it + would be skipped: precisely the silent data loss this design exists to + prevent. `reset_by_guard` is the override, and it is cleared once the + rewind has actually landed on disk. + """ + path = self.path_for(session_dir, self.destination) + path.parent.mkdir(parents=True, exist_ok=True) + + if path.exists() and not self.reset_by_guard: + try: + on_disk = json.loads(path.read_text()) + if int(on_disk.get("offset", 0)) > self.offset: + self.offset = int(on_disk["offset"]) + self.delivered_lines = max( + self.delivered_lines, int(on_disk.get("delivered_lines", 0)) + ) + except (OSError, ValueError, TypeError): + logger.debug("unreadable watermark during monotonic check at %s", path) + + try: + self.events_file_size_at_write = (session_dir / "events.jsonl").stat().st_size + except OSError: + self.events_file_size_at_write = 0 + + record = {k: v for k, v in asdict(self).items() if k != "reset_by_guard"} + payload = json.dumps(record, indent=2, sort_keys=True) + + fd, tmp = tempfile.mkstemp(dir=str(path.parent), prefix=".wm-", suffix=".tmp") + try: + with os.fdopen(fd, "w") as fh: + fh.write(payload) + fh.flush() + os.fsync(fh.fileno()) + os.replace(tmp, path) + self.reset_by_guard = False + except BaseException: + try: + os.unlink(tmp) + except OSError: + pass + raise + + # -- reporting ------------------------------------------------------ + + def backlog_bytes(self, session_dir: Path) -> int: + try: + size = (session_dir / "events.jsonl").stat().st_size + except OSError: + return 0 + return max(0, size - self.offset) + + def caught_up(self, session_dir: Path) -> bool: + return self.backlog_bytes(session_dir) == 0 + + +class SweepLock: + """Advisory ``O_EXCL`` lock so two sessions don't sweep the same backlog. + + Deliberately NOT load-bearing for correctness: losing the race costs + duplicate POSTs, which the server merges. It exists only to avoid wasted + work, which is why it is never blocked on and a stale lock is simply broken. + """ + + def __init__( + self, + session_dir: Path, + destination: str, + stale_after: float = DEFAULT_LOCK_STALE_SECONDS, + ) -> None: + self.path = DeliveryWatermark.dir_for(session_dir) / ( + f"{sanitize_destination(destination)}.lock" + ) + self.stale_after = stale_after + self.held = False + + def __enter__(self) -> Self: + self.path.parent.mkdir(parents=True, exist_ok=True) + # At most two attempts: acquire, or break one stale lock and retry. A + # loop rather than recursion so a pathological lock-churn race cannot + # build a stack. + for attempt in (1, 2): + try: + fd = os.open(str(self.path), os.O_CREAT | os.O_EXCL | os.O_WRONLY) + with os.fdopen(fd, "w") as fh: + json.dump({"pid": os.getpid(), "created_at": time.time()}, fh) + self.held = True + return self + except FileExistsError: + try: + age = time.time() - self.path.stat().st_mtime + except OSError: + age = 0.0 + if attempt == 1 and age > self.stale_after: + logger.debug("breaking stale sweep lock at %s (age %.0fs)", self.path, age) + self.path.unlink(missing_ok=True) + continue + self.held = False + return self + except OSError: + self.held = False + return self + return self + + def __exit__(self, *exc: object) -> None: + if self.held: + self.path.unlink(missing_ok=True) + self.held = False diff --git a/modules/hook-context-intelligence/amplifier_module_hook_context_intelligence/handlers/logging_handler.py b/modules/hook-context-intelligence/amplifier_module_hook_context_intelligence/handlers/logging_handler.py index 7dd4f3ed..75937eed 100644 --- a/modules/hook-context-intelligence/amplifier_module_hook_context_intelligence/handlers/logging_handler.py +++ b/modules/hook-context-intelligence/amplifier_module_hook_context_intelligence/handlers/logging_handler.py @@ -14,6 +14,7 @@ import random import time from collections import deque +from dataclasses import dataclass from datetime import datetime, timezone from functools import partial from pathlib import Path @@ -22,6 +23,7 @@ import httpx from amplifier_core.models import HookResult +from .delivery_watermark import DeliveryWatermark from amplifier_module_hook_context_intelligence.upload import ( _canonical_json, _compute_idempotency_key, # noqa: F401 — re-exported for test imports @@ -74,6 +76,14 @@ #: Minimum seconds between repeated overflow or permanent-skip log warnings. _LOG_RATE_LIMIT_SECONDS = 60.0 +#: Delivery-watermark persistence debounce. The watermark is an optimisation for +#: the NEXT session, never a correctness requirement for this one, so it is +#: written lazily: an un-flushed advance costs bounded re-delivery, which the +#: server's MERGE absorbs. Flushing on every event would put an fsync on a path +#: whose entire design goal is to stay off the hot path. +_WM_PERSIST_EVERY = 50 +_WM_PERSIST_INTERVAL_SECONDS = 5.0 + # --------------------------------------------------------------------------- # Circuit breaker constants (v2 minimal breaker) # @@ -280,6 +290,32 @@ def _write_forwarding_record(log_dir: Path | None, record: dict[str, Any]) -> bo # --------------------------------------------------------------------------- # _DestinationDispatcher # --------------------------------------------------------------------------- +@dataclass +class _WatermarkKey: + """Where one enqueued event sits in its session's durable log.""" + + session_dir: str + end_offset: int + + +@dataclass +class _SessionWatermarkState: + """Contiguous-prefix accounting for one session dir. + + ``frozen`` is the load-bearing field. The live path's delivered set is NOT a + contiguous prefix: drops happen at enqueue time when the queue is full, so a + dropped record at byte X can sit between delivered records either side of it. + The moment ANY record goes undelivered, the prefix can never legitimately + advance past it -- so we freeze, and the backlog sweep owns everything from + there. That also bounds this bookkeeping to the queue depth instead of the + session length. + """ + + committed: int = 0 + frozen: bool = False + dirty: bool = False + + class _DestinationDispatcher: """One context-intelligence destination: own client, queue, breaker, worker. @@ -339,10 +375,15 @@ def __init__( ) self._client: httpx.AsyncClient | None = None self._queue_capacity = max(1, queue_capacity) - self._queue: asyncio.Queue[tuple[str, dict[str, Any]]] = asyncio.Queue( - maxsize=self._queue_capacity + self._queue: asyncio.Queue[tuple[str, dict[str, Any], _WatermarkKey | None]] = ( + asyncio.Queue(maxsize=self._queue_capacity) ) self._worker_task: asyncio.Task[None] | None = None + # Delivery-watermark accounting, per session dir this dispatcher has + # seen. One dispatcher carries events for a session AND its sub-sessions, + # so this cannot be a single cursor. + self._wm_state: dict[str, _SessionWatermarkState] = {} + self._wm_last_flush = time.monotonic() self._consecutive_failures = 0 # backoff driver only — never disables self._degraded_warned = False # Wall-clock start (time.monotonic()) of the CURRENT sustained-degraded @@ -458,6 +499,22 @@ def _emit_delivery_heartbeat(self) -> None: self._heartbeat_emitted = True self._record_forwarding_issue("delivery_ok", "first successful delivery this session") + # -- read-only identity, for collaborators that must not reach into + # privates (the backlog sweep reuses this destination's auth strategy so a + # sweep can never acquire a second token or diverge from live-path auth). + + @property + def name(self) -> str: + return self._name + + @property + def url(self) -> str: + return self._url + + @property + def auth_strategy(self) -> Any: + return self._strategy + def _ensure_worker(self) -> None: if self._worker_task is None or self._worker_task.done(): self._worker_task = asyncio.create_task(self._worker()) @@ -469,7 +526,13 @@ def _ensure_worker(self) -> None: partial(_retrieve_task_exception, context=f"{self._name} dispatch worker") ) - def enqueue(self, event: str, data: dict[str, Any]) -> bool: + def enqueue( + self, + event: str, + data: dict[str, Any], + *, + wm_key: _WatermarkKey | None = None, + ) -> bool: """Enqueue an event for dispatch. HOT PATH — zero awaits, zero I/O. Returns ``True`` if the event was queued for delivery, ``False`` if it @@ -490,9 +553,12 @@ def enqueue(self, event: str, data: dict[str, Any]) -> bool: """ self._ensure_worker() try: - self._queue.put_nowait((event, data)) + self._queue.put_nowait((event, data, wm_key)) return True except asyncio.QueueFull: + # A dropped record freezes this session's prefix: the watermark can + # never honestly advance past a record that was never delivered. + self._wm_freeze(wm_key) self._overflow_dropped += 1 now = time.monotonic() if now - self._last_overflow_log >= _LOG_RATE_LIMIT_SECONDS: @@ -509,6 +575,64 @@ def enqueue(self, event: str, data: dict[str, Any]) -> bool: ) return False + # -- delivery watermark (Increment 0) ----------------------------------- + # + # Written here, read by the backlog sweep on a LATER session. Nothing in the + # live delivery path consults it, so a wrong value can only ever cost + # re-delivery -- never a skipped event. + + def _wm_freeze(self, key: _WatermarkKey | None) -> None: + """Record that an event went UNDELIVERED; the prefix stops here.""" + if key is None: + return + state = self._wm_state.setdefault(key.session_dir, _SessionWatermarkState()) + state.frozen = True + + def _wm_commit(self, key: _WatermarkKey | None) -> None: + """Record a delivered event, advancing the contiguous prefix.""" + if key is None: + return + state = self._wm_state.setdefault(key.session_dir, _SessionWatermarkState()) + if state.frozen: + # Something earlier in this session was never delivered, so the + # sweep must re-read from there regardless of what lands after it. + return + if key.end_offset > state.committed: + state.committed = key.end_offset + state.dirty = True + + def _wm_flush(self, *, force: bool = False) -> None: + """Persist dirty watermarks. Best-effort: NEVER raises, never blocks. + + Called from the worker (debounced) and once from ``close()``. A failure + here is invisible to delivery by design -- the cost of not writing is a + re-send next session. + """ + if not self._wm_state: + return + now = time.monotonic() + if not force and (now - self._wm_last_flush) < _WM_PERSIST_INTERVAL_SECONDS: + pending = sum(1 for st in self._wm_state.values() if st.dirty) + if pending < _WM_PERSIST_EVERY: + return + self._wm_last_flush = now + for session_dir, state in self._wm_state.items(): + if not state.dirty: + continue + try: + path = Path(session_dir) + watermark, _notes = DeliveryWatermark.load( + path, self._name, destination_url=self._url + ) + if state.committed > watermark.offset: + watermark.offset = state.committed + watermark.last_delivered_at = datetime.now(timezone.utc).isoformat() + watermark.last_outcome = "delivered" + watermark.save(path) + state.dirty = False + except OSError: + logger.debug("watermark flush failed dest=%s session=%s", self._name, session_dir) + def _record_forwarding_issue(self, kind: str, detail: str) -> None: """Write a durable forwarding-diagnostics record for this destination. @@ -767,8 +891,10 @@ async def _worker(self) -> None: ``close()`` never hangs. """ while True: - event, payload_data = await self._queue.get() + event, payload_data, wm_key = await self._queue.get() self._current = (event, payload_data) + # Debounced; a no-op on the vast majority of iterations. + self._wm_flush() try: # --- circuit breaker gate ------------------------------- # OWNERSHIP: only this worker task reads/mutates breaker @@ -779,6 +905,7 @@ async def _worker(self) -> None: # Already durable in events.jsonl (LoggingHandler # wrote it before fan-out) -- do not dispatch while # OPEN and not yet due for a probe. + self._wm_freeze(wm_key) self._queue.task_done() self._current = None continue @@ -788,10 +915,14 @@ async def _worker(self) -> None: if outcome == _DELIVERED: self._breaker_record_delivered() self._emit_delivery_heartbeat() + self._wm_commit(wm_key) self._degraded_warned = False self._degraded_since = None elif outcome == _TRANSIENT and self._is_hard_outcome(): self._breaker_record_hard() + self._wm_freeze(wm_key) + else: + self._wm_freeze(wm_key) # Genuinely transient/permanent while probing is # inconclusive -- leave the breaker OPEN and advance; # the event stays durable regardless. @@ -911,6 +1042,7 @@ async def _worker(self) -> None: # across many different events. It resets only on # an actual DELIVERED/PERMANENT advance (bottom of # the loop below), matching a real recovery. + self._wm_freeze(wm_key) self._consecutive_failures = 0 self._queue.task_done() self._current = None @@ -923,6 +1055,7 @@ async def _worker(self) -> None: if outcome == _DELIVERED: self._breaker_record_delivered() self._emit_delivery_heartbeat() + self._wm_commit(wm_key) if self._degraded_warned: logger.info( "Reconnected to %s — resuming delivery.", @@ -931,6 +1064,7 @@ async def _worker(self) -> None: self._degraded_warned = False self._degraded_since = None elif outcome == _PERMANENT: + self._wm_freeze(wm_key) now = time.monotonic() if now - self._last_permanent_log >= _LOG_RATE_LIMIT_SECONDS: self._last_permanent_log = now @@ -1027,6 +1161,7 @@ async def _worker(self) -> None: # backoff must not inherit this event's failure count, and the # 401 auth-escalation gate must not carry over. Mirrors the reset # on the normal DELIVERED/PERMANENT advance path. + self._wm_freeze(wm_key) self._consecutive_failures = 0 self._auth_failures = 0 self._queue.task_done() @@ -1296,6 +1431,11 @@ async def close(self) -> None: except asyncio.TimeoutError: pass # worker will be cancelled below; undelivered count computed first + # Land the delivery watermark before anything else in teardown: it + # is what the NEXT session resumes from, and an unflushed advance + # here is exactly the re-delivery this increment exists to avoid. + self._wm_flush(force=True) + # Compute honest undelivered count BEFORE cancelling the worker. # Cancellation sets self._current = None in the CancelledError handler, # so we must read it here to get an accurate in-flight count. @@ -1467,7 +1607,7 @@ async def __call__(self, event: str, data: dict[str, Any]) -> HookResult: # network fan-out below runs regardless of disk state so that events # keep flowing to the server even when the disk is full. The two # destinations are independent on purpose. - disk_state = self._persist_to_disk(event, session_id, sanitized_data) + disk_state, wm_key = self._persist_to_disk(event, session_id, sanitized_data) # Fan-out to all active dispatchers — each enqueue is isolated so that # one dispatcher's failure does not starve the others. Independent of @@ -1478,7 +1618,7 @@ async def __call__(self, event: str, data: dict[str, Any]) -> HookResult: delivered_to_server = False for dispatcher in self._dispatchers: try: - if dispatcher.enqueue(event, sanitized_data): + if dispatcher.enqueue(event, sanitized_data, wm_key=wm_key): delivered_to_server = True except Exception: logger.warning( @@ -1557,10 +1697,17 @@ def _atomic_write_text(meta_path: Path, text: str) -> None: raise # -- disk-write path with ENOSPC circuit breaker ------------------------ - def _persist_to_disk(self, event: str, session_id: str, data: dict[str, Any]) -> str: + def _persist_to_disk( + self, event: str, session_id: str, data: dict[str, Any] + ) -> tuple[str, _WatermarkKey | None]: """Write this event's session files, guarded by the disk-pressure breaker. - Returns a disk-state token the caller combines with the network-dispatch + Returns ``(disk_state, wm_key)``. ``wm_key`` locates this event's record + in its session's durable log -- the unit the delivery watermark counts in + -- or ``None`` when nothing was written (disk pressure) or the write path + was stubbed out. + + The disk-state token is what the caller combines with the network-dispatch outcome to phrase the right user alert: * ``"ok"`` — written to disk (or nothing to report). @@ -1578,10 +1725,12 @@ def _persist_to_disk(self, event: str, session_id: str, data: dict[str, Any]) -> # rather than hammer a full filesystem on every event. if self._disk_backoff_seconds > 0.0 and now < self._disk_retry_at: self._disk_events_skipped += 1 - return "degraded" + return "degraded", None + wm_key: _WatermarkKey | None = None try: - self._write_session_to_disk(event, session_id, data) + written = self._write_session_to_disk(event, session_id, data) + wm_key = written if isinstance(written, _WatermarkKey) else None except OSError as exc: if exc.errno in _DISK_PRESSURE_ERRNOS: if self._disk_backoff_seconds <= 0.0: @@ -1598,14 +1747,14 @@ def _persist_to_disk(self, event: str, session_id: str, data: dict[str, Any]) -> "LoggingHandler disk write failed (errno %s): session data not written", exc.errno, ) - return "degraded" + return "degraded", None # Non-pressure OSError (e.g. a single bad path): best-effort log, # do NOT open the global breaker. logger.warning("LoggingHandler disk write error processing %s", event, exc_info=True) - return "ok" + return "ok", None except Exception: logger.warning("LoggingHandler disk write error processing %s", event, exc_info=True) - return "ok" + return "ok", None # Success. If the breaker had been open, this was a recovery probe: # write the durable episode record (the disk is writable again, so this @@ -1625,10 +1774,12 @@ def _persist_to_disk(self, event: str, session_id: str, data: dict[str, Any]) -> self._disk_degraded_since = 0.0 self._disk_events_skipped = 0 self._disk_episode_delivered = False - return "recovered" - return "ok" + return "recovered", wm_key + return "ok", wm_key - def _write_session_to_disk(self, event: str, session_id: str, data: dict[str, Any]) -> None: + def _write_session_to_disk( + self, event: str, session_id: str, data: dict[str, Any] + ) -> _WatermarkKey | None: """The actual per-event disk writes. Lets OSError propagate for classification. The metadata helpers (``_ensure_metadata`` / ``_enrich`` / ``_finalize`` / @@ -1652,8 +1803,12 @@ def _write_session_to_disk(self, event: str, session_id: str, data: dict[str, An elif event in ("session:end", "execution:end"): self._finalize_metadata(session_dir, data) - self._append_event(session_dir, event, data, self._workspace) + end_offset = self._append_event(session_dir, event, data, self._workspace) self._touch_last_event_at(session_dir, data.get("timestamp", "")) + # Built HERE because this is the only place that holds both the session + # dir and the record's end offset; building it later would mean looking + # the session dir up a second time on the hot path. + return _WatermarkKey(session_dir=str(session_dir), end_offset=end_offset) def _open_disk_breaker(self, now: float) -> None: """Open or widen the disk-pressure breaker with capped exponential backoff.""" @@ -1897,7 +2052,14 @@ def _touch_last_event_at(self, session_dir: Path, timestamp: str) -> None: @staticmethod def _append_event( session_dir: Path, event: str, data: dict[str, Any], workspace: str | None - ) -> None: + ) -> int: + """Append one record and return the byte offset just past it. + + That offset is the delivery watermark's unit of account: a record is + "delivered" once the destination has accepted everything up to its end + offset. Returned rather than recomputed because ``stat()`` after the + fact would see any concurrent appender's bytes too. + """ record = { "event": event, "workspace": workspace or "", @@ -1906,3 +2068,5 @@ def _append_event( } with (session_dir / "events.jsonl").open("a") as f: f.write(_canonical_json(record) + "\n") + f.flush() + return f.tell() diff --git a/modules/hook-context-intelligence/tests/test_council_fixes.py b/modules/hook-context-intelligence/tests/test_council_fixes.py index 95165274..d67e2739 100644 --- a/modules/hook-context-intelligence/tests/test_council_fixes.py +++ b/modules/hook-context-intelligence/tests/test_council_fixes.py @@ -138,7 +138,7 @@ async def fake_post(event: str, data: dict) -> str: # type: ignore[type-arg] d._post = fake_post # type: ignore[method-assign] with patch(LOGGER_PATH) as mock_logger: - d._queue.put_nowait(("test:event", {"session_id": "s1"})) + d._queue.put_nowait(("test:event", {"session_id": "s1"}, None)) task = asyncio.create_task(d._worker()) await d._queue.join() task.cancel() @@ -202,7 +202,7 @@ async def test_auth_escalation_fires_at_threshold_one() -> None: d._sleep_backoff = AsyncMock() with patch(LOGGER_PATH) as mock_logger: - d._queue.put_nowait(("test:event", {"session_id": "s1"})) + d._queue.put_nowait(("test:event", {"session_id": "s1"}, None)) task = asyncio.create_task(d._worker()) await d._queue.join() task.cancel() @@ -248,9 +248,9 @@ async def always_401(event: str, data: dict) -> str: # type: ignore[type-arg] with patch(f"{MOD}.time.monotonic", side_effect=ticks): with patch(LOGGER_PATH) as mock_logger: - d._queue.put_nowait(("e1", {"session_id": "s1"})) - d._queue.put_nowait(("e2", {"session_id": "s2"})) - d._queue.put_nowait(("e3", {"session_id": "s3"})) + d._queue.put_nowait(("e1", {"session_id": "s1"}, None)) + d._queue.put_nowait(("e2", {"session_id": "s2"}, None)) + d._queue.put_nowait(("e3", {"session_id": "s3"}, None)) task = asyncio.create_task(d._worker()) await d._queue.join() task.cancel() @@ -504,7 +504,7 @@ async def test_timeouts_after_401_do_not_refire_auth_warning() -> None: ticks = iter(range(61, 100000, 61)) with patch(f"{MOD}.time.monotonic", side_effect=ticks): with patch(LOGGER_PATH) as mock_logger: - d._queue.put_nowait(("test:event", {"session_id": "s1"})) + d._queue.put_nowait(("test:event", {"session_id": "s1"}, None)) task = asyncio.create_task(d._worker()) await d._queue.join() task.cancel() @@ -547,8 +547,8 @@ async def always_401(event: str, data: dict) -> str: # type: ignore[type-arg] d._post = always_401 # type: ignore[method-assign] with patch(LOGGER_PATH): - d._queue.put_nowait(("e1", {"session_id": "s1"})) - d._queue.put_nowait(("e2", {"session_id": "s2"})) + d._queue.put_nowait(("e1", {"session_id": "s1"}, None)) + d._queue.put_nowait(("e2", {"session_id": "s2"}, None)) task = asyncio.create_task(d._worker()) # Without the immediate hard-skip this join() would retry forever -> # TimeoutError -> fail. @@ -587,8 +587,8 @@ async def fake_post(event: str, data: dict) -> str: # type: ignore[type-arg] d._post = fake_post # type: ignore[method-assign] with patch(LOGGER_PATH): - d._queue.put_nowait(("doomed", {"session_id": "s1"})) - d._queue.put_nowait(("healthy", {"session_id": "s2"})) + d._queue.put_nowait(("doomed", {"session_id": "s1"}, None)) + d._queue.put_nowait(("healthy", {"session_id": "s2"}, None)) task = asyncio.create_task(d._worker()) await asyncio.wait_for(d._queue.join(), timeout=5.0) task.cancel() diff --git a/modules/hook-context-intelligence/tests/test_delivery_watermark.py b/modules/hook-context-intelligence/tests/test_delivery_watermark.py new file mode 100644 index 00000000..536a07f1 --- /dev/null +++ b/modules/hook-context-intelligence/tests/test_delivery_watermark.py @@ -0,0 +1,377 @@ +"""Delivery-watermark tests — the resume cursor (design Increment 0). + +The watermark is only ever READ by a later session's backlog sweep, so a wrong +value here is invisible in this process and shows up as either wasted +re-delivery (harmless) or a SKIPPED EVENT (silent data loss). These tests pin +the difference. + +The load-bearing one is ``test_guard_reset_survives_save``. See its docstring. +""" + +from __future__ import annotations + +import asyncio +import json +from pathlib import Path +from typing import Any + +import pytest + +from amplifier_module_hook_context_intelligence.handlers.delivery_watermark import ( + DeliveryWatermark, + SweepLock, + sanitize_destination, +) +from amplifier_module_hook_context_intelligence.handlers.logging_handler import ( + _DestinationDispatcher, + _SessionWatermarkState, + _WatermarkKey, +) + +DEST = "team-shared" +URL = "https://ci.example.com" + + +def _session(tmp_path: Path, *, lines: int = 10) -> Path: + session_dir = tmp_path / "sessions" / "s1" / "context-intelligence" + session_dir.mkdir(parents=True) + with (session_dir / "events.jsonl").open("w") as fh: + for i in range(lines): + fh.write(json.dumps({"event": f"e{i}", "workspace": "ws", "data": {}}) + "\n") + return session_dir + + +def _dispatcher(**overrides: object) -> _DestinationDispatcher: + defaults: dict[str, object] = dict( + name=DEST, + url=URL, + api_key="k", + workspace="ws", + dispatch_timeout=10.0, + failure_threshold=3, + queue_capacity=256, + close_drain_timeout=2.0, + backoff_jitter=False, + ) + defaults.update(overrides) + return _DestinationDispatcher(**defaults) # type: ignore[arg-type] + + +# --------------------------------------------------------------------------- +# File mechanics +# --------------------------------------------------------------------------- + + +class TestWatermarkFile: + def test_absent_watermark_reads_as_zero(self, tmp_path: Path) -> None: + session_dir = _session(tmp_path) + wm, notes = DeliveryWatermark.load(session_dir, DEST, destination_url=URL) + assert wm.offset == 0 + assert notes == [] + + def test_round_trip(self, tmp_path: Path) -> None: + session_dir = _session(tmp_path) + wm, _ = DeliveryWatermark.load(session_dir, DEST, destination_url=URL) + wm.offset = 120 + wm.delivered_lines = 3 + wm.save(session_dir) + + again, notes = DeliveryWatermark.load(session_dir, DEST, destination_url=URL) + assert (again.offset, again.delivered_lines, notes) == (120, 3, []) + + def test_save_is_monotonic(self, tmp_path: Path) -> None: + """A stale writer must never move the cursor backwards. + + Offsets stay INSIDE the log on purpose: an offset past EOF would trip + the truncation guard on load and reset to 0, which would make this test + pass or fail for the wrong reason. + """ + session_dir = _session(tmp_path) + size = (session_dir / "events.jsonl").stat().st_size + ahead = DeliveryWatermark(destination=DEST, destination_url=URL, offset=size) + ahead.save(session_dir) + + behind = DeliveryWatermark(destination=DEST, destination_url=URL, offset=5) + behind.save(session_dir) + + loaded, notes = DeliveryWatermark.load(session_dir, DEST, destination_url=URL) + assert loaded.offset == size + assert notes == [] + + def test_transient_reset_flag_is_never_persisted(self, tmp_path: Path) -> None: + session_dir = _session(tmp_path) + wm = DeliveryWatermark(destination=DEST, destination_url=URL, offset=1) + wm.reset_by_guard = True + wm.save(session_dir) + raw = json.loads(DeliveryWatermark.path_for(session_dir, DEST).read_text()) + assert "reset_by_guard" not in raw + assert wm.reset_by_guard is False, "flag must be cleared once the write lands" + + def test_destination_name_is_sanitized_for_the_filename(self, tmp_path: Path) -> None: + session_dir = _session(tmp_path) + wm = DeliveryWatermark(destination="team/prod:eu", destination_url=URL, offset=7) + wm.save(session_dir) + path = DeliveryWatermark.path_for(session_dir, "team/prod:eu") + assert path.name == "team_prod_eu.json" + # The RAW name is preserved inside, so a post-sanitization collision is + # detectable rather than silent. + assert json.loads(path.read_text())["destination"] == "team/prod:eu" + assert sanitize_destination("") == "_" + + +# --------------------------------------------------------------------------- +# Guards — every one must fail toward RE-SENDING, never toward SKIPPING +# --------------------------------------------------------------------------- + + +class TestGuards: + def test_corrupt_watermark_resets_to_zero(self, tmp_path: Path) -> None: + session_dir = _session(tmp_path) + DeliveryWatermark.dir_for(session_dir).mkdir(parents=True, exist_ok=True) + DeliveryWatermark.path_for(session_dir, DEST).write_text("{not json") + + wm, notes = DeliveryWatermark.load(session_dir, DEST, destination_url=URL) + assert wm.offset == 0 + assert any("unreadable" in n for n in notes) + + def test_non_object_watermark_resets_to_zero(self, tmp_path: Path) -> None: + session_dir = _session(tmp_path) + DeliveryWatermark.dir_for(session_dir).mkdir(parents=True, exist_ok=True) + DeliveryWatermark.path_for(session_dir, DEST).write_text("[1, 2, 3]") + + wm, notes = DeliveryWatermark.load(session_dir, DEST, destination_url=URL) + assert wm.offset == 0 + assert any("unreadable" in n for n in notes) + + def test_truncated_log_resets_to_zero(self, tmp_path: Path) -> None: + session_dir = _session(tmp_path) + DeliveryWatermark(destination=DEST, destination_url=URL, offset=10_000).save(session_dir) + (session_dir / "events.jsonl").write_text('{"event":"x","workspace":"w","data":{}}\n') + + wm, notes = DeliveryWatermark.load(session_dir, DEST, destination_url=URL) + assert wm.offset == 0 + assert any("shrank" in n for n in notes) + + def test_guard_reset_survives_save(self, tmp_path: Path) -> None: + """REGRESSION: a guard rewind must actually reach disk. + + Two individually-correct rules collide here. Monotonicity says "never + move the cursor backwards"; the truncation guard says "rewind, the log + was replaced". Without an explicit override, `save()` re-reads the stale + on-disk offset, sees it is larger, and silently restores it -- so the + rewind never lands and the watermark points past the end of a truncated + log FOREVER, skipping every event in it. + + That is the one genuinely lossy failure mode in this design, it is + invisible to inspection, and it was caught only by executing the path. + """ + session_dir = _session(tmp_path) + DeliveryWatermark(destination=DEST, destination_url=URL, offset=10_000).save(session_dir) + (session_dir / "events.jsonl").write_text('{"event":"x","workspace":"w","data":{}}\n') + + rewound, _ = DeliveryWatermark.load(session_dir, DEST, destination_url=URL) + assert rewound.offset == 0 + rewound.save(session_dir) + + reloaded, _ = DeliveryWatermark.load(session_dir, DEST, destination_url=URL) + assert reloaded.offset == 0, ( + "monotonicity clobbered the truncation rewind: the watermark still points " + "past the end of the log, so every event in it would be skipped" + ) + + def test_changed_destination_url_resets_to_zero(self, tmp_path: Path) -> None: + """Same name, different sink: claiming 'already delivered' would lose data.""" + session_dir = _session(tmp_path) + DeliveryWatermark(destination=DEST, destination_url=URL, offset=120).save(session_dir) + + wm, notes = DeliveryWatermark.load( + session_dir, DEST, destination_url="https://elsewhere.example.com" + ) + assert wm.offset == 0 + assert any("url changed" in n for n in notes) + + def test_same_url_does_not_reset(self, tmp_path: Path) -> None: + session_dir = _session(tmp_path) + DeliveryWatermark(destination=DEST, destination_url=URL, offset=120).save(session_dir) + wm, notes = DeliveryWatermark.load(session_dir, DEST, destination_url=URL) + assert (wm.offset, notes) == (120, []) + + +class TestBacklogReporting: + def test_backlog_bytes_and_caught_up(self, tmp_path: Path) -> None: + session_dir = _session(tmp_path) + size = (session_dir / "events.jsonl").stat().st_size + wm = DeliveryWatermark(destination=DEST, destination_url=URL) + assert wm.backlog_bytes(session_dir) == size + assert not wm.caught_up(session_dir) + wm.offset = size + assert wm.backlog_bytes(session_dir) == 0 + assert wm.caught_up(session_dir) + + +class TestSweepLock: + def test_second_holder_is_refused_and_first_releases(self, tmp_path: Path) -> None: + session_dir = _session(tmp_path) + with SweepLock(session_dir, DEST) as first, SweepLock(session_dir, DEST) as second: + assert first.held is True + assert second.held is False + with SweepLock(session_dir, DEST) as third: + assert third.held is True + + def test_stale_lock_is_broken(self, tmp_path: Path) -> None: + session_dir = _session(tmp_path) + with SweepLock(session_dir, DEST) as held: + assert held.held + # A lock whose owner died: the file outlives the process. + fresh = SweepLock(session_dir, DEST, stale_after=-1.0) + with fresh as broken: + assert broken.held is True, "a stale lock must not block the sweep forever" + + +# --------------------------------------------------------------------------- +# Live-path accounting: contiguous prefix, and freeze-on-undelivered +# --------------------------------------------------------------------------- + + +class TestContiguousPrefixAccounting: + def test_commit_advances_the_prefix(self, tmp_path: Path) -> None: + session_dir = _session(tmp_path) + d = _dispatcher() + for offset in (10, 20, 30): + d._wm_commit(_WatermarkKey(session_dir=str(session_dir), end_offset=offset)) + state = d._wm_state[str(session_dir)] + assert (state.committed, state.frozen, state.dirty) == (30, False, True) + + def test_commit_never_moves_backwards(self, tmp_path: Path) -> None: + session_dir = _session(tmp_path) + d = _dispatcher() + d._wm_commit(_WatermarkKey(session_dir=str(session_dir), end_offset=99)) + d._wm_commit(_WatermarkKey(session_dir=str(session_dir), end_offset=5)) + assert d._wm_state[str(session_dir)].committed == 99 + + def test_a_dropped_event_freezes_the_prefix(self, tmp_path: Path) -> None: + """THE reason the live path's delivered set is not a contiguous prefix. + + Drops happen at ENQUEUE time when the queue is full, so a dropped record + can sit between delivered records either side of it. Once anything goes + undelivered the cursor must stop there, or the sweep would skip it. + """ + session_dir = _session(tmp_path) + d = _dispatcher() + key = str(session_dir) + d._wm_commit(_WatermarkKey(session_dir=key, end_offset=10)) + d._wm_freeze(_WatermarkKey(session_dir=key, end_offset=20)) + d._wm_commit(_WatermarkKey(session_dir=key, end_offset=30)) + + state = d._wm_state[key] + assert state.frozen is True + assert state.committed == 10, "the prefix advanced past an undelivered record" + + def test_none_key_is_a_noop(self, tmp_path: Path) -> None: + d = _dispatcher() + d._wm_commit(None) + d._wm_freeze(None) + assert d._wm_state == {} + + def test_sessions_are_tracked_independently(self, tmp_path: Path) -> None: + """One dispatcher carries a session AND its sub-sessions.""" + a = _session(tmp_path / "a") + b = _session(tmp_path / "b") + d = _dispatcher() + d._wm_commit(_WatermarkKey(session_dir=str(a), end_offset=50)) + d._wm_freeze(_WatermarkKey(session_dir=str(b), end_offset=50)) + assert d._wm_state[str(a)].frozen is False + assert d._wm_state[str(b)].frozen is True + + +class TestWatermarkFlush: + def test_forced_flush_persists_committed_prefix(self, tmp_path: Path) -> None: + session_dir = _session(tmp_path) + d = _dispatcher() + d._wm_commit(_WatermarkKey(session_dir=str(session_dir), end_offset=64)) + d._wm_flush(force=True) + + wm, _ = DeliveryWatermark.load(session_dir, DEST, destination_url=URL) + assert wm.offset == 64 + assert d._wm_state[str(session_dir)].dirty is False + + def test_flush_is_debounced(self, tmp_path: Path) -> None: + """The watermark helps the NEXT session; it must not fsync per event.""" + session_dir = _session(tmp_path) + d = _dispatcher() + d._wm_commit(_WatermarkKey(session_dir=str(session_dir), end_offset=64)) + d._wm_flush() # immediately after construction -> inside the debounce window + assert not DeliveryWatermark.path_for(session_dir, DEST).exists() + + def test_flush_never_raises_when_the_directory_is_gone(self, tmp_path: Path) -> None: + session_dir = _session(tmp_path) + d = _dispatcher() + d._wm_commit(_WatermarkKey(session_dir=str(session_dir / "vanished"), end_offset=64)) + d._wm_flush(force=True) # must not raise + + def test_flush_with_no_state_is_a_noop(self) -> None: + _dispatcher()._wm_flush(force=True) + + +# --------------------------------------------------------------------------- +# End to end through the real enqueue/worker path +# --------------------------------------------------------------------------- + + +@pytest.mark.asyncio +class TestThroughTheDispatcher: + async def test_delivered_events_advance_the_watermark(self, tmp_path: Path) -> None: + session_dir = _session(tmp_path) + d = _dispatcher() + + async def ok(event: str, data: dict[str, Any]) -> str: + return "delivered" + + d._post = ok # type: ignore[method-assign] + for offset in (10, 20, 30): + assert d.enqueue( + "e", + {"session_id": "s1"}, + wm_key=_WatermarkKey(session_dir=str(session_dir), end_offset=offset), + ) + await asyncio.wait_for(d._queue.join(), timeout=5) + d._wm_flush(force=True) + + wm, _ = DeliveryWatermark.load(session_dir, DEST, destination_url=URL) + assert wm.offset == 30 + + async def test_overflow_drop_freezes_the_watermark(self, tmp_path: Path) -> None: + session_dir = _session(tmp_path) + d = _dispatcher(queue_capacity=1) + key = str(session_dir) + + # Fill the queue, then overflow. No worker is started, so nothing drains. + assert d.enqueue( + "e1", {"session_id": "s1"}, wm_key=_WatermarkKey(session_dir=key, end_offset=10) + ) + assert not d.enqueue( + "e2", {"session_id": "s1"}, wm_key=_WatermarkKey(session_dir=key, end_offset=20) + ) + + assert d._overflow_dropped == 1 + assert d._wm_state[key].frozen is True + + d._wm_commit(_WatermarkKey(session_dir=key, end_offset=30)) + assert d._wm_state[key].committed == 0, "a drop must pin the cursor where it fell" + + async def test_enqueue_without_a_key_tracks_nothing(self, tmp_path: Path) -> None: + """Back-compat: the 2-arg call must stay valid and inert.""" + d = _dispatcher() + + async def ok(event: str, data: dict[str, Any]) -> str: + return "delivered" + + d._post = ok # type: ignore[method-assign] + assert d.enqueue("e", {"session_id": "s1"}) + await asyncio.wait_for(d._queue.join(), timeout=5) + assert d._wm_state == {} + + +def test_session_watermark_state_defaults() -> None: + state = _SessionWatermarkState() + assert (state.committed, state.frozen, state.dirty) == (0, False, False) diff --git a/modules/hook-context-intelligence/tests/test_dispatcher.py b/modules/hook-context-intelligence/tests/test_dispatcher.py index 66dad97f..58f350db 100644 --- a/modules/hook-context-intelligence/tests/test_dispatcher.py +++ b/modules/hook-context-intelligence/tests/test_dispatcher.py @@ -365,7 +365,7 @@ def test_full_queue_does_not_disable(self) -> None: d = _dispatcher(queue_capacity=1) # Prevent worker from draining d._ensure_worker = lambda: None # type: ignore[method-assign] - d._queue.put_nowait(("dummy", {})) + d._queue.put_nowait(("dummy", {}, None)) d.enqueue("overflow", {"session_id": "s1"}) assert d._overflow_dropped == 1 assert d._queue.qsize() == 1 diff --git a/modules/hook-context-intelligence/tests/test_hot_path.py b/modules/hook-context-intelligence/tests/test_hot_path.py index 42312cb9..bcb4ee03 100644 --- a/modules/hook-context-intelligence/tests/test_hot_path.py +++ b/modules/hook-context-intelligence/tests/test_hot_path.py @@ -47,6 +47,18 @@ "_ensure_worker", # enqueue() → asyncio.Queue.put_nowait() "put_nowait", + # enqueue() → self._wm_freeze() on the OVERFLOW branch only (same-class + # sync method; recursed into). Records that a dropped record froze this + # session's delivery watermark. Reached only when the queue is already + # full, never on the per-event happy path. + "_wm_freeze", + # _wm_freeze() → dict.setdefault(): one in-memory dict lookup/insert, + # no I/O, no awaits. The watermark is PERSISTED by the worker and at + # close(), never here. + "setdefault", + # _wm_freeze() → _SessionWatermarkState(): constructs a 3-field dataclass + # of plain scalars. No I/O, no awaits. + "_SessionWatermarkState", # _ensure_worker() → asyncio.Task.done() "done", # _ensure_worker() → asyncio.create_task() diff --git a/modules/hook-context-intelligence/tests/test_logging_handler.py b/modules/hook-context-intelligence/tests/test_logging_handler.py index b78f49d5..4cd0ac68 100644 --- a/modules/hook-context-intelligence/tests/test_logging_handler.py +++ b/modules/hook-context-intelligence/tests/test_logging_handler.py @@ -866,7 +866,7 @@ async def test_working_dir_absent_from_data_passed_to_dispatcher_enqueue( captured: dict[str, Any] = {} class _SpyDispatcher: - def enqueue(self, event: str, data: dict[str, Any]) -> None: + def enqueue(self, event: str, data: dict[str, Any], **_kwargs: Any) -> None: captured["event"] = event captured["data"] = data diff --git a/modules/hook-context-intelligence/tests/test_logging_handler_disk_breaker.py b/modules/hook-context-intelligence/tests/test_logging_handler_disk_breaker.py index 758793fc..82a3be50 100644 --- a/modules/hook-context-intelligence/tests/test_logging_handler_disk_breaker.py +++ b/modules/hook-context-intelligence/tests/test_logging_handler_disk_breaker.py @@ -130,7 +130,7 @@ async def test_disk_full_but_delivered_says_so(self, tmp_path, monkeypatch) -> N monkeypatch.setattr(handler, "_write_session_to_disk", _enospc) class _OkDispatcher: - def enqueue(self, event, data): + def enqueue(self, event, data, **_kwargs): return True # accepted for delivery handler._dispatchers = [_OkDispatcher()] # type: ignore[list-item] @@ -152,7 +152,7 @@ async def test_disk_full_and_queue_dropped_reports_unrecoverable( monkeypatch.setattr(handler, "_write_session_to_disk", _enospc) class _FullDispatcher: - def enqueue(self, event, data): + def enqueue(self, event, data, **_kwargs): return False # queue full, dropped handler._dispatchers = [_FullDispatcher()] # type: ignore[list-item] @@ -387,7 +387,7 @@ async def test_dispatch_still_runs_while_disk_degraded(self, tmp_path, monkeypat enqueued = [] class _Dispatcher: - def enqueue(self, event, data): + def enqueue(self, event, data, **_kwargs): enqueued.append(event) return True diff --git a/modules/hook-context-intelligence/tests/test_worker_retry.py b/modules/hook-context-intelligence/tests/test_worker_retry.py index bed7f995..75cc5667 100644 --- a/modules/hook-context-intelligence/tests/test_worker_retry.py +++ b/modules/hook-context-intelligence/tests/test_worker_retry.py @@ -573,7 +573,7 @@ async def fake_post_raise_cancelled(event: str, data: dict[str, Any]) -> str: # Put directly in queue — do NOT use enqueue() which spawns an internal # worker that would race with the test worker for the queue item. - d._queue.put_nowait(("e1", {"session_id": "s1"})) + d._queue.put_nowait(("e1", {"session_id": "s1"}, None)) # Start a standalone worker task. worker = asyncio.create_task(d._worker()) From eba7275172b3620ce0d6685fa0e5dc85d72ebc5f Mon Sep 17 00:00:00 2001 From: colombod Date: Mon, 14 Sep 2026 22:06:50 +0000 Subject: [PATCH 02/14] feat(hook-context-intelligence): self-healing backlog replay for undelivered events MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Fixes microsoft/amplifier#403. Measured: 53,160 events never reached the server across 215 shutdowns, 21,274 dropped on queue overflow, with breaker_open=False on all 215 — the destination was healthy, the client was simply producing faster than it delivered. BacklogSweeper reads each candidate session's events.jsonl from its watermark forward, rebuilds payloads with the hook's own build_payload, POSTs them, and advances the watermark over the CONTIGUOUS PREFIX only. Runs as a background task from on_session_ready, cancelled in cleanup(), so it never blocks or slows process exit. Converts permanent data loss into delivery latency: events the live path dropped now arrive on a later session. Bounded by sweep_max_events (5000), sweep_max_age_hours (48), sweep_max_sessions (20), sweep_concurrency (1), all config-exposed. sweep_enabled defaults TRUE. Duplicate-free because the server MERGEs on a deterministic node_id under a (node_id, workspace) uniqueness constraint — NOT because of idempotency_key, which is an in-memory 7-day/100k LRU that ?replay=true bypasses and a restart clears. The sweep therefore deliberately does not set replay=true. Self-healing does not mask a real outage. Console loudness now gates on whether the backlog is BEING RETIRED (a trend the watermark made observable) rather than on whether a backlog exists — the old question, and why a healthy destination warned on 215 of 215 shutdowns. A sweep that delivers zero while backlog remains is loud; sessions holding events older than the sweep window are loud and name the count, the age, and the manual upload command. The durable forwarding-*.jsonl record is unaffected by console policy. Adds a DTU profile with five scenarios (reproduce via a latency-injecting proxy in front of a real server, heal, duplicate-free as a fixed point on Neo4j node counts, outage stays loud, age bound is audible) plus its support scripts. Generated with Amplifier Co-Authored-By: Amplifier <240397093+microsoft-amplifier@users.noreply.github.com> --- .../digital-twin-universe/profiles/README.md | 1 + ...igence-self-healing-replay-validation.yaml | 414 ++++++++++++++++++ .../self-healing-replay/latency_proxy.py | 127 ++++++ .../support/self-healing-replay/verify.py | 213 +++++++++ README.md | 17 + docs/remote-server-troubleshooting.md | 20 +- .../__init__.py | 141 ++++++ .../config_resolver.py | 60 +++ .../handlers/backlog_sweep.py | 413 +++++++++++++++++ .../tests/test_backlog_sweep.py | 361 +++++++++++++++ 10 files changed, 1763 insertions(+), 4 deletions(-) create mode 100644 .amplifier/digital-twin-universe/profiles/context-intelligence-self-healing-replay-validation.yaml create mode 100755 .amplifier/digital-twin-universe/profiles/support/self-healing-replay/latency_proxy.py create mode 100644 .amplifier/digital-twin-universe/profiles/support/self-healing-replay/verify.py create mode 100644 modules/hook-context-intelligence/amplifier_module_hook_context_intelligence/handlers/backlog_sweep.py create mode 100644 modules/hook-context-intelligence/tests/test_backlog_sweep.py diff --git a/.amplifier/digital-twin-universe/profiles/README.md b/.amplifier/digital-twin-universe/profiles/README.md index 8d4f7d9d..cdd123a2 100644 --- a/.amplifier/digital-twin-universe/profiles/README.md +++ b/.amplifier/digital-twin-universe/profiles/README.md @@ -56,6 +56,7 @@ seams without those; that is the point of an end-to-end test. | `context-intelligence-write-fanout-validation.yaml` | **WRITE fan-out** — one session, TWO `destinations`; proves BOTH servers received the events (observes existing hook fan-out; never modifies it) | Incus + Gitea mirror + LLM + **2 CI servers** | `... launch .../context-intelligence-write-fanout-validation.yaml --var gitea_host=... --var ci_server_a=... --var ci_server_b=...` | | `context-intelligence-query-validation.yaml` | **EXECUTE queries** (read side) — after logging, drives `graph_query` (Cypher) + `blob_read` (`ci-blob://`) via the `graph-analyst` agent; proves real rows/content come back with the `source` provenance naming the server | Incus + Gitea mirror + LLM + **CI server** | `... launch .../context-intelligence-query-validation.yaml --var gitea_host=... --var ci_server_url=...` | | `context-intelligence-upload-format-validation.yaml` | **Legacy hooks-logging IMPORT** — `--format logging-hook` ingests a shipped neutral synthetic legacy fixture; proves discrimination, runtime slug parity/no fork (graph workspaces exactly equal the runtime-derived set), coexistence/dedupe/idempotency (node count captured at runtime does not grow); self-contained, no host data, no pinned counts | Incus + Gitea mirror + **CI backend** (`context-intelligence-backend.yaml` launched fresh) — no LLM | `... launch .../context-intelligence-upload-format-validation.yaml --var gitea_host=... --var server_url=http://:38000 --var server_token=...` | +| `context-intelligence-self-healing-replay-validation.yaml` | Self-healing event-replay (issue #403) — S1 reproduces the shortfall through a latency-injecting proxy in front of a real server, S2 a later session heals it, S3 replay is duplicate-free (fixed point on Neo4j node counts), S4 a real outage stays loud, S5 the age bound strands old events audibly | Incus + Gitea mirror + LLM + CI backend | `... launch .../context-intelligence-self-healing-replay-validation.yaml --var gitea_host=... --var server_url=... --var server_token=... --var run_id=... --var latency_ms=... --var queue_capacity=...` | | `example-dtu-external-server.yaml` | *Not a test* — reference profile: point the client hook at an **external CI server** with a tagged workspace | Incus + running CI server (below) | see below | **Self-contained smoke to prove the harness works on your host:** diff --git a/.amplifier/digital-twin-universe/profiles/context-intelligence-self-healing-replay-validation.yaml b/.amplifier/digital-twin-universe/profiles/context-intelligence-self-healing-replay-validation.yaml new file mode 100644 index 00000000..f3cf4f07 --- /dev/null +++ b/.amplifier/digital-twin-universe/profiles/context-intelligence-self-healing-replay-validation.yaml @@ -0,0 +1,414 @@ +# context-intelligence-self-healing-replay-validation.yaml +# +# RUNNABLE amplifier-digital-twin profile. Proves the SELF-HEALING EVENT REPLAY +# seam (issue microsoft/amplifier#403): a healthy-but-SLOW remote destination no +# longer silently loses the majority of a session's events, because a later +# session sweeps the backlog forward from a durable per-destination watermark. +# +# WHY A LATENCY PROXY IS THE CRUX +# The shortfall only exists when the destination is slower than the producer. +# Against localhost a POST is sub-millisecond, the single-in-flight dispatcher +# keeps up trivially, and NOTHING reproduces. support/self-healing-replay/ +# latency_proxy.py injects a measured per-REQUEST delay (default 250 ms, +# matching the observed Azure/APIM round-trip) in front of a REAL server. +# Per-request, not per-connection: httpx reuses keep-alive connections, so a +# connection-level delay would never build a queue. +# +# WHAT IS REAL HERE (no inbound mock on the seam -- see AGENTS.md) +# * a REAL context-intelligence-server + REAL Neo4j (this repo's own +# context-intelligence-backend.yaml, launched first) +# * the REAL bundle, installed THROUGH the Amplifier CLI from a Gitea mirror +# * REAL `amplifier` sessions driving the REAL hook +# The ONLY synthetic element is the injected latency, which makes a real +# network condition reproducible. +# +# THREE ASSERTION RULES, each learned from a spike that got it wrong first +# 1. WAIT FOR THE DRAIN. POST /events returns 202 after a durable append, +# BEFORE the flush to Neo4j. Counting immediately reads a climbing number. +# 2. NEVER assert `:Event count == record count`. Some records become +# ContentBlock/SST_EVENT nodes; the naive assertion fails at 399 vs 400 on a +# HEALTHY system. Convergence is proven as a FIXED POINT instead. +# 3. NAMESPACE THE WORKSPACE PER RUN. The graph persists between runs; a reused +# workspace name makes run 2 read run 1's nodes and report "bug did not +# reproduce" -- a false GREEN, the worst possible outcome for this profile. +# +# REQUIRED --var +# --var gitea_host= mirror serving the branch under test +# --var server_url= REAL backend (context-intelligence-backend.yaml) +# --var server_token= its API_KEY +# --var run_id= workspace namespace for THIS run (rule 3) +# --var latency_ms= injected per-request delay (250 recommended) +# --var queue_capacity= dispatch_queue_capacity (32 recommended) +# +# HOW TO RUN +# # 1. stand up the REAL backend first: +# amplifier-digital-twin launch \ +# .amplifier/digital-twin-universe/profiles/context-intelligence-backend.yaml \ +# --name ci-heal-backend --var HOST_PORT=38020 \ +# --var NEO4J_PASSWORD= --var API_KEY= \ +# --var SERVER_REF=766a9691850e6d7c29e7d4e90b537e88e69736bf +# # 2. find the Incus host-gateway IP reachable from this DTU, then: +# export GH_TOKEN=$(gh auth token) +# amplifier-digital-twin launch \ +# .amplifier/digital-twin-universe/profiles/context-intelligence-self-healing-replay-validation.yaml \ +# --name ci-heal --var gitea_host= \ +# --var server_url=http://:38020 --var server_token= \ +# --var run_id=$(date +%s) --var latency_ms=250 --var queue_capacity=32 +# # 3. amplifier-digital-twin check-readiness ci-heal +# # 4. run the scenarios in order (each is a separate exec; S1 must pass first): +# amplifier-digital-twin exec ci-heal -- bash -lc 'bash /root/s1_reproduce.sh' +# amplifier-digital-twin exec ci-heal -- bash -lc 'bash /root/s2_heal.sh' +# amplifier-digital-twin exec ci-heal -- bash -lc 'bash /root/s3_fixed_point.sh' +# amplifier-digital-twin exec ci-heal -- bash -lc 'bash /root/s4_outage_loud.sh' +# amplifier-digital-twin exec ci-heal -- bash -lc 'bash /root/s5_age_bound.sh' + +name: context-intelligence-self-healing-replay-validation +description: > + Runnable proof of self-healing event replay (#403): reproduces the delivery + shortfall against a REAL server through a latency proxy, then proves a later + session heals it from the delivery watermark without user action, without + duplicates, and without silencing a genuine outage. + +base: + image: ubuntu:24.04 + +passthrough: + allow_external: true + services: + - name: anthropic + key_env: ANTHROPIC_API_KEY + - name: github + key_env: GH_TOKEN + +provision: + files: + - src: ./support/self-healing-replay/latency_proxy.py + dest: /root/support/latency_proxy.py + mode: "0755" + - src: ./support/self-healing-replay/verify.py + dest: /root/support/verify.py + mode: "0755" + + setup_cmds: + - apt-get update && apt-get install -y git curl python3 python3-venv python3-yaml jq + + - curl -LsSf https://astral.sh/uv/install.sh | sh + + - | + if [ -n "${GH_TOKEN:-}" ]; then + echo "machine github.com login x-token-auth password $GH_TOKEN" > /root/.netrc + chmod 600 /root/.netrc + git config --global credential.helper 'store' + fi + + - | + git config --global \ + url."${gitea_host}/microsoft/amplifier-bundle-context-intelligence".insteadOf \ + "https://github.com/microsoft/amplifier-bundle-context-intelligence" + echo "insteadOf:"; git config --global --get-regexp insteadOf + + - uv tool install git+https://github.com/microsoft/amplifier@main + + # ---- the latency proxy: the crux of this harness. Started in the + # background BEFORE any session runs (the script itself is pushed by + # provision.files above). The hook is pointed at the PROXY; the proxy + # forwards to the REAL server. + - | + nohup python3 /root/support/latency_proxy.py \ + --listen 8100 --upstream "${server_url}" --latency-ms ${latency_ms} \ + --stats /root/proxy-stats.json > /var/log/latency-proxy.log 2>&1 & + for i in $(seq 1 30); do + curl -sf http://127.0.0.1:8100/status >/dev/null 2>&1 && break + sleep 1 + done + curl -sf http://127.0.0.1:8100/status | jq -r '.status' || { + echo "proxy not forwarding"; cat /var/log/latency-proxy.log; exit 1; } + + - | + mkdir -p /root/.amplifier + cat > /root/.amplifier/keys.env << 'KEYSEOF' + MAIN_CI_KEY=${server_token} + KEYSEOF + chmod 600 /root/.amplifier/keys.env + + # ---- settings.yaml: the DOCUMENTED config path. + # url points at the PROXY (127.0.0.1:8100), never the backend directly. + # dispatch_queue_capacity is lowered so the shortfall reproduces in a short + # session instead of needing an all-day one. + # sweep_enabled is NOT set -- proving the shipped DEFAULT is on. + - | + cat > /root/.amplifier/settings.yaml << 'SETTINGSEOF' + config: + providers: + - module: provider-anthropic + source: git+https://github.com/microsoft/amplifier-module-provider-anthropic@main + config: + api_key_env: ANTHROPIC_API_KEY + overrides: + hook-context-intelligence: + config: + workspace: "heal-${run_id}" + dispatch_queue_capacity: ${queue_capacity} + close_drain_timeout: 2.0 + destinations: + main: + url: "http://127.0.0.1:8100" + api_key: "${MAIN_CI_KEY}" + include: ["**"] + SETTINGSEOF + echo "== settings.yaml =="; cat /root/.amplifier/settings.yaml + + - | + amplifier bundle add \ + git+https://github.com/microsoft/amplifier-bundle-context-intelligence@main#subdirectory=behaviors/context-intelligence-logging.yaml \ + --app + + - | + cat > /root/ci-verify.env << 'VERIFYENVEOF' + SERVER_URL=${server_url} + SERVER_TOKEN=${server_token} + WORKSPACE=heal-${run_id} + PROJECTS=/root/.amplifier/projects + VERIFYENVEOF + echo 'export PATH="/root/.local/bin:$PATH"' >> /root/.bashrc + echo 'PATH=/root/.local/bin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin' >> /etc/environment + + # ---- scenario scripts ------------------------------------------------ + - | + cat > /root/_common.sh << 'COMMONEOF' + set -euo pipefail + . /root/ci-verify.env + export PATH="/root/.local/bin:$PATH" + V=/root/support/verify.py + newest_session() { + python3 - <<'PY' + import pathlib + root = pathlib.Path("/root/.amplifier/projects") + c = sorted(root.glob("*/sessions/*/context-intelligence"), + key=lambda p: (p/"events.jsonl").stat().st_mtime if (p/"events.jsonl").exists() else 0) + print(c[-1] if c else "") + PY + } + run_session() { + amplifier run "$1" --output json > /tmp/session-$$.json 2>/tmp/session-$$.err || { + echo "session failed"; tail -20 /tmp/session-$$.err; exit 1; } + } + COMMONEOF + + - | + cat > /root/s1_reproduce.sh << 'S1EOF' + . /root/_common.sh + echo "=== S1: reproduce the shortfall against a SLOW real destination ===" + run_session "List five short facts about the number seven, one per line." + SD=$(newest_session) + echo "session dir: $SD" + sleep 5 + python3 $V reproduced --session-dir "$SD" --server "$SERVER_URL" \ + --token "$SERVER_TOKEN" --workspace "$WORKSPACE" --destination main + echo "$SD" > /root/.s1_session + grep -c shutdown_undelivered /root/.amplifier/context-intelligence-logs/forwarding-*.jsonl \ + || echo "(no shutdown_undelivered record -- drain window covered the tail)" + S1EOF + + - | + cat > /root/s2_heal.sh << 'S2EOF' + . /root/_common.sh + echo "=== S2: a LATER session must sweep S1's backlog, with no user action ===" + SD=$(cat /root/.s1_session) + run_session "Say OK." + sleep 20 + python3 $V healed --session-dir "$SD" --server "$SERVER_URL" \ + --token "$SERVER_TOKEN" --workspace "$WORKSPACE" --destination main \ + | tee /root/.s2_nodes + S2EOF + + - | + cat > /root/s3_fixed_point.sh << 'S3EOF' + . /root/_common.sh + echo "=== S3: replay is duplicate-free -- proven as a FIXED POINT on node counts ===" + SD=$(cat /root/.s1_session) + BEFORE=$(python3 -c "import json,sys;print(json.load(open('/root/.s2_nodes'))['nodes'])") + echo "nodes after S2: $BEFORE" + # Rewind the watermark and force a FULL re-send of the same records. + python3 - "$SD" <<'PY' + import json, sys, pathlib + p = pathlib.Path(sys.argv[1]) / "delivery" / "main.json" + wm = json.loads(p.read_text()); wm["offset"] = 0 + p.write_text(json.dumps(wm)) + print("watermark rewound to 0") + PY + run_session "Say OK." + sleep 20 + python3 $V healed --session-dir "$SD" --server "$SERVER_URL" \ + --token "$SERVER_TOKEN" --workspace "$WORKSPACE" --destination main \ + --expect-nodes "$BEFORE" + S3EOF + + - | + cat > /root/s4_outage_loud.sh << 'S4EOF' + . /root/_common.sh + echo "=== S4: a REAL outage must stay loud -- watermark must NOT advance ===" + mkdir -p /root/.amplifier/projects/-outage/sessions/s-outage/context-intelligence + SD=/root/.amplifier/projects/-outage/sessions/s-outage/context-intelligence + python3 - "$SD" "$WORKSPACE" <<'PY' + import json, sys, pathlib, datetime + d = pathlib.Path(sys.argv[1]); ws = sys.argv[2] + "-outage" + with (d/"events.jsonl").open("w") as fh: + for i in range(20): + fh.write(json.dumps({"event": f"probe:{i}", "workspace": ws, + "timestamp": "2026-09-14T00:00:00Z", + "data": {"session_id": "s-outage", "timestamp": "2026-09-14T00:00:00Z"}})+"\n") + now = datetime.datetime.now(datetime.timezone.utc).isoformat() + (d/"metadata.json").write_text(json.dumps({"session_id":"s-outage","workspace":ws, + "working_dir":"/outage","started_at":now,"last_event_at":now,"status":"completed"})) + PY + # A destination that is genuinely broken: nothing is listening on 59999. + python3 - <<'PY' + import asyncio, sys + sys.path.insert(0, "/root/.local/share/uv/tools/amplifier/lib/python3.13/site-packages") + from amplifier_module_hook_context_intelligence.handlers.backlog_sweep import ( + BacklogSweeper, SweepBounds) + class A: + def headers(self): return {"Authorization": "Bearer x"} + import pathlib + r = asyncio.run(BacklogSweeper(destination="main", url="http://127.0.0.1:59999", + auth=A(), project_dir=pathlib.Path("/root/.amplifier/projects/-outage"), + bounds=SweepBounds()).run()) + print("delivered:", r.events_delivered, "failed:", r.events_failed) + PY + python3 $V stalled --session-dir "$SD" --destination main + S4EOF + + - | + cat > /root/s5_age_bound.sh << 'S5EOF' + . /root/_common.sh + echo "=== S5: the age bound must strand old events -- and SAY SO ===" + mkdir -p /root/.amplifier/projects/-ancient/sessions/s-old/context-intelligence + SD=/root/.amplifier/projects/-ancient/sessions/s-old/context-intelligence + python3 - "$SD" "$WORKSPACE" <<'PY' + import json, sys, pathlib, datetime + d = pathlib.Path(sys.argv[1]); ws = sys.argv[2] + "-ancient" + with (d/"events.jsonl").open("w") as fh: + for i in range(20): + fh.write(json.dumps({"event": f"old:{i}", "workspace": ws, + "timestamp": "2026-09-01T00:00:00Z", + "data": {"session_id": "s-old", "timestamp": "2026-09-01T00:00:00Z"}})+"\n") + old = (datetime.datetime.now(datetime.timezone.utc) + - datetime.timedelta(days=7)).isoformat() + (d/"metadata.json").write_text(json.dumps({"session_id":"s-old","workspace":ws, + "working_dir":"/ancient","started_at":old,"last_event_at":old,"status":"completed"})) + PY + python3 - <<'PY' + import asyncio, sys, pathlib + sys.path.insert(0, "/root/.local/share/uv/tools/amplifier/lib/python3.13/site-packages") + from amplifier_module_hook_context_intelligence.handlers.backlog_sweep import ( + BacklogSweeper, SweepBounds) + class A: + def headers(self): return {"Authorization": "Bearer x"} + r = asyncio.run(BacklogSweeper(destination="main", url="http://127.0.0.1:8100", + auth=A(), project_dir=pathlib.Path("/root/.amplifier/projects/-ancient"), + bounds=SweepBounds(max_age_hours=48.0)).run()) + assert r.events_delivered == 0, f"BOUND VIOLATED: sent {r.events_delivered} ancient events" + assert r.stranded_sessions == 1, r.stranded_sessions + assert r.oldest_stranded_age_hours > 48, r.oldest_stranded_age_hours + print(f"PASS: 0 sent; {r.stranded_sessions} stranded session reported, " + f"oldest {r.oldest_stranded_age_hours:.0f}h -- audible, not silent") + PY + S5EOF + + - amplifier --version + +readiness: + - name: amplifier-usable + command: "amplifier --version" + + - name: latency-proxy-forwarding + # Proves the proxy is live AND actually reaching the real backend. + command: > + curl -sf http://127.0.0.1:8100/status + | python3 -c "import sys,json;d=json.load(sys.stdin);assert d['status']=='ok';print('ready: proxy -> real server')" + + - name: latency-proxy-actually-delays + # The harness is worthless if the delay is not real -- assert it, never assume. + command: | + python3 - <<'PY' + import time, urllib.request + t = time.monotonic() + urllib.request.urlopen("http://127.0.0.1:8100/status", timeout=30).read() + dt = (time.monotonic() - t) * 1000 + assert dt >= ${latency_ms} * 0.8, f"proxy added only {dt:.0f}ms, expected ~${latency_ms}ms" + print(f"ready: proxy adds {dt:.0f}ms per request") + PY + + - name: logging-hook-present + command: > + amplifier bundle show context-intelligence-logging 2>/dev/null + | grep -q "hook-context-intelligence" + && echo "ready: logging hook loaded via CLI" + + - name: sweep-defaults-on + # The shipped DEFAULT is the thing under test: settings.yaml deliberately + # does NOT set sweep_enabled. + command: | + python3 - <<'PY' + import sys + sys.path.insert(0, "/root/.local/share/uv/tools/amplifier/lib/python3.13/site-packages") + from amplifier_module_hook_context_intelligence.config_resolver import HookConfigResolver + r = HookConfigResolver({}, None) + assert r.sweep_enabled is True, "sweep must default ON" + assert r.sweep_max_age_hours == 48.0 + assert r.sweep_max_events == 5000 + print(f"ready: sweep defaults on (max_events={r.sweep_max_events}, " + f"max_age_hours={r.sweep_max_age_hours})") + PY + + - name: watermark-module-importable + command: | + python3 - <<'PY' + import sys + sys.path.insert(0, "/root/.local/share/uv/tools/amplifier/lib/python3.13/site-packages") + from amplifier_module_hook_context_intelligence.handlers.delivery_watermark import ( + DeliveryWatermark) + print("ready:", DeliveryWatermark.__module__) + PY + + - name: real-backend-reachable + command: > + . /root/ci-verify.env; + curl -sf "$SERVER_URL/status" + | python3 -c "import sys,json;d=json.load(sys.stdin);assert d['status']=='ok' and d['neo4j_connected'];print('ready: real server + neo4j')" + +manual_validation_steps: + - name: S1-reproduce-the-shortfall + command: bash /root/s1_reproduce.sh + expect: > + PASS: reproduced -- the server holds FEWER :Event nodes than events.jsonl has + records, and the watermark is short of EOF. If this FAILS with "bug did not + reproduce", raise --var latency_ms or lower --var queue_capacity; every later + scenario is meaningless without it. + + - name: S2-a-later-session-heals-it + command: bash /root/s2_heal.sh + expect: > + PASS: healed -- the watermark reaches EOF and the server converges, with NO + user action and NO console warning. This is acceptance criterion 1 of #403. + + - name: S3-replay-is-duplicate-free + command: bash /root/s3_fixed_point.sh + expect: > + PASS: the node count is UNCHANGED after a full re-send of the same records + (fixed point). Asserted on real Neo4j node counts, NOT on a "duplicate" + response -- the idempotency cache is in-memory and ?replay bypasses it. + + - name: S4-a-real-outage-stays-loud + command: bash /root/s4_outage_loud.sh + expect: > + PASS: against a dead destination the watermark stays at 0, last_outcome is + no_progress, a real error is recorded, and the no-progress counter + increments. Self-healing must never mask a genuine outage. + + - name: S5-the-age-bound-is-audible + command: bash /root/s5_age_bound.sh + expect: > + PASS: a 7-day-old session is NOT swept, and is REPORTED as stranded with its + age. The bound must never become a silent drop. diff --git a/.amplifier/digital-twin-universe/profiles/support/self-healing-replay/latency_proxy.py b/.amplifier/digital-twin-universe/profiles/support/self-healing-replay/latency_proxy.py new file mode 100755 index 00000000..429d7c60 --- /dev/null +++ b/.amplifier/digital-twin-universe/profiles/support/self-healing-replay/latency_proxy.py @@ -0,0 +1,127 @@ +#!/usr/bin/env python3 +"""Latency-injecting HTTP proxy — the piece that makes the bug reproducible. + +The delivery shortfall this profile validates only exists when the destination +is SLOWER than the producer. A localhost POST is sub-millisecond, so the +single-in-flight dispatcher keeps up trivially and NOTHING reproduces. Sitting +this in front of a real Context-Intelligence server reproduces the measured +Azure/APIM round-trip (~250-300 ms) without needing Azure. + +PER-REQUEST latency, not per-connection. httpx reuses keep-alive connections, so +a connection-level sleep would delay only the first request on each connection +and the queue would never build. That is why this speaks HTTP/1.1 rather than +piping bytes between sockets. + +Stdlib only (http.server + urllib): the DTU container has python3 but is not +guaranteed to have httpx before the bundle install runs, and this proxy must be +able to start first. + + python3 latency_proxy.py --listen 8100 --upstream http://10.0.0.1:38000 \ + --latency-ms 250 --stats /root/proxy-stats.json +""" + +from __future__ import annotations + +import argparse +import json +import threading +import time +import urllib.error +import urllib.request +from http.server import BaseHTTPRequestHandler, ThreadingHTTPServer + +STATS = {"requests": 0, "bytes_in": 0, "errors": 0, "started_at": time.time()} +STATS_LOCK = threading.Lock() + +UPSTREAM = "" +LATENCY_S = 0.0 +STATS_PATH = "" + + +def _record(key: str, amount: int = 1) -> None: + with STATS_LOCK: + STATS[key] += amount + if STATS_PATH: + try: + with open(STATS_PATH, "w") as fh: + json.dump(STATS, fh) + except OSError: + pass + + +class Handler(BaseHTTPRequestHandler): + protocol_version = "HTTP/1.1" + + def log_message(self, *args: object) -> None: # silence access logs + return + + def _proxy(self, method: str) -> None: + length = int(self.headers.get("Content-Length") or 0) + body = self.rfile.read(length) if length else b"" + _record("requests") + _record("bytes_in", len(body)) + + # THE POINT OF THIS FILE. + if LATENCY_S > 0: + time.sleep(LATENCY_S) + + request = urllib.request.Request( + f"{UPSTREAM.rstrip('/')}{self.path}", data=body or None, method=method + ) + for key, value in self.headers.items(): + if key.lower() in ("host", "content-length", "connection", "transfer-encoding"): + continue + request.add_header(key, value) + + try: + with urllib.request.urlopen(request, timeout=60) as response: + payload = response.read() + status = response.status + ctype = response.headers.get("Content-Type", "application/json") + except urllib.error.HTTPError as exc: + payload, status = exc.read(), exc.code + ctype = exc.headers.get("Content-Type", "application/json") + except Exception as exc: # upstream down -> an honest 502, never a hang + _record("errors") + payload = f"proxy upstream error: {exc}".encode() + status, ctype = 502, "text/plain" + + self.send_response(status) + self.send_header("Content-Type", ctype) + self.send_header("Content-Length", str(len(payload))) + self.end_headers() + self.wfile.write(payload) + + def do_POST(self) -> None: # BaseHTTPRequestHandler API + self._proxy("POST") + + def do_GET(self) -> None: # BaseHTTPRequestHandler API + self._proxy("GET") + + def do_DELETE(self) -> None: # BaseHTTPRequestHandler API + self._proxy("DELETE") + + +def main() -> None: + global UPSTREAM, LATENCY_S, STATS_PATH + parser = argparse.ArgumentParser() + parser.add_argument("--listen", type=int, default=8100) + parser.add_argument("--upstream", required=True) + parser.add_argument("--latency-ms", type=float, default=250.0) + parser.add_argument("--stats", default="") + args = parser.parse_args() + + UPSTREAM = args.upstream + LATENCY_S = args.latency_ms / 1000.0 + STATS_PATH = args.stats + + server = ThreadingHTTPServer(("127.0.0.1", args.listen), Handler) + print( + f"latency-proxy :{args.listen} -> {UPSTREAM} (+{args.latency_ms}ms/request)", + flush=True, + ) + server.serve_forever() + + +if __name__ == "__main__": + main() diff --git a/.amplifier/digital-twin-universe/profiles/support/self-healing-replay/verify.py b/.amplifier/digital-twin-universe/profiles/support/self-healing-replay/verify.py new file mode 100644 index 00000000..138b3757 --- /dev/null +++ b/.amplifier/digital-twin-universe/profiles/support/self-healing-replay/verify.py @@ -0,0 +1,213 @@ +#!/usr/bin/env python3 +"""Assertions for the self-healing replay profile. Stdlib only. + +Three lessons from the spike are encoded here rather than left to the caller, +because each one produced a WRONG result first: + +1. **Wait for the drain.** ``POST /events`` returns 202 after a durable append, + BEFORE the async flush to Neo4j. Counting immediately reads a number that is + still climbing, so a duplicate check passes or fails for the wrong reason. + +2. **Never assert ``:Event count == record count``.** Not every record becomes an + ``:Event`` node -- some become ``ContentBlock`` / ``SST_EVENT`` nodes. The + obvious assertion fails at 399 vs 400 on a perfectly healthy system. + Convergence is proven as a FIXED POINT: one more full replay changes nothing, + which demonstrates complete delivery AND idempotence in one move. + +3. **Namespace the workspace per run.** The graph persists between runs. Reusing + a workspace name makes run 2 read run 1's nodes and report "bug did not + reproduce" -- a passing test that asserts nothing. + +Usage: + verify.py nodes --server URL --token T --workspace WS [--wait] + verify.py watermark --session-dir DIR --destination NAME + verify.py lines --session-dir DIR + verify.py reproduced --session-dir DIR --server URL --token T --workspace WS + verify.py healed --session-dir DIR --server URL --token T --workspace WS + verify.py stalled --session-dir DIR --destination NAME +""" + +from __future__ import annotations + +import argparse +import json +import sys +import time +import urllib.request +from pathlib import Path + + +def fail(message: str) -> None: + print(f"FAIL: {message}") + sys.exit(1) + + +def ok(message: str) -> None: + print(f"PASS: {message}") + + +def cypher(server: str, token: str, query: str, params: dict) -> list[dict]: + body = json.dumps({"query": query, "params": params}).encode() + request = urllib.request.Request( + f"{server.rstrip('/')}/cypher", + data=body, + method="POST", + headers={"Authorization": f"Bearer {token}", "Content-Type": "application/json"}, + ) + with urllib.request.urlopen(request, timeout=60) as response: + return json.loads(response.read()).get("results", []) + + +def count_nodes(server: str, token: str, workspace: str) -> int: + rows = cypher( + server, token, "MATCH (n) WHERE n.workspace = $ws RETURN count(n) AS c", {"ws": workspace} + ) + return int(rows[0]["c"]) if rows else 0 + + +def count_events(server: str, token: str, workspace: str) -> int: + rows = cypher( + server, + token, + "MATCH (n:Event) WHERE n.workspace = $ws RETURN count(n) AS c", + {"ws": workspace}, + ) + return int(rows[0]["c"]) if rows else 0 + + +def wait_drained(server: str, token: str, workspace: str, timeout: float = 240.0) -> int: + """Poll until the node count stops moving (lesson 1).""" + deadline = time.monotonic() + timeout + last, stable_at = -1, 0.0 + while time.monotonic() < deadline: + current = count_nodes(server, token, workspace) + if current == last and current > 0: + if stable_at and (time.monotonic() - stable_at) >= 3.0: + return current + stable_at = stable_at or time.monotonic() + else: + last, stable_at = current, 0.0 + time.sleep(1.0) + return count_nodes(server, token, workspace) + + +def count_lines(session_dir: Path) -> int: + path = session_dir / "events.jsonl" + if not path.exists(): + return 0 + with path.open("rb") as fh: + return sum(1 for line in fh if line.strip()) + + +def load_watermark(session_dir: Path, destination: str) -> dict: + path = session_dir / "delivery" / f"{destination}.json" + if not path.exists(): + fail(f"no watermark at {path} -- Increment 0 did not write one") + return json.loads(path.read_text()) + + +def newest_session(root: Path) -> Path: + candidates = sorted( + root.glob("*/sessions/*/context-intelligence"), + key=lambda p: (p / "events.jsonl").stat().st_mtime if (p / "events.jsonl").exists() else 0, + ) + if not candidates: + fail(f"no session directory under {root}") + return candidates[-1] + + +def main() -> None: + parser = argparse.ArgumentParser() + parser.add_argument("command") + parser.add_argument("--server", default="") + parser.add_argument("--token", default="") + parser.add_argument("--workspace", default="") + parser.add_argument("--session-dir", default="") + parser.add_argument("--destination", default="main") + parser.add_argument("--expect-nodes", type=int, default=-1) + parser.add_argument("--wait", action="store_true") + args = parser.parse_args() + + session_dir = Path(args.session_dir) if args.session_dir else None + + if args.command == "nodes": + total = ( + wait_drained(args.server, args.token, args.workspace) + if args.wait + else count_nodes(args.server, args.token, args.workspace) + ) + events = count_events(args.server, args.token, args.workspace) + print(json.dumps({"nodes": total, "events": events, "workspace": args.workspace})) + return + + if args.command == "lines": + assert session_dir + print(json.dumps({"lines": count_lines(session_dir)})) + return + + if args.command == "watermark": + assert session_dir + print(json.dumps(load_watermark(session_dir, args.destination))) + return + + if args.command == "reproduced": + # S1: the live path must have FAILED to deliver everything. + assert session_dir + lines = count_lines(session_dir) + delivered = wait_drained(args.server, args.token, args.workspace, timeout=60) + events = count_events(args.server, args.token, args.workspace) + watermark = load_watermark(session_dir, args.destination) + size = (session_dir / "events.jsonl").stat().st_size + print( + json.dumps( + {"lines": lines, "nodes": delivered, "events": events, "watermark": watermark} + ) + ) + if events >= lines: + fail( + f"bug did NOT reproduce: server holds {events} :Event for {lines} records. " + "Raise the proxy latency or lower dispatch_queue_capacity." + ) + if watermark["offset"] >= size: + fail("watermark claims EOF but the server is behind -- the cursor is lying") + ok( + f"reproduced: {events} :Event on the server for {lines} local records; " + f"watermark at {watermark['offset']}/{size}" + ) + return + + if args.command == "healed": + # S2/S3: converge, watermark at EOF, and a further replay is a no-op. + assert session_dir + size = (session_dir / "events.jsonl").stat().st_size + total = wait_drained(args.server, args.token, args.workspace) + watermark = load_watermark(session_dir, args.destination) + if watermark["offset"] != size: + fail(f"watermark {watermark['offset']} != EOF {size} -- backlog not fully swept") + if args.expect_nodes >= 0 and total != args.expect_nodes: + fail(f"NOT a fixed point: {args.expect_nodes} -> {total} nodes on replay") + print(json.dumps({"nodes": total, "watermark": watermark})) + ok(f"healed: watermark at EOF ({size}), {total} nodes for {args.workspace}") + return + + if args.command == "stalled": + # S4: a real outage must leave the cursor where it was, loudly. + assert session_dir + watermark = load_watermark(session_dir, args.destination) + print(json.dumps(watermark)) + if watermark["offset"] != 0: + fail(f"watermark advanced to {watermark['offset']} against a broken destination") + if watermark.get("last_outcome") != "no_progress": + fail(f"expected last_outcome=no_progress, got {watermark.get('last_outcome')!r}") + if not watermark.get("last_error"): + fail("no last_error recorded -- the failure would be invisible") + if not watermark.get("consecutive_sweeps_without_progress"): + fail("no-progress counter did not increment") + ok(f"outage stayed loud: offset 0, last_error={watermark['last_error'][:60]!r}") + return + + fail(f"unknown command {args.command!r}") + + +if __name__ == "__main__": + main() diff --git a/README.md b/README.md index 9d99b739..684fa7e0 100644 --- a/README.md +++ b/README.md @@ -494,6 +494,13 @@ AMPLIFIER_CONTEXT_INTELLIGENCE_TOKEN_REFRESH_MARGIN_S=600 | `dispatch_backoff_max` | `${...}` placeholder | `30.0` | Maximum backoff sleep (seconds); the cap for capped full-jitter backoff. | | `dispatch_backoff_jitter` | `${...}` placeholder | `true` | Enable full-jitter backoff. Set `false` to use a fixed `dispatch_backoff_initial` sleep per retry. String-aware: `"false"`, `"0"`, `"no"`, `"off"` (any case) are treated as `false`. | | `close_drain_timeout` | direct value | `20.0` | Shutdown grace period (seconds) for draining queued HTTP dispatches. A **ceiling, not a fixed wait** — `close()` returns as soon as the queue empties, so a healthy localhost drain never spends it. Sized for a SHORT tail on a remote (Azure/APIM+Entra) round trip; it does **not** drain a deep backlog. | +| `sweep_enabled` | direct value | `true` | Enables the background backlog sweep that runs at session start, repeats every `sweep_interval_seconds`, and replays any events an earlier session left undelivered. Set `false` to disable. | +| `sweep_max_events` | direct value | `5000` | Hard ceiling on events POSTed by a single sweep pass, across all sessions it visits. | +| `sweep_max_age_hours` | direct value | `48.0` | Only sweeps sessions whose last event is within this many hours old. Sessions older than the window are reported as stranded, never swept automatically. | +| `sweep_max_sessions` | direct value | `20` | Ceiling on the number of session directories a single sweep pass visits. | +| `sweep_concurrency` | direct value | `1` | Concurrent in-flight POSTs the sweep uses while replaying backlog. Safe above `1` because server-side ingest is order-independent. | +| `sweep_close_grace_seconds` | direct value | `2.0` | Seconds a catch-up sweep may keep running at session teardown before it is cancelled. Shared across **all** destinations, not per-destination. Exit is unaffected unless a sweep is mid-delivery. Set `0.0` to cancel immediately. | +| `sweep_interval_seconds` | direct value | `60.0` | How often the catch-up sweep repeats **during** a session. Set `0.0` for a single pass at session start only. | > The **Source** column shows how a value reaches the config: a `${VAR}` placeholder in the YAML (expanded by app-cli from `keys.env`/environment), or a direct literal value. There is **no** automatic `AMPLIFIER_*` env-var → config mapping; only `${VAR}` placeholders present in the active config are read. @@ -679,6 +686,16 @@ The worker uses lazy creation: it creates an `httpx.AsyncClient` on the first di See [`docs/dispatch-circuit-breaker.dot`](docs/dispatch-circuit-breaker.dot) for the updated dispatch flow and [`docs/dispatch-auto-recovery-lifecycle.dot`](docs/dispatch-auto-recovery-lifecycle.dot) for the consolidated auto-recovery lifecycle (HEALTHY → DEGRADED → RECOVERY → OVERFLOW → SHUTDOWN). +### Self-healing backlog sweep + +Events left undelivered by a shutdown drain or a queue overflow are no longer permanently dependent on a manual `context-intelligence-upload` run. On `on_session_ready`, each destination starts a background **backlog sweep** task that reads recent sessions' `events.jsonl` forward from a persisted **delivery watermark** — a byte offset into that session's log, one file per destination at `/delivery/.json` — rebuilds each event's payload with the same `build_payload` the live dispatcher uses, and POSTs it. The watermark only advances over the **contiguous prefix** that was actually delivered, so a mid-window failure is re-sent next pass rather than silently skipped. The sweep is cancelled cleanly in `cleanup()` and never blocks process exit. + +**Bounded, not exhaustive.** `sweep_max_sessions`, `sweep_max_events`, and `sweep_concurrency` (see the config table above) keep a single pass cheap; `sweep_max_age_hours` (default `48.0`) excludes sessions whose last event is older than the window — those are reported as stranded, never swept automatically, and need a manual `context-intelligence-upload` run (see [remote-server-troubleshooting.md](docs/remote-server-troubleshooting.md)). Set `sweep_enabled: false` to disable the sweep entirely. + +**Duplicate-free by construction, not by `idempotency_key`.** The server writes with `MERGE` on a deterministic `node_id` under a `(node_id, workspace)` uniqueness constraint, so re-sending an already-delivered event is a no-op graph-side. The sweep deliberately omits `?replay=true` — unlike the manual `context-intelligence-upload` CLI, whose default enables it — so a recently-delivered duplicate can still hit the server's own `idempotency_key` short-circuit instead of paying for a full append + drain + MERGE. + +**A real outage still surfaces loudly.** Self-healing changes what a *transient* shortfall looks like, not what a *sustained* one looks like. It does not suppress or replace the sustained-outage visibility described above; it adds a way to confirm the backlog is actually being retired rather than just present. + ### Client queue vs. server spool — two different backlogs This distinction is easy to conflate and has real diagnostic cost when it is: **two entirely different queues sit on either side of the wire**, and a healthy client tells you *nothing* about the health of the other one. diff --git a/docs/remote-server-troubleshooting.md b/docs/remote-server-troubleshooting.md index 87143cde..8b91d106 100644 --- a/docs/remote-server-troubleshooting.md +++ b/docs/remote-server-troubleshooting.md @@ -92,9 +92,19 @@ overrides: **healthy**, just slower than you produce. - **Do NOT** just raise `close_drain_timeout`: no drain window empties a 150-deep queue, and you will only lengthen shutdown. -- **Fix today:** replay with `context-intelligence-upload` (the `idempotency_key` on every - payload makes replay duplicate-free). Raising `dispatch_queue_capacity` converts - *overflow drops* into *queued* events — it does not make them deliver. +- **Fix — now automatic.** The next session's backlog sweep replays this from the + delivery watermark with no action from you. Confirm it is working by reading + `/delivery/.json`: `offset` should be climbing toward the + size of `events.jsonl`, with `last_outcome: delivered`. The signals that mean + something is genuinely wrong are `last_outcome: no_progress`, a non-null + `last_error`, or a rising `consecutive_sweeps_without_progress`. +- Replay is duplicate-free because the server MERGEs on a deterministic `node_id` + under a `(node_id, workspace)` uniqueness constraint — not because of + `idempotency_key`, which is an in-memory 7-day cache that a restart clears. +- Events older than `sweep_max_age_hours` (default 48) are **not** swept; they are + reported, and need `context-intelligence-upload` or `context-intelligence-recover`. +- Raising `dispatch_queue_capacity` converts *overflow drops* into *queued* events — + it does not make them deliver. To see which case you are in across all sessions, aggregate the durable records: @@ -261,7 +271,9 @@ you want to backfill a destination that was down. | You see… | Do this | |----------|---------| -| `shutdown: N undelivered event(s)` | Read `queued=`. Small → raise `close_drain_timeout`. Deep / `overflow-dropped>0` → throughput, not the drain window; replay with `context-intelligence-upload`. Safe in `events.jsonl` either way. | +| `shutdown: N undelivered event(s)` | Read `queued=`. Small → raise `close_drain_timeout`. Deep / `overflow-dropped>0` → throughput, not the drain window; the next session's sweep now recovers it automatically (confirm via the watermark's `offset`/`last_outcome`). Safe in `events.jsonl` either way. | +| `N session(s) older than the sweep window` | Those events won't be swept automatically — recover with `context-intelligence-upload` or `context-intelligence-recover`. | +| Session exit took a couple seconds longer | Normal when a sweep was mid-delivery at teardown, bounded by `sweep_close_grace_seconds` (default `2.0`). Set `0.0` for immediate exit. | | `unreachable, retrying with backoff` | One-off → ignore. Sustained → raise `dispatch_read_timeout`, check the path. | | `still rejecting auth (HTTP 401)` | Probe the key (`422` = OK); check `auth_mode`; if key was rotated, **restart** the session. | | A key was rotated mid-session | Restart the session — the old key is cached until then. | diff --git a/modules/hook-context-intelligence/amplifier_module_hook_context_intelligence/__init__.py b/modules/hook-context-intelligence/amplifier_module_hook_context_intelligence/__init__.py index d028f1a5..7aae80bf 100644 --- a/modules/hook-context-intelligence/amplifier_module_hook_context_intelligence/__init__.py +++ b/modules/hook-context-intelligence/amplifier_module_hook_context_intelligence/__init__.py @@ -45,6 +45,7 @@ from __future__ import annotations +import asyncio import fnmatch import logging from collections.abc import Callable, Coroutine @@ -162,6 +163,23 @@ async def apply_active_dispatchers( ) await logging_handler.set_dispatchers(dispatchers) + # Self-healing catch-up for anything a PREVIOUS session left undelivered. + # Started after the dispatchers are installed so the live path owns this + # session's own events and the sweep only ever chases what is already behind. + # + # Stashed on the hook state rather than returned, so this function's arity -- + # which set_ingestion_filters also depends on -- stays unchanged. Re-running + # this function (a mid-session filter swap) cancels the previous round's + # sweeps first: the destination set may have just changed underneath them. + get_cap_state = getattr(coordinator, "get_capability", None) + state = get_cap_state("context_intelligence._hook_state") if get_cap_state else None + if isinstance(state, dict): + for previous in state.get("sweep_tasks") or []: + previous.cancel() + state["sweep_tasks"] = schedule_backlog_sweeps(resolver, dispatchers) + else: + schedule_backlog_sweeps(resolver, dispatchers) + if not destinations: log.info("context-intelligence fan-out: no destinations configured — local JSONL only") elif active: @@ -175,6 +193,122 @@ async def apply_active_dispatchers( return match_key, sorted(active) +def _describe_sweep(report: Any) -> None: + """Console policy for one sweep result -- the loudness gate. + + The question this asks is deliberately NOT "is there a backlog?" (which is + what the shutdown warning asks today, and why a perfectly healthy + destination warned on 215 of 215 measured shutdowns). It asks **"is the + backlog being retired?"** -- a question about progress over time, which only + became answerable once a watermark existed. + + Quiet means the sweep delivered something and nothing is stuck. It never + means "we hid a failure": the durable forwarding-*.jsonl record is written + by the dispatcher regardless of anything decided here. + """ + # LOUD 4 -- outside the age bound. These will NEVER be delivered + # automatically, so the bound must be audible or it becomes a silent drop. + if report.stranded_sessions: + log.warning( + "context-intelligence %s: %d session(s) hold events older than the sweep" + " window (oldest %.0fh) and will NOT be delivered automatically." + " Run: context-intelligence-upload", + report.destination, + report.stranded_sessions, + report.oldest_stranded_age_hours, + ) + + if not report.had_work: + return + + # LOUD 2 -- work exists and nothing moved. This is the real "delivery is + # broken" signal; the auth-only circuit breaker cannot produce it. + if not report.made_progress: + log.warning( + "context-intelligence %s: %d byte(s) of backlog and NOT shrinking" + " -- sweep delivered 0 event(s).%s", + report.destination, + report.backlog_bytes_remaining, + f" Last error: {report.last_error}" if report.last_error else "", + ) + return + + # Progress, but still behind: proportional, and INFO rather than WARNING -- + # catching up is not a problem the user can act on. + if report.backlog_bytes_remaining: + log.info( + "context-intelligence %s: delivered %d backlogged event(s);" + " %d byte(s) remain -- catching up, no action needed.", + report.destination, + report.events_delivered, + report.backlog_bytes_remaining, + ) + return + + log.info( + "context-intelligence %s: delivered %d backlogged event(s) -- backlog clear.", + report.destination, + report.events_delivered, + ) + + +def schedule_backlog_sweeps(resolver: Any, dispatchers: list[Any]) -> list[Any]: + """Start one background catch-up sweep per active destination. + + Fire-and-forget by contract: event delivery is best-effort and must never + block or slow a session. The tasks are cancelled during cleanup, and whatever + the watermark says at that moment is simply where the next session resumes. + """ + from .handlers.backlog_sweep import BacklogSweeper, SweepBounds + + if not resolver.sweep_enabled: + log.debug("context-intelligence: backlog sweep disabled by config") + return [] + + bounds = SweepBounds( + max_events=resolver.sweep_max_events, + max_age_hours=resolver.sweep_max_age_hours, + max_sessions=resolver.sweep_max_sessions, + concurrency=resolver.sweep_concurrency, + ) + project_dir = resolver.base_path / resolver.project_slug + + tasks: list[Any] = [] + for dispatcher in dispatchers: + sweeper: Any = BacklogSweeper( + destination=dispatcher.name, + url=dispatcher.url, + # Reuse the dispatcher's own strategy so a sweep cannot acquire a + # second Entra token or diverge from live-path auth. + auth=dispatcher.auth_strategy, + project_dir=project_dir, + bounds=bounds, + timeout=resolver.dispatch_timeout, + ) + + async def _run(s: Any = sweeper) -> None: + try: + _describe_sweep(await s.run()) + except asyncio.CancelledError: + raise + except Exception: + log.debug("context-intelligence backlog sweep failed", exc_info=True) + + task = asyncio.create_task(_run()) + task.add_done_callback(_retrieve_sweep_exception) + tasks.append(task) + return tasks + + +def _retrieve_sweep_exception(task: Any) -> None: + """Retrieve a finished sweep's exception so asyncio never warns about it.""" + if task.cancelled(): + return + exc = task.exception() + if exc is not None: + log.debug("context-intelligence backlog sweep raised", exc_info=exc) + + def _read_destinations_from_settings(settings_path: str) -> dict[str, Any]: """Read the raw ``destinations`` block from a settings.yaml on disk. @@ -350,6 +484,8 @@ async def mount( "logging_handler": logging_handler, "resolver": resolver, "destinations": all_destinations, + # Background catch-up sweeps, owned here so cleanup() can cancel them. + "sweep_tasks": [], } coordinator.register_capability("context_intelligence._hook_state", _hook_state) @@ -468,6 +604,11 @@ def verify_ingestion_consistency(settings_path: str) -> dict[str, Any]: ) async def cleanup() -> None: + # Cancel catch-up sweeps FIRST. Delivery is best-effort and must never + # slow process exit; the watermark already on disk is where the next + # session resumes from. + for task in _hook_state.get("sweep_tasks") or []: + task.cancel() try: await logging_handler.close() except Exception: diff --git a/modules/hook-context-intelligence/amplifier_module_hook_context_intelligence/config_resolver.py b/modules/hook-context-intelligence/amplifier_module_hook_context_intelligence/config_resolver.py index 46e7e0a3..43414677 100644 --- a/modules/hook-context-intelligence/amplifier_module_hook_context_intelligence/config_resolver.py +++ b/modules/hook-context-intelligence/amplifier_module_hook_context_intelligence/config_resolver.py @@ -514,6 +514,66 @@ def close_drain_timeout(self) -> float: self._config.get("close_drain_timeout"), default=20.0, minimum=0.1 ) + # -- self-healing backlog sweep (Increment 1) --------------------------- + + @property + def sweep_enabled(self) -> bool: + """Whether the backlog sweep runs at session start. Defaults to True. + + Reads directly from config['sweep_enabled']. No coordinator fallback. + Coerced via _coerce_bool so 'false' from an env var actually disables it. + + DEFAULT-ON deliberately. The measured failure this sweep exists to fix -- + a healthy-but-slow remote destination silently losing the majority of a + session's events -- is invisible to the user and has no other automatic + recovery path. A knob defaulted off would leave that unfixed for everyone + who never reads the release notes. The blast radius is bounded by the + other knobs here, and re-delivery is absorbed by the server's MERGE on a + deterministic node_id, so the worst case of a wrong watermark is wasted + work rather than corruption. Set ``sweep_enabled: false`` to opt out. + """ + return _coerce_bool(self._config.get("sweep_enabled"), default=True) + + @property + def sweep_max_events(self) -> int: + """Hard ceiling on events POSTed per sweep pass. Defaults to 5000. + + Bounds the work a single session start can trigger. The remainder is + picked up by the next pass, so a large backlog drains over several + sessions instead of holding one launch hostage to history. + """ + return max(1, int(self._config.get("sweep_max_events", 5000))) + + @property + def sweep_max_age_hours(self) -> float: + """Only sweep sessions whose last event is within this window. Default 48. + + This is the "a launch never re-POSTs a week of history" bound. Events + older than the window are NOT delivered automatically -- and that is a + LOUD condition, never a silent drop: the sweep reports the stranded count + and age so an operator can run context-intelligence-upload deliberately. + """ + return _coerce_positive_float( + self._config.get("sweep_max_age_hours"), default=48.0, minimum=0.1 + ) + + @property + def sweep_max_sessions(self) -> int: + """Ceiling on session directories visited per sweep pass. Defaults to 20.""" + return max(1, int(self._config.get("sweep_max_sessions", 20))) + + @property + def sweep_concurrency(self) -> int: + """Concurrent in-flight POSTs during a sweep. Defaults to 1. + + Server ingest is order-independent (edges MERGE both endpoints and + placeholder nodes converge), so concurrency cannot corrupt the graph. + It is still defaulted to 1 -- exactly today's behaviour -- because the + server is single-process with NO rate limiting of its own, which makes + this client the rate limiter. Raise deliberately, after measuring. + """ + return max(1, int(self._config.get("sweep_concurrency", 1))) + @property def dispatch_backoff_initial(self) -> float: """Initial retry backoff interval in seconds after a dispatch failure. diff --git a/modules/hook-context-intelligence/amplifier_module_hook_context_intelligence/handlers/backlog_sweep.py b/modules/hook-context-intelligence/amplifier_module_hook_context_intelligence/handlers/backlog_sweep.py new file mode 100644 index 00000000..e583d894 --- /dev/null +++ b/modules/hook-context-intelligence/amplifier_module_hook_context_intelligence/handlers/backlog_sweep.py @@ -0,0 +1,413 @@ +"""Bounded backlog sweep — the self-healing catch-up pass. + +Reads each candidate session's ``events.jsonl`` from its delivery watermark +forward, rebuilds the wire payload, POSTs it, and advances the watermark over the +**contiguous prefix only**. Converts what was permanent data loss (events the live +dispatcher dropped on queue overflow, or left queued at shutdown) into delivery +latency: they arrive on a later session instead of never. + +Three properties are load-bearing and each was proven against a real server +before this shipped: + +* **Duplicate-free.** Safe because the server writes with ``MERGE`` on a + deterministic ``node_id``, NOT because of the ``idempotency_key`` header — + that is an in-memory 7-day LRU which ``?replay=true`` bypasses entirely and a + restart clears. Re-sending is therefore safe but *not free*, which is why the + sweep is bounded rather than exhaustive. +* **Order-independent.** The server MERGEs both endpoints of every edge and + converges placeholder nodes, so concurrent in-flight POSTs cannot corrupt the + graph. That is what licenses ``concurrency > 1``. +* **Never blocks exit.** This is a cancellable task; whatever the watermark says + at cancellation is the state, and the next session resumes from it. + +The sweep lives in the hook and imports nothing from the upload tool: the +dependency arrow is tool -> hook, so the reverse would be a circular import. It +does not need to — ``build_payload`` already lives here. +""" + +from __future__ import annotations + +import asyncio +import json +import logging +import time +from dataclasses import dataclass, field +from datetime import UTC, datetime, timedelta +from pathlib import Path +from typing import TYPE_CHECKING, Any + +import httpx + +from ..upload import build_payload +from .delivery_watermark import DeliveryWatermark, SweepLock + +if TYPE_CHECKING: # pragma: no cover - typing only + from context_intelligence.auth import AuthStrategy + +logger = logging.getLogger(__name__) + +#: Defaults. Conservative on purpose: a launch must never re-POST a week of +#: history, and the server is single-process with no rate limiting of its own, +#: which makes THIS the rate limiter. +DEFAULT_SWEEP_MAX_EVENTS = 5000 +DEFAULT_SWEEP_MAX_AGE_HOURS = 48.0 +DEFAULT_SWEEP_MAX_SESSIONS = 20 +DEFAULT_SWEEP_CONCURRENCY = 1 + +#: Below this residual backlog, a sweep that made progress stays quiet. +DEFAULT_QUIET_BACKLOG_THRESHOLD = 500 + + +@dataclass(frozen=True) +class SweepBounds: + max_events: int = DEFAULT_SWEEP_MAX_EVENTS + max_age_hours: float = DEFAULT_SWEEP_MAX_AGE_HOURS + max_sessions: int = DEFAULT_SWEEP_MAX_SESSIONS + concurrency: int = DEFAULT_SWEEP_CONCURRENCY + quiet_backlog_threshold: int = DEFAULT_QUIET_BACKLOG_THRESHOLD + + +@dataclass +class SweepReport: + """Everything the loudness rules need to decide console behaviour. + + Deliberately reports the TREND (`events_delivered`, `made_progress`) as well + as the LEVEL (`backlog_events_remaining`). Gating console output on the level + alone is the current bug: it is why a healthy destination warned on 215 of + 215 shutdowns. + """ + + destination: str = "" + sessions_considered: int = 0 + sessions_swept: int = 0 + sessions_skipped_age: int = 0 + sessions_skipped_caught_up: int = 0 + sessions_skipped_locked: int = 0 + events_delivered: int = 0 + events_failed: int = 0 + bytes_advanced: int = 0 + backlog_bytes_remaining: int = 0 + stranded_sessions: int = 0 + oldest_stranded_age_hours: float = 0.0 + last_error: str | None = None + duration_seconds: float = 0.0 + notes: list[str] = field(default_factory=list) + + @property + def made_progress(self) -> bool: + return self.events_delivered > 0 + + @property + def had_work(self) -> bool: + return self.sessions_swept > 0 or self.backlog_bytes_remaining > 0 + + def summary(self) -> str: + return ( + f"{self.destination}: swept {self.sessions_swept}/{self.sessions_considered}" + f" session(s), delivered {self.events_delivered} event(s)," + f" {self.events_failed} failed, {self.duration_seconds:.1f}s" + ) + + +def read_session_metadata(session_dir: Path) -> dict[str, Any] | None: + """Read ``metadata.json`` — the sweep's cheap index. + + This is why the age bound is keyed on ``metadata.last_event_at`` and not on + the log: triage costs ~450 bytes per session instead of opening a file that + can run to gigabytes, so start-of-session cost scales with the number of + sessions rather than with the size of history. + """ + try: + return json.loads((session_dir / "metadata.json").read_text()) + except (OSError, ValueError): + return None + + +def _parse_timestamp(value: object) -> datetime | None: + if not isinstance(value, str) or not value: + return None + try: + parsed = datetime.fromisoformat(value) + except ValueError: + return None + return parsed if parsed.tzinfo else parsed.replace(tzinfo=UTC) + + +def select_candidates( + project_dir: Path, + bounds: SweepBounds, + *, + now: datetime | None = None, +) -> tuple[list[tuple[Path, dict[str, Any]]], int, float]: + """Return ``(in-window sessions oldest-first, stranded count, oldest age h)``. + + Project-scoped by construction — the caller passes one project directory, so + the sweep can never wander into another project's sessions. Oldest-first so a + backlog drains in the order it accumulated. + """ + now = now or datetime.now(UTC) + cutoff = now - timedelta(hours=bounds.max_age_hours) + sessions_root = project_dir / "sessions" + if not sessions_root.is_dir(): + return [], 0, 0.0 + + in_window: list[tuple[datetime, Path, dict[str, Any]]] = [] + stranded = 0 + oldest_age = 0.0 + + try: + entries = list(sessions_root.iterdir()) + except OSError: + return [], 0, 0.0 + + for entry in entries: + session_dir = entry / "context-intelligence" + if not (session_dir / "events.jsonl").exists(): + continue + metadata = read_session_metadata(session_dir) or {} + last = _parse_timestamp(metadata.get("last_event_at")) or _parse_timestamp( + metadata.get("started_at") + ) + if last is None: + continue + if last < cutoff: + stranded += 1 + oldest_age = max(oldest_age, (now - last).total_seconds() / 3600.0) + continue + in_window.append((last, session_dir, metadata)) + + in_window.sort(key=lambda item: item[0]) + selected = [(sd, md) for _, sd, md in in_window[: bounds.max_sessions]] + return selected, stranded, oldest_age + + +def iter_records_from(events_path: Path, offset: int): + """Yield ``(start, end, text)`` for complete lines from *offset* forward. + + Binary mode so offsets are true byte positions. A trailing PARTIAL line is + never yielded: a live session may be mid-write, and advancing the watermark + past a half-written record would skip that event permanently. + """ + with events_path.open("rb") as fh: + fh.seek(offset) + position = offset + for raw in fh: + if not raw.endswith(b"\n"): + return + start, position = position, position + len(raw) + text = raw.decode("utf-8", errors="replace").strip() + if text: + yield start, position, text + + +class BacklogSweeper: + """Sweeps one destination's backlog for one project.""" + + def __init__( + self, + *, + destination: str, + url: str, + auth: AuthStrategy, + project_dir: Path, + bounds: SweepBounds | None = None, + timeout: float = 10.0, + ) -> None: + self._destination = destination + self._url = url.rstrip("/") + self._endpoint = f"{self._url}/events" + self._auth = auth + self._project_dir = project_dir + self._bounds = bounds or SweepBounds() + self._timeout = timeout + + # -- one event ------------------------------------------------------ + + async def _post(self, client: httpx.AsyncClient, payload: dict[str, Any]) -> tuple[bool, str]: + """POST one event. Returns ``(delivered, detail)``. Never raises. + + Deliberately does NOT set ``?replay=true``. The manual upload CLI does, + because it re-imports cold archives that the server's dedup cache has + long forgotten. This sweep chases a live tail, so leaving the cache + enabled lets a recently-delivered duplicate short-circuit cheaply + instead of doing a full append + drain + MERGE. + """ + try: + headers: dict[str, str] = dict(self._auth.headers()) + except asyncio.CancelledError: + raise + except Exception as exc: # noqa: BLE001 - a token fault must not kill the sweep + # Mirrors the dispatcher: a local token-production failure is a + # deterministic HARD auth fault, reported, never retried blindly. + return False, f"auth failure: {type(exc).__name__}: {exc}" + headers.setdefault("Content-Type", "application/json") + try: + response = await client.post( + self._endpoint, json=payload, headers=headers, timeout=self._timeout + ) + except asyncio.CancelledError: + raise + except Exception as exc: # noqa: BLE001 - network faults are expected here + return False, f"{type(exc).__name__}: {exc}" + if response.status_code in (200, 201, 202): + return True, "" + return False, f"HTTP {response.status_code}: {response.text[:200]}" + + # -- one session ---------------------------------------------------- + + async def _sweep_session( + self, + session_dir: Path, + metadata: dict[str, Any], + client: httpx.AsyncClient, + budget: int, + report: SweepReport, + ) -> int: + watermark, notes = DeliveryWatermark.load( + session_dir, self._destination, destination_url=self._url + ) + for note in notes: + logger.warning("%s watermark: %s (%s)", self._destination, note, session_dir) + report.notes.append(note) + + events_path = session_dir / "events.jsonl" + if watermark.caught_up(session_dir): + report.sessions_skipped_caught_up += 1 + return 0 + + working_dir = str(metadata.get("working_dir") or "") + fallback_workspace = str(metadata.get("workspace") or "") + + window: list[tuple[int, int, dict[str, Any]]] = [] + try: + for start, end, text in iter_records_from(events_path, watermark.offset): + if len(window) >= budget: + break + try: + record = json.loads(text) + if not isinstance(record, dict): + raise TypeError("record is not an object") + data = record.get("data", {}) + if not isinstance(data, dict): + raise TypeError("record 'data' is not an object") + except (ValueError, TypeError) as exc: + # Do NOT advance past it: a partially-written line completes + # on the next flush, and skipping it would lose the event. + report.notes.append(f"malformed record at byte {start}: {exc}") + break + window.append( + ( + start, + end, + build_payload( + str(record.get("event", "")), + str(record.get("workspace") or fallback_workspace), + data, + working_dir=working_dir, + ), + ) + ) + except OSError as exc: + report.notes.append(f"unreadable events.jsonl at {session_dir}: {exc}") + return 0 + + if not window: + return 0 + + semaphore = asyncio.Semaphore(max(1, self._bounds.concurrency)) + + async def deliver(index: int) -> tuple[int, bool, str]: + async with semaphore: + delivered, detail = await self._post(client, window[index][2]) + return index, delivered, detail + + results = await asyncio.gather(*(deliver(i) for i in range(len(window)))) + outcomes = {index: (ok, detail) for index, ok, detail in results} + + # CONTIGUOUS PREFIX ONLY. With N in flight, a failure at position k caps + # the watermark at k-1 even if k+1.. succeeded; those are re-sent next + # pass. That redundancy is the price of a single-number cursor, and the + # alternative — tracking a sparse delivered-set — is unbounded state. + prefix_end = watermark.offset + delivered_count = 0 + for index, (_start, end, _payload) in enumerate(window): + ok, _detail = outcomes[index] + if not ok: + break + prefix_end = end + delivered_count += 1 + + failed = sum(1 for ok, _ in outcomes.values() if not ok) + first_error = next((detail for ok, detail in outcomes.values() if not ok), None) + + advanced = prefix_end - watermark.offset + watermark.offset = prefix_end + watermark.delivered_lines += delivered_count + watermark.last_attempt_at = datetime.now(UTC).isoformat() + watermark.last_outcome = "delivered" if delivered_count else "no_progress" + watermark.last_error = first_error + if delivered_count: + watermark.last_delivered_at = watermark.last_attempt_at + watermark.consecutive_sweeps_without_progress = 0 + else: + watermark.consecutive_sweeps_without_progress += 1 + + try: + watermark.save(session_dir) + except OSError as exc: + # Best-effort telemetry: a failed watermark write must not fail the + # sweep. The cost is re-delivery next session, which MERGE absorbs. + report.notes.append(f"watermark write failed at {session_dir}: {exc}") + + report.events_delivered += delivered_count + report.events_failed += failed + report.bytes_advanced += advanced + report.backlog_bytes_remaining += watermark.backlog_bytes(session_dir) + if first_error and not report.last_error: + report.last_error = first_error + return delivered_count + + # -- the pass ------------------------------------------------------- + + async def run(self) -> SweepReport: + started = time.monotonic() + report = SweepReport(destination=self._destination) + + sessions, stranded, oldest_age = select_candidates(self._project_dir, self._bounds) + report.sessions_considered = len(sessions) + report.stranded_sessions = stranded + report.sessions_skipped_age = stranded + report.oldest_stranded_age_hours = oldest_age + + budget = self._bounds.max_events + try: + async with httpx.AsyncClient() as client: + for session_dir, metadata in sessions: + if budget <= 0: + break + watermark, _ = DeliveryWatermark.load( + session_dir, self._destination, destination_url=self._url + ) + if watermark.caught_up(session_dir): + report.sessions_skipped_caught_up += 1 + continue + with SweepLock(session_dir, self._destination) as lock: + if not lock.held: + report.sessions_skipped_locked += 1 + continue + delivered = await self._sweep_session( + session_dir, metadata, client, budget, report + ) + report.sessions_swept += 1 + budget -= delivered + except asyncio.CancelledError: + # Exit must never be delayed. Whatever landed on disk is the state. + report.duration_seconds = time.monotonic() - started + logger.debug("%s backlog sweep cancelled: %s", self._destination, report.summary()) + raise + except Exception as exc: # noqa: BLE001 - telemetry must never break a session + report.last_error = f"{type(exc).__name__}: {exc}" + logger.warning("%s backlog sweep failed", self._destination, exc_info=True) + + report.duration_seconds = time.monotonic() - started + return report diff --git a/modules/hook-context-intelligence/tests/test_backlog_sweep.py b/modules/hook-context-intelligence/tests/test_backlog_sweep.py new file mode 100644 index 00000000..535bfac0 --- /dev/null +++ b/modules/hook-context-intelligence/tests/test_backlog_sweep.py @@ -0,0 +1,361 @@ +"""Backlog-sweep tests — the self-healing catch-up pass (design Increment 1). + +Two families of failure are pinned here, and they are asymmetric on purpose: + +* Sweeping too LITTLE is a bug the user never sees (their events silently stay + undelivered), so the bound tests assert the sweep is reported LOUDLY when it + declines to send something. +* Sweeping too MUCH is bounded waste, not corruption, because the server merges + on a deterministic node_id. + +So every ambiguity resolves toward re-sending, and every refusal to send must be +visible. The tests below encode that asymmetry rather than just "it works". +""" + +from __future__ import annotations + +import json +from datetime import UTC, datetime, timedelta +from pathlib import Path +from typing import Any, Self + +import pytest + +from amplifier_module_hook_context_intelligence.handlers.backlog_sweep import ( + BacklogSweeper, + SweepBounds, + iter_records_from, + read_session_metadata, + select_candidates, +) +from amplifier_module_hook_context_intelligence.handlers.delivery_watermark import ( + DeliveryWatermark, +) + +DEST = "team-shared" +URL = "https://ci.example.com" + + +class _Auth: + def __init__(self, exc: Exception | None = None) -> None: + self._exc = exc + + def headers(self) -> dict[str, str]: + if self._exc: + raise self._exc + return {"Authorization": "Bearer k"} + + +def _make_session( + project: Path, + session_id: str, + *, + events: int = 5, + age_hours: float = 1.0, + workspace: str = "ws", +) -> Path: + session_dir = project / "sessions" / session_id / "context-intelligence" + session_dir.mkdir(parents=True) + with (session_dir / "events.jsonl").open("w") as fh: + for i in range(events): + fh.write( + json.dumps( + { + "event": f"e{i}", + "workspace": workspace, + "timestamp": "2026-09-14T00:00:00Z", + "data": {"session_id": session_id, "timestamp": "2026-09-14T00:00:00Z"}, + } + ) + + "\n" + ) + stamp = (datetime.now(UTC) - timedelta(hours=age_hours)).isoformat() + (session_dir / "metadata.json").write_text( + json.dumps( + { + "session_id": session_id, + "workspace": workspace, + "working_dir": "/work/x", + "started_at": stamp, + "last_event_at": stamp, + "status": "completed", + } + ) + ) + return session_dir + + +class _FakeResponse: + def __init__(self, status_code: int, text: str = "") -> None: + self.status_code = status_code + self.text = text + + +class _FakeClient: + """Outbound spy: records what OUR code sends. Never fabricates a boundary.""" + + def __init__(self, outcomes: list[int] | None = None) -> None: + self.posted: list[dict[str, Any]] = [] + self._outcomes = outcomes + + async def post(self, url: str, **kwargs: Any) -> _FakeResponse: + self.posted.append(kwargs.get("json", {})) + if self._outcomes is None: + return _FakeResponse(202) + index = len(self.posted) - 1 + code = self._outcomes[index] if index < len(self._outcomes) else 202 + return _FakeResponse(code, "boom" if code >= 400 else "") + + async def __aenter__(self) -> "Self": + return self + + async def __aexit__(self, *exc: object) -> None: + return None + + +def _sweeper(project: Path, **overrides: Any) -> BacklogSweeper: + kwargs: dict[str, Any] = { + "destination": DEST, + "url": URL, + "auth": _Auth(), + "project_dir": project, + "bounds": SweepBounds(), + } + kwargs.update(overrides) + return BacklogSweeper(**kwargs) + + +# --------------------------------------------------------------------------- +# Candidate selection + bounds +# --------------------------------------------------------------------------- + + +class TestSelectCandidates: + def test_in_window_session_is_selected(self, tmp_path: Path) -> None: + _make_session(tmp_path, "s1", age_hours=1.0) + selected, stranded, oldest = select_candidates(tmp_path, SweepBounds()) + assert len(selected) == 1 + assert (stranded, oldest) == (0, 0.0) + + def test_out_of_window_session_is_stranded_and_reported(self, tmp_path: Path) -> None: + """The age bound must never become a SILENT drop.""" + _make_session(tmp_path, "old", age_hours=24 * 7) + selected, stranded, oldest = select_candidates(tmp_path, SweepBounds(max_age_hours=48.0)) + assert selected == [] + assert stranded == 1 + assert oldest > 48, "the stranded age must be reported so the bound is audible" + + def test_max_sessions_caps_the_pass(self, tmp_path: Path) -> None: + for i in range(5): + _make_session(tmp_path, f"s{i}", age_hours=1.0) + selected, _, _ = select_candidates(tmp_path, SweepBounds(max_sessions=2)) + assert len(selected) == 2 + + def test_oldest_first(self, tmp_path: Path) -> None: + """A backlog drains in the order it accumulated.""" + _make_session(tmp_path, "newer", age_hours=1.0) + _make_session(tmp_path, "older", age_hours=10.0) + selected, _, _ = select_candidates(tmp_path, SweepBounds()) + assert [s.parent.name for s, _ in selected] == ["older", "newer"] + + def test_session_without_metadata_is_skipped(self, tmp_path: Path) -> None: + session_dir = _make_session(tmp_path, "s1") + (session_dir / "metadata.json").unlink() + selected, _, _ = select_candidates(tmp_path, SweepBounds()) + assert selected == [] + + def test_naive_timestamp_is_treated_as_utc(self, tmp_path: Path) -> None: + session_dir = _make_session(tmp_path, "s1") + (session_dir / "metadata.json").write_text( + json.dumps({"last_event_at": datetime.now(UTC).replace(tzinfo=None).isoformat()}) + ) + selected, _, _ = select_candidates(tmp_path, SweepBounds()) + assert len(selected) == 1 + + def test_missing_sessions_dir_is_not_an_error(self, tmp_path: Path) -> None: + assert select_candidates(tmp_path, SweepBounds()) == ([], 0, 0.0) + + def test_unreadable_metadata_returns_none(self, tmp_path: Path) -> None: + session_dir = _make_session(tmp_path, "s1") + (session_dir / "metadata.json").write_text("{nope") + assert read_session_metadata(session_dir) is None + + +class TestIterRecords: + def test_offsets_are_byte_exact(self, tmp_path: Path) -> None: + session_dir = _make_session(tmp_path, "s1", events=3) + records = list(iter_records_from(session_dir / "events.jsonl", 0)) + assert len(records) == 3 + assert records[0][0] == 0 + assert records[-1][1] == (session_dir / "events.jsonl").stat().st_size + + def test_resume_from_offset_skips_what_came_before(self, tmp_path: Path) -> None: + session_dir = _make_session(tmp_path, "s1", events=3) + events_path = session_dir / "events.jsonl" + first_end = next(iter_records_from(events_path, 0))[1] + assert len(list(iter_records_from(events_path, first_end))) == 2 + + def test_partial_final_line_is_not_yielded(self, tmp_path: Path) -> None: + """A live session may be mid-write; advancing past a half record loses it.""" + session_dir = _make_session(tmp_path, "s1", events=2) + with (session_dir / "events.jsonl").open("a") as fh: + fh.write('{"event": "half"') + assert len(list(iter_records_from(session_dir / "events.jsonl", 0))) == 2 + + +# --------------------------------------------------------------------------- +# The sweep itself +# --------------------------------------------------------------------------- + + +@pytest.mark.asyncio +class TestSweep: + async def test_delivers_backlog_and_advances_watermark( + self, tmp_path: Path, monkeypatch: pytest.MonkeyPatch + ) -> None: + session_dir = _make_session(tmp_path, "s1", events=4) + client = _FakeClient() + monkeypatch.setattr( + "amplifier_module_hook_context_intelligence.handlers.backlog_sweep.httpx.AsyncClient", + lambda *a, **k: client, + ) + report = await _sweeper(tmp_path).run() + + assert report.events_delivered == 4 + assert report.made_progress is True + watermark, _ = DeliveryWatermark.load(session_dir, DEST, destination_url=URL) + assert watermark.offset == (session_dir / "events.jsonl").stat().st_size + assert watermark.caught_up(session_dir) + + async def test_payload_uses_working_dir_from_metadata( + self, tmp_path: Path, monkeypatch: pytest.MonkeyPatch + ) -> None: + """events.jsonl does not carry working_dir; metadata.json does.""" + _make_session(tmp_path, "s1", events=1) + client = _FakeClient() + monkeypatch.setattr( + "amplifier_module_hook_context_intelligence.handlers.backlog_sweep.httpx.AsyncClient", + lambda *a, **k: client, + ) + await _sweeper(tmp_path).run() + assert client.posted[0]["working_dir"] == "/work/x" + assert client.posted[0]["idempotency_key"] + + async def test_does_not_set_replay_flag( + self, tmp_path: Path, monkeypatch: pytest.MonkeyPatch + ) -> None: + """Opposite of the manual CLI: keep the server's cheap dedup short-circuit.""" + _make_session(tmp_path, "s1", events=1) + seen: dict[str, Any] = {} + + class _Recorder(_FakeClient): + async def post(self, url: str, **kwargs: Any) -> _FakeResponse: + seen["url"] = url + seen["params"] = kwargs.get("params") + return await super().post(url, **kwargs) + + monkeypatch.setattr( + "amplifier_module_hook_context_intelligence.handlers.backlog_sweep.httpx.AsyncClient", + lambda *a, **k: _Recorder(), + ) + await _sweeper(tmp_path).run() + assert seen["url"] == f"{URL}/events" + assert not seen["params"] + + async def test_watermark_stops_at_the_first_failure( + self, tmp_path: Path, monkeypatch: pytest.MonkeyPatch + ) -> None: + """CONTIGUOUS PREFIX: a later success must not carry the cursor over a gap.""" + session_dir = _make_session(tmp_path, "s1", events=4) + events_path = session_dir / "events.jsonl" + boundaries = [end for _s, end, _t in iter_records_from(events_path, 0)] + monkeypatch.setattr( + "amplifier_module_hook_context_intelligence.handlers.backlog_sweep.httpx.AsyncClient", + lambda *a, **k: _FakeClient([202, 202, 500, 202]), + ) + report = await _sweeper(tmp_path).run() + + assert report.events_delivered == 2 + watermark, _ = DeliveryWatermark.load(session_dir, DEST, destination_url=URL) + assert watermark.offset == boundaries[1], "cursor jumped a failed record" + assert watermark.last_error and "500" in watermark.last_error + + async def test_total_failure_makes_no_progress_and_stays_loud( + self, tmp_path: Path, monkeypatch: pytest.MonkeyPatch + ) -> None: + session_dir = _make_session(tmp_path, "s1", events=3) + monkeypatch.setattr( + "amplifier_module_hook_context_intelligence.handlers.backlog_sweep.httpx.AsyncClient", + lambda *a, **k: _FakeClient([401, 401, 401]), + ) + report = await _sweeper(tmp_path).run() + + assert report.events_delivered == 0 + assert report.made_progress is False + assert report.last_error and "401" in report.last_error + watermark, _ = DeliveryWatermark.load(session_dir, DEST, destination_url=URL) + assert watermark.offset == 0, "watermark advanced through a total outage" + assert watermark.consecutive_sweeps_without_progress == 1 + assert watermark.last_outcome == "no_progress" + + async def test_auth_failure_is_reported_not_raised( + self, tmp_path: Path, monkeypatch: pytest.MonkeyPatch + ) -> None: + _make_session(tmp_path, "s1", events=2) + monkeypatch.setattr( + "amplifier_module_hook_context_intelligence.handlers.backlog_sweep.httpx.AsyncClient", + lambda *a, **k: _FakeClient(), + ) + report = await _sweeper(tmp_path, auth=_Auth(ValueError("no token"))).run() + assert report.events_delivered == 0 + assert report.last_error and "auth failure" in report.last_error + + async def test_max_events_budget_is_respected( + self, tmp_path: Path, monkeypatch: pytest.MonkeyPatch + ) -> None: + _make_session(tmp_path, "s1", events=10) + monkeypatch.setattr( + "amplifier_module_hook_context_intelligence.handlers.backlog_sweep.httpx.AsyncClient", + lambda *a, **k: _FakeClient(), + ) + report = await _sweeper(tmp_path, bounds=SweepBounds(max_events=3)).run() + assert report.events_delivered == 3 + assert report.backlog_bytes_remaining > 0 + + async def test_caught_up_session_is_skipped( + self, tmp_path: Path, monkeypatch: pytest.MonkeyPatch + ) -> None: + session_dir = _make_session(tmp_path, "s1", events=3) + size = (session_dir / "events.jsonl").stat().st_size + DeliveryWatermark(destination=DEST, destination_url=URL, offset=size).save(session_dir) + client = _FakeClient() + monkeypatch.setattr( + "amplifier_module_hook_context_intelligence.handlers.backlog_sweep.httpx.AsyncClient", + lambda *a, **k: client, + ) + report = await _sweeper(tmp_path).run() + assert client.posted == [] + assert report.sessions_skipped_caught_up == 1 + + async def test_malformed_record_halts_the_cursor_rather_than_skipping_it( + self, tmp_path: Path, monkeypatch: pytest.MonkeyPatch + ) -> None: + session_dir = _make_session(tmp_path, "s1", events=2) + with (session_dir / "events.jsonl").open("a") as fh: + fh.write("[1,2,3]\n") + fh.write(json.dumps({"event": "after", "workspace": "ws", "data": {}}) + "\n") + monkeypatch.setattr( + "amplifier_module_hook_context_intelligence.handlers.backlog_sweep.httpx.AsyncClient", + lambda *a, **k: _FakeClient(), + ) + report = await _sweeper(tmp_path).run() + assert report.events_delivered == 2 + assert any("malformed" in n for n in report.notes) + watermark, _ = DeliveryWatermark.load(session_dir, DEST, destination_url=URL) + assert not watermark.caught_up(session_dir) + + async def test_empty_project_is_a_clean_noop(self, tmp_path: Path) -> None: + report = await _sweeper(tmp_path).run() + assert report.sessions_considered == 0 + assert report.had_work is False + assert report.made_progress is False From a1f51fbbbe855a5a9e536014be7c14d1533e7851 Mon Sep 17 00:00:00 2001 From: colombod Date: Mon, 14 Sep 2026 23:01:54 +0000 Subject: [PATCH 03/14] fix(hook-context-intelligence): enable bounded graceful sweep scheduling instead of task cancellation at teardown MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit A DTU run against a real context-intelligence-server (6.7.0) exposed that the sweep mechanism was correct while its scheduling was not. Run directly against the same backlog, the sweep cleared 22 events (0 failed) in 6.6s. Scheduled inside a session it delivered zero events because cleanup() cancelled the background task at teardown, and a short session ends before the first ~250ms POST completes. Every unit test was green throughout — the defect only existed at wall-clock time. Two fixes, both config-exposed: * sweep_close_grace_seconds (default 2.0, 0.0 disables): cleanup() now awaits in-flight sweeps for a bounded grace period before cancelling. This deliberately amends the previously stated hard constraint 'event delivery must never block or slow process exit'. That absolute was kept so literally that the feature never ran. It is now an explicit, bounded, and configurable budget: 'never slows exit by more than N seconds' — which is testable, whereas an absolute was not. * sweep_interval_seconds (default 60.0, 0.0 = single pass): the sweep now repeats during the session instead of running once at start. This prevents a busy session's backlog from growing all day, and it makes teardown timing stop mattering. The continuous sweep and the live dispatcher need no coordination. While the live path keeps up it advances the watermark itself so the sweep skips the session as caught-up. The moment the live path drops or fails a record it freezes the watermark and the sweep resumes from exactly that point. Stranded-session warnings are now reported once per session instead of on every interval tick, since they describe the backlog rather than individual passes. Adds tests/test_sweep_scheduling.py (14 tests) covering the bounded grace, the repeat loop, loop survival across a failing pass, cancellation, and the loudness gate including stranded-warning suppression. Gates: 740 module tests + 839 root tests pass, ruff clean, pyright clean. Generated with Amplifier Co-Authored-By: Amplifier <240397093+microsoft-amplifier@users.noreply.github.com> --- ...igence-self-healing-replay-validation.yaml | 62 +++-- .../__init__.py | 74 ++++-- .../config_resolver.py | 33 +++ .../handlers/backlog_sweep.py | 9 + .../tests/test_sweep_scheduling.py | 238 ++++++++++++++++++ 5 files changed, 372 insertions(+), 44 deletions(-) create mode 100644 modules/hook-context-intelligence/tests/test_sweep_scheduling.py diff --git a/.amplifier/digital-twin-universe/profiles/context-intelligence-self-healing-replay-validation.yaml b/.amplifier/digital-twin-universe/profiles/context-intelligence-self-healing-replay-validation.yaml index f3cf4f07..25d6ff1e 100644 --- a/.amplifier/digital-twin-universe/profiles/context-intelligence-self-healing-replay-validation.yaml +++ b/.amplifier/digital-twin-universe/profiles/context-intelligence-self-healing-replay-validation.yaml @@ -180,6 +180,11 @@ provision: . /root/ci-verify.env export PATH="/root/.local/bin:$PATH" V=/root/support/verify.py + # The hook module is loaded from the CLI-resolved bundle cache, not from the + # tool venv's site-packages -- so anything importing it must say so. + CI_CACHE=$(ls -d /root/.amplifier/cache/amplifier-bundle-context-intelligence-* | head -1) + export PYTHONPATH="$CI_CACHE:$CI_CACHE/modules/hook-context-intelligence" + CI_PY=/root/.local/share/uv/tools/amplifier/bin/python newest_session() { python3 - <<'PY' import pathlib @@ -190,7 +195,7 @@ provision: PY } run_session() { - amplifier run "$1" --output json > /tmp/session-$$.json 2>/tmp/session-$$.err || { + amplifier run "$1" --output-format json > /tmp/session-$$.json 2>/tmp/session-$$.err || { echo "session failed"; tail -20 /tmp/session-$$.err; exit 1; } } COMMONEOF @@ -263,9 +268,8 @@ provision: "working_dir":"/outage","started_at":now,"last_event_at":now,"status":"completed"})) PY # A destination that is genuinely broken: nothing is listening on 59999. - python3 - <<'PY' - import asyncio, sys - sys.path.insert(0, "/root/.local/share/uv/tools/amplifier/lib/python3.13/site-packages") + $CI_PY - <<'PY' + import asyncio from amplifier_module_hook_context_intelligence.handlers.backlog_sweep import ( BacklogSweeper, SweepBounds) class A: @@ -298,9 +302,8 @@ provision: (d/"metadata.json").write_text(json.dumps({"session_id":"s-old","workspace":ws, "working_dir":"/ancient","started_at":old,"last_event_at":old,"status":"completed"})) PY - python3 - <<'PY' - import asyncio, sys, pathlib - sys.path.insert(0, "/root/.local/share/uv/tools/amplifier/lib/python3.13/site-packages") + $CI_PY - <<'PY' + import asyncio, pathlib from amplifier_module_hook_context_intelligence.handlers.backlog_sweep import ( BacklogSweeper, SweepBounds) class A: @@ -340,36 +343,45 @@ readiness: print(f"ready: proxy adds {dt:.0f}ms per request") PY - - name: logging-hook-present + - name: branch-bundle-resolved-from-mirror + # The code under test must be THIS branch, not main. Assert on the cache the + # CLI actually resolved, so a silently-stale mirror cannot produce a green run. command: > - amplifier bundle show context-intelligence-logging 2>/dev/null - | grep -q "hook-context-intelligence" - && echo "ready: logging hook loaded via CLI" + C=$(ls -d /root/.amplifier/cache/amplifier-bundle-context-intelligence-* | head -1); + test -f "$C/modules/hook-context-intelligence/amplifier_module_hook_context_intelligence/handlers/delivery_watermark.py" + && test -f "$C/modules/hook-context-intelligence/amplifier_module_hook_context_intelligence/handlers/backlog_sweep.py" + && echo "ready: branch bundle in cache @ $(git -C "$C" log -1 --pretty=%h) with the new handlers" - name: sweep-defaults-on # The shipped DEFAULT is the thing under test: settings.yaml deliberately - # does NOT set sweep_enabled. + # does NOT set sweep_enabled. Imported from the CLI-resolved cache (the hook + # module is loaded from there, not installed into the tool venv). command: | - python3 - <<'PY' - import sys - sys.path.insert(0, "/root/.local/share/uv/tools/amplifier/lib/python3.13/site-packages") + C=$(ls -d /root/.amplifier/cache/amplifier-bundle-context-intelligence-* | head -1) + PYTHONPATH="$C:$C/modules/hook-context-intelligence" \ + /root/.local/share/uv/tools/amplifier/bin/python - <<'PY' from amplifier_module_hook_context_intelligence.config_resolver import HookConfigResolver r = HookConfigResolver({}, None) assert r.sweep_enabled is True, "sweep must default ON" - assert r.sweep_max_age_hours == 48.0 - assert r.sweep_max_events == 5000 - print(f"ready: sweep defaults on (max_events={r.sweep_max_events}, " - f"max_age_hours={r.sweep_max_age_hours})") + assert r.sweep_max_events == 5000, r.sweep_max_events + assert r.sweep_max_age_hours == 48.0, r.sweep_max_age_hours + assert r.sweep_max_sessions == 20, r.sweep_max_sessions + assert r.sweep_concurrency == 1, r.sweep_concurrency + print(f"ready: sweep defaults ON (max_events={r.sweep_max_events}, " + f"max_age_hours={r.sweep_max_age_hours}, max_sessions={r.sweep_max_sessions}, " + f"concurrency={r.sweep_concurrency})") PY - - name: watermark-module-importable + - name: new-handlers-importable command: | - python3 - <<'PY' - import sys - sys.path.insert(0, "/root/.local/share/uv/tools/amplifier/lib/python3.13/site-packages") + C=$(ls -d /root/.amplifier/cache/amplifier-bundle-context-intelligence-* | head -1) + PYTHONPATH="$C:$C/modules/hook-context-intelligence" \ + /root/.local/share/uv/tools/amplifier/bin/python - <<'PY' from amplifier_module_hook_context_intelligence.handlers.delivery_watermark import ( - DeliveryWatermark) - print("ready:", DeliveryWatermark.__module__) + DeliveryWatermark, SweepLock) + from amplifier_module_hook_context_intelligence.handlers.backlog_sweep import ( + BacklogSweeper, SweepBounds) + print("ready:", DeliveryWatermark.__module__, "+", BacklogSweeper.__module__) PY - name: real-backend-reachable diff --git a/modules/hook-context-intelligence/amplifier_module_hook_context_intelligence/__init__.py b/modules/hook-context-intelligence/amplifier_module_hook_context_intelligence/__init__.py index 7aae80bf..0002ee42 100644 --- a/modules/hook-context-intelligence/amplifier_module_hook_context_intelligence/__init__.py +++ b/modules/hook-context-intelligence/amplifier_module_hook_context_intelligence/__init__.py @@ -193,7 +193,7 @@ async def apply_active_dispatchers( return match_key, sorted(active) -def _describe_sweep(report: Any) -> None: +def _describe_sweep(report: Any, *, suppress_stranded: bool = False) -> None: """Console policy for one sweep result -- the loudness gate. The question this asks is deliberately NOT "is there a backlog?" (which is @@ -208,7 +208,7 @@ def _describe_sweep(report: Any) -> None: """ # LOUD 4 -- outside the age bound. These will NEVER be delivered # automatically, so the bound must be audible or it becomes a silent drop. - if report.stranded_sessions: + if report.stranded_sessions and not suppress_stranded: log.warning( "context-intelligence %s: %d session(s) hold events older than the sweep" " window (oldest %.0fh) and will NOT be delivered automatically." @@ -253,11 +253,22 @@ def _describe_sweep(report: Any) -> None: def schedule_backlog_sweeps(resolver: Any, dispatchers: list[Any]) -> list[Any]: - """Start one background catch-up sweep per active destination. - - Fire-and-forget by contract: event delivery is best-effort and must never - block or slow a session. The tasks are cancelled during cleanup, and whatever - the watermark says at that moment is simply where the next session resumes. + """Start one CONTINUOUS catch-up sweep per active destination. + + Runs an immediate pass at session start, then repeats every + ``sweep_interval_seconds``. Continuous rather than one-shot for two reasons, + both measured rather than assumed: + + * A one-shot start-of-session sweep is hostage to how long the session + happens to last. In a DTU against a real server it delivered ZERO events, + because teardown cancelled it before the first round-trip completed. + * Repeating during the session is what actually stops a busy session's + backlog growing all day -- the live dispatcher's ceiling is one event per + round-trip, and nothing else reduces the queue while events keep arriving. + + Still best-effort: the tasks are cancelled at teardown after a bounded grace + (``sweep_close_grace_seconds``), and the watermark on disk is where the next + session resumes from. """ from .handlers.backlog_sweep import BacklogSweeper, SweepBounds @@ -286,13 +297,23 @@ def schedule_backlog_sweeps(resolver: Any, dispatchers: list[Any]) -> list[Any]: timeout=resolver.dispatch_timeout, ) - async def _run(s: Any = sweeper) -> None: - try: - _describe_sweep(await s.run()) - except asyncio.CancelledError: - raise - except Exception: - log.debug("context-intelligence backlog sweep failed", exc_info=True) + async def _run(s: Any = sweeper, interval: float = resolver.sweep_interval_seconds) -> None: + # Stranded-session warnings are a property of the BACKLOG, not of a + # pass, so they would repeat verbatim every interval. Report once per + # session and let the durable forwarding record carry the rest. + reported_stranded = False + while True: + try: + report = await s.run() + _describe_sweep(report, suppress_stranded=reported_stranded) + reported_stranded = reported_stranded or bool(report.stranded_sessions) + except asyncio.CancelledError: + raise + except Exception: + log.debug("context-intelligence backlog sweep failed", exc_info=True) + if interval <= 0: + return + await asyncio.sleep(interval) task = asyncio.create_task(_run()) task.add_done_callback(_retrieve_sweep_exception) @@ -604,11 +625,26 @@ def verify_ingestion_consistency(settings_path: str) -> dict[str, Any]: ) async def cleanup() -> None: - # Cancel catch-up sweeps FIRST. Delivery is best-effort and must never - # slow process exit; the watermark already on disk is where the next - # session resumes from. - for task in _hook_state.get("sweep_tasks") or []: - task.cancel() + # Give a catch-up sweep a BOUNDED grace to land, then cancel it. + # + # The original contract was "never slows process exit". It kept that + # promise so literally that the sweep never ran at all: a short session + # ends before the first several-hundred-millisecond POST completes, so a + # DTU run measured ZERO events delivered while the same sweep, given + # wall-clock, cleared the backlog in seconds. The constraint is now an + # explicit budget -- "never slows exit by more than + # sweep_close_grace_seconds" (default 2.0, set 0.0 to disable) -- which + # is bounded, configurable and testable, where an absolute was neither. + sweep_tasks = list(_hook_state.get("sweep_tasks") or []) + if sweep_tasks: + grace = resolver.sweep_close_grace_seconds + if grace > 0: + try: + await asyncio.wait(sweep_tasks, timeout=grace) + except Exception: + log.debug("sweep grace wait failed", exc_info=True) + for task in sweep_tasks: + task.cancel() try: await logging_handler.close() except Exception: diff --git a/modules/hook-context-intelligence/amplifier_module_hook_context_intelligence/config_resolver.py b/modules/hook-context-intelligence/amplifier_module_hook_context_intelligence/config_resolver.py index 43414677..b2f619b6 100644 --- a/modules/hook-context-intelligence/amplifier_module_hook_context_intelligence/config_resolver.py +++ b/modules/hook-context-intelligence/amplifier_module_hook_context_intelligence/config_resolver.py @@ -562,6 +562,39 @@ def sweep_max_sessions(self) -> int: """Ceiling on session directories visited per sweep pass. Defaults to 20.""" return max(1, int(self._config.get("sweep_max_sessions", 20))) + @property + def sweep_close_grace_seconds(self) -> float: + """Seconds a catch-up sweep may keep running at teardown. Default 2.0. + + An EXPLICIT, DECLARED budget replacing an absolute that defeated the + feature. The original contract was "never slows process exit", and it + kept that promise so literally that the sweep never ran: cleanup() + cancelled the task at session teardown, and a short session ends before + the first several-hundred-millisecond POST lands. Measured in a DTU + against a real server: a session-scheduled sweep delivered ZERO events, + while the same sweep given wall-clock cleared the whole backlog in 6.6s. + + So the constraint is now "never slows exit by more than this many + seconds", which is bounded, configurable, and testable. Set 0.0 to + restore cancel-immediately behaviour. + """ + return _coerce_positive_float( + self._config.get("sweep_close_grace_seconds"), default=2.0, minimum=0.0 + ) + + @property + def sweep_interval_seconds(self) -> float: + """Cadence of the in-session catch-up sweep. Default 60.0; 0 disables. + + With a repeat interval the sweep stops being a start-of-session event and + becomes continuous catch-up -- which is what actually keeps a busy + session's backlog from growing all day, and what makes teardown timing + stop mattering. Set 0.0 for a single pass at session start. + """ + return _coerce_positive_float( + self._config.get("sweep_interval_seconds"), default=60.0, minimum=0.0 + ) + @property def sweep_concurrency(self) -> int: """Concurrent in-flight POSTs during a sweep. Defaults to 1. diff --git a/modules/hook-context-intelligence/amplifier_module_hook_context_intelligence/handlers/backlog_sweep.py b/modules/hook-context-intelligence/amplifier_module_hook_context_intelligence/handlers/backlog_sweep.py index e583d894..f57bc7d4 100644 --- a/modules/hook-context-intelligence/amplifier_module_hook_context_intelligence/handlers/backlog_sweep.py +++ b/modules/hook-context-intelligence/amplifier_module_hook_context_intelligence/handlers/backlog_sweep.py @@ -23,6 +23,15 @@ The sweep lives in the hook and imports nothing from the upload tool: the dependency arrow is tool -> hook, so the reverse would be a circular import. It does not need to — ``build_payload`` already lives here. + +**Interaction with the live path, when running continuously.** The two never +fight over the same records, and nothing has to coordinate them. While the live +dispatcher keeps up it advances that session's watermark itself, so the sweep +sees the session as caught up and skips it entirely. The moment the live path +drops or fails a record it FREEZES the watermark there — it can no longer +honestly advance — and the sweep resumes from exactly that point. So the sweep +is idle on healthy sessions and is the only thing that can recover an unhealthy +one. """ from __future__ import annotations diff --git a/modules/hook-context-intelligence/tests/test_sweep_scheduling.py b/modules/hook-context-intelligence/tests/test_sweep_scheduling.py new file mode 100644 index 00000000..e0165a17 --- /dev/null +++ b/modules/hook-context-intelligence/tests/test_sweep_scheduling.py @@ -0,0 +1,238 @@ +"""Sweep SCHEDULING tests — the half that unit tests missed the first time. + +The sweep mechanism was correct and every mechanism test was green, yet in a real +DTU run it delivered ZERO events. The defect was entirely in *when* it got to +run: ``cleanup()`` cancelled the task at session teardown, and a short session +ends before the first several-hundred-millisecond POST completes. + +So these tests pin the two scheduling properties that failure exposed, neither of +which is observable from the sweeper in isolation: + +* teardown grants a BOUNDED grace before cancelling (and honours 0.0), and +* the sweep REPEATS during the session instead of running once. +""" + +from __future__ import annotations + +import asyncio +from typing import Any + +import pytest + +from amplifier_module_hook_context_intelligence import ( + _describe_sweep, + schedule_backlog_sweeps, +) +from amplifier_module_hook_context_intelligence.config_resolver import HookConfigResolver +from amplifier_module_hook_context_intelligence.handlers.backlog_sweep import SweepReport + + +class _Resolver: + """Only the attributes the scheduler reads.""" + + def __init__(self, tmp_path: Any, **overrides: Any) -> None: + self.sweep_enabled = True + self.sweep_max_events = 5000 + self.sweep_max_age_hours = 48.0 + self.sweep_max_sessions = 20 + self.sweep_concurrency = 1 + self.sweep_interval_seconds = 0.0 + self.sweep_close_grace_seconds = 2.0 + self.dispatch_timeout = 10.0 + self.base_path = tmp_path + self.project_slug = "-proj" + for key, value in overrides.items(): + setattr(self, key, value) + + +class _Dispatcher: + def __init__(self) -> None: + self.name = "main" + self.url = "https://ci.example.com" + self.auth_strategy = type("A", (), {"headers": lambda self: {}})() + + +class TestConfigDefaults: + def test_grace_and_interval_defaults(self) -> None: + resolver = HookConfigResolver({}, None) + assert resolver.sweep_close_grace_seconds == 2.0 + assert resolver.sweep_interval_seconds == 60.0 + + def test_grace_can_be_disabled_with_zero(self) -> None: + """0.0 restores the original cancel-immediately behaviour.""" + assert ( + HookConfigResolver({"sweep_close_grace_seconds": 0}, None).sweep_close_grace_seconds + == 0.0 + ) + + def test_garbage_falls_back_to_default(self) -> None: + resolver = HookConfigResolver({"sweep_close_grace_seconds": "nonsense"}, None) + assert resolver.sweep_close_grace_seconds == 2.0 + + +@pytest.mark.asyncio +class TestSchedulingLoop: + async def test_disabled_sweep_schedules_nothing(self, tmp_path: Any) -> None: + tasks = schedule_backlog_sweeps(_Resolver(tmp_path, sweep_enabled=False), [_Dispatcher()]) + assert tasks == [] + + async def test_single_pass_when_interval_is_zero( + self, tmp_path: Any, monkeypatch: pytest.MonkeyPatch + ) -> None: + runs = 0 + + async def fake_run(self: Any) -> SweepReport: + nonlocal runs + runs += 1 + return SweepReport(destination="main") + + monkeypatch.setattr( + "amplifier_module_hook_context_intelligence.handlers.backlog_sweep.BacklogSweeper.run", + fake_run, + ) + tasks = schedule_backlog_sweeps( + _Resolver(tmp_path, sweep_interval_seconds=0.0), [_Dispatcher()] + ) + await asyncio.gather(*tasks) + assert runs == 1 + + async def test_repeats_on_the_interval( + self, tmp_path: Any, monkeypatch: pytest.MonkeyPatch + ) -> None: + """THE fix for the DTU failure: one pass per session was not enough.""" + runs = 0 + + async def fake_run(self: Any) -> SweepReport: + nonlocal runs + runs += 1 + return SweepReport(destination="main") + + monkeypatch.setattr( + "amplifier_module_hook_context_intelligence.handlers.backlog_sweep.BacklogSweeper.run", + fake_run, + ) + tasks = schedule_backlog_sweeps( + _Resolver(tmp_path, sweep_interval_seconds=0.01), [_Dispatcher()] + ) + await asyncio.sleep(0.08) + for task in tasks: + task.cancel() + await asyncio.gather(*tasks, return_exceptions=True) + assert runs >= 3, f"continuous catch-up ran only {runs} time(s)" + + async def test_a_failing_pass_does_not_kill_the_loop( + self, tmp_path: Any, monkeypatch: pytest.MonkeyPatch + ) -> None: + runs = 0 + + async def fake_run(self: Any) -> SweepReport: + nonlocal runs + runs += 1 + if runs == 1: + raise RuntimeError("transient") + return SweepReport(destination="main") + + monkeypatch.setattr( + "amplifier_module_hook_context_intelligence.handlers.backlog_sweep.BacklogSweeper.run", + fake_run, + ) + tasks = schedule_backlog_sweeps( + _Resolver(tmp_path, sweep_interval_seconds=0.01), [_Dispatcher()] + ) + await asyncio.sleep(0.06) + for task in tasks: + task.cancel() + await asyncio.gather(*tasks, return_exceptions=True) + assert runs >= 2, "the loop died on the first failure" + + async def test_cancellation_is_honoured( + self, tmp_path: Any, monkeypatch: pytest.MonkeyPatch + ) -> None: + async def fake_run(self: Any) -> SweepReport: + await asyncio.sleep(10) + return SweepReport(destination="main") + + monkeypatch.setattr( + "amplifier_module_hook_context_intelligence.handlers.backlog_sweep.BacklogSweeper.run", + fake_run, + ) + tasks = schedule_backlog_sweeps( + _Resolver(tmp_path, sweep_interval_seconds=1.0), [_Dispatcher()] + ) + await asyncio.sleep(0) + for task in tasks: + task.cancel() + await asyncio.gather(*tasks, return_exceptions=True) + assert all(task.cancelled() or task.done() for task in tasks) + + +@pytest.mark.asyncio +class TestTeardownGrace: + async def test_grace_lets_an_in_flight_pass_finish(self) -> None: + """A bounded wait, then cancel -- the shape cleanup() implements.""" + finished = False + + async def work() -> None: + nonlocal finished + await asyncio.sleep(0.02) + finished = True + + task = asyncio.create_task(work()) + await asyncio.wait([task], timeout=1.0) + task.cancel() + assert finished is True + + async def test_grace_is_bounded_and_does_not_wait_forever(self) -> None: + task = asyncio.create_task(asyncio.sleep(10)) + loop = asyncio.get_running_loop() + started = loop.time() + await asyncio.wait([task], timeout=0.05) + task.cancel() + await asyncio.gather(task, return_exceptions=True) + assert (loop.time() - started) < 1.0, "teardown exceeded its declared budget" + + +class TestLoudnessGate: + def _report(self, **kwargs: Any) -> SweepReport: + report = SweepReport(destination="main") + for key, value in kwargs.items(): + setattr(report, key, value) + return report + + def test_quiet_when_caught_up(self, caplog: pytest.LogCaptureFixture) -> None: + with caplog.at_level("WARNING"): + _describe_sweep(self._report(sessions_swept=1, events_delivered=5)) + assert not [r for r in caplog.records if r.levelname == "WARNING"] + + def test_loud_when_no_progress_against_a_backlog( + self, caplog: pytest.LogCaptureFixture + ) -> None: + with caplog.at_level("WARNING"): + _describe_sweep( + self._report( + sessions_swept=1, + events_delivered=0, + backlog_bytes_remaining=9000, + last_error="HTTP 401", + ) + ) + assert any("NOT shrinking" in r.getMessage() for r in caplog.records) + + def test_loud_about_stranded_sessions(self, caplog: pytest.LogCaptureFixture) -> None: + """The age bound must be audible or it is a silent drop.""" + with caplog.at_level("WARNING"): + _describe_sweep(self._report(stranded_sessions=2, oldest_stranded_age_hours=168.0)) + message = " ".join(r.getMessage() for r in caplog.records) + assert "older than the sweep window" in message + assert "context-intelligence-upload" in message + + def test_stranded_warning_can_be_suppressed_after_the_first_pass( + self, caplog: pytest.LogCaptureFixture + ) -> None: + """A continuous loop must not repeat a backlog-shaped warning every tick.""" + with caplog.at_level("WARNING"): + _describe_sweep( + self._report(stranded_sessions=2, oldest_stranded_age_hours=168.0), + suppress_stranded=True, + ) + assert not [r for r in caplog.records if r.levelname == "WARNING"] From cade9b33b59253bce395648475c6e36dbd48d631 Mon Sep 17 00:00:00 2001 From: colombod Date: Mon, 14 Sep 2026 23:27:00 +0000 Subject: [PATCH 04/14] fix(hook-context-intelligence): commit sweep progress in chunks so cancellation keeps it A DTU run exposed a second scheduling defect one layer below the first: the sweep wrote its watermark only after the ENTIRE window completed, so being cancelled at session teardown discarded every delivery the pass had made. A sweep that genuinely re-sent events left its cursor at 0 and the work had to be redone next session -- the same class of bug the teardown grace fixed, and equally invisible to unit tests that never cancel a pass. Delivery now runs in chunks of sweep_concurrency, committing the contiguous prefix after each chunk, and a CancelledError persists the prefix reached so far before re-raising. Worst-case loss on teardown is one chunk instead of the whole pass. Adds two tests pinning the property: a sweep cancelled after five deliveries keeps exactly those five (last_outcome=cancelled), and one cancelled before any delivery records no_progress with the cursor untouched. Also fixes the S3 DTU scenario's parsing of verify.py output. Gates: 742 module tests, ruff clean, pyright 0 errors. Generated with Amplifier Co-Authored-By: Amplifier <240397093+microsoft-amplifier@users.noreply.github.com> --- ...igence-self-healing-replay-validation.yaml | 3 +- .../handlers/backlog_sweep.py | 92 +++++++++++-------- .../tests/test_backlog_sweep.py | 64 +++++++++++++ 3 files changed, 118 insertions(+), 41 deletions(-) diff --git a/.amplifier/digital-twin-universe/profiles/context-intelligence-self-healing-replay-validation.yaml b/.amplifier/digital-twin-universe/profiles/context-intelligence-self-healing-replay-validation.yaml index 25d6ff1e..f293759b 100644 --- a/.amplifier/digital-twin-universe/profiles/context-intelligence-self-healing-replay-validation.yaml +++ b/.amplifier/digital-twin-universe/profiles/context-intelligence-self-healing-replay-validation.yaml @@ -232,7 +232,8 @@ provision: . /root/_common.sh echo "=== S3: replay is duplicate-free -- proven as a FIXED POINT on node counts ===" SD=$(cat /root/.s1_session) - BEFORE=$(python3 -c "import json,sys;print(json.load(open('/root/.s2_nodes'))['nodes'])") + # verify.py prints the JSON line THEN a PASS: line, so take the JSON one. + BEFORE=$(grep -m1 '^{' /root/.s2_nodes | python3 -c "import json,sys;print(json.load(sys.stdin)['nodes'])") echo "nodes after S2: $BEFORE" # Rewind the watermark and force a FULL re-send of the same records. python3 - "$SD" <<'PY' diff --git a/modules/hook-context-intelligence/amplifier_module_hook_context_intelligence/handlers/backlog_sweep.py b/modules/hook-context-intelligence/amplifier_module_hook_context_intelligence/handlers/backlog_sweep.py index f57bc7d4..b13d4203 100644 --- a/modules/hook-context-intelligence/amplifier_module_hook_context_intelligence/handlers/backlog_sweep.py +++ b/modules/hook-context-intelligence/amplifier_module_hook_context_intelligence/handlers/backlog_sweep.py @@ -323,50 +323,62 @@ async def _sweep_session( if not window: return 0 - semaphore = asyncio.Semaphore(max(1, self._bounds.concurrency)) - - async def deliver(index: int) -> tuple[int, bool, str]: - async with semaphore: - delivered, detail = await self._post(client, window[index][2]) - return index, delivered, detail - - results = await asyncio.gather(*(deliver(i) for i in range(len(window)))) - outcomes = {index: (ok, detail) for index, ok, detail in results} - - # CONTIGUOUS PREFIX ONLY. With N in flight, a failure at position k caps - # the watermark at k-1 even if k+1.. succeeded; those are re-sent next - # pass. That redundancy is the price of a single-number cursor, and the - # alternative — tracking a sparse delivered-set — is unbounded state. + # Deliver in CHUNKS, committing the watermark after each one. + # + # A single gather over the whole window looks tidier and is wrong: this + # task is cancelled at session teardown, and a cancellation mid-gather + # threw away EVERY delivery the pass had made, because the watermark was + # only written at the end. Measured in a DTU: a sweep that genuinely + # re-sent events left its cursor at 0 and the work had to be redone. + # Chunking bounds that loss to one chunk. + chunk = max(1, self._bounds.concurrency) prefix_end = watermark.offset delivered_count = 0 - for index, (_start, end, _payload) in enumerate(window): - ok, _detail = outcomes[index] - if not ok: - break - prefix_end = end - delivered_count += 1 - - failed = sum(1 for ok, _ in outcomes.values() if not ok) - first_error = next((detail for ok, detail in outcomes.values() if not ok), None) - - advanced = prefix_end - watermark.offset - watermark.offset = prefix_end - watermark.delivered_lines += delivered_count - watermark.last_attempt_at = datetime.now(UTC).isoformat() - watermark.last_outcome = "delivered" if delivered_count else "no_progress" - watermark.last_error = first_error - if delivered_count: - watermark.last_delivered_at = watermark.last_attempt_at - watermark.consecutive_sweeps_without_progress = 0 - else: - watermark.consecutive_sweeps_without_progress += 1 + failed = 0 + first_error: str | None = None + stop = False + + def _persist(outcome: str) -> None: + advanced_now = prefix_end - watermark.offset + watermark.offset = prefix_end + watermark.delivered_lines += delivered_count + watermark.last_attempt_at = datetime.now(UTC).isoformat() + watermark.last_outcome = outcome + watermark.last_error = first_error + if delivered_count: + watermark.last_delivered_at = watermark.last_attempt_at + watermark.consecutive_sweeps_without_progress = 0 + elif outcome == "no_progress": + watermark.consecutive_sweeps_without_progress += 1 + try: + watermark.save(session_dir) + except OSError as exc: + report.notes.append(f"watermark write failed at {session_dir}: {exc}") + return advanced_now try: - watermark.save(session_dir) - except OSError as exc: - # Best-effort telemetry: a failed watermark write must not fail the - # sweep. The cost is re-delivery next session, which MERGE absorbs. - report.notes.append(f"watermark write failed at {session_dir}: {exc}") + for start_index in range(0, len(window), chunk): + batch = window[start_index : start_index + chunk] + results = await asyncio.gather( + *(self._post(client, payload) for _s, _e, payload in batch) + ) + for (_start, end, _payload), (delivered, detail) in zip(batch, results): + if not delivered: + failed += 1 + first_error = first_error or detail + stop = True + break + # CONTIGUOUS PREFIX ONLY: the cursor may only pass a record + # once every record before it has been accepted. + prefix_end = end + delivered_count += 1 + if stop: + break + advanced = _persist("delivered" if delivered_count else "no_progress") + except asyncio.CancelledError: + # Teardown. Keep what we actually achieved rather than redoing it. + _persist("cancelled" if delivered_count else "no_progress") + raise report.events_delivered += delivered_count report.events_failed += failed diff --git a/modules/hook-context-intelligence/tests/test_backlog_sweep.py b/modules/hook-context-intelligence/tests/test_backlog_sweep.py index 535bfac0..75f84db8 100644 --- a/modules/hook-context-intelligence/tests/test_backlog_sweep.py +++ b/modules/hook-context-intelligence/tests/test_backlog_sweep.py @@ -14,6 +14,7 @@ from __future__ import annotations +import asyncio import json from datetime import UTC, datetime, timedelta from pathlib import Path @@ -359,3 +360,66 @@ async def test_empty_project_is_a_clean_noop(self, tmp_path: Path) -> None: assert report.sessions_considered == 0 assert report.had_work is False assert report.made_progress is False + + +@pytest.mark.asyncio +class TestCancellationSafety: + """A cancelled sweep must KEEP the progress it actually made. + + Found in a DTU, not in a unit test: the watermark used to be written only + after the whole window completed, so teardown cancellation threw away every + delivery the pass had made and the work had to be redone from scratch next + session. Delivery now commits in chunks, and cancellation persists the + contiguous prefix reached so far. + """ + + async def test_cancelled_sweep_keeps_its_contiguous_prefix( + self, tmp_path: Path, monkeypatch: pytest.MonkeyPatch + ) -> None: + session_dir = _make_session(tmp_path, "s1", events=20) + boundaries = [end for _s, end, _t in iter_records_from(session_dir / "events.jsonl", 0)] + + posted = 0 + + class _SlowClient(_FakeClient): + async def post(self, url: str, **kwargs: Any) -> _FakeResponse: + nonlocal posted + posted += 1 + if posted > 5: + # Stand in for teardown arriving mid-pass. + raise asyncio.CancelledError + return await super().post(url, **kwargs) + + monkeypatch.setattr( + "amplifier_module_hook_context_intelligence.handlers.backlog_sweep.httpx.AsyncClient", + lambda *a, **k: _SlowClient(), + ) + with pytest.raises(asyncio.CancelledError): + await _sweeper(tmp_path).run() + + watermark, _ = DeliveryWatermark.load(session_dir, DEST, destination_url=URL) + assert watermark.offset == boundaries[4], ( + f"cancelled sweep lost its progress: offset {watermark.offset}, " + f"expected {boundaries[4]} (5 delivered records)" + ) + assert watermark.last_outcome == "cancelled" + + async def test_cancelled_before_any_delivery_records_no_progress( + self, tmp_path: Path, monkeypatch: pytest.MonkeyPatch + ) -> None: + session_dir = _make_session(tmp_path, "s1", events=5) + + class _DeadClient(_FakeClient): + async def post(self, url: str, **kwargs: Any) -> _FakeResponse: + raise asyncio.CancelledError + + monkeypatch.setattr( + "amplifier_module_hook_context_intelligence.handlers.backlog_sweep.httpx.AsyncClient", + lambda *a, **k: _DeadClient(), + ) + with pytest.raises(asyncio.CancelledError): + await _sweeper(tmp_path).run() + + watermark, _ = DeliveryWatermark.load(session_dir, DEST, destination_url=URL) + assert watermark.offset == 0 + assert watermark.last_outcome == "no_progress" From 64867d8d25043b57c2a92e21ad43ec7937c1a9c3 Mon Sep 17 00:00:00 2001 From: colombod Date: Mon, 14 Sep 2026 23:38:06 +0000 Subject: [PATCH 05/14] test(dtu): scope the duplicate-free check per session and drive the sweep to EOF Two corrections to the self-healing DTU profile, both found by running it. S3 asserted the fixed point on a WORKSPACE-wide node count while itself driving extra sessions to advance the sweep -- so those sessions' brand-new events inflated the total and were indistinguishable from duplicates (56 -> 161, a false FAIL). verify.py gains count_session_nodes, filtering on the deterministic node_id prefix, and the check is now scoped to the session actually replayed. Result: 25 -> 25 nodes after a full forced re-send of all 26 records. S3 also expected one short session to complete a forced full re-send. It cannot: 26 records at 250ms is ~6.5s against a session plus a 2s teardown grace. The scenario now drives sessions until the cursor reaches EOF, which is a truer test anyway -- it demonstrates that chunked progress ACCUMULATES across sessions (observed: 0 -> 123800 -> 128471 -> 129234). All five scenarios now pass against a real server + real Neo4j. Generated with Amplifier Co-Authored-By: Amplifier <240397093+microsoft-amplifier@users.noreply.github.com> --- ...igence-self-healing-replay-validation.yaml | 34 ++++++++++---- .../support/self-healing-replay/verify.py | 45 ++++++++++++++++++- 2 files changed, 69 insertions(+), 10 deletions(-) diff --git a/.amplifier/digital-twin-universe/profiles/context-intelligence-self-healing-replay-validation.yaml b/.amplifier/digital-twin-universe/profiles/context-intelligence-self-healing-replay-validation.yaml index f293759b..1d1bfaf0 100644 --- a/.amplifier/digital-twin-universe/profiles/context-intelligence-self-healing-replay-validation.yaml +++ b/.amplifier/digital-twin-universe/profiles/context-intelligence-self-healing-replay-validation.yaml @@ -232,9 +232,13 @@ provision: . /root/_common.sh echo "=== S3: replay is duplicate-free -- proven as a FIXED POINT on node counts ===" SD=$(cat /root/.s1_session) - # verify.py prints the JSON line THEN a PASS: line, so take the JSON one. - BEFORE=$(grep -m1 '^{' /root/.s2_nodes | python3 -c "import json,sys;print(json.load(sys.stdin)['nodes'])") - echo "nodes after S2: $BEFORE" + # Scope the baseline to THIS session: driving more sessions below adds their own + # new events to the workspace, which a workspace-wide count cannot tell apart + # from duplicates. + BEFORE=$(python3 $V session-nodes --session-dir "$SD" --server "$SERVER_URL" \ + --token "$SERVER_TOKEN" --workspace "$WORKSPACE" \ + | python3 -c "import json,sys;print(json.load(sys.stdin)['nodes'])") + echo "session nodes after S2: $BEFORE" # Rewind the watermark and force a FULL re-send of the same records. python3 - "$SD" <<'PY' import json, sys, pathlib @@ -243,8 +247,19 @@ provision: p.write_text(json.dumps(wm)) print("watermark rewound to 0") PY - run_session "Say OK." - sleep 20 + # A forced full re-send is larger than one short session's sweep budget, so drive + # sessions until the cursor is back at EOF. Each session's sweep keeps the + # progress it made (chunked commit); this proves that accumulation works, and is + # the honest way to reach the state the fixed-point claim is actually about. + SIZE=$(stat -c%s "$SD/events.jsonl") + for i in 1 2 3 4 5; do + OFF=$(python3 -c "import json;print(json.load(open('$SD/delivery/main.json'))['offset'])") + echo " attempt $i: watermark $OFF / $SIZE" + [ "$OFF" = "$SIZE" ] && break + run_session "Say OK." + sleep 8 + done + sleep 12 python3 $V healed --session-dir "$SD" --server "$SERVER_URL" \ --token "$SERVER_TOKEN" --workspace "$WORKSPACE" --destination main \ --expect-nodes "$BEFORE" @@ -409,9 +424,12 @@ manual_validation_steps: - name: S3-replay-is-duplicate-free command: bash /root/s3_fixed_point.sh expect: > - PASS: the node count is UNCHANGED after a full re-send of the same records - (fixed point). Asserted on real Neo4j node counts, NOT on a "duplicate" - response -- the idempotency cache is in-memory and ?replay bypasses it. + PASS: the count of nodes belonging to THAT SESSION is unchanged after a full + re-send of every one of its records (fixed point). Asserted on real Neo4j + node counts, NOT on a "duplicate" response -- the idempotency cache is + in-memory and ?replay bypasses it. Scoped per session because the sessions + this scenario drives to advance the sweep add their own new events to the + workspace, which a workspace-wide count cannot tell apart from duplicates. - name: S4-a-real-outage-stays-loud command: bash /root/s4_outage_loud.sh diff --git a/.amplifier/digital-twin-universe/profiles/support/self-healing-replay/verify.py b/.amplifier/digital-twin-universe/profiles/support/self-healing-replay/verify.py index 138b3757..09691bcc 100644 --- a/.amplifier/digital-twin-universe/profiles/support/self-healing-replay/verify.py +++ b/.amplifier/digital-twin-universe/profiles/support/self-healing-replay/verify.py @@ -91,6 +91,25 @@ def wait_drained(server: str, token: str, workspace: str, timeout: float = 240.0 return count_nodes(server, token, workspace) +def count_session_nodes(server: str, token: str, workspace: str, session_id: str) -> int: + """Nodes belonging to ONE session. + + The fixed-point check must be scoped this way. A workspace-wide count is + wrong the moment the scenario runs further sessions to drive the sweep -- + their brand-new events inflate the total and look exactly like duplicates. + node_id is deterministic and prefixed with the session id (see the server's + make_node_id), so the prefix is an exact per-session filter. + """ + rows = cypher( + server, + token, + "MATCH (n) WHERE n.workspace = $ws AND n.node_id STARTS WITH $prefix " + "RETURN count(n) AS c", + {"ws": workspace, "prefix": f"{session_id}__"}, + ) + return int(rows[0]["c"]) if rows else 0 + + def count_lines(session_dir: Path) -> int: path = session_dir / "events.jsonl" if not path.exists(): @@ -176,6 +195,21 @@ def main() -> None: ) return + if args.command == "session-nodes": + assert session_dir + session_id = session_dir.parent.name + print( + json.dumps( + { + "session_id": session_id, + "nodes": count_session_nodes( + args.server, args.token, args.workspace, session_id + ), + } + ) + ) + return + if args.command == "healed": # S2/S3: converge, watermark at EOF, and a further replay is a no-op. assert session_dir @@ -184,8 +218,15 @@ def main() -> None: watermark = load_watermark(session_dir, args.destination) if watermark["offset"] != size: fail(f"watermark {watermark['offset']} != EOF {size} -- backlog not fully swept") - if args.expect_nodes >= 0 and total != args.expect_nodes: - fail(f"NOT a fixed point: {args.expect_nodes} -> {total} nodes on replay") + if args.expect_nodes >= 0: + session_id = session_dir.parent.name + scoped = count_session_nodes(args.server, args.token, args.workspace, session_id) + if scoped != args.expect_nodes: + fail( + f"NOT a fixed point for session {session_id}: " + f"{args.expect_nodes} -> {scoped} nodes after a full replay" + ) + print(json.dumps({"session_nodes": scoped, "workspace_nodes": total})) print(json.dumps({"nodes": total, "watermark": watermark})) ok(f"healed: watermark at EOF ({size}), {total} nodes for {args.workspace}") return From 05215123edcdd12b9159b060cb8cdd57d1e3c670 Mon Sep 17 00:00:00 2001 From: colombod Date: Tue, 15 Sep 2026 09:19:23 +0000 Subject: [PATCH 06/14] fix(hook-context-intelligence): only spend the teardown grace on a sweep that is working The grace was being paid on EVERY session exit, including the overwhelmingly common case of nothing to sweep. Measured at a flat 2.003s added to every exit -- precisely the cost the original "never slows exit" rule existed to prevent, and a straight regression on the healthy path. Cause: the sweep task is an infinite loop (continuous catch-up), so it never completes. Waiting on the TASK therefore always burned the entire budget, whether or not a pass was in flight. Teardown now waits for the sweep to be IDLE -- its current pass finished -- rather than for the task to end, via an asyncio.Event cleared around each pass and a shared deadline across destinations. Measured after the fix: idle / nothing to do : 0.000s mid-pass, delivering : 2.002s (the declared budget, and only then) grace = 0.0 : 0.000s So the honest statement of the contract is: exit is unaffected unless a catch-up sweep is mid-delivery, in which case it may take up to sweep_close_grace_seconds (default 2.0, shared across all destinations, 0.0 disables). Adds four regression tests: idle costs nothing, an in-flight sweep may use but not exceed the budget, zero grace never waits, and the budget is shared across destinations rather than multiplied by them. Gates: 746 module tests, 839 root tests, ruff clean, pyright 0 errors. Generated with Amplifier Co-Authored-By: Amplifier <240397093+microsoft-amplifier@users.noreply.github.com> --- .../__init__.py | 73 ++++++++-- .../tests/test_sweep_scheduling.py | 132 +++++++++++++++--- 2 files changed, 178 insertions(+), 27 deletions(-) diff --git a/modules/hook-context-intelligence/amplifier_module_hook_context_intelligence/__init__.py b/modules/hook-context-intelligence/amplifier_module_hook_context_intelligence/__init__.py index 0002ee42..1b814ff6 100644 --- a/modules/hook-context-intelligence/amplifier_module_hook_context_intelligence/__init__.py +++ b/modules/hook-context-intelligence/amplifier_module_hook_context_intelligence/__init__.py @@ -252,6 +252,28 @@ def _describe_sweep(report: Any, *, suppress_stranded: bool = False) -> None: ) +class _SweepHandle: + """A running catch-up sweep, plus whether it is mid-pass right now. + + The distinction is the whole point. The sweep task is an infinite loop, so it + NEVER completes -- waiting on the task itself at teardown burns the entire + grace budget every single time, including the overwhelmingly common case + where there is nothing to sweep and the task is simply asleep between + passes. Measured: a flat 2.003s added to every exit. + + So teardown waits for the sweep to be IDLE (its current pass finished), not + for the task to end. Idle costs nothing; only a pass genuinely in flight can + spend the budget. + """ + + def __init__(self, task: Any, idle: Any) -> None: + self.task = task + self.idle = idle + + def cancel(self) -> None: + self.task.cancel() + + def schedule_backlog_sweeps(resolver: Any, dispatchers: list[Any]) -> list[Any]: """Start one CONTINUOUS catch-up sweep per active destination. @@ -297,12 +319,19 @@ def schedule_backlog_sweeps(resolver: Any, dispatchers: list[Any]) -> list[Any]: timeout=resolver.dispatch_timeout, ) - async def _run(s: Any = sweeper, interval: float = resolver.sweep_interval_seconds) -> None: + idle = asyncio.Event() + + async def _run( + s: Any = sweeper, + interval: float = resolver.sweep_interval_seconds, + idle: Any = idle, + ) -> None: # Stranded-session warnings are a property of the BACKLOG, not of a # pass, so they would repeat verbatim every interval. Report once per # session and let the durable forwarding record carry the rest. reported_stranded = False while True: + idle.clear() try: report = await s.run() _describe_sweep(report, suppress_stranded=reported_stranded) @@ -311,16 +340,42 @@ async def _run(s: Any = sweeper, interval: float = resolver.sweep_interval_secon raise except Exception: log.debug("context-intelligence backlog sweep failed", exc_info=True) + finally: + idle.set() if interval <= 0: return await asyncio.sleep(interval) task = asyncio.create_task(_run()) task.add_done_callback(_retrieve_sweep_exception) - tasks.append(task) + tasks.append(_SweepHandle(task, idle)) return tasks +async def await_sweeps_idle(handles: list[Any], grace: float) -> None: + """Wait, bounded by *grace*, for every sweep to finish its current pass. + + Returns IMMEDIATELY when nothing is mid-pass, which is the normal case. Only + a sweep actually delivering can spend any of the budget, and no sweep can + spend more than *grace* seconds of it. + """ + if grace <= 0: + return + loop = asyncio.get_running_loop() + deadline = loop.time() + grace + for handle in handles: + remaining = deadline - loop.time() + if remaining <= 0: + return + try: + await asyncio.wait_for(handle.idle.wait(), timeout=remaining) + except (TimeoutError, asyncio.TimeoutError): + return + except Exception: + log.debug("sweep idle wait failed", exc_info=True) + return + + def _retrieve_sweep_exception(task: Any) -> None: """Retrieve a finished sweep's exception so asyncio never warns about it.""" if task.cancelled(): @@ -637,14 +692,12 @@ async def cleanup() -> None: # is bounded, configurable and testable, where an absolute was neither. sweep_tasks = list(_hook_state.get("sweep_tasks") or []) if sweep_tasks: - grace = resolver.sweep_close_grace_seconds - if grace > 0: - try: - await asyncio.wait(sweep_tasks, timeout=grace) - except Exception: - log.debug("sweep grace wait failed", exc_info=True) - for task in sweep_tasks: - task.cancel() + try: + await await_sweeps_idle(sweep_tasks, resolver.sweep_close_grace_seconds) + except Exception: + log.debug("sweep grace wait failed", exc_info=True) + for handle in sweep_tasks: + handle.cancel() try: await logging_handler.close() except Exception: diff --git a/modules/hook-context-intelligence/tests/test_sweep_scheduling.py b/modules/hook-context-intelligence/tests/test_sweep_scheduling.py index e0165a17..a4ebd966 100644 --- a/modules/hook-context-intelligence/tests/test_sweep_scheduling.py +++ b/modules/hook-context-intelligence/tests/test_sweep_scheduling.py @@ -21,6 +21,7 @@ from amplifier_module_hook_context_intelligence import ( _describe_sweep, + await_sweeps_idle, schedule_backlog_sweeps, ) from amplifier_module_hook_context_intelligence.config_resolver import HookConfigResolver @@ -73,8 +74,9 @@ def test_garbage_falls_back_to_default(self) -> None: @pytest.mark.asyncio class TestSchedulingLoop: async def test_disabled_sweep_schedules_nothing(self, tmp_path: Any) -> None: - tasks = schedule_backlog_sweeps(_Resolver(tmp_path, sweep_enabled=False), [_Dispatcher()]) - assert tasks == [] + assert ( + schedule_backlog_sweeps(_Resolver(tmp_path, sweep_enabled=False), [_Dispatcher()]) == [] + ) async def test_single_pass_when_interval_is_zero( self, tmp_path: Any, monkeypatch: pytest.MonkeyPatch @@ -90,10 +92,10 @@ async def fake_run(self: Any) -> SweepReport: "amplifier_module_hook_context_intelligence.handlers.backlog_sweep.BacklogSweeper.run", fake_run, ) - tasks = schedule_backlog_sweeps( + handles = schedule_backlog_sweeps( _Resolver(tmp_path, sweep_interval_seconds=0.0), [_Dispatcher()] ) - await asyncio.gather(*tasks) + await asyncio.gather(*(h.task for h in handles)) assert runs == 1 async def test_repeats_on_the_interval( @@ -111,13 +113,13 @@ async def fake_run(self: Any) -> SweepReport: "amplifier_module_hook_context_intelligence.handlers.backlog_sweep.BacklogSweeper.run", fake_run, ) - tasks = schedule_backlog_sweeps( + handles = schedule_backlog_sweeps( _Resolver(tmp_path, sweep_interval_seconds=0.01), [_Dispatcher()] ) await asyncio.sleep(0.08) - for task in tasks: - task.cancel() - await asyncio.gather(*tasks, return_exceptions=True) + for handle in handles: + handle.cancel() + await asyncio.gather(*(h.task for h in handles), return_exceptions=True) assert runs >= 3, f"continuous catch-up ran only {runs} time(s)" async def test_a_failing_pass_does_not_kill_the_loop( @@ -136,13 +138,13 @@ async def fake_run(self: Any) -> SweepReport: "amplifier_module_hook_context_intelligence.handlers.backlog_sweep.BacklogSweeper.run", fake_run, ) - tasks = schedule_backlog_sweeps( + handles = schedule_backlog_sweeps( _Resolver(tmp_path, sweep_interval_seconds=0.01), [_Dispatcher()] ) await asyncio.sleep(0.06) - for task in tasks: - task.cancel() - await asyncio.gather(*tasks, return_exceptions=True) + for handle in handles: + handle.cancel() + await asyncio.gather(*(h.task for h in handles), return_exceptions=True) assert runs >= 2, "the loop died on the first failure" async def test_cancellation_is_honoured( @@ -156,14 +158,14 @@ async def fake_run(self: Any) -> SweepReport: "amplifier_module_hook_context_intelligence.handlers.backlog_sweep.BacklogSweeper.run", fake_run, ) - tasks = schedule_backlog_sweeps( + handles = schedule_backlog_sweeps( _Resolver(tmp_path, sweep_interval_seconds=1.0), [_Dispatcher()] ) await asyncio.sleep(0) - for task in tasks: - task.cancel() - await asyncio.gather(*tasks, return_exceptions=True) - assert all(task.cancelled() or task.done() for task in tasks) + for handle in handles: + handle.cancel() + await asyncio.gather(*(h.task for h in handles), return_exceptions=True) + assert all(h.task.cancelled() or h.task.done() for h in handles) @pytest.mark.asyncio @@ -236,3 +238,99 @@ def test_stranded_warning_can_be_suppressed_after_the_first_pass( suppress_stranded=True, ) assert not [r for r in caplog.records if r.levelname == "WARNING"] + + +@pytest.mark.asyncio +class TestExitIsNotSlowedWhenIdle: + """The grace must be spent ONLY on a sweep that is actually delivering. + + REGRESSION. The sweep task is an infinite loop, so it never completes -- + waiting on the TASK at teardown burned the entire budget on every exit, + including the overwhelmingly common case of nothing to sweep. Measured at a + flat 2.003s added to every session exit, which is precisely the cost the + original "never slows exit" rule existed to prevent. Teardown now waits for + the sweep to be IDLE, not for the task to end. + """ + + async def _cost(self, handles: list[Any], grace: float) -> float: + loop = asyncio.get_running_loop() + started = loop.time() + await await_sweeps_idle(handles, grace) + for handle in handles: + handle.cancel() + await asyncio.gather(*(h.task for h in handles), return_exceptions=True) + return loop.time() - started + + async def test_idle_sweep_costs_nothing_at_exit( + self, tmp_path: Any, monkeypatch: pytest.MonkeyPatch + ) -> None: + async def instant(self: Any) -> SweepReport: + return SweepReport(destination="main") + + monkeypatch.setattr( + "amplifier_module_hook_context_intelligence.handlers.backlog_sweep.BacklogSweeper.run", + instant, + ) + handles = schedule_backlog_sweeps( + _Resolver(tmp_path, sweep_interval_seconds=60.0), [_Dispatcher()] + ) + await asyncio.sleep(0.05) # first pass done; task now idle between passes + assert await self._cost(handles, grace=2.0) < 0.2, ( + "an idle sweep spent the teardown budget -- every exit pays for nothing" + ) + + async def test_in_flight_sweep_may_use_the_budget_but_not_exceed_it( + self, tmp_path: Any, monkeypatch: pytest.MonkeyPatch + ) -> None: + async def slow(self: Any) -> SweepReport: + await asyncio.sleep(10) + return SweepReport(destination="main") + + monkeypatch.setattr( + "amplifier_module_hook_context_intelligence.handlers.backlog_sweep.BacklogSweeper.run", + slow, + ) + handles = schedule_backlog_sweeps( + _Resolver(tmp_path, sweep_interval_seconds=60.0), [_Dispatcher()] + ) + await asyncio.sleep(0.05) + cost = await self._cost(handles, grace=0.3) + assert 0.2 < cost < 1.0, f"budget not honoured: {cost:.3f}s" + + async def test_zero_grace_never_waits( + self, tmp_path: Any, monkeypatch: pytest.MonkeyPatch + ) -> None: + async def slow(self: Any) -> SweepReport: + await asyncio.sleep(10) + return SweepReport(destination="main") + + monkeypatch.setattr( + "amplifier_module_hook_context_intelligence.handlers.backlog_sweep.BacklogSweeper.run", + slow, + ) + handles = schedule_backlog_sweeps( + _Resolver(tmp_path, sweep_interval_seconds=60.0), [_Dispatcher()] + ) + await asyncio.sleep(0.05) + assert await self._cost(handles, grace=0.0) < 0.2 + + async def test_budget_is_shared_across_destinations_not_per_destination( + self, tmp_path: Any, monkeypatch: pytest.MonkeyPatch + ) -> None: + """Three slow destinations must not cost three graces.""" + + async def slow(self: Any) -> SweepReport: + await asyncio.sleep(10) + return SweepReport(destination="main") + + monkeypatch.setattr( + "amplifier_module_hook_context_intelligence.handlers.backlog_sweep.BacklogSweeper.run", + slow, + ) + handles = schedule_backlog_sweeps( + _Resolver(tmp_path, sweep_interval_seconds=60.0), + [_Dispatcher(), _Dispatcher(), _Dispatcher()], + ) + await asyncio.sleep(0.05) + cost = await self._cost(handles, grace=0.3) + assert cost < 1.0, f"budget multiplied by destination count: {cost:.3f}s" From 03899b7b0c30dde1a8388b790a3f80994cb0f8f0 Mon Sep 17 00:00:00 2001 From: colombod Date: Tue, 15 Sep 2026 09:27:06 +0000 Subject: [PATCH 07/14] docs: document the two scheduling knobs, the exit budget, and the lesson README gains sweep_close_grace_seconds and sweep_interval_seconds, corrects the sweep from one-shot to continuous, and states the exit cost plainly: unaffected normally, up to the grace only when a sweep is mid-delivery, budget shared across destinations, 0.0 disables, progress kept on cancellation. remote-server-troubleshooting.md gains an entry for 'why did exit take a couple of seconds longer', framing it as evidence the bundle was actively recovering events rather than a fault, plus a quick-reference row. AGENTS.md records why the seam gate earned its keep here: three defects shipped past a green 740-test suite and were caught only by a real DTU run, all three the same shape -- work performed but not recorded, or a wait bounded on the wrong thing -- plus the test-design lesson about scoping a uniqueness assertion to the entity actually replayed. Generated with Amplifier Co-Authored-By: Amplifier <240397093+microsoft-amplifier@users.noreply.github.com> --- .../support/self-healing-replay/verify.py | 3 +- AGENTS.md | 32 +++++++++++++++++++ README.md | 6 +++- docs/remote-server-troubleshooting.md | 21 ++++++++++++ 4 files changed, 59 insertions(+), 3 deletions(-) diff --git a/.amplifier/digital-twin-universe/profiles/support/self-healing-replay/verify.py b/.amplifier/digital-twin-universe/profiles/support/self-healing-replay/verify.py index 09691bcc..b65e2547 100644 --- a/.amplifier/digital-twin-universe/profiles/support/self-healing-replay/verify.py +++ b/.amplifier/digital-twin-universe/profiles/support/self-healing-replay/verify.py @@ -103,8 +103,7 @@ def count_session_nodes(server: str, token: str, workspace: str, session_id: str rows = cypher( server, token, - "MATCH (n) WHERE n.workspace = $ws AND n.node_id STARTS WITH $prefix " - "RETURN count(n) AS c", + "MATCH (n) WHERE n.workspace = $ws AND n.node_id STARTS WITH $prefix RETURN count(n) AS c", {"ws": workspace, "prefix": f"{session_id}__"}, ) return int(rows[0]["c"]) if rows else 0 diff --git a/AGENTS.md b/AGENTS.md index b9b68c59..9b7e7349 100644 --- a/AGENTS.md +++ b/AGENTS.md @@ -120,6 +120,38 @@ including ANY agent / skill / mode / tool / networking / auth edit → units + ` real DTU run + the evaluation harness, with captured evidence.** Skipping the live run on a seam change is how a green build ships a broken bundle. +## Scheduling defects: what a green unit suite structurally cannot see + +A worked example, from the self-healing replay work (#403), of *why* the seam gate above is +not bureaucracy. Three defects shipped past a fully green 740-test suite and were each +caught only by a real DTU run against a real, slow destination: + +1. **The background task never ran.** Scheduled inside a session it delivered **zero** + events, because `cleanup()` cancelled it before its first several-hundred-millisecond + request completed. The code was correct; it simply never got wall-clock. +2. **Cancellation discarded completed work.** Progress was persisted only after a whole + batch finished, so teardown threw away every delivery already made. +3. **The fix for (1) taxed every exit.** It waited on a task that never completes (an + infinite loop), turning a 2-second *ceiling* into a flat 2-second *cost* on every + session exit, including the common case with no work to do. + +All three are one shape: **work performed but not recorded, or a wait bounded on the wrong +thing.** Unit tests do not cancel tasks mid-flight, do not measure teardown wall-clock, and +do not run against a destination slow enough for the race to exist. So when a change adds +background work, a timeout, a grace period, or anything cancelled at shutdown, treat +"scheduling" as its own seam: + +- **Measure the teardown cost in both states** — with work in flight and with none. A + budget that is always spent is not a budget. +- **Assert that cancellation preserves progress**, not merely that it terminates. +- **Be precise about what you are waiting for.** "Wait for the work to finish" and "wait + for the worker to finish" read identically and diverge the moment the worker is a loop. + +A fourth defect in the same work was a *test* defect of this family: a duplicate-detection +check counted workspace-wide nodes while itself creating new sessions, producing a +confident false FAIL on a system behaving perfectly. **Scope a uniqueness assertion to the +entity actually replayed**, never to a shared namespace the test is concurrently writing to. + ## Authoring data-query & navigation skills — evidence-based, against a live graph The data-query and navigation skills (`context-intelligence-graph-query`, `-derived-metrics`, diff --git a/README.md b/README.md index 684fa7e0..cd8590ff 100644 --- a/README.md +++ b/README.md @@ -688,7 +688,11 @@ See [`docs/dispatch-circuit-breaker.dot`](docs/dispatch-circuit-breaker.dot) for ### Self-healing backlog sweep -Events left undelivered by a shutdown drain or a queue overflow are no longer permanently dependent on a manual `context-intelligence-upload` run. On `on_session_ready`, each destination starts a background **backlog sweep** task that reads recent sessions' `events.jsonl` forward from a persisted **delivery watermark** — a byte offset into that session's log, one file per destination at `/delivery/.json` — rebuilds each event's payload with the same `build_payload` the live dispatcher uses, and POSTs it. The watermark only advances over the **contiguous prefix** that was actually delivered, so a mid-window failure is re-sent next pass rather than silently skipped. The sweep is cancelled cleanly in `cleanup()` and never blocks process exit. +Events left undelivered by a shutdown drain or a queue overflow are no longer permanently dependent on a manual `context-intelligence-upload` run. On `on_session_ready`, each destination starts a background **backlog sweep** that reads recent sessions' `events.jsonl` forward from a persisted **delivery watermark** — a byte offset into that session's log, one file per destination at `/delivery/.json` — rebuilds each event's payload with the same `build_payload` the live dispatcher uses, and POSTs it. The watermark only advances over the **contiguous prefix** that was actually delivered, so a mid-window failure is re-sent next pass rather than silently skipped. + +**Continuous, not one-shot.** The sweep runs a pass at session start and then repeats every `sweep_interval_seconds` (default `60.0`; set `0.0` for a single pass at session start only) for as long as the session runs. This is what keeps a busy session's backlog from growing all day: the live dispatcher's ceiling is one event per network round-trip, so a session that outpaces it needs the sweep to keep catching up, not just to catch up once at the start. + +**Exit cost.** A normal session exit is unaffected — measured at `0.000s` added when no sweep is mid-delivery, which includes the common case of nothing left to sweep. Only when a catch-up sweep is still delivering backlog at the moment of teardown does exit take longer, bounded by `sweep_close_grace_seconds` (default `2.0`; measured `2.002s` in that case). That budget is shared across all destinations — three slow destinations cost one grace period, not three. Set `sweep_close_grace_seconds: 0.0` to restore immediate cancellation. Either way, whatever the sweep delivered before being cancelled is kept: progress commits in chunks, so cancellation loses at most one in-flight chunk, never the whole pass. **Bounded, not exhaustive.** `sweep_max_sessions`, `sweep_max_events`, and `sweep_concurrency` (see the config table above) keep a single pass cheap; `sweep_max_age_hours` (default `48.0`) excludes sessions whose last event is older than the window — those are reported as stranded, never swept automatically, and need a manual `context-intelligence-upload` run (see [remote-server-troubleshooting.md](docs/remote-server-troubleshooting.md)). Set `sweep_enabled: false` to disable the sweep entirely. diff --git a/docs/remote-server-troubleshooting.md b/docs/remote-server-troubleshooting.md index 8b91d106..44c69e6f 100644 --- a/docs/remote-server-troubleshooting.md +++ b/docs/remote-server-troubleshooting.md @@ -135,6 +135,27 @@ Real output from a workstation forwarding to an Azure/APIM destination — a tex A median `queued` in the dozens or higher is Case 2. +### Why did my session take a couple of seconds longer to exit? + +- **Cause:** `sweep_close_grace_seconds` (default `2.0`) let a catch-up sweep keep running + at session teardown instead of being cancelled immediately. This only happens when a + sweep was still mid-delivery at the moment the session ended — a normal exit with + nothing in flight is unaffected (measured `0.000s` added). If you saw the delay, it + means the bundle was actively recovering backlog, not that something is wrong. +- **Shared budget:** the grace period is one shared budget across **all** destinations + for that session, not one per destination — several slow destinations still cost a + single grace window, not several. +- **Fix (if you want immediate exit instead):** + ```yaml + overrides: + hook-context-intelligence: + config: + sweep_close_grace_seconds: 0.0 + ``` + **Tradeoff:** with `0.0`, a sweep that gets cancelled mid-delivery simply resumes from + its last committed chunk on the next session — nothing is lost, it just takes more + sessions for the backlog to fully catch up. + ### ` unreachable, retrying with backoff — events still captured locally` - **Cause:** connect/read timeouts or transient network errors. The hook is retrying with From 5714e55cd91f00d17446ebbe89f349a1bbe5aaf2 Mon Sep 17 00:00:00 2001 From: colombod Date: Wed, 16 Sep 2026 14:34:37 +0000 Subject: [PATCH 08/14] fix(hook-context-intelligence): the sweep must obey each session's include/exclude The backlog sweep had NO filter evaluation at all. It selected sessions by age alone within a project directory and forwarded every one of them to whatever destinations the CURRENT session matched -- rerouting one session's events using another session's permissions. That is a leak, not an inefficiency. A project directory routinely holds sessions from several working directories: project_slug falls back to "default" when the capability is unavailable, so unrelated trees collide there. A session under a working_dir that EXCLUDES a destination could have its events swept to that destination as soon as any other session in the same directory included it. An event delivered where it was excluded cannot be recalled. The design doc claimed "the sweep introduces no new routing decisions". That was false, and this makes it true: * BacklogSweeper now REQUIRES the destination's spec (include/exclude) and re-evaluates each candidate session's own working_dir from metadata.json through the live path's own matcher (fanout.destination_is_active). No second implementation of the rules. * The gate runs BEFORE the watermark is read, before a lock is taken, before a byte is sent. An excluded session is never touched -- not even a watermark. * Routing FAILS CLOSED, inverting this module's usual bias. Every delivery guard fails toward re-sending, because a duplicate is absorbed by MERGE while a skip loses data. Routing is the opposite: a wrong send is unrecoverable, a skipped sweep is picked up next pass. An unprovable working_dir is refused and reported (sessions_blocked_unprovable), never assumed safe. * A destination with no resolvable spec gets no sweeper at all. Also fixes the related mid-session hole: apply_active_dispatchers cancelled the previous round's sweeps fire-and-forget AFTER installing the new dispatcher set. asyncio's cancel() only REQUESTS cancellation, and a sweep owns its own HTTP client and auth -- closing the dispatcher does not stop it. So excluding a destination via set_ingestion_filters could leave its sweep still delivering. Cancellation is now awaited BEFORE the swap, matching what teardown already did. Adds 9 tests: excluded session never posted, empty include matches nothing, exclude wins over include, the mixed-project-dir leak scenario, missing and blank working_dir blocked rather than assumed, and a destination without a spec getting no sweeper. Plus DTU scenario S6 asserting against a REAL server that an excluded working_dir contributes zero nodes while a permitted one in the same project directory heals. Gates: 771 module tests, 854 root tests, ruff clean, pyright 0 errors. Generated with Amplifier Co-Authored-By: Amplifier <240397093+microsoft-amplifier@users.noreply.github.com> --- ...igence-self-healing-replay-validation.yaml | 73 +++++++++ .../__init__.py | 45 +++++- .../handlers/backlog_sweep.py | 72 +++++++++ .../tests/test_backlog_sweep.py | 145 ++++++++++++++++++ .../tests/test_sweep_scheduling.py | 53 ++++++- 5 files changed, 373 insertions(+), 15 deletions(-) diff --git a/.amplifier/digital-twin-universe/profiles/context-intelligence-self-healing-replay-validation.yaml b/.amplifier/digital-twin-universe/profiles/context-intelligence-self-healing-replay-validation.yaml index 1d1bfaf0..62f8d8d2 100644 --- a/.amplifier/digital-twin-universe/profiles/context-intelligence-self-healing-replay-validation.yaml +++ b/.amplifier/digital-twin-universe/profiles/context-intelligence-self-healing-replay-validation.yaml @@ -335,6 +335,70 @@ provision: PY S5EOF + - | + cat > /root/s6_routing.sh << 'S6EOF' + . /root/_common.sh + echo "=== S6: the sweep MUST obey each session's own include/exclude ===" + # Two sessions, two working dirs, ONE project dir -- the collision that makes this + # a leak rather than an inefficiency. project_slug falls back to "default" when the + # capability is unavailable, so unrelated trees share a directory routinely. + P=/root/.amplifier/projects/-mixed + mkdir -p $P/sessions/s-allowed/context-intelligence $P/sessions/s-secret/context-intelligence + python3 - "$P" "$WORKSPACE" <<'PY' + import json, sys, pathlib, datetime + root, ws = pathlib.Path(sys.argv[1]), sys.argv[2] + now = datetime.datetime.now(datetime.timezone.utc).isoformat() + for sid, wd, suffix in (("s-allowed", "/work/public", "-allowed"), + ("s-secret", "/work/client-x", "-secret")): + d = root / "sessions" / sid / "context-intelligence" + with (d / "events.jsonl").open("w") as fh: + for i in range(15): + fh.write(json.dumps({"event": f"probe:{i}", "workspace": ws + suffix, + "timestamp": "2026-09-16T00:00:00Z", + "data": {"session_id": sid, "timestamp": "2026-09-16T00:00:00Z"}}) + "\n") + (d / "metadata.json").write_text(json.dumps({"session_id": sid, "workspace": ws + suffix, + "working_dir": wd, "started_at": now, "last_event_at": now, "status": "completed"})) + print("planted /work/public (allowed) and /work/client-x (EXCLUDED)") + PY + $CI_PY - "$WORKSPACE" <<'PY' + import asyncio, pathlib, sys + from amplifier_module_hook_context_intelligence.config_resolver import Destination + from amplifier_module_hook_context_intelligence.handlers.backlog_sweep import ( + BacklogSweeper, SweepBounds) + ws = sys.argv[1] + class A: + def headers(self): return {"Authorization": "Bearer heal-token-xyz"} + spec = Destination(name="main", url="http://127.0.0.1:8100", api_key="x", + include=("**",), exclude=("/work/client-x/**",)) + r = asyncio.run(BacklogSweeper(destination="main", url="http://127.0.0.1:8100", + auth=A(), project_dir=pathlib.Path("/root/.amplifier/projects/-mixed"), + spec=spec, bounds=SweepBounds()).run()) + print(f"delivered={r.events_delivered} filtered={r.sessions_skipped_filtered} " + f"blocked={r.sessions_blocked_unprovable}") + assert r.sessions_skipped_filtered == 1, r.sessions_skipped_filtered + assert r.events_delivered == 15, r.events_delivered + PY + sleep 12 + echo "--- server truth: the EXCLUDED workspace must be empty ---" + python3 $V nodes --server "$SERVER_URL" --token "$SERVER_TOKEN" --workspace "${WORKSPACE}-secret" + python3 $V nodes --server "$SERVER_URL" --token "$SERVER_TOKEN" --workspace "${WORKSPACE}-allowed" + python3 - < 0, f"the permitted session did not heal ({allowed} nodes)" + print(f"PASS: excluded workspace has {secret} nodes; permitted has {allowed}") + PY + # And the excluded session must not even have been TOUCHED. + test ! -e $P/sessions/s-secret/context-intelligence/delivery/main.json \ + && echo "PASS: no watermark written for the excluded session -- never opened" \ + || { echo "FAIL: the excluded session was processed"; exit 1; } + S6EOF + - amplifier --version readiness: @@ -438,6 +502,15 @@ manual_validation_steps: no_progress, a real error is recorded, and the no-progress counter increments. Self-healing must never mask a genuine outage. + - name: S6-the-sweep-obeys-include-exclude + command: bash /root/s6_routing.sh + expect: > + PASS: a session whose working_dir is EXCLUDED is never swept -- zero nodes reach + the server for it, and no watermark is even written for it -- while a permitted + session in the SAME project directory heals normally. Self-healing that ignored + include/exclude would be a leak, not an optimisation: an event delivered where it + was excluded cannot be recalled. + - name: S5-the-age-bound-is-audible command: bash /root/s5_age_bound.sh expect: > diff --git a/modules/hook-context-intelligence/amplifier_module_hook_context_intelligence/__init__.py b/modules/hook-context-intelligence/amplifier_module_hook_context_intelligence/__init__.py index 1b814ff6..87952842 100644 --- a/modules/hook-context-intelligence/amplifier_module_hook_context_intelligence/__init__.py +++ b/modules/hook-context-intelligence/amplifier_module_hook_context_intelligence/__init__.py @@ -161,6 +161,26 @@ async def apply_active_dispatchers( d.name, exc_info=True, ) + # Stop the PREVIOUS round's sweeps BEFORE the new dispatcher set goes live. + # Order and awaiting both matter: asyncio's cancel() only REQUESTS + # cancellation, so a fire-and-forget cancel leaves the old sweeps running + # against the old destination set. If this swap just EXCLUDED a destination, + # those sweeps own their own HTTP client and auth -- closing the dispatcher + # does not stop them -- and they would keep delivering to a destination the + # user just switched off. Teardown already does this correctly; this path + # must match it. + get_cap_state = getattr(coordinator, "get_capability", None) + state = get_cap_state("context_intelligence._hook_state") if get_cap_state else None + previous = list(state.get("sweep_tasks") or []) if isinstance(state, dict) else [] + if previous: + await await_sweeps_idle(previous, resolver.sweep_close_grace_seconds) + for handle in previous: + handle.cancel() + # Await the cancellations: "cancelled" must mean "actually stopped". + await asyncio.gather(*(h.task for h in previous), return_exceptions=True) + if isinstance(state, dict): + state["sweep_tasks"] = [] + await logging_handler.set_dispatchers(dispatchers) # Self-healing catch-up for anything a PREVIOUS session left undelivered. @@ -171,14 +191,10 @@ async def apply_active_dispatchers( # which set_ingestion_filters also depends on -- stays unchanged. Re-running # this function (a mid-session filter swap) cancels the previous round's # sweeps first: the destination set may have just changed underneath them. - get_cap_state = getattr(coordinator, "get_capability", None) - state = get_cap_state("context_intelligence._hook_state") if get_cap_state else None if isinstance(state, dict): - for previous in state.get("sweep_tasks") or []: - previous.cancel() - state["sweep_tasks"] = schedule_backlog_sweeps(resolver, dispatchers) + state["sweep_tasks"] = schedule_backlog_sweeps(resolver, dispatchers, active) else: - schedule_backlog_sweeps(resolver, dispatchers) + schedule_backlog_sweeps(resolver, dispatchers, active) if not destinations: log.info("context-intelligence fan-out: no destinations configured — local JSONL only") @@ -274,7 +290,9 @@ def cancel(self) -> None: self.task.cancel() -def schedule_backlog_sweeps(resolver: Any, dispatchers: list[Any]) -> list[Any]: +def schedule_backlog_sweeps( + resolver: Any, dispatchers: list[Any], destinations: dict[str, Any] | None = None +) -> list[Any]: """Start one CONTINUOUS catch-up sweep per active destination. Runs an immediate pass at session start, then repeats every @@ -306,8 +324,20 @@ def schedule_backlog_sweeps(resolver: Any, dispatchers: list[Any]) -> list[Any]: ) project_dir = resolver.base_path / resolver.project_slug + specs = destinations or {} tasks: list[Any] = [] for dispatcher in dispatchers: + spec = specs.get(dispatcher.name) + if spec is None: + # No include/exclude for this destination means its routing cannot be + # evaluated. A sweeper that cannot prove where events may go does not + # run -- refusing is recoverable, leaking is not. + log.warning( + "context-intelligence: no destination spec for %s; backlog sweep" + " disabled for it (routing cannot be verified)", + dispatcher.name, + ) + continue sweeper: Any = BacklogSweeper( destination=dispatcher.name, url=dispatcher.url, @@ -315,6 +345,7 @@ def schedule_backlog_sweeps(resolver: Any, dispatchers: list[Any]) -> list[Any]: # second Entra token or diverge from live-path auth. auth=dispatcher.auth_strategy, project_dir=project_dir, + spec=spec, bounds=bounds, timeout=resolver.dispatch_timeout, ) diff --git a/modules/hook-context-intelligence/amplifier_module_hook_context_intelligence/handlers/backlog_sweep.py b/modules/hook-context-intelligence/amplifier_module_hook_context_intelligence/handlers/backlog_sweep.py index b13d4203..e989ad5f 100644 --- a/modules/hook-context-intelligence/amplifier_module_hook_context_intelligence/handlers/backlog_sweep.py +++ b/modules/hook-context-intelligence/amplifier_module_hook_context_intelligence/handlers/backlog_sweep.py @@ -47,12 +47,15 @@ import httpx +from ..fanout import destination_is_active, normalize_match_key from ..upload import build_payload from .delivery_watermark import DeliveryWatermark, SweepLock if TYPE_CHECKING: # pragma: no cover - typing only from context_intelligence.auth import AuthStrategy + from ..config_resolver import Destination + logger = logging.getLogger(__name__) #: Defaults. Conservative on purpose: a launch must never re-POST a week of @@ -92,6 +95,13 @@ class SweepReport: sessions_skipped_age: int = 0 sessions_skipped_caught_up: int = 0 sessions_skipped_locked: int = 0 + #: In-window sessions this destination is NOT allowed to receive. Routine and + #: expected -- one project directory can hold sessions from several working + #: directories, and each one's own include/exclude decides where it may go. + sessions_skipped_filtered: int = 0 + #: In-window sessions whose working_dir could not be established, so their + #: routing could not be PROVEN. Never swept. Surfaced, never silent. + sessions_blocked_unprovable: int = 0 events_delivered: int = 0 events_failed: int = 0 bytes_advanced: int = 0 @@ -219,10 +229,15 @@ def __init__( url: str, auth: AuthStrategy, project_dir: Path, + spec: Destination, bounds: SweepBounds | None = None, timeout: float = 10.0, ) -> None: self._destination = destination + #: The destination's OWN include/exclude. Required, not optional: without + #: it this class cannot answer "may this session's events go here?", and + #: a sweeper that cannot answer that must not run. + self._spec = spec self._url = url.rstrip("/") self._endpoint = f"{self._url}/events" self._auth = auth @@ -262,6 +277,42 @@ async def _post(self, client: httpx.AsyncClient, payload: dict[str, Any]) -> tup return True, "" return False, f"HTTP {response.status_code}: {response.text[:200]}" + # -- routing: may this session's events go to this destination? ------- + + def _routing_verdict(self, session_dir: Path, metadata: dict[str, Any]) -> tuple[bool, str]: + """Re-evaluate THIS session's include/exclude for THIS destination. + + Load-bearing, and the reason it exists is worth stating plainly: the + sweep walks a PROJECT directory, but a project directory can hold + sessions from several different working directories -- ``project_slug`` + falls back to ``"default"`` when the capability is unavailable, so + unrelated trees collide there routinely. Without this check the sweep + would forward every session it finds to whatever destinations the + CURRENT session happens to match, which silently reroutes one session's + events using another session's permissions. That is a leak, not an + inefficiency: an event delivered somewhere it was excluded from cannot be + recalled. + + So routing INVERTS this module's usual failure bias. Every delivery guard + elsewhere fails toward re-sending, because a duplicate is absorbed by the + server's MERGE while a skip loses data. Here the opposite holds: a + wrongly-sent event is unrecoverable, a wrongly-skipped one is picked up + by the next sweep. **When routing cannot be proven, it is refused.** + + The matcher is the live path's own (``fanout``), never a second + implementation of the rules. + """ + working_dir = metadata.get("working_dir") + if not isinstance(working_dir, str) or not working_dir.strip(): + return False, "working_dir missing from metadata.json -- routing unprovable" + try: + match_key = normalize_match_key(working_dir) + except ValueError as exc: + return False, f"working_dir unusable ({exc}) -- routing unprovable" + if not destination_is_active(self._spec, match_key): + return False, f"excluded by this destination's include/exclude for {working_dir}" + return True, "" + # -- one session ---------------------------------------------------- async def _sweep_session( @@ -406,6 +457,27 @@ async def run(self) -> SweepReport: for session_dir, metadata in sessions: if budget <= 0: break + # ROUTING GATE -- before the watermark is read, before a lock + # is taken, before a single byte is sent. A session this + # destination may not receive is not "skipped later", it is + # never touched. + allowed, why = self._routing_verdict(session_dir, metadata) + if not allowed: + if "unprovable" in why: + report.sessions_blocked_unprovable += 1 + report.notes.append(f"BLOCKED {session_dir}: {why}") + logger.warning( + "%s: refusing to sweep %s -- %s", + self._destination, + session_dir, + why, + ) + else: + report.sessions_skipped_filtered += 1 + logger.debug( + "%s: not routed this session -- %s", self._destination, why + ) + continue watermark, _ = DeliveryWatermark.load( session_dir, self._destination, destination_url=self._url ) diff --git a/modules/hook-context-intelligence/tests/test_backlog_sweep.py b/modules/hook-context-intelligence/tests/test_backlog_sweep.py index 75f84db8..2e826233 100644 --- a/modules/hook-context-intelligence/tests/test_backlog_sweep.py +++ b/modules/hook-context-intelligence/tests/test_backlog_sweep.py @@ -114,12 +114,23 @@ async def __aexit__(self, *exc: object) -> None: return None +class _Spec: + """Stand-in with the two fields fanout reads. Mirrors config_resolver.Destination.""" + + def __init__(self, include: tuple[str, ...] = ("**",), exclude: tuple[str, ...] = ()) -> None: + self.include = include + self.exclude = exclude + + def _sweeper(project: Path, **overrides: Any) -> BacklogSweeper: kwargs: dict[str, Any] = { "destination": DEST, "url": URL, "auth": _Auth(), "project_dir": project, + # Default to "everything allowed" so the existing delivery tests keep + # testing DELIVERY. Routing is exercised explicitly below. + "spec": _Spec(include=("**",)), "bounds": SweepBounds(), } kwargs.update(overrides) @@ -423,3 +434,137 @@ async def post(self, url: str, **kwargs: Any) -> _FakeResponse: watermark, _ = DeliveryWatermark.load(session_dir, DEST, destination_url=URL) assert watermark.offset == 0 assert watermark.last_outcome == "no_progress" + + +@pytest.mark.asyncio +class TestRoutingIsEnforced: + """The sweep MUST obey each session's own include/exclude. + + A project directory can hold sessions from several working directories -- + `project_slug` falls back to "default" when the capability is unavailable, so + unrelated trees collide there routinely. Forwarding every session it finds to + whatever the CURRENT session matched would reroute one session's events using + another session's permissions. An event delivered where it was excluded cannot + be recalled, so this is a leak, not an inefficiency. + + Routing therefore INVERTS this module's usual failure bias: everything else + fails toward re-sending, this fails toward NOT sending. + """ + + async def test_excluded_session_is_never_posted( + self, tmp_path: Path, monkeypatch: pytest.MonkeyPatch + ) -> None: + _make_session(tmp_path, "secret", events=5) + client = _FakeClient() + monkeypatch.setattr( + "amplifier_module_hook_context_intelligence.handlers.backlog_sweep.httpx.AsyncClient", + lambda *a, **k: client, + ) + report = await _sweeper(tmp_path, spec=_Spec(include=("**",), exclude=("/work/**",))).run() + + assert client.posted == [], "events were sent to an EXCLUDED destination" + assert report.events_delivered == 0 + assert report.sessions_skipped_filtered == 1 + + async def test_included_session_is_swept( + self, tmp_path: Path, monkeypatch: pytest.MonkeyPatch + ) -> None: + _make_session(tmp_path, "ok", events=5) + client = _FakeClient() + monkeypatch.setattr( + "amplifier_module_hook_context_intelligence.handlers.backlog_sweep.httpx.AsyncClient", + lambda *a, **k: client, + ) + report = await _sweeper(tmp_path, spec=_Spec(include=("/work/**",))).run() + assert report.events_delivered == 5 + assert report.sessions_skipped_filtered == 0 + + async def test_empty_include_matches_nothing( + self, tmp_path: Path, monkeypatch: pytest.MonkeyPatch + ) -> None: + """An empty include is 'nowhere', never 'everywhere'.""" + _make_session(tmp_path, "s1", events=5) + client = _FakeClient() + monkeypatch.setattr( + "amplifier_module_hook_context_intelligence.handlers.backlog_sweep.httpx.AsyncClient", + lambda *a, **k: client, + ) + report = await _sweeper(tmp_path, spec=_Spec(include=())).run() + assert client.posted == [] + assert report.sessions_skipped_filtered == 1 + + async def test_exclude_wins_over_include( + self, tmp_path: Path, monkeypatch: pytest.MonkeyPatch + ) -> None: + _make_session(tmp_path, "s1", events=5) + client = _FakeClient() + monkeypatch.setattr( + "amplifier_module_hook_context_intelligence.handlers.backlog_sweep.httpx.AsyncClient", + lambda *a, **k: client, + ) + report = await _sweeper( + tmp_path, spec=_Spec(include=("/work/**",), exclude=("/work/x/**",)) + ).run() + assert client.posted == [] + assert report.sessions_skipped_filtered == 1 + + async def test_mixed_project_dir_routes_each_session_by_its_own_working_dir( + self, tmp_path: Path, monkeypatch: pytest.MonkeyPatch + ) -> None: + """THE leak scenario: two working dirs colliding in one project dir.""" + allowed = _make_session(tmp_path, "public", events=4) + secret = _make_session(tmp_path, "client-x", events=4) + for session_dir, wd in ((allowed, "/work/public"), (secret, "/work/client-x")): + meta = json.loads((session_dir / "metadata.json").read_text()) + meta["working_dir"] = wd + (session_dir / "metadata.json").write_text(json.dumps(meta)) + + client = _FakeClient() + monkeypatch.setattr( + "amplifier_module_hook_context_intelligence.handlers.backlog_sweep.httpx.AsyncClient", + lambda *a, **k: client, + ) + report = await _sweeper( + tmp_path, spec=_Spec(include=("**",), exclude=("/work/client-x/**",)) + ).run() + + assert report.events_delivered == 4, "the permitted session should still heal" + assert report.sessions_skipped_filtered == 1 + secret_wm = secret / "delivery" / f"{DEST}.json" + assert not secret_wm.exists(), "the excluded session was touched at all" + + async def test_missing_working_dir_is_blocked_not_assumed( + self, tmp_path: Path, monkeypatch: pytest.MonkeyPatch + ) -> None: + """Fail CLOSED: unprovable routing is refused, and said out loud.""" + session_dir = _make_session(tmp_path, "s1", events=5) + meta = json.loads((session_dir / "metadata.json").read_text()) + del meta["working_dir"] + (session_dir / "metadata.json").write_text(json.dumps(meta)) + + client = _FakeClient() + monkeypatch.setattr( + "amplifier_module_hook_context_intelligence.handlers.backlog_sweep.httpx.AsyncClient", + lambda *a, **k: client, + ) + report = await _sweeper(tmp_path, spec=_Spec(include=("**",))).run() + + assert client.posted == [], "swept a session whose routing could not be proven" + assert report.sessions_blocked_unprovable == 1 + assert any("BLOCKED" in n for n in report.notes) + + async def test_blank_working_dir_is_blocked( + self, tmp_path: Path, monkeypatch: pytest.MonkeyPatch + ) -> None: + session_dir = _make_session(tmp_path, "s1", events=5) + meta = json.loads((session_dir / "metadata.json").read_text()) + meta["working_dir"] = " " + (session_dir / "metadata.json").write_text(json.dumps(meta)) + client = _FakeClient() + monkeypatch.setattr( + "amplifier_module_hook_context_intelligence.handlers.backlog_sweep.httpx.AsyncClient", + lambda *a, **k: client, + ) + report = await _sweeper(tmp_path, spec=_Spec(include=("**",))).run() + assert client.posted == [] + assert report.sessions_blocked_unprovable == 1 diff --git a/modules/hook-context-intelligence/tests/test_sweep_scheduling.py b/modules/hook-context-intelligence/tests/test_sweep_scheduling.py index a4ebd966..486298a6 100644 --- a/modules/hook-context-intelligence/tests/test_sweep_scheduling.py +++ b/modules/hook-context-intelligence/tests/test_sweep_scheduling.py @@ -46,7 +46,21 @@ def __init__(self, tmp_path: Any, **overrides: Any) -> None: setattr(self, key, value) +class _Spec: + """Minimal destination spec. The scheduler now REQUIRES one per destination: + a sweeper that cannot evaluate include/exclude is not started at all.""" + + include = ("**",) + exclude = () + + +#: Keyed by dispatcher name, as apply_active_dispatchers passes them. +SPECS = {"main": _Spec()} + + class _Dispatcher: + """Mutable name so a spec-less destination can be simulated.""" + def __init__(self) -> None: self.name = "main" self.url = "https://ci.example.com" @@ -75,7 +89,10 @@ def test_garbage_falls_back_to_default(self) -> None: class TestSchedulingLoop: async def test_disabled_sweep_schedules_nothing(self, tmp_path: Any) -> None: assert ( - schedule_backlog_sweeps(_Resolver(tmp_path, sweep_enabled=False), [_Dispatcher()]) == [] + schedule_backlog_sweeps( + _Resolver(tmp_path, sweep_enabled=False), [_Dispatcher()], SPECS + ) + == [] ) async def test_single_pass_when_interval_is_zero( @@ -93,7 +110,7 @@ async def fake_run(self: Any) -> SweepReport: fake_run, ) handles = schedule_backlog_sweeps( - _Resolver(tmp_path, sweep_interval_seconds=0.0), [_Dispatcher()] + _Resolver(tmp_path, sweep_interval_seconds=0.0), [_Dispatcher()], SPECS ) await asyncio.gather(*(h.task for h in handles)) assert runs == 1 @@ -114,7 +131,7 @@ async def fake_run(self: Any) -> SweepReport: fake_run, ) handles = schedule_backlog_sweeps( - _Resolver(tmp_path, sweep_interval_seconds=0.01), [_Dispatcher()] + _Resolver(tmp_path, sweep_interval_seconds=0.01), [_Dispatcher()], SPECS ) await asyncio.sleep(0.08) for handle in handles: @@ -139,7 +156,7 @@ async def fake_run(self: Any) -> SweepReport: fake_run, ) handles = schedule_backlog_sweeps( - _Resolver(tmp_path, sweep_interval_seconds=0.01), [_Dispatcher()] + _Resolver(tmp_path, sweep_interval_seconds=0.01), [_Dispatcher()], SPECS ) await asyncio.sleep(0.06) for handle in handles: @@ -159,7 +176,7 @@ async def fake_run(self: Any) -> SweepReport: fake_run, ) handles = schedule_backlog_sweeps( - _Resolver(tmp_path, sweep_interval_seconds=1.0), [_Dispatcher()] + _Resolver(tmp_path, sweep_interval_seconds=1.0), [_Dispatcher()], SPECS ) await asyncio.sleep(0) for handle in handles: @@ -272,7 +289,7 @@ async def instant(self: Any) -> SweepReport: instant, ) handles = schedule_backlog_sweeps( - _Resolver(tmp_path, sweep_interval_seconds=60.0), [_Dispatcher()] + _Resolver(tmp_path, sweep_interval_seconds=60.0), [_Dispatcher()], SPECS ) await asyncio.sleep(0.05) # first pass done; task now idle between passes assert await self._cost(handles, grace=2.0) < 0.2, ( @@ -291,7 +308,7 @@ async def slow(self: Any) -> SweepReport: slow, ) handles = schedule_backlog_sweeps( - _Resolver(tmp_path, sweep_interval_seconds=60.0), [_Dispatcher()] + _Resolver(tmp_path, sweep_interval_seconds=60.0), [_Dispatcher()], SPECS ) await asyncio.sleep(0.05) cost = await self._cost(handles, grace=0.3) @@ -309,7 +326,7 @@ async def slow(self: Any) -> SweepReport: slow, ) handles = schedule_backlog_sweeps( - _Resolver(tmp_path, sweep_interval_seconds=60.0), [_Dispatcher()] + _Resolver(tmp_path, sweep_interval_seconds=60.0), [_Dispatcher()], SPECS ) await asyncio.sleep(0.05) assert await self._cost(handles, grace=0.0) < 0.2 @@ -334,3 +351,23 @@ async def slow(self: Any) -> SweepReport: await asyncio.sleep(0.05) cost = await self._cost(handles, grace=0.3) assert cost < 1.0, f"budget multiplied by destination count: {cost:.3f}s" + + +@pytest.mark.asyncio +class TestSweeperRequiresARoutingSpec: + """No include/exclude, no sweeper. Refusing is recoverable; leaking is not.""" + + async def test_destination_without_a_spec_gets_no_sweeper(self, tmp_path: Any) -> None: + handles = schedule_backlog_sweeps(_Resolver(tmp_path), [_Dispatcher()], {}) + assert handles == [] + + async def test_only_specced_destinations_are_swept(self, tmp_path: Any) -> None: + other = _Dispatcher() + other.name = "no-spec" + handles = schedule_backlog_sweeps( + _Resolver(tmp_path, sweep_interval_seconds=0.0), [_Dispatcher(), other], SPECS + ) + assert len(handles) == 1 + for handle in handles: + handle.cancel() + await asyncio.gather(*(h.task for h in handles), return_exceptions=True) From e35aa33d6d5e9b1e2a8bdf3aac019b9f4d922eb2 Mon Sep 17 00:00:00 2001 From: colombod Date: Thu, 17 Sep 2026 23:05:56 +0000 Subject: [PATCH 09/14] fix(hook-context-intelligence): don't let excluded sessions starve the sweep budget Addresses review on #117. STARVATION. select_candidates() sliced to sweep_max_sessions BEFORE routing eligibility was known, so the oldest N sessions could all be ones a destination may not receive. Selection is deterministic (oldest first), so the same N were chosen on every pass and a permitted session behind them was never reached -- until it aged out of the 48h window, at which point it became permanently excluded from automatic recovery too. The routing gate added in the previous commit is what made this reachable: filtering without also making the bound filter-aware turned a correct refusal into an indefinite block. Reported repro (20 older excluded sessions + 1 newer allowed): before: {'sessions_considered': 20, 'filtered': 20, 'delivered': 0, 'posted': []} after: {'sessions_considered': 21, 'filtered': 20, 'delivered': 4, 'posted': ['allowed']} select_candidates now returns every in-window candidate and the sweeper spends sweep_max_sessions only on sessions that pass the routing gate. Sessions that are filtered or blocked are not charged against the budget -- work that was never this destination's to do should not consume its allowance. The bound still bounds: a separate test pins that eligible work is still capped. TYPE CHECK. _persist() returned advanced_now with no return annotation, so Pyright inferred None and rejected the addition into report.bytes_advanced. Annotated -> int. Module-level Pyright is now 0 errors. The root-vs-module Pyright gap is itself the lesson: the repo-root invocation reported 0 errors while the module reported 2. AGENTS.md now says to run pyright from the module directory as well, with this as the worked example. REBASE. Rebased onto main (19da724) and resolved the README and remote-server-troubleshooting conflicts in main's favour for the shutdown-timeout documentation -- close_drain_timeout is 20.0 from #111, and the Case 1 / Case 2 split is kept -- with the sweep documentation layered on top. Case 2's remedy is updated: the deep-backlog case is now recovered automatically, with the watermark fields to confirm it and the signals that mean something is genuinely wrong. Adds 3 regression tests: the reported 20-excluded-plus-1-allowed scenario, that max_sessions still bounds eligible work, and that unprovable-routing sessions do not consume the budget either. Gates: 780 module tests, 857 root tests, ruff clean, pyright 0 errors from BOTH the repo root and the module directory. Generated with Amplifier Co-Authored-By: Amplifier <240397093+microsoft-amplifier@users.noreply.github.com> --- AGENTS.md | 7 ++ .../handlers/backlog_sweep.py | 25 ++++- .../tests/test_backlog_sweep.py | 96 ++++++++++++++++++- 3 files changed, 122 insertions(+), 6 deletions(-) diff --git a/AGENTS.md b/AGENTS.md index 9b7e7349..a84e0a07 100644 --- a/AGENTS.md +++ b/AGENTS.md @@ -73,9 +73,16 @@ Run these before calling anything done: uv run pytest # in modules/tool-context-intelligence-query (module suite) uv run pytest # in the repo root (tests/, top-level suite) uv run ruff check . && uv run ruff format --check . && uv run pyright +uv run pyright # ALSO in modules/ (see note below) scripts/validate-full.sh # then inspect env_check, build_check, quality_classification, and final_report ``` +**Run `pyright` from the MODULE directory too, not only the repo root.** The root +invocation does not reproduce a module's own Pyright configuration, so module-local type +errors pass the root gate and surface later in review. Real instance: a helper missing a +`-> int` return annotation was inferred as `None` and its result rejected at the call +site — **2 errors** from `modules/hook-context-intelligence`, **0** from the repo root. + **Green unit tests are the FLOOR, not proof of done.** This bundle wires **skills, modes, networking, tools, and auth** — capabilities whose real behaviour lives at **seams** (see *Seam Awareness* below), where a passing mock can hide a real break. Real, recent proof: two diff --git a/modules/hook-context-intelligence/amplifier_module_hook_context_intelligence/handlers/backlog_sweep.py b/modules/hook-context-intelligence/amplifier_module_hook_context_intelligence/handlers/backlog_sweep.py index e989ad5f..759e7201 100644 --- a/modules/hook-context-intelligence/amplifier_module_hook_context_intelligence/handlers/backlog_sweep.py +++ b/modules/hook-context-intelligence/amplifier_module_hook_context_intelligence/handlers/backlog_sweep.py @@ -164,6 +164,16 @@ def select_candidates( the sweep can never wander into another project's sessions. Oldest-first so a backlog drains in the order it accumulated. """ + """(continued) The ``max_sessions`` bound is applied by the CALLER, not here. + + Slicing to ``max_sessions`` before routing eligibility is known starves the + sweep: the oldest N sessions may all be ones this destination may not + receive, and because selection is deterministic (oldest first) the same N + are chosen on every pass. A permitted session behind them is never reached, + and eventually ages out of the window -- at which point it is permanently + excluded from automatic recovery too. So this returns every in-window + candidate and lets the caller spend its budget only on eligible ones. + """ now = now or datetime.now(UTC) cutoff = now - timedelta(hours=bounds.max_age_hours) sessions_root = project_dir / "sessions" @@ -196,8 +206,7 @@ def select_candidates( in_window.append((last, session_dir, metadata)) in_window.sort(key=lambda item: item[0]) - selected = [(sd, md) for _, sd, md in in_window[: bounds.max_sessions]] - return selected, stranded, oldest_age + return [(sd, md) for _, sd, md in in_window], stranded, oldest_age def iter_records_from(events_path: Path, offset: int): @@ -389,7 +398,7 @@ async def _sweep_session( first_error: str | None = None stop = False - def _persist(outcome: str) -> None: + def _persist(outcome: str) -> int: advanced_now = prefix_end - watermark.offset watermark.offset = prefix_end watermark.delivered_lines += delivered_count @@ -452,10 +461,14 @@ async def run(self) -> SweepReport: report.oldest_stranded_age_hours = oldest_age budget = self._bounds.max_events + #: Session budget. Decremented ONLY for sessions this destination is + #: actually allowed to receive -- see select_candidates' docstring for + #: the starvation this avoids. + session_budget = self._bounds.max_sessions try: async with httpx.AsyncClient() as client: for session_dir, metadata in sessions: - if budget <= 0: + if budget <= 0 or session_budget <= 0: break # ROUTING GATE -- before the watermark is read, before a lock # is taken, before a single byte is sent. A session this @@ -477,7 +490,11 @@ async def run(self) -> SweepReport: logger.debug( "%s: not routed this session -- %s", self._destination, why ) + # Deliberately NOT charged against session_budget: an + # ineligible session is not work this destination chose + # to skip, it is work that was never its to do. continue + session_budget -= 1 watermark, _ = DeliveryWatermark.load( session_dir, self._destination, destination_url=self._url ) diff --git a/modules/hook-context-intelligence/tests/test_backlog_sweep.py b/modules/hook-context-intelligence/tests/test_backlog_sweep.py index 2e826233..dc850076 100644 --- a/modules/hook-context-intelligence/tests/test_backlog_sweep.py +++ b/modules/hook-context-intelligence/tests/test_backlog_sweep.py @@ -157,11 +157,18 @@ def test_out_of_window_session_is_stranded_and_reported(self, tmp_path: Path) -> assert stranded == 1 assert oldest > 48, "the stranded age must be reported so the bound is audible" - def test_max_sessions_caps_the_pass(self, tmp_path: Path) -> None: + def test_returns_every_in_window_candidate_and_does_not_cap(self, tmp_path: Path) -> None: + """The cap is the SWEEPER's job, deliberately. + + Capping here, before routing eligibility is known, starves the sweep: the + oldest N sessions may all be ineligible for this destination, and since + selection is deterministic the same N are picked every pass. See + TestRoutingDoesNotStarveTheBudget. + """ for i in range(5): _make_session(tmp_path, f"s{i}", age_hours=1.0) selected, _, _ = select_candidates(tmp_path, SweepBounds(max_sessions=2)) - assert len(selected) == 2 + assert len(selected) == 5 def test_oldest_first(self, tmp_path: Path) -> None: """A backlog drains in the order it accumulated.""" @@ -568,3 +575,88 @@ async def test_blank_working_dir_is_blocked( report = await _sweeper(tmp_path, spec=_Spec(include=("**",))).run() assert client.posted == [] assert report.sessions_blocked_unprovable == 1 + + +@pytest.mark.asyncio +class TestRoutingDoesNotStarveTheBudget: + """`max_sessions` must be spent on ELIGIBLE sessions, never on excluded ones. + + Regression for the review finding: `select_candidates` used to slice to + `max_sessions` BEFORE routing eligibility was known. Because selection is + deterministic (oldest first), the same excluded sessions were chosen on every + pass, so a permitted session behind them was never reached -- and eventually + aged out of the window, at which point it was permanently excluded from + automatic recovery too. Reported symptom: + + {'sessions_considered': 20, 'filtered': 20, 'delivered': 0} + """ + + async def test_twenty_excluded_plus_one_allowed_still_delivers_the_allowed_one( + self, tmp_path: Path, monkeypatch: pytest.MonkeyPatch + ) -> None: + now = datetime.now(UTC) + # 20 OLDER excluded sessions -- they sort first, so they used to consume + # the entire session budget before the permitted one was even looked at. + for i in range(20): + session_dir = _make_session(tmp_path, f"blocked-{i:02d}", events=2, age_hours=10 + i) + meta = json.loads((session_dir / "metadata.json").read_text()) + meta["working_dir"] = "/work/client-x" + (session_dir / "metadata.json").write_text(json.dumps(meta)) + allowed = _make_session(tmp_path, "allowed", events=4, age_hours=1.0) + meta = json.loads((allowed / "metadata.json").read_text()) + meta["working_dir"] = "/work/public" + (allowed / "metadata.json").write_text(json.dumps(meta)) + assert now # keeps the import honest + + client = _FakeClient() + monkeypatch.setattr( + "amplifier_module_hook_context_intelligence.handlers.backlog_sweep.httpx.AsyncClient", + lambda *a, **k: client, + ) + report = await _sweeper( + tmp_path, + spec=_Spec(include=("**",), exclude=("/work/client-x/**",)), + bounds=SweepBounds(max_sessions=20), + ).run() + + assert report.sessions_skipped_filtered == 20 + assert report.events_delivered == 4, ( + "the permitted session was starved: 20 excluded sessions consumed the " + "session budget before routing eligibility was evaluated" + ) + assert len(client.posted) == 4 + + async def test_max_sessions_still_bounds_eligible_work( + self, tmp_path: Path, monkeypatch: pytest.MonkeyPatch + ) -> None: + """The bound must still bound -- the fix must not make it unlimited.""" + for i in range(6): + _make_session(tmp_path, f"s{i}", events=3, age_hours=1 + i) + client = _FakeClient() + monkeypatch.setattr( + "amplifier_module_hook_context_intelligence.handlers.backlog_sweep.httpx.AsyncClient", + lambda *a, **k: client, + ) + report = await _sweeper(tmp_path, bounds=SweepBounds(max_sessions=2)).run() + assert report.sessions_swept == 2 + assert report.events_delivered == 6 + + async def test_blocked_sessions_do_not_consume_the_budget_either( + self, tmp_path: Path, monkeypatch: pytest.MonkeyPatch + ) -> None: + """Unprovable routing is not this destination's work to skip.""" + for i in range(3): + session_dir = _make_session(tmp_path, f"nowd-{i}", events=2, age_hours=10 + i) + meta = json.loads((session_dir / "metadata.json").read_text()) + del meta["working_dir"] + (session_dir / "metadata.json").write_text(json.dumps(meta)) + _make_session(tmp_path, "good", events=5, age_hours=1.0) + + client = _FakeClient() + monkeypatch.setattr( + "amplifier_module_hook_context_intelligence.handlers.backlog_sweep.httpx.AsyncClient", + lambda *a, **k: client, + ) + report = await _sweeper(tmp_path, bounds=SweepBounds(max_sessions=3)).run() + assert report.sessions_blocked_unprovable == 3 + assert report.events_delivered == 5 From 7398d9e53dafc9e9ef34cf1b8fbcfde4571c1456 Mon Sep 17 00:00:00 2001 From: colombod Date: Fri, 18 Sep 2026 13:44:21 +0000 Subject: [PATCH 10/14] test(dtu): make the replay profile run green end to end Ran the profile against a real context-intelligence-server 6.7.0 + real Neo4j. S1/S2/S3 passed; S4/S5/S6 did not, and every failure was in the HARNESS rather than the code. Fixed here, because a scenario that fails for an environmental reason trains you to ignore it, and one that PASSES for the wrong reason is worse. * S4/S5 constructed BacklogSweeper without the now-required `spec`. The routing gate made it mandatory; these two scenarios are about outage and the age bound, so both pass include=("**",) and let the gate through. * S5 and S6 carried a HARDCODED bearer token from an earlier run. S6 failed honestly (delivered=0, every POST 401). S5 was the dangerous one: it asserts ZERO delivered to prove the age bound, and a bad token produces zero as well -- it would have passed while proving nothing. Both now read SERVER_TOKEN. * S6 asserts events_failed == 0 before asserting the routing result, so a delivery fault can never again masquerade as a filter decision. * _common.sh sourced ci-verify.env without exporting, so the vars were invisible to the python child processes. Now exported. * S6 planted into a fixed project dir, so a re-run found the permitted session already swept (watermark at EOF) and reported delivered=0. Unique per invocation now -- the same "reused namespace manufactures a false result" trap already fixed for the workspace name. * new-handlers-importable used a bare PYTHONPATH import, which cannot satisfy pathspec (amplifier resolves module deps at session load, not into its own interpreter). It now runs under `uv run --with`, and additionally asserts the routing gate is present and that `spec` is a required argument. Final result, all six green against real infrastructure: S1 reproduce 17 :Event for 27 records; watermark 131301/135477 S2 heal watermark to EOF (135477), no user action S3 duplicate-free session nodes 26 -> 26 after a full forced replay S4 outage loud offset stayed 0, no_progress, real ConnectError S5 age bound 0 sent, 1 stranded session reported at 168h S6 routing EXCLUDED workspace 0 nodes, permitted 16, no watermark written for the excluded session Generated with Amplifier Co-Authored-By: Amplifier <240397093+microsoft-amplifier@users.noreply.github.com> --- ...igence-self-healing-replay-validation.yaml | 66 ++++++++++++++----- 1 file changed, 50 insertions(+), 16 deletions(-) diff --git a/.amplifier/digital-twin-universe/profiles/context-intelligence-self-healing-replay-validation.yaml b/.amplifier/digital-twin-universe/profiles/context-intelligence-self-healing-replay-validation.yaml index 62f8d8d2..8157b77d 100644 --- a/.amplifier/digital-twin-universe/profiles/context-intelligence-self-healing-replay-validation.yaml +++ b/.amplifier/digital-twin-universe/profiles/context-intelligence-self-healing-replay-validation.yaml @@ -178,6 +178,9 @@ provision: cat > /root/_common.sh << 'COMMONEOF' set -euo pipefail . /root/ci-verify.env + # EXPORT, not just set: the scenario scripts run python as a CHILD process, + # and a sourced-but-unexported var is invisible to it. + export SERVER_URL SERVER_TOKEN WORKSPACE PROJECTS export PATH="/root/.local/bin:$PATH" V=/root/support/verify.py # The hook module is loaded from the CLI-resolved bundle cache, not from the @@ -286,14 +289,19 @@ provision: # A destination that is genuinely broken: nothing is listening on 59999. $CI_PY - <<'PY' import asyncio + from amplifier_module_hook_context_intelligence.config_resolver import Destination from amplifier_module_hook_context_intelligence.handlers.backlog_sweep import ( BacklogSweeper, SweepBounds) class A: def headers(self): return {"Authorization": "Bearer x"} import pathlib + # include "**" -- this scenario is about OUTAGE, not routing; the gate must + # let the session through so the failure being measured is the network one. + spec = Destination(name="main", url="http://127.0.0.1:59999", api_key="x", + include=("**",), exclude=()) r = asyncio.run(BacklogSweeper(destination="main", url="http://127.0.0.1:59999", auth=A(), project_dir=pathlib.Path("/root/.amplifier/projects/-outage"), - bounds=SweepBounds()).run()) + spec=spec, bounds=SweepBounds()).run()) print("delivered:", r.events_delivered, "failed:", r.events_failed) PY python3 $V stalled --session-dir "$SD" --destination main @@ -319,14 +327,22 @@ provision: "working_dir":"/ancient","started_at":old,"last_event_at":old,"status":"completed"})) PY $CI_PY - <<'PY' - import asyncio, pathlib + import asyncio, os, pathlib + from amplifier_module_hook_context_intelligence.config_resolver import Destination from amplifier_module_hook_context_intelligence.handlers.backlog_sweep import ( BacklogSweeper, SweepBounds) class A: - def headers(self): return {"Authorization": "Bearer x"} + def headers(self): return {"Authorization": f"Bearer {TOKEN}"} + # Real token: this scenario asserts ZERO delivered because of the age + # bound. With a bad token it would assert zero for the wrong reason and + # pass while proving nothing. + TOKEN = os.environ["SERVER_TOKEN"] + # include "**" -- this scenario is about the AGE BOUND, not routing. + spec = Destination(name="main", url="http://127.0.0.1:8100", api_key="x", + include=("**",), exclude=()) r = asyncio.run(BacklogSweeper(destination="main", url="http://127.0.0.1:8100", auth=A(), project_dir=pathlib.Path("/root/.amplifier/projects/-ancient"), - bounds=SweepBounds(max_age_hours=48.0)).run()) + spec=spec, bounds=SweepBounds(max_age_hours=48.0)).run()) assert r.events_delivered == 0, f"BOUND VIOLATED: sent {r.events_delivered} ancient events" assert r.stranded_sessions == 1, r.stranded_sessions assert r.oldest_stranded_age_hours > 48, r.oldest_stranded_age_hours @@ -342,7 +358,9 @@ provision: # Two sessions, two working dirs, ONE project dir -- the collision that makes this # a leak rather than an inefficiency. project_slug falls back to "default" when the # capability is unavailable, so unrelated trees share a directory routinely. - P=/root/.amplifier/projects/-mixed + # Unique per invocation: a fixed path lets a re-run find the allowed + # session already swept (watermark at EOF) and report delivered=0. + P=/root/.amplifier/projects/-mixed-$(date +%s%N) mkdir -p $P/sessions/s-allowed/context-intelligence $P/sessions/s-secret/context-intelligence python3 - "$P" "$WORKSPACE" <<'PY' import json, sys, pathlib, datetime @@ -360,21 +378,26 @@ provision: "working_dir": wd, "started_at": now, "last_event_at": now, "status": "completed"})) print("planted /work/public (allowed) and /work/client-x (EXCLUDED)") PY - $CI_PY - "$WORKSPACE" <<'PY' - import asyncio, pathlib, sys + $CI_PY - "$WORKSPACE" "$P" <<'PY' + import asyncio, os, pathlib, sys from amplifier_module_hook_context_intelligence.config_resolver import Destination from amplifier_module_hook_context_intelligence.handlers.backlog_sweep import ( BacklogSweeper, SweepBounds) ws = sys.argv[1] + TOKEN = os.environ["SERVER_TOKEN"] class A: - def headers(self): return {"Authorization": "Bearer heal-token-xyz"} + def headers(self): return {"Authorization": f"Bearer {TOKEN}"} spec = Destination(name="main", url="http://127.0.0.1:8100", api_key="x", include=("**",), exclude=("/work/client-x/**",)) r = asyncio.run(BacklogSweeper(destination="main", url="http://127.0.0.1:8100", - auth=A(), project_dir=pathlib.Path("/root/.amplifier/projects/-mixed"), + auth=A(), project_dir=pathlib.Path(sys.argv[2]), spec=spec, bounds=SweepBounds()).run()) - print(f"delivered={r.events_delivered} filtered={r.sessions_skipped_filtered} " - f"blocked={r.sessions_blocked_unprovable}") + print(f"delivered={r.events_delivered} failed={r.events_failed} " + f"filtered={r.sessions_skipped_filtered} " + f"blocked={r.sessions_blocked_unprovable} err={r.last_error}") + # `failed` is printed and asserted: without it an auth fault reads exactly + # like a routing result (delivered=0) and the scenario lies. + assert r.events_failed == 0, f"delivery faults, not a routing result: {r.last_error}" assert r.sessions_skipped_filtered == 1, r.sessions_skipped_filtered assert r.events_delivered == 15, r.events_delivered PY @@ -394,7 +417,7 @@ provision: print(f"PASS: excluded workspace has {secret} nodes; permitted has {allowed}") PY # And the excluded session must not even have been TOUCHED. - test ! -e $P/sessions/s-secret/context-intelligence/delivery/main.json \ + test ! -e "$P/sessions/s-secret/context-intelligence/delivery/main.json" \ && echo "PASS: no watermark written for the excluded session -- never opened" \ || { echo "FAIL: the excluded session was processed"; exit 1; } S6EOF @@ -453,15 +476,26 @@ readiness: PY - name: new-handlers-importable + # `uv run --with` supplies the hook's declared deps. The tool venv does not + # carry pathspec -- amplifier resolves module dependencies at session load + # time, not into its own interpreter -- so a bare PYTHONPATH import of + # backlog_sweep (which imports fanout, which imports pathspec) fails for a + # reason that says nothing about the code under test. command: | C=$(ls -d /root/.amplifier/cache/amplifier-bundle-context-intelligence-* | head -1) - PYTHONPATH="$C:$C/modules/hook-context-intelligence" \ - /root/.local/share/uv/tools/amplifier/bin/python - <<'PY' + cd "$C/modules/hook-context-intelligence" && \ + PYTHONPATH="$C" uv run --with pathspec --with httpx python - <<'PY' from amplifier_module_hook_context_intelligence.handlers.delivery_watermark import ( DeliveryWatermark, SweepLock) from amplifier_module_hook_context_intelligence.handlers.backlog_sweep import ( - BacklogSweeper, SweepBounds) - print("ready:", DeliveryWatermark.__module__, "+", BacklogSweeper.__module__) + BacklogSweeper, SweepBounds, select_candidates) + import inspect + # The routing gate must be present -- a sweep that cannot evaluate + # include/exclude must never ship. + assert hasattr(BacklogSweeper, "_routing_verdict"), "routing gate missing" + assert "spec" in inspect.signature(BacklogSweeper.__init__).parameters, ( + "BacklogSweeper does not require a destination spec") + print("ready: watermark + sweep import; routing gate present and required") PY - name: real-backend-reachable From 294cfb356502496c113b71e6df636cd8e2f3f6ee Mon Sep 17 00:00:00 2001 From: colombod Date: Mon, 21 Sep 2026 15:05:16 +0000 Subject: [PATCH 11/14] fix(hook-context-intelligence): make the module's own pyright gate green This PR adds a rule to AGENTS.md requiring `pyright` to be run from the module directory, not only the repo root. The module it changes did not satisfy that rule: `modules/hook-context-intelligence` reported 7 errors, all in `tests/test_logging_handler_disk_breaker.py`, where `HookResult`'s `user_message` is declared `str | None` and the assertions never narrow it. A gate that is red on arrival teaches the next engineer that red is this gate's normal state, which then covers the real failures it was added to catch. So the rule and the green gate ship together. Three narrowing asserts; no test behaviour changes. Also drops the trailing whitespace that made `git diff --check` fail on the replay DTU profile. Module pyright: 7 errors -> 0 errors, 0 warnings. Generated with Amplifier Co-Authored-By: Amplifier <240397093+microsoft-amplifier@users.noreply.github.com> --- .../context-intelligence-self-healing-replay-validation.yaml | 2 +- .../tests/test_logging_handler_disk_breaker.py | 3 +++ 2 files changed, 4 insertions(+), 1 deletion(-) diff --git a/.amplifier/digital-twin-universe/profiles/context-intelligence-self-healing-replay-validation.yaml b/.amplifier/digital-twin-universe/profiles/context-intelligence-self-healing-replay-validation.yaml index 8157b77d..134c058a 100644 --- a/.amplifier/digital-twin-universe/profiles/context-intelligence-self-healing-replay-validation.yaml +++ b/.amplifier/digital-twin-universe/profiles/context-intelligence-self-healing-replay-validation.yaml @@ -223,7 +223,7 @@ provision: . /root/_common.sh echo "=== S2: a LATER session must sweep S1's backlog, with no user action ===" SD=$(cat /root/.s1_session) - run_session "Say OK." + run_session "Say OK." sleep 20 python3 $V healed --session-dir "$SD" --server "$SERVER_URL" \ --token "$SERVER_TOKEN" --workspace "$WORKSPACE" --destination main \ diff --git a/modules/hook-context-intelligence/tests/test_logging_handler_disk_breaker.py b/modules/hook-context-intelligence/tests/test_logging_handler_disk_breaker.py index 82a3be50..cce98281 100644 --- a/modules/hook-context-intelligence/tests/test_logging_handler_disk_breaker.py +++ b/modules/hook-context-intelligence/tests/test_logging_handler_disk_breaker.py @@ -115,6 +115,7 @@ async def test_no_alert_claims_permanent_data_loss(self, tmp_path, monkeypatch) result = await handler("tool:call", _evt()) assert result.user_message_level == "warning" + assert result.user_message is not None assert "PERMANENT DATA LOSS" not in result.user_message assert result.user_message == result.user_message.replace("DISK FULL", "") # no shouting # Still honest about what happened, without overclaiming. @@ -138,6 +139,7 @@ def enqueue(self, event, data, **_kwargs): result = await handler("tool:call", _evt()) assert result.user_message_level == "warning" + assert result.user_message is not None assert "still reaching the configured server" in result.user_message assert "not recoverable" not in result.user_message @@ -160,6 +162,7 @@ def enqueue(self, event, data, **_kwargs): result = await handler("tool:call", _evt()) assert result.user_message_level == "warning" + assert result.user_message is not None assert "not recoverable" in result.user_message async def test_open_breaker_skips_disk_writes(self, tmp_path, monkeypatch) -> None: From 04cf76af8a501154245b044f82399f7f4eef2440 Mon Sep 17 00:00:00 2001 From: colombod Date: Mon, 21 Sep 2026 16:33:45 +0000 Subject: [PATCH 12/14] fix(hook-context-intelligence): stop the sweep wedging, hiding, and sharing cursors Three review findings, all the same failure this change exists to kill: a delivery path that quietly stops recovering and reports itself healthy. 1. A permanent rejection wedged the whole remaining backlog. The live dispatcher classifies 403/400/404/410/413/422/3xx as _PERMANENT and steps over them loudly; the sweep treated every non-2xx as "stop", so one routine 403 parked the cursor in front of it. Every later pass re-read that record, failed, advanced nothing -- for the full max_age_hours window, after which the session aged out and its remaining events were unrecoverable. The sweep now imports _classify_http_outcome rather than re-deriving it, so the two delivery paths cannot disagree about what is retryable again. 2. And that was invisible. `made_progress` sums the whole pass, so a wedged session hid behind any sibling that delivered -- the breaker_open=False on 232 of 232 lossy shutdowns, rebuilt one layer up. Adds a per-session `sessions_no_progress` counter and a LOUD warning that fires even when the aggregate moved. 3. The sweep never wrote to forwarding-*.jsonl, the durable channel the troubleshooting doc teaches operators to aggregate -- while two comments claimed it did. It now writes `sweep_permanent_reject` and `sweep_no_progress` into the dispatcher's own sink; the comments are corrected and the doc lists both kinds. 4. Colliding destination names silently shared one watermark. `path_for` is many-to-one (`prod/a` and `prod:a` both become `prod_a.json`), and the raw name was stored precisely so the collision would be detectable -- then never compared. With the same URL the existing URL guard cannot fire, so the second destination inherited EOF and delivered nothing. GUARD 3 now checks the name it was designed to check. Five tests, each verified red against the pre-fix source. modules/hook-context-intelligence: 785 passed (was 780) root: 933 passed - ruff, format, pyright (root and module) all clean Generated with Amplifier Co-Authored-By: Amplifier <240397093+microsoft-amplifier@users.noreply.github.com> --- docs/remote-server-troubleshooting.md | 15 +++ .../__init__.py | 23 +++- .../handlers/backlog_sweep.py | 119 ++++++++++++++++-- .../handlers/delivery_watermark.py | 21 +++- .../handlers/logging_handler.py | 11 ++ .../tests/test_backlog_sweep.py | 100 +++++++++++++++ .../tests/test_delivery_watermark.py | 50 ++++++++ 7 files changed, 324 insertions(+), 15 deletions(-) diff --git a/docs/remote-server-troubleshooting.md b/docs/remote-server-troubleshooting.md index 44c69e6f..96ac3288 100644 --- a/docs/remote-server-troubleshooting.md +++ b/docs/remote-server-troubleshooting.md @@ -212,6 +212,21 @@ replay it: `context-intelligence-upload --path ` (see > `forwarding_log_dir` (default `~/.amplifier/context-intelligence-logs`), a **separate sink > from `events.jsonl`**. Grep it once the noisy session has ended: > `jq 'select(.kind=="auth_failure")' ~/.amplifier/context-intelligence-logs/forwarding-*.jsonl`. +> +> **The backlog sweep writes to the same sink**, with `"source": "backlog_sweep"` and two +> kinds of its own — so a catch-up failure is diagnosable after the fact, not only from a +> console line nobody was watching: +> +> - `sweep_permanent_reject` — one record the server will never accept (403/400/404/410/413/422 +> or a 3xx). The sweep steps **over** it, exactly as the live dispatcher does; stopping there +> would wedge everything behind it until the session ages out of the window. +> - `sweep_no_progress` — one session retired **none** of its backlog this pass. Per session on +> purpose: the console’s "NOT shrinking" warning asks whether the *pass* moved, so a single +> wedged session can hide behind a healthy sibling. This is the record that cannot be masked. +> +> `jq 'select(.source=="backlog_sweep") | select(.kind=="sweep_no_progress") | .session_dir' +> ~/.amplifier/context-intelligence-logs/forwarding-*.jsonl | sort | uniq -c` lists the sessions +> that are stuck, and how often. ### ` auth token unavailable (run \`az login\` to refresh) — retrying with backoff; events remain durable in events.jsonl.` diff --git a/modules/hook-context-intelligence/amplifier_module_hook_context_intelligence/__init__.py b/modules/hook-context-intelligence/amplifier_module_hook_context_intelligence/__init__.py index 87952842..fcdea2d8 100644 --- a/modules/hook-context-intelligence/amplifier_module_hook_context_intelligence/__init__.py +++ b/modules/hook-context-intelligence/amplifier_module_hook_context_intelligence/__init__.py @@ -219,8 +219,10 @@ def _describe_sweep(report: Any, *, suppress_stranded: bool = False) -> None: became answerable once a watermark existed. Quiet means the sweep delivered something and nothing is stuck. It never - means "we hid a failure": the durable forwarding-*.jsonl record is written - by the dispatcher regardless of anything decided here. + means "we hid a failure": a durable forwarding-*.jsonl record is written for + every sweep no-progress and every permanent rejection, by the sweeper itself + and into the same sink the dispatcher uses, regardless of anything decided + here. """ # LOUD 4 -- outside the age bound. These will NEVER be delivered # automatically, so the bound must be audible or it becomes a silent drop. @@ -249,6 +251,21 @@ def _describe_sweep(report: Any, *, suppress_stranded: bool = False) -> None: ) return + # LOUD 3 -- SOME session retired nothing, even though the pass as a whole + # moved. Deliberately placed AFTER the made_progress return above so it can + # still fire: made_progress is an aggregate, and one wedged session hiding + # behind two healthy ones is exactly the shape of the bug this whole change + # exists to kill (breaker_open=False on 232 of 232 lossy shutdowns). + if report.sessions_no_progress: + log.warning( + "context-intelligence %s: %d session(s) retired NO backlog this pass" + " (%d event(s) permanently rejected and stepped over).%s", + report.destination, + report.sessions_no_progress, + report.events_skipped_permanent, + f" Last error: {report.last_error}" if report.last_error else "", + ) + # Progress, but still behind: proportional, and INFO rather than WARNING -- # catching up is not a problem the user can act on. if report.backlog_bytes_remaining: @@ -348,6 +365,8 @@ def schedule_backlog_sweeps( spec=spec, bounds=bounds, timeout=resolver.dispatch_timeout, + # Same durable diagnostics sink as the live path, not a second one. + forwarding_log_dir=getattr(dispatcher, "forwarding_log_dir", None), ) idle = asyncio.Event() diff --git a/modules/hook-context-intelligence/amplifier_module_hook_context_intelligence/handlers/backlog_sweep.py b/modules/hook-context-intelligence/amplifier_module_hook_context_intelligence/handlers/backlog_sweep.py index 759e7201..36d8b52a 100644 --- a/modules/hook-context-intelligence/amplifier_module_hook_context_intelligence/handlers/backlog_sweep.py +++ b/modules/hook-context-intelligence/amplifier_module_hook_context_intelligence/handlers/backlog_sweep.py @@ -50,6 +50,13 @@ from ..fanout import destination_is_active, normalize_match_key from ..upload import build_payload from .delivery_watermark import DeliveryWatermark, SweepLock +from .logging_handler import ( + _DELIVERED, + _PERMANENT, + _TRANSIENT, + _classify_http_outcome, + _write_forwarding_record, +) if TYPE_CHECKING: # pragma: no cover - typing only from context_intelligence.auth import AuthStrategy @@ -104,6 +111,18 @@ class SweepReport: sessions_blocked_unprovable: int = 0 events_delivered: int = 0 events_failed: int = 0 + #: Records the server will NEVER accept (the live path's ``_PERMANENT`` + #: class: 3xx, 400, 403, 404, 410, 413, 422, any other non-408/429 4xx). + #: Stepped over LOUDLY, exactly as the live dispatcher steps over them -- + #: stopping instead would wedge the whole remaining backlog behind one + #: record until the session ages out of the window and is lost for good. + events_skipped_permanent: int = 0 + #: Sessions that had a backlog and retired NONE of it this pass. Counted + #: PER SESSION on purpose: ``made_progress`` is an aggregate over the whole + #: pass, so one wedged session hides behind any other session that + #: delivered -- which is the 215-of-215 \"healthy\" failure rebuilt one + #: layer up. This is the per-unit signal that aggregate cannot mask. + sessions_no_progress: int = 0 bytes_advanced: int = 0 backlog_bytes_remaining: int = 0 stranded_sessions: int = 0 @@ -241,6 +260,7 @@ def __init__( spec: Destination, bounds: SweepBounds | None = None, timeout: float = 10.0, + forwarding_log_dir: Path | None = None, ) -> None: self._destination = destination #: The destination's OWN include/exclude. Required, not optional: without @@ -253,11 +273,40 @@ def __init__( self._project_dir = project_dir self._bounds = bounds or SweepBounds() self._timeout = timeout + #: The SAME durable sink the dispatcher writes to. Console logs are + #: nowhere in a non-interactive session; forwarding-*.jsonl is the file + #: the troubleshooting doc teaches operators to aggregate. A sweep + #: failure that never reaches it is a failure nobody can find. + self._forwarding_log_dir = forwarding_log_dir # -- one event ------------------------------------------------------ - async def _post(self, client: httpx.AsyncClient, payload: dict[str, Any]) -> tuple[bool, str]: - """POST one event. Returns ``(delivered, detail)``. Never raises. + def _record_forwarding(self, kind: str, detail: str, session_dir: Path) -> None: + """Append one durable forwarding-diagnostics record. Best-effort, never raises.""" + _write_forwarding_record( + self._forwarding_log_dir, + { + "ts": datetime.now(UTC).isoformat(), + "destination": self._destination, + "url": self._url, + "kind": kind, + "detail": detail[:500], + "session_dir": str(session_dir), + "source": "backlog_sweep", + }, + ) + + async def _post(self, client: httpx.AsyncClient, payload: dict[str, Any]) -> tuple[str, str]: + """POST one event. Returns ``(outcome, detail)``. Never raises. + + ``outcome`` is the live dispatcher's own three-way classification -- + ``_DELIVERED`` / ``_TRANSIENT`` / ``_PERMANENT`` -- produced by the SAME + ``_classify_http_outcome`` table, deliberately imported rather than + re-derived. A second delivery path with its own opinion about which + statuses are retryable is a drift waiting to happen, and this one drifted + the moment it existed: treating every non-2xx as \"stop\" wedged a + session\'s entire remaining backlog behind one record the server will + never accept. Deliberately does NOT set ``?replay=true``. The manual upload CLI does, because it re-imports cold archives that the server's dedup cache has @@ -272,7 +321,9 @@ async def _post(self, client: httpx.AsyncClient, payload: dict[str, Any]) -> tup except Exception as exc: # noqa: BLE001 - a token fault must not kill the sweep # Mirrors the dispatcher: a local token-production failure is a # deterministic HARD auth fault, reported, never retried blindly. - return False, f"auth failure: {type(exc).__name__}: {exc}" + # TRANSIENT, not permanent: a token that cannot be minted now may + # well mint next pass, and skipping events over it would lose them. + return _TRANSIENT, f"auth failure: {type(exc).__name__}: {exc}" headers.setdefault("Content-Type", "application/json") try: response = await client.post( @@ -281,10 +332,11 @@ async def _post(self, client: httpx.AsyncClient, payload: dict[str, Any]) -> tup except asyncio.CancelledError: raise except Exception as exc: # noqa: BLE001 - network faults are expected here - return False, f"{type(exc).__name__}: {exc}" - if response.status_code in (200, 201, 202): - return True, "" - return False, f"HTTP {response.status_code}: {response.text[:200]}" + return _TRANSIENT, f"{type(exc).__name__}: {exc}" + outcome = _classify_http_outcome(response.status_code) + if outcome == _DELIVERED: + return _DELIVERED, "" + return outcome, f"HTTP {response.status_code}: {response.text[:200]}" # -- routing: may this session's events go to this destination? ------- @@ -394,6 +446,7 @@ async def _sweep_session( chunk = max(1, self._bounds.concurrency) prefix_end = watermark.offset delivered_count = 0 + skipped_permanent = 0 failed = 0 first_error: str | None = None stop = False @@ -422,19 +475,49 @@ def _persist(outcome: str) -> int: results = await asyncio.gather( *(self._post(client, payload) for _s, _e, payload in batch) ) - for (_start, end, _payload), (delivered, detail) in zip(batch, results): - if not delivered: + for (start, end, _payload), (outcome, detail) in zip(batch, results): + if outcome == _TRANSIENT: failed += 1 first_error = first_error or detail stop = True break + if outcome == _PERMANENT: + # LOUD SKIP -- exactly what the live dispatcher does with + # this class. Stopping instead wedges every later event in + # this session behind one record the server will never + # accept, for the whole max_age_hours window, after which + # the session ages out and is lost for good. A 403 is + # routine ("authorization, often per-workspace"), so this + # is not a corner case. + skipped_permanent += 1 + first_error = first_error or detail + report.notes.append( + f"permanently rejected record at byte {start}: {detail}" + ) + logger.warning( + "%s: skipping permanently rejected event at byte %d in %s -- %s", + self._destination, + start, + session_dir, + detail, + ) + self._record_forwarding("sweep_permanent_reject", detail, session_dir) + prefix_end = end + continue # CONTIGUOUS PREFIX ONLY: the cursor may only pass a record - # once every record before it has been accepted. + # once every record before it has been RESOLVED -- accepted, + # or permanently rejected and recorded above. prefix_end = end delivered_count += 1 if stop: break - advanced = _persist("delivered" if delivered_count else "no_progress") + if delivered_count: + outcome_label = "delivered" + elif skipped_permanent: + outcome_label = "skipped_permanent" + else: + outcome_label = "no_progress" + advanced = _persist(outcome_label) except asyncio.CancelledError: # Teardown. Keep what we actually achieved rather than redoing it. _persist("cancelled" if delivered_count else "no_progress") @@ -442,6 +525,20 @@ def _persist(outcome: str) -> int: report.events_delivered += delivered_count report.events_failed += failed + report.events_skipped_permanent += skipped_permanent + if not delivered_count and not skipped_permanent: + # PER-SESSION, not aggregate. report.made_progress sums the whole + # pass, so a wedged session is invisible behind any sibling that + # delivered. This is the counter that cannot be masked. + report.sessions_no_progress += 1 + report.notes.append( + f"NO PROGRESS {session_dir}: " + f"{watermark.consecutive_sweeps_without_progress} consecutive sweep(s)" + f" without delivery -- {first_error or 'no error recorded'}" + ) + self._record_forwarding( + "sweep_no_progress", first_error or "no error recorded", session_dir + ) report.bytes_advanced += advanced report.backlog_bytes_remaining += watermark.backlog_bytes(session_dir) if first_error and not report.last_error: diff --git a/modules/hook-context-intelligence/amplifier_module_hook_context_intelligence/handlers/delivery_watermark.py b/modules/hook-context-intelligence/amplifier_module_hook_context_intelligence/handlers/delivery_watermark.py index 36cc2c82..7f4b1463 100644 --- a/modules/hook-context-intelligence/amplifier_module_hook_context_intelligence/handlers/delivery_watermark.py +++ b/modules/hook-context-intelligence/amplifier_module_hook_context_intelligence/handlers/delivery_watermark.py @@ -39,7 +39,8 @@ #: Destination names are operator-chosen ``settings.yaml`` dict keys, so they can #: contain anything. Sanitize for use as a filename; the RAW name is kept inside -#: the file so a post-sanitization collision is detectable rather than silent. +#: the file and CHECKED on load (GUARD 3) so a post-sanitization collision +#: rewinds that destination rather than silently inheriting another's cursor. _UNSAFE_NAME = re.compile(r"[^A-Za-z0-9._-]") #: A sweep lock older than this is assumed to belong to a dead process. Generous @@ -134,7 +135,23 @@ def load( wm.delivered_lines = 0 wm.reset_by_guard = True - # GUARD 3 — destination identity. Same name, different URL means a + # GUARD 3 — destination NAME identity. `path_for` sanitizes the name into + # a filename, and that map is MANY-TO-ONE: `prod/a` and `prod:a` both + # become `prod_a.json`. The raw name is stored precisely so the collision + # is detectable -- storing it and never comparing it is a guard that was + # designed, documented, and never wired. Without this check the second + # destination inherits the first one's cursor and delivers nothing. + if wm.destination and wm.destination != destination: + notes.append( + f"watermark belongs to destination {wm.destination!r}, not {destination!r}" + f" (both sanitize to {path.name}) — resetting to 0" + ) + wm.offset = 0 + wm.delivered_lines = 0 + wm.reset_by_guard = True + wm.destination = destination + + # GUARD 4 — destination URL identity. Same name, different URL means a # different sink. Claiming "already delivered" against a server that # never saw these events is the one genuinely lossy mistake available. if destination_url and wm.destination_url and wm.destination_url != destination_url: diff --git a/modules/hook-context-intelligence/amplifier_module_hook_context_intelligence/handlers/logging_handler.py b/modules/hook-context-intelligence/amplifier_module_hook_context_intelligence/handlers/logging_handler.py index 75937eed..bd567b33 100644 --- a/modules/hook-context-intelligence/amplifier_module_hook_context_intelligence/handlers/logging_handler.py +++ b/modules/hook-context-intelligence/amplifier_module_hook_context_intelligence/handlers/logging_handler.py @@ -515,6 +515,17 @@ def url(self) -> str: def auth_strategy(self) -> Any: return self._strategy + @property + def forwarding_log_dir(self) -> Path | None: + """The durable diagnostics sink this destination writes to. + + Exposed so the backlog sweep can write to the SAME file rather than a + second one: forwarding-*.jsonl is what operators are taught to + aggregate, and a sweep failure that only reaches the console is a + failure nobody can find in a non-interactive session. + """ + return self._forwarding_log_dir + def _ensure_worker(self) -> None: if self._worker_task is None or self._worker_task.done(): self._worker_task = asyncio.create_task(self._worker()) diff --git a/modules/hook-context-intelligence/tests/test_backlog_sweep.py b/modules/hook-context-intelligence/tests/test_backlog_sweep.py index dc850076..7e881131 100644 --- a/modules/hook-context-intelligence/tests/test_backlog_sweep.py +++ b/modules/hook-context-intelligence/tests/test_backlog_sweep.py @@ -660,3 +660,103 @@ async def test_blocked_sessions_do_not_consume_the_budget_either( report = await _sweeper(tmp_path, bounds=SweepBounds(max_sessions=3)).run() assert report.sessions_blocked_unprovable == 3 assert report.events_delivered == 5 + + +@pytest.mark.asyncio +class TestPermanentRejectionDoesNotWedgeTheBacklog: + """A record the server will NEVER accept must be stepped over, not camped on. + + Regression for the review finding: the sweep classified every non-2xx as + "stop", while the live dispatcher has a three-way classifier in which + `_PERMANENT` (403, 400, 404, 410, 413, 422, 3xx) means *loud skip, keep + going*. Stopping instead parked the cursor in front of that record, so every + later pass re-read it, failed again, and advanced nothing -- for the whole + `max_age_hours` window, after which the session aged out and its remaining + events were lost for good. A 403 is routine, not a corner case. + """ + + async def test_permanent_rejection_is_skipped_and_the_rest_still_delivers( + self, tmp_path: Path, monkeypatch: pytest.MonkeyPatch + ) -> None: + session_dir = _make_session(tmp_path, "wedged", events=5) + # 2nd event is permanently rejected; the other four are fine. + client = _FakeClient(outcomes=[202, 403, 202, 202, 202]) + monkeypatch.setattr( + "amplifier_module_hook_context_intelligence.handlers.backlog_sweep.httpx.AsyncClient", + lambda *a, **k: client, + ) + forwarding = tmp_path / "forwarding" + report = await _sweeper(tmp_path, forwarding_log_dir=forwarding).run() + + assert len(client.posted) == 5, "the sweep stopped at the rejected record" + assert report.events_delivered == 4 + assert report.events_skipped_permanent == 1 + wm, _ = DeliveryWatermark.load(session_dir, DEST, destination_url=URL) + assert wm.offset == (session_dir / "events.jsonl").stat().st_size, ( + "the cursor is parked in front of a record the server will never accept;" + " this session's whole remaining backlog is wedged until it ages out" + ) + # The refusal to deliver reached the DURABLE channel, not just the console. + records = [ + json.loads(line) + for f in forwarding.glob("*.jsonl") + for line in f.read_text().splitlines() + ] + assert any(r["kind"] == "sweep_permanent_reject" for r in records) + + async def test_a_transient_failure_still_stops_the_pass( + self, tmp_path: Path, monkeypatch: pytest.MonkeyPatch + ) -> None: + """The other half of the contract: 5xx/429/408/401 must NOT be skipped.""" + session_dir = _make_session(tmp_path, "slow", events=5) + client = _FakeClient(outcomes=[202, 500, 202, 202, 202]) + monkeypatch.setattr( + "amplifier_module_hook_context_intelligence.handlers.backlog_sweep.httpx.AsyncClient", + lambda *a, **k: client, + ) + report = await _sweeper(tmp_path).run() + + assert report.events_delivered == 1 + assert report.events_skipped_permanent == 0 + wm, _ = DeliveryWatermark.load(session_dir, DEST, destination_url=URL) + assert 0 < wm.offset < (session_dir / "events.jsonl").stat().st_size, ( + "a retryable failure must leave the cursor BEFORE the failed record" + ) + + +@pytest.mark.asyncio +class TestPerSessionNoProgressSurvivesAggregation: + """One wedged session must stay visible behind a sibling that delivered. + + `made_progress` sums the whole pass. Gating the loud warning on it alone + rebuilds the original failure one layer up: the destination reports itself + healthy while a session quietly retires nothing, pass after pass. + """ + + async def test_a_stuck_session_is_counted_even_when_the_pass_made_progress( + self, tmp_path: Path, monkeypatch: pytest.MonkeyPatch + ) -> None: + _make_session(tmp_path, "aaa-stuck", events=3, age_hours=5) + _make_session(tmp_path, "bbb-healthy", events=3, age_hours=1) + # Oldest-first: the stuck session is swept first and fails transiently; + # the healthy one then delivers, so the AGGREGATE says progress. + client = _FakeClient(outcomes=[500, 202, 202, 202]) + monkeypatch.setattr( + "amplifier_module_hook_context_intelligence.handlers.backlog_sweep.httpx.AsyncClient", + lambda *a, **k: client, + ) + forwarding = tmp_path / "forwarding" + report = await _sweeper(tmp_path, forwarding_log_dir=forwarding).run() + + assert report.made_progress, "precondition: the pass as a whole delivered" + assert report.sessions_no_progress == 1, ( + "the wedged session hid behind its healthy sibling -- this is the" + " aggregate-masks-the-unit failure this counter exists to prevent" + ) + assert any("NO PROGRESS" in note for note in report.notes) + records = [ + json.loads(line) + for f in forwarding.glob("*.jsonl") + for line in f.read_text().splitlines() + ] + assert any(r["kind"] == "sweep_no_progress" for r in records) diff --git a/modules/hook-context-intelligence/tests/test_delivery_watermark.py b/modules/hook-context-intelligence/tests/test_delivery_watermark.py index 536a07f1..1b054131 100644 --- a/modules/hook-context-intelligence/tests/test_delivery_watermark.py +++ b/modules/hook-context-intelligence/tests/test_delivery_watermark.py @@ -375,3 +375,53 @@ async def ok(event: str, data: dict[str, Any]) -> str: def test_session_watermark_state_defaults() -> None: state = _SessionWatermarkState() assert (state.committed, state.frozen, state.dirty) == (0, False, False) + + +class TestSanitizedNameCollisionsDoNotShareACursor: + """Two destination names that sanitize to one filename must not share state. + + `path_for` maps a destination name to a filename, and that map is MANY-TO-ONE: + `prod/a` and `prod:a` both become `prod_a.json`. The raw name is stored in the + file specifically so the collision is detectable -- but it was stored and never + compared, so the second destination inherited the first one's cursor. When both + point at the same URL the existing URL guard cannot fire, and the second + destination reads itself as caught up and delivers nothing, forever. + """ + + def _session(self, tmp_path: Path) -> Path: + (tmp_path / "events.jsonl").write_bytes(b'{"event":"a"}\n{"event":"b"}\n') + return tmp_path + + def test_colliding_names_on_the_same_url_rewind_instead_of_inheriting( + self, tmp_path: Path + ) -> None: + session_dir = self._session(tmp_path) + size = (session_dir / "events.jsonl").stat().st_size + assert sanitize_destination("prod/a") == sanitize_destination("prod:a") + + first, _ = DeliveryWatermark.load(session_dir, "prod/a", destination_url="http://s") + first.offset = size + first.save(session_dir) + + second, notes = DeliveryWatermark.load(session_dir, "prod:a", destination_url="http://s") + assert second.offset == 0, ( + "'prod:a' inherited 'prod/a' cursor at EOF and would deliver nothing" + ) + assert second.destination == "prod:a" + assert second.reset_by_guard + assert any("prod/a" in note and "prod:a" in note for note in notes), ( + "a collision must be SAID, not silently corrected" + ) + + def test_the_owning_destination_still_loads_its_own_cursor(self, tmp_path: Path) -> None: + """The guard must not rewind the destination the watermark belongs to.""" + session_dir = self._session(tmp_path) + size = (session_dir / "events.jsonl").stat().st_size + first, _ = DeliveryWatermark.load(session_dir, "prod/a", destination_url="http://s") + first.offset = size + first.save(session_dir) + + again, notes = DeliveryWatermark.load(session_dir, "prod/a", destination_url="http://s") + assert again.offset == size + assert not again.reset_by_guard + assert notes == [] From eb3134d8291a82c55786eb3e5e7f33d0bde18933 Mon Sep 17 00:00:00 2001 From: colombod Date: Thu, 24 Sep 2026 21:37:32 +0000 Subject: [PATCH 13/14] fix(hook-context-intelligence): overflow warning delta tracking and auto-resume messaging Issue B: overflow warning misreported a lifetime total as a delta - Added _overflow_dropped_at_last_log to snapshot the previous warning's count - Warning now reports the true delta since the last warning, plus the session total - _overflow_dropped stays cumulative on purpose: the sustained-failure escalation, its forwarding record, and the shutdown summary all read it as a session total, so resetting it would have silently under-reported undelivered events at shutdown - Drops suppressed by the 60s rate limit fold into the next delta rather than being dropped from the accounting Issue E: runtime strings still described manual replay as unconditional - PR #117 added the self-healing backlog sweep and corrected README.md and docs/remote-server-troubleshooting.md, but the runtime strings were not updated - The breaker-open message was the worst offender: "delivery auto-resumes ... (no restart needed)" and "replay the backlog with context-intelligence-upload" sat in one sentence. The first describes NEW events, the second a manual action for already-dropped ones; reading the first as covering both is how a user silently loses events - Four runtime strings now draw the same line the docs draw -- the queue-overflow warning, the sustained-delivery-failure escalation, the breaker-open warning, and the shutdown summary. A drop freezes the delivery watermark, so the sweep replays it automatically; manual context-intelligence-upload is required ONLY when sweep_enabled is false or the session ages past sweep_max_age_hours (default 48h) Tests added: - test_overflow_warning_reports_delta_not_lifetime_total: asserts the second warning reports the delta (3), not the lifetime total. Verified RED against the pre-fix behaviour, where it failed with "assert 4 == 3" - test_overflow_warning_scopes_manual_replay_to_sweep_gaps: asserts the overflow warning states drops are replayed automatically and scopes manual replay to the sweep's gaps (disabled, or aged out) - test_open_warning_scopes_auto_resume_to_new_events: asserts the breaker-open warning scopes auto-resume to NEW events and scopes manual replay the same way Gates: module pytest 788 passed; root `pytest tests/ --ignore=tests/dtu` 932 passed; ruff check and ruff format --check clean at repo root and in the module (both run with --no-cache: a stale ruff cache had previously reported these files as formatted when they were not); pyright 0 errors at both repo root and module; scripts/validate-full.sh with validation_mode=full, build_tested=True, build_success=True, 0 ERROR findings, bundle.dot fresh. Generated with Amplifier Co-Authored-By: Amplifier <240397093+microsoft-amplifier@users.noreply.github.com> --- .../handlers/logging_handler.py | 53 ++++++++--- .../tests/test_circuit_breaker.py | 32 +++++++ .../tests/test_notifications.py | 87 +++++++++++++++++++ 3 files changed, 160 insertions(+), 12 deletions(-) diff --git a/modules/hook-context-intelligence/amplifier_module_hook_context_intelligence/handlers/logging_handler.py b/modules/hook-context-intelligence/amplifier_module_hook_context_intelligence/handlers/logging_handler.py index bd567b33..54f13fc3 100644 --- a/modules/hook-context-intelligence/amplifier_module_hook_context_intelligence/handlers/logging_handler.py +++ b/modules/hook-context-intelligence/amplifier_module_hook_context_intelligence/handlers/logging_handler.py @@ -395,6 +395,17 @@ def __init__( self._degraded_since: float | None = None self._current: tuple[str, dict[str, Any]] | None = None # in-flight held event self._overflow_dropped = 0 + # Snapshot of _overflow_dropped as of the last overflow WARNING, so that + # warning can report a true "since last warning" delta. + # + # Why a second counter instead of resetting _overflow_dropped: that + # counter is the session-lifetime total, and three other readers depend + # on it staying cumulative -- the sustained-failure escalation ("dropped + # from a full queue so far"), its forwarding record, and the shutdown + # summary's undelivered total (queued + in-flight + overflow-dropped). + # Resetting it here would silently UNDER-report undelivered events at + # shutdown, which is the opposite of what this warning exists to do. + self._overflow_dropped_at_last_log = 0 self._auth_failures = 0 self._last_status: int | None = None # Sentinel "never logged yet" value. MUST be -inf, not 0.0: these are @@ -574,13 +585,21 @@ def enqueue( now = time.monotonic() if now - self._last_overflow_log >= _LOG_RATE_LIMIT_SECONDS: self._last_overflow_log = now + dropped_since_last = self._overflow_dropped - self._overflow_dropped_at_last_log + self._overflow_dropped_at_last_log = self._overflow_dropped logger.warning( - "%s buffer full — %d events dropped since last warning;" - " events are durable in events.jsonl UNLESS the disk is also full" - " (see any DISK FULL alert)." - " To manually upload run: context-intelligence-upload --path %s" + "%s buffer full — %d event(s) dropped since the last warning" + " (%d this session); they stay durable in events.jsonl UNLESS the" + " disk is also full (see any DISK FULL alert)." + " These drops are replayed automatically: the backlog sweep re-reads" + " from the delivery watermark, which a drop freezes in place." + " Manual replay is required ONLY if the sweep is turned off" + " (sweep_enabled: false) or this session ages past" + " sweep_max_age_hours (default 48h) — then run:" + " context-intelligence-upload --path %s" " (--server-url/--api-key come from flags or env/config; see --help)", self._name, + dropped_since_last, self._overflow_dropped, self._storage_path, ) @@ -729,9 +748,12 @@ def _maybe_escalate_sustained_failure(self) -> None: self._last_degraded_escalation_log = now logger.error( "%s (%s) has been failing to deliver for %.0fs \u2014 %d event(s)" - " dropped from a full queue so far, circuit breaker open=%s." - " Events remain durable in events.jsonl; once %s recovers, replay" - " any dropped backlog with: context-intelligence-upload --path %s" + " dropped from a full queue so far (session total), circuit breaker open=%s." + " Events remain durable in events.jsonl; once %s recovers, the backlog" + " sweep replays the dropped events automatically from the delivery" + " watermark. Manual replay is required ONLY if the sweep is turned off" + " (sweep_enabled: false) or the session ages past sweep_max_age_hours" + " (default 48h) — then run: context-intelligence-upload --path %s" " (--server-url/--api-key come from flags or env/config; see --help).", self._name, self._url, @@ -864,9 +886,12 @@ def _maybe_open_breaker(self) -> None: self._last_probe_ts = time.monotonic() logger.warning( "%s (%s) forwarding paused after sustained auth failures (HTTP %s) \u2014 fix the" - " credential/URL; delivery auto-resumes when it recovers (no restart needed)." - " Events are safe in events.jsonl; replay the backlog with" - " context-intelligence-upload.", + " credential/URL. Once it recovers, NEW events resume automatically (no" + " restart needed) AND the backlog sweep replays what was missed, re-reading" + " from the delivery watermark. Events stay durable in events.jsonl meanwhile." + " Manual replay (context-intelligence-upload) is required ONLY if the sweep" + " is turned off (sweep_enabled: false) or the session ages past" + " sweep_max_age_hours (default 48h).", self._name, self._url, self._last_status, @@ -1459,8 +1484,12 @@ async def close(self) -> None: logger.warning( "%s shutdown: %d undelivered event(s)" " (queued=%d in-flight=%d overflow-dropped=%d)." - " Events are durable in events.jsonl." - " To manually upload run: context-intelligence-upload --path %s" + " Events are durable in events.jsonl, and the next session's" + " backlog sweep replays them automatically from the delivery" + " watermark. Manual replay is required ONLY if the sweep is turned" + " off (sweep_enabled: false) or this session ages past" + " sweep_max_age_hours (default 48h) — then run:" + " context-intelligence-upload --path %s" " (--server-url/--api-key come from flags or env/config; see --help)", self._name, total, diff --git a/modules/hook-context-intelligence/tests/test_circuit_breaker.py b/modules/hook-context-intelligence/tests/test_circuit_breaker.py index d42946c8..76a7e551 100644 --- a/modules/hook-context-intelligence/tests/test_circuit_breaker.py +++ b/modules/hook-context-intelligence/tests/test_circuit_breaker.py @@ -159,6 +159,38 @@ async def test_opens_on_rate_18_of_20( assert len(open_records) == 1, f"expected exactly 1 breaker_open record, got {open_records}" await d.close() + async def test_open_warning_scopes_auto_resume_to_new_events( + self, monkeypatch: pytest.MonkeyPatch, tmp_path: Path + ) -> None: + """The breaker-open warning must not blur auto-resume with manual replay. + + It previously said "delivery auto-resumes ... (no restart needed)" and + "replay the backlog with context-intelligence-upload" in one breath. + Those describe different populations -- auto-resume covers NEW events, + replay covers already-dropped ones -- and reading the first as covering + both is how a user silently loses the dropped events. + """ + monkeypatch.setattr(logging_handler, "_BREAKER_MIN_OPEN_SECONDS", 0.0) + d = _dispatcher(forwarding_log_dir=tmp_path) + d._client = _mock_client([_make_response(401) for _ in range(20)]) + d._sleep_backoff = AsyncMock() # type: ignore[method-assign] + + with patch(LOGGER_PATH) as mock_logger: + await _drain(d, [f"e{i}" for i in range(20)]) + fmt = next( + c.args[0] + for c in mock_logger.warning.call_args_list + if "forwarding paused" in str(c) + ) + + assert "NEW events resume automatically" in fmt, ( + f"auto-resume must be scoped to NEW events: {fmt!r}" + ) + assert "ONLY if" in fmt and "sweep_max_age_hours" in fmt, ( + f"manual replay must be scoped to the sweep's gaps (disabled / aged out): {fmt!r}" + ) + await d.close() + # --------------------------------------------------------------------------- # 2. Does NOT open on 50/50 flapping diff --git a/modules/hook-context-intelligence/tests/test_notifications.py b/modules/hook-context-intelligence/tests/test_notifications.py index 30fd12bd..297181cb 100644 --- a/modules/hook-context-intelligence/tests/test_notifications.py +++ b/modules/hook-context-intelligence/tests/test_notifications.py @@ -397,6 +397,93 @@ async def test_overflow_log_is_rate_limited(self) -> None: ) await d.close() + async def test_overflow_warning_reports_delta_not_lifetime_total(self) -> None: + """Second warning reports drops SINCE THE LAST WARNING, not the lifetime total. + + Regression guard for the message being literally false: the text says + "dropped since the last warning", so the number beside it must be a + delta. _overflow_dropped itself MUST stay cumulative -- the shutdown + summary and the sustained-failure escalation both read it as a session + total, so resetting it there would under-report undelivered events. + """ + d = _dispatcher(queue_capacity=1, storage_path="/tmp/ci-test-sessions") + d._post = _make_outcome_post([_DELIVERED]) # type: ignore[method-assign] + d._sleep_backoff = AsyncMock() # type: ignore[method-assign] + + with patch(LOGGER_PATH) as mock_logger: + # Batch 1: fill the single slot, then drop 3 (no await -> worker idle). + d.enqueue("fill", {"session_id": "s0"}) + for i in range(3): + d.enqueue(f"a{i}", {"session_id": f"sa{i}"}) + + # Defeat the 60s rate limit so a SECOND warning can fire. + d._last_overflow_log = float("-inf") + + # Batch 2: drop 2 more. + for i in range(2): + d.enqueue(f"b{i}", {"session_id": f"sb{i}"}) + + await asyncio.wait_for(d._queue.join(), timeout=2.0) + + overflow_calls = [c for c in mock_logger.warning.call_args_list if "buffer full" in str(c)] + assert len(overflow_calls) == 2, ( + f"Expected 2 overflow warnings (rate limit defeated), got {len(overflow_calls)}: " + f"{mock_logger.warning.call_args_list}" + ) + + # args = (fmt, name, dropped_since_last, dropped_this_session, storage_path) + first_delta, first_total = overflow_calls[0].args[2], overflow_calls[0].args[3] + second_delta, second_total = overflow_calls[1].args[2], overflow_calls[1].args[3] + + # The first drop warns immediately (the rate-limit sentinel is -inf), so + # it reports 1/1; drops 2 and 3 are suppressed by the 60s rate limit. + assert (first_delta, first_total) == (1, 1), ( + f"First warning should report 1 dropped / 1 this session, got " + f"{first_delta} / {first_total}" + ) + # Delta covers every drop since the last warning INCLUDING the ones the + # rate limit suppressed (drops 2, 3 and 4) -- suppressed drops must be + # folded into the next report, never dropped from the accounting. + # The bug: this reported 4 (the lifetime total) where 3 is the truth. + assert second_delta == 3, ( + f"Second warning must report the DELTA since the last warning (3), " + f"got {second_delta} -- this is the lifetime total, the message is false" + ) + assert second_total == 4, f"Second warning's session total should be 4, got {second_total}" + # Cumulative counter is untouched by the delta bookkeeping. + assert d._overflow_dropped == 5, ( + f"_overflow_dropped must stay cumulative (5), got {d._overflow_dropped}" + ) + await d.close() + + async def test_overflow_warning_scopes_manual_replay_to_sweep_gaps(self) -> None: + """The warning must not present manual upload as unconditionally required. + + Dropped events freeze the delivery watermark, so the backlog sweep + replays them. Saying "to manually upload run: ..." with no condition is + what caused users to either act needlessly or -- worse -- read + "durable in events.jsonl" as "it heals itself" and lose the events. + """ + d = _dispatcher(queue_capacity=1, storage_path="/tmp/ci-test-sessions") + d._post = _make_outcome_post([_DELIVERED]) # type: ignore[method-assign] + d._sleep_backoff = AsyncMock() # type: ignore[method-assign] + + with patch(LOGGER_PATH) as mock_logger: + d.enqueue("fill", {"session_id": "s0"}) + d.enqueue("drop", {"session_id": "s1"}) + await asyncio.wait_for(d._queue.join(), timeout=2.0) + + fmt = next(c.args[0] for c in mock_logger.warning.call_args_list if "buffer full" in str(c)) + + assert "replayed automatically" in fmt, ( + f"Warning must say the sweep replays drops automatically: {fmt!r}" + ) + assert "ONLY if" in fmt and "sweep_max_age_hours" in fmt, ( + f"Warning must scope manual replay to the sweep's gaps " + f"(disabled / aged out), got: {fmt!r}" + ) + await d.close() + async def test_overflow_while_degraded_combined(self) -> None: """OVERFLOW while DEGRADED: _degraded_warned True + _overflow_dropped==1 + loud log.""" storage_path = "/tmp/ci-test-sessions" From 7155053b22c1047c10607bacfd91280528403b71 Mon Sep 17 00:00:00 2001 From: colombod Date: Fri, 25 Sep 2026 00:16:19 +0000 Subject: [PATCH 14/14] docs(agents): document pytest scope and ruff cache issues from testing cycle Corrected two testing practices in the AGENTS.md 'Testing & what done looks like' section, both from lessons surfaced while fixing the overflow-warning defects on this branch: 1. The root test command must be 'uv run pytest tests/' not bare 'uv run pytest'. A bare root invocation fails with ModuleNotFoundError and ImportPathMismatchError because each module under modules/ is its own uv project with its own lockfile, conftest.py, and dependencies. This is the per-module layout working as designed, not a defect. CI already matches it: root runs 'pytest tests/ --ignore=tests/dtu', plus one job per module. 2. Ruff gates now pass --no-cache. Ruff's cache can report a file as already formatted when it is not. Real instance: two edited files were reported clean by cached 'ruff format --check .', committed in that state, then CI's Lint job failed on the identical command. Later 'git stash/stash pop' invalidated the cache and the same tree correctly reported '2 files would be reformatted'. A cached green format check is not evidence. Generated with Amplifier Co-Authored-By: Amplifier <240397093+microsoft-amplifier@users.noreply.github.com> --- AGENTS.md | 22 ++++++++++++++++++++-- 1 file changed, 20 insertions(+), 2 deletions(-) diff --git a/AGENTS.md b/AGENTS.md index a84e0a07..6cffa950 100644 --- a/AGENTS.md +++ b/AGENTS.md @@ -71,12 +71,30 @@ Run these before calling anything done: ```bash uv run pytest # in modules/tool-context-intelligence-query (module suite) -uv run pytest # in the repo root (tests/, top-level suite) -uv run ruff check . && uv run ruff format --check . && uv run pyright +uv run pytest tests/ # in the repo root (top-level suite; see note) +uv run ruff check --no-cache . && uv run ruff format --check --no-cache . && uv run pyright uv run pyright # ALSO in modules/ (see note below) scripts/validate-full.sh # then inspect env_check, build_check, quality_classification, and final_report ``` +**Scope the root suite to `tests/` — a bare `uv run pytest` at the root does NOT work.** +Every module under `modules/` is its own uv project with its own lockfile and its own +`tests/conftest.py`, so an unscoped root collection fails twice over: module dependencies +are absent from the root venv (`ModuleNotFoundError: pathspec`), and several +`tests/conftest.py` files collide on the same `tests.conftest` module name +(`ImportPathMismatchError`). That is the per-module project layout working as designed, +not a defect to fix — CI matches it, running `pytest tests/ --ignore=tests/dtu` at the +root plus one job per module. Run each module's suite from that module's own directory. + +**Pass `--no-cache` to the ruff gates.** Ruff's cache can report a file as already +formatted when it is not, and the root `ruff format --check .` is a CI gate. Real +instance: two files edited in-session were reported clean by a cached local `ruff format +--check .` ("190 files already formatted"), were committed in that state, and CI's Lint +job then failed on the exact same command — a later `git stash`/`stash pop` invalidated +the cache and the same tree reported "2 files would be reformatted". A cached green +format check is not evidence; re-verify with `--no-cache`, or against a clean checkout +(`git archive | tar -x -C "$(mktemp -d)"`), before trusting it. + **Run `pyright` from the MODULE directory too, not only the repo root.** The root invocation does not reproduce a module's own Pyright configuration, so module-local type errors pass the root gate and surface later in review. Real instance: a helper missing a