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..134c058a --- /dev/null +++ b/.amplifier/digital-twin-universe/profiles/context-intelligence-self-healing-replay-validation.yaml @@ -0,0 +1,552 @@ +# 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, 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 + # 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 + 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-format 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) + # 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 + 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 + # 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" + 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. + $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"), + spec=spec, 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 + $CI_PY - <<'PY' + 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": 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"), + 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 + 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 + + - | + 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. + # 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 + 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" "$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": 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(sys.argv[2]), + spec=spec, bounds=SweepBounds()).run()) + 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 + 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: + - 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: 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: > + 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. Imported from the CLI-resolved cache (the hook + # module is loaded from there, not installed into the tool venv). + 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' + 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_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: 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) + 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, 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 + 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 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 + 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: 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: > + 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..b65e2547 --- /dev/null +++ b/.amplifier/digital-twin-universe/profiles/support/self-healing-replay/verify.py @@ -0,0 +1,253 @@ +#!/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_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(): + 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 == "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 + 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: + 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 + + 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/AGENTS.md b/AGENTS.md index b9b68c59..6cffa950 100644 --- a/AGENTS.md +++ b/AGENTS.md @@ -71,11 +71,36 @@ 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 +`-> 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 @@ -120,6 +145,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 9d99b739..cd8590ff 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,20 @@ 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** 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. + +**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..96ac3288 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: @@ -125,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 @@ -181,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.` @@ -261,7 +307,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..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 @@ -45,6 +45,7 @@ from __future__ import annotations +import asyncio import fnmatch import logging from collections.abc import Callable, Coroutine @@ -160,8 +161,41 @@ 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. + # 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. + if isinstance(state, dict): + state["sweep_tasks"] = schedule_backlog_sweeps(resolver, dispatchers, active) + else: + schedule_backlog_sweeps(resolver, dispatchers, active) + if not destinations: log.info("context-intelligence fan-out: no destinations configured — local JSONL only") elif active: @@ -175,6 +209,232 @@ async def apply_active_dispatchers( return match_key, sorted(active) +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 + 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": 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. + 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." + " 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 + + # 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: + 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, + ) + + +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], 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 + ``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 + + 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 + + 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, + # 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, + 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() + + 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) + 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) + 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(_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(): + 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 +610,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 +730,24 @@ def verify_ingestion_consistency(settings_path: str) -> dict[str, Any]: ) async def cleanup() -> None: + # 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: + 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/amplifier_module_hook_context_intelligence/config_resolver.py b/modules/hook-context-intelligence/amplifier_module_hook_context_intelligence/config_resolver.py index 46e7e0a3..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 @@ -514,6 +514,99 @@ 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_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. + + 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..36d8b52a --- /dev/null +++ b/modules/hook-context-intelligence/amplifier_module_hook_context_intelligence/handlers/backlog_sweep.py @@ -0,0 +1,620 @@ +"""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. + +**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 + +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 ..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 + + from ..config_resolver import Destination + +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 + #: 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 + #: 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 + 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. + """ + """(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" + 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]) + return [(sd, md) for _, sd, md in in_window], 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, + 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 + #: 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 + 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 ------------------------------------------------------ + + 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 + 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. + # 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( + 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 _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? ------- + + 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( + 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 + + # 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 + skipped_permanent = 0 + failed = 0 + first_error: str | None = None + stop = False + + def _persist(outcome: str) -> int: + 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: + 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), (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 RESOLVED -- accepted, + # or permanently rejected and recorded above. + prefix_end = end + delivered_count += 1 + if stop: + break + 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") + raise + + 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: + 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 + #: 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 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 + # 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 + ) + # 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 + ) + 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/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..7f4b1463 --- /dev/null +++ b/modules/hook-context-intelligence/amplifier_module_hook_context_intelligence/handlers/delivery_watermark.py @@ -0,0 +1,287 @@ +"""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 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 +#: 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 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: + 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..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 @@ -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 @@ -354,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 @@ -458,6 +510,33 @@ 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 + + @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()) @@ -469,7 +548,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,25 +575,94 @@ 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: 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, ) 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. @@ -594,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, @@ -729,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, @@ -767,8 +927,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 +941,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 +951,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 +1078,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 +1091,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 +1100,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 +1197,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 +1467,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. @@ -1308,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, @@ -1467,7 +1647,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 +1658,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 +1737,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 +1765,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 +1787,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 +1814,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 +1843,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 +2092,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 +2108,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_backlog_sweep.py b/modules/hook-context-intelligence/tests/test_backlog_sweep.py new file mode 100644 index 00000000..7e881131 --- /dev/null +++ b/modules/hook-context-intelligence/tests/test_backlog_sweep.py @@ -0,0 +1,762 @@ +"""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 asyncio +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 + + +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) + 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_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) == 5 + + 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 + + +@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" + + +@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 + + +@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 + + +@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_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_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..1b054131 --- /dev/null +++ b/modules/hook-context-intelligence/tests/test_delivery_watermark.py @@ -0,0 +1,427 @@ +"""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) + + +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 == [] 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..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. @@ -130,7 +131,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] @@ -138,6 +139,7 @@ def enqueue(self, event, data): 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 @@ -152,7 +154,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] @@ -160,6 +162,7 @@ def enqueue(self, event, data): 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: @@ -387,7 +390,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_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" 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..486298a6 --- /dev/null +++ b/modules/hook-context-intelligence/tests/test_sweep_scheduling.py @@ -0,0 +1,373 @@ +"""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, + await_sweeps_idle, + 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 _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" + 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: + assert ( + schedule_backlog_sweeps( + _Resolver(tmp_path, sweep_enabled=False), [_Dispatcher()], SPECS + ) + == [] + ) + + 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, + ) + handles = schedule_backlog_sweeps( + _Resolver(tmp_path, sweep_interval_seconds=0.0), [_Dispatcher()], SPECS + ) + await asyncio.gather(*(h.task for h in handles)) + 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, + ) + handles = schedule_backlog_sweeps( + _Resolver(tmp_path, sweep_interval_seconds=0.01), [_Dispatcher()], SPECS + ) + await asyncio.sleep(0.08) + 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( + 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, + ) + handles = schedule_backlog_sweeps( + _Resolver(tmp_path, sweep_interval_seconds=0.01), [_Dispatcher()], SPECS + ) + await asyncio.sleep(0.06) + 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( + 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, + ) + handles = schedule_backlog_sweeps( + _Resolver(tmp_path, sweep_interval_seconds=1.0), [_Dispatcher()], SPECS + ) + await asyncio.sleep(0) + 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 +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"] + + +@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()], SPECS + ) + 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()], SPECS + ) + 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()], SPECS + ) + 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" + + +@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) 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())