diff --git a/commands/research-queue.md b/commands/research-queue.md new file mode 100644 index 0000000..4c94bcc --- /dev/null +++ b/commands/research-queue.md @@ -0,0 +1,37 @@ +# /research-queue — Live Perplexity Research Queue Status + +Show the current state of the global Perplexity research FIFO queue — the cross-session +serialization layer that all concurrent `/research-perplexity` runs pass through. Use this to see +what's running, who's waiting and where, and whether anything is failing. + +## What to do + +1. **Read the live snapshot:** `~/.claude/council-logs/perplexity-queue.json` (atomically written; + has a monotonic `version` — if you read it twice, trust the higher `version`). + - If the file does not exist: no research has run through the queue yet — say so and stop. + +2. **Render a compact status:** + - **Active:** the currently-running run — `session`, query preview, `elapsed_s`, `heartbeat_age_s`. + If `active` is null → "idle (no run in progress)". + - **Queued (FIFO order):** each waiting run — `position`, `session`, query preview, `wait_s`. + Empty list → "none waiting". + - **Recent:** the last few `completed`/`error`/`timeout` runs with `duration_s` and status. + - **Stats:** `depth` (currently waiting), `total_today`, `errors_today`. + +3. **For deeper history**, read the tail of `~/.claude/council-logs/perplexity-activity.jsonl` — + the append-only event log (`enqueued`/`started`/`completed`/`error`/`timeout`), each line carrying + a shared `run_id` that links to `instrumentation-query.jsonl` and `runs.jsonl`. + +4. **Flag anything unhealthy and suggest a fix:** + - Active run with `heartbeat_age_s` > 120s → likely stalled/dead holder (the queue auto-reclaims + via PID-liveness + TTL, but surface it). + - Deep queue (many waiting) → congestion; expected under heavy concurrency. + - Recent `error`/`timeout` events → check the keeper/session health. + - If the queue is misbehaving, the instant kill-switch is `RESEARCH_QUEUE_ENABLED=0` (runs then + pass straight through, no queuing), and `RESEARCH_QUEUE_MAX_WAIT` (default 1200s) bounds the wait. + +## Notes +- Source of truth is the ticket dir `~/.claude/config/research-queue/tickets/`; the JSON is a + derived snapshot. If the JSON looks stale, list the ticket dir to cross-check. +- The `research_queue_status` MCP tool (browser-bridge) returns the same snapshot programmatically. +- Architecture + operations: `~/.claude/docs/plans/2026-07-11-perplexity-research-queue-design.md`. diff --git a/council-automation/browser_bridge_keeper.py b/council-automation/browser_bridge_keeper.py new file mode 100644 index 0000000..1795732 --- /dev/null +++ b/council-automation/browser_bridge_keeper.py @@ -0,0 +1,300 @@ +"""browser_bridge_keeper.py — keep the Claude Browser Bridge Chrome always running. + +The browser-bridge MCP (remote Claude's browser automation) relies on a Chrome +MV3 extension whose service worker is a WebSocket CLIENT to the MCP server at +ws://127.0.0.1:8765. When that Chrome is closed the bridge disconnects. The user +is almost always remote, so the bridge is dead most of the time. + +This keeper guarantees the Chrome that HAS the bridge extension is always up. + +Host = the user's DEFAULT Chrome profile (`AppData\\Local\\Google\\Chrome\\User Data`, +profile "Default"). WHY the default profile and not a dedicated one: + - The bridge extension is installed UNPACKED (developer-mode Load-unpacked, + manifest location=4) in the DEFAULT profile and loads reliably there. + - On this machine (AzureAD-managed, Chrome 150) the `--load-extension` + command-line flag is IGNORED — verified 2026-07-12 via a CDP probe (0 + service-worker targets) — so a dedicated profile CANNOT force-load the + extension. Google is deprecating command-line extension loading. + - The default profile is also logged into the sites the automation needs + (Facebook, etc.), which a fresh dedicated profile would not be. + +Architecture (mirrors session_keeper.py's one-shot pivot): each run checks +whether a default-profile Chrome is alive; if not, it launches one detached and +exits. Windows Task Scheduler drives the watchdog cadence (AtLogOn + every 5 min). + +Usage: + python browser_bridge_keeper.py # ensure the bridge Chrome is up (one-shot) + python browser_bridge_keeper.py --status # is a default-profile Chrome running? + python browser_bridge_keeper.py --stop # clear keeper state (does NOT close your Chrome) + +To stop auto-relaunch: install_bridge_keeper_task.ps1 -Uninstall. +""" +from __future__ import annotations + +import argparse +import os +import signal +import subprocess +import sys +import time +from pathlib import Path + +# --------------------------------------------------------------------------- +# Constants +# --------------------------------------------------------------------------- + +# The bridge extension lives in the DEFAULT profile. We target it explicitly so +# Chrome opens the profile that actually has the extension even if the user has +# multiple profiles. +PROFILE_DIRECTORY = "Default" + +PID_FILE = Path.home() / ".claude" / "config" / "bridge_keeper.pid" +LOG_PATH = Path.home() / ".claude" / "logs" / "browser_bridge_keeper.log" + +LAUNCH_CONFIRM_TIMEOUT_S = 15 # how long to wait for the launched Chrome to appear + +# Windows constants +_DETACHED_PROCESS = 0x00000008 +_CREATE_NEW_PROCESS_GROUP = 0x00000200 +_STARTF_USESHOWWINDOW = 0x00000001 +_SW_SHOWMINNOACTIVE = 7 # start minimized, do NOT activate (no focus steal) + + +# --------------------------------------------------------------------------- +# Logging / PID state +# --------------------------------------------------------------------------- + +def _log(msg: str) -> None: + """Emit a timestamped keeper log line (also lands in LOG_PATH under Task Scheduler).""" + ts = time.strftime("%H:%M:%S") + print(f"[bridge-keeper {ts}] {msg}", flush=True) + + +def _write_pid() -> None: + PID_FILE.parent.mkdir(parents=True, exist_ok=True) + PID_FILE.write_text(str(os.getpid()), encoding="utf-8") + + +def _clear_pid() -> None: + try: + PID_FILE.unlink() + except FileNotFoundError: + pass + + +def _harden_for_windows_daemon() -> None: + """Redirect fds 1/2 to LOG_PATH so Task Scheduler runs are diagnosable. + + Called from main() ONLY for the keep action, AFTER the --status/--stop + branches, so operator output for those isn't swallowed into the log. + """ + if sys.platform != "win32": + return + try: + LOG_PATH.parent.mkdir(parents=True, exist_ok=True) + log_fd = os.open(str(LOG_PATH), os.O_WRONLY | os.O_CREAT | os.O_APPEND, 0o644) + os.dup2(log_fd, 1) + os.dup2(log_fd, 2) + os.close(log_fd) + sys.stdout = os.fdopen(1, "w", buffering=1) + sys.stderr = os.fdopen(2, "w", buffering=1) + except (OSError, ValueError): + pass + for sig_name in ("SIGBREAK", "SIGINT"): + sig = getattr(signal, sig_name, None) + if sig is not None: + try: + signal.signal(sig, signal.SIG_IGN) + except (ValueError, OSError): + pass + + +# --------------------------------------------------------------------------- +# Chrome discovery / process scanning +# --------------------------------------------------------------------------- + +def _find_chrome_executable() -> str | None: + """Find a Chrome executable on Windows (system install locations).""" + candidates = [ + Path(os.environ.get("PROGRAMFILES", r"C:\Program Files")) / "Google" / "Chrome" / "Application" / "chrome.exe", + Path(os.environ.get("PROGRAMFILES(X86)", r"C:\Program Files (x86)")) / "Google" / "Chrome" / "Application" / "chrome.exe", + Path(os.environ.get("LOCALAPPDATA", "")) / "Google" / "Chrome" / "Application" / "chrome.exe", + ] + for c in candidates: + if c.exists(): + return str(c) + return None + + +def _default_chrome_pids() -> list[int]: + """Read-only: PIDs of DEFAULT-profile Chrome BROWSER processes. + + A default-profile Chrome's main (browser) process has no `--type=` and no + explicit `--user-data-dir=` (our keeper profiles always set one, so this + cleanly distinguishes the user's real Chrome from session_keeper/other + custom-profile Chromes). Non-empty ⇒ the bridge Chrome is alive. Windows-only. + """ + if sys.platform != "win32": + return [] + try: + ps_cmd = ( + "Get-CimInstance Win32_Process -Filter \"Name='chrome.exe'\" | " + "Where-Object { $_.CommandLine -and $_.CommandLine -notlike '*--type=*' " + "-and $_.CommandLine -notlike '*--user-data-dir=*' } | " + "Select-Object -ExpandProperty ProcessId" + ) + result = subprocess.run( + ["powershell", "-NoProfile", "-Command", ps_cmd], + capture_output=True, text=True, timeout=15, + ) + pids: list[int] = [] + for line in (result.stdout or "").splitlines(): + line = line.strip() + if line.isdigit(): + pids.append(int(line)) + return pids + except Exception: + return [] + + +def _chrome_version(chrome_exe: str) -> str: + """Return Chrome's product version, or 'unknown' (logged each launch).""" + if sys.platform != "win32": + return "unknown" + try: + result = subprocess.run( + ["powershell", "-NoProfile", "-Command", + f"(Get-Item '{chrome_exe}').VersionInfo.ProductVersion"], + capture_output=True, text=True, timeout=10, + ) + v = (result.stdout or "").strip() + return v or "unknown" + except Exception: + return "unknown" + + +# --------------------------------------------------------------------------- +# Launch +# --------------------------------------------------------------------------- + +def _launch_default_chrome() -> bool: + """Launch the user's DEFAULT-profile Chrome (which has the bridge extension), + detached and started minimized (a hint — Chrome restores its own window + state, which is correct for the user's real browser). Returns True if a live + default-profile Chrome is observed afterward. + """ + chrome_exe = _find_chrome_executable() + if not chrome_exe: + _log("ERROR: Chrome not found in standard install locations. Install Google Chrome.") + return False + + _log(f"Chrome {_chrome_version(chrome_exe)} | launching default profile '{PROFILE_DIRECTORY}'") + + # Minimal flags — this is the user's REAL browser, so we do NOT force it + # offscreen, disable occlusion, or force-minimize it. No explicit + # --user-data-dir (uses the default User Data dir). No URL — let Chrome do + # its normal startup / session restore per the user's settings. + chrome_args = [ + chrome_exe, + f"--profile-directory={PROFILE_DIRECTORY}", + "--no-first-run", + "--no-default-browser-check", + ] + + creationflags = 0 + startupinfo = None + if sys.platform == "win32": + creationflags = _DETACHED_PROCESS | _CREATE_NEW_PROCESS_GROUP + startupinfo = subprocess.STARTUPINFO() + startupinfo.dwFlags |= _STARTF_USESHOWWINDOW + startupinfo.wShowWindow = _SW_SHOWMINNOACTIVE + + _log("Launching default-profile Chrome (detached, minimized hint)...") + try: + subprocess.Popen( + chrome_args, + creationflags=creationflags, + startupinfo=startupinfo, + stdin=subprocess.DEVNULL, + stdout=subprocess.DEVNULL, + stderr=subprocess.DEVNULL, + close_fds=True, + ) + except Exception as e: # noqa: BLE001 + _log(f"ERROR: failed to launch Chrome: {e}") + return False + + deadline = time.time() + LAUNCH_CONFIRM_TIMEOUT_S + pids: list[int] = [] + while time.time() < deadline: + pids = _default_chrome_pids() + if pids: + break + time.sleep(1) + + if not pids: + _log(f"ERROR: default-profile Chrome did not appear within {LAUNCH_CONFIRM_TIMEOUT_S}s.") + return False + + _log(f"Bridge Chrome up (default profile, pids={pids}). Extension should reconnect the WS bridge.") + return True + + +# --------------------------------------------------------------------------- +# Subcommands +# --------------------------------------------------------------------------- + +def status() -> None: + pids = _default_chrome_pids() + if pids: + _log(f"Default-profile Chrome RUNNING (pids={pids}) — bridge host is up.") + else: + _log("Default-profile Chrome NOT running — bridge host is down.") + + +def stop() -> None: + # Deliberately does NOT kill Chrome: this mode manages the user's REAL + # browser, and force-closing it would discard their tabs. Just clear keeper + # state; use install_bridge_keeper_task.ps1 -Uninstall to stop auto-relaunch. + _clear_pid() + _log("Keeper state cleared. This mode manages your real Chrome and will NOT " + "force-close it. Uninstall the scheduled task to stop auto-relaunch; " + "close Chrome yourself if you want it down.") + + +def ensure_running() -> int: + """One-shot: launch the default-profile Chrome if it isn't already up.""" + pids = _default_chrome_pids() + if pids: + _log(f"Bridge Chrome already up (default profile, pids={pids}); nothing to do.") + return 0 + ok = _launch_default_chrome() + return 0 if ok else 1 + + +# --------------------------------------------------------------------------- +# Entry point +# --------------------------------------------------------------------------- + +def main() -> None: + parser = argparse.ArgumentParser(description="Keep the Claude Browser Bridge Chrome alive.") + parser.add_argument("--status", action="store_true", help="Report whether the bridge Chrome is running") + parser.add_argument("--stop", action="store_true", help="Clear keeper state (does NOT close your Chrome)") + args = parser.parse_args() + + if args.status: + status() + return + if args.stop: + stop() + return + + # Keep action only: now safe to redirect stdio to the log (see docstring). + _harden_for_windows_daemon() + _write_pid() + code = ensure_running() + sys.exit(code) + + +if __name__ == "__main__": + main() diff --git a/council-automation/council_browser.py b/council-automation/council_browser.py index 93cf26e..b30d0d7 100644 --- a/council-automation/council_browser.py +++ b/council-automation/council_browser.py @@ -63,7 +63,27 @@ VISION_POLL_INTERVAL_SYNTHESIS, ) -from submission_lock import get_submit_lock +import research_queue +from submission_lock import get_submit_lock, start_lock_heartbeat + +# Env flag values (case-insensitive) treated as "enabled". A bare +# `os.environ.get(...)` truthiness check would treat FLAG=0/FLAG=false +# as enabled too (any non-empty string is truthy) -- _flag_enabled() +# normalizes that footgun for every RESEARCH_QUEUE_* flag read below. +_TRUTHY_FLAG_VALUES = {"1", "true", "yes", "on"} + + +def _flag_enabled(env_var: str) -> bool: + """Return True only if `env_var` is set to a recognized truthy value. + + Recognized truthy values (case-insensitive): "1", "true", "yes", + "on". Unset, empty, or any other value (including "0"/"false") is + treated as disabled. + """ + value = os.environ.get(env_var) + if value is None: + return False + return value.strip().lower() in _TRUTHY_FLAG_VALUES class BrowserBusyError(Exception): @@ -392,6 +412,14 @@ def _is_reasoning_trail_only(text: str) -> bool: ) +# A synthesis at/above this length is treated as a complete answer, never a +# failure worth flagging: the truncation heuristic (rule (d)) is unreliable at +# this size (reasoning-trail-inflated .prose peak). Chosen from the empirical +# 197-vs-6379-char gap (Jul 12-14): 8x above the failure ceiling, ~2200-char +# buffer below the smallest known-good output. Perplexity-verified 2026-07-14. +SUBSTANTIAL_SYNTHESIS_CHARS = 2500 + + def _validate_result(text: str, peak_len: int | None = None) -> str: """Post-extraction semantic-completeness check (Perplexity #4, 2026-06-15). @@ -416,10 +444,21 @@ def _validate_result(text: str, peak_len: int | None = None) -> str: s = (text or "").strip() if not s: return "empty" - # (d) length regression vs streaming peak. - if isinstance(peak_len, (int, float)) and peak_len >= 100: - if (peak_len - len(s)) / peak_len > 0.15: - return "suspect_truncated" + # (d) length regression vs streaming peak — GATED to non-substantial outputs. + # On large structured answers the streaming .prose peak is inflated by + # transient reasoning-trail text that collapses on final extraction, so a + # COMPLETE 6-13K-char answer trips the >15% regression check. Empirically + # (Jul 12-14 instrumentation) this was the SOLE false-positive source: every + # false "truncated" flag was on an output >=6000 chars, while every genuine + # near-empty failure was <300 chars. Gate (d) below SUBSTANTIAL_SYNTHESIS_CHARS + # so it still catches truncation of short/medium answers (where the .prose + # peak is a reliable baseline). Rules (a)/(b) stay UNCONDITIONAL so a + # structural cut mid-fence / mid-token is still caught at any size + # (per Perplexity plan-verification 2026-07-14). + if len(s) < SUBSTANTIAL_SYNTHESIS_CHARS: + if isinstance(peak_len, (int, float)) and peak_len >= 100: + if (peak_len - len(s)) / peak_len > 0.15: + return "suspect_truncated" # (a) unclosed code fence. if s.count("```") % 2 == 1: return "suspect_truncated" @@ -1045,6 +1084,9 @@ async def _ensure_fresh_session(self, reason: str = "") -> None: freshness = self._check_session_freshness(self.session_path) if hasattr(self, "_query_inst"): self._query_inst["cookies_stale_critical"] = freshness.get("stale_critical", []) + # Pre-guard min critical-cookie TTL — the value the guard decided on, + # which is what lets calibration tune SESSION_FRESHNESS_THRESHOLD_S. + self._query_inst["min_critical_ttl_s"] = freshness.get("min_critical_ttl_s") stale = freshness.get("stale_critical") or [] soon = freshness.get("expiring_soon") or [] if not stale and not soon: @@ -1338,16 +1380,53 @@ async def _acquire_submit_lock(self): critical section. `FileLock.acquire` is blocking; we offload to a worker thread so the asyncio event loop keeps pumping (network IO, timer callbacks) while we wait our turn. + + Under RESEARCH_QUEUE_STOPGAP (see `run()`), submit_lock is held + for the whole run (minutes, not the ~10-25s submit window this + lock was designed for). Two adjustments only apply under that + flag: (1) acquire with a long timeout (RESEARCH_QUEUE_MAX_WAIT, + default 1200s) so a waiting session queues instead of erroring + out on the short default timeout; (2) start a background + heartbeat that refreshes the lock file's mtime so the 180s + stale-reclaim in `get_submit_lock()` never mistakes a live + long-held lock for a crashed one. Default (flag unset) behavior + is unchanged -- default timeout, no heartbeat. """ - lock = get_submit_lock() + stopgap = _flag_enabled("RESEARCH_QUEUE_STOPGAP") + timeout = None + if stopgap: + try: + timeout = float(os.environ.get("RESEARCH_QUEUE_MAX_WAIT", "1200")) + except ValueError: + timeout = 1200.0 + lock = get_submit_lock(timeout=timeout) _log( f"submit_lock waiting timeout_s={lock.timeout:.0f} " f"path={lock.lock_file}" ) await asyncio.to_thread(lock.acquire) _log(f"submit_lock acquired path={lock.lock_file}") + if stopgap: + self._submit_lock_heartbeat = start_lock_heartbeat(lock) + _log("submit_lock heartbeat started (RESEARCH_QUEUE_STOPGAP)") return lock + def _stop_submit_lock_heartbeat(self) -> None: + """Stop and clear the submit-lock heartbeat thread, if running. + + Idempotent and safe to call unconditionally: when + RESEARCH_QUEUE_STOPGAP is unset (default), the heartbeat is + never started, `self._submit_lock_heartbeat` stays unset/None, + and this is a silent no-op. + """ + heartbeat = getattr(self, "_submit_lock_heartbeat", None) + if heartbeat is not None: + try: + heartbeat.stop() + except Exception: + pass + self._submit_lock_heartbeat = None + async def activate_mode(self, page) -> bool: """Activate the configured Perplexity mode via slash command. @@ -2849,7 +2928,70 @@ async def _cleanup_browser(self) -> None: self._browser = None async def run(self, query: str) -> dict: - """Full pipeline: semaphore -> start -> validate -> query -> wait -> extract.""" + """Full pipeline, FIFO-serialized: research_queue slot -> semaphore -> + start -> validate -> query -> wait -> extract. + + The research_queue slot is the OUTERMOST layer -- it wraps the + entire existing pipeline in `_run_impl` (semaphore, Chrome + launch, submit_lock, extract), so acquisition order is always + queue -> submit_lock, never reversed, and at most one run() + across ALL concurrent Claude Code sessions is ever inside + `_run_impl` at a time. + + `acquire_slot()` is a SYNC context manager whose __enter__ blocks + in a poll-wait loop (up to research_queue.MAX_WAIT_S) -- entered + and exited via `asyncio.to_thread` (same pattern as + `_acquire_submit_lock`'s `asyncio.to_thread(lock.acquire)`) so a + waiting run() never blocks this process's asyncio event loop. + + Kill switch: `RESEARCH_QUEUE_ENABLED=0` makes `acquire_slot()` a + true no-op (see research_queue.py) -- `run()` then behaves + byte-for-byte as it did before this wiring (no ticket/log/ + snapshot files, no serialization). + + `_run_impl` swallows almost all failures internally and returns + an `{"error": ...}` dict rather than raising (see its own + `except Exception` block), so a real exception essentially never + reaches this wrapper. To make the central + `perplexity-activity.jsonl` record "error" (not "completed") for + those logical failures too, a synthetic exc_info is passed into + `slot_cm.__exit__` when the result dict carries an "error" key -- + this is NOT re-raised; run()'s external contract (always returns + a dict, never raises for expected failures) is unchanged. + """ + session_id = f"{Path.cwd().name}:{os.getpid()}" + slot_cm = research_queue.acquire_slot( + session=session_id, query_preview=query, mode=self.perplexity_mode + ) + slot = await asyncio.to_thread(slot_cm.__enter__) + self._run_id = slot.get("run_id") + + _exc_info: tuple = (None, None, None) + try: + result = await self._run_impl(query) + if isinstance(result, dict) and result.get("error"): + _exc_info = ( + RuntimeError, + RuntimeError(str(result.get("error"))[:200]), + None, + ) + return result + except BaseException as e: + _exc_info = (type(e), e, e.__traceback__) + raise + finally: + await asyncio.to_thread(lambda: slot_cm.__exit__(*_exc_info)) + + async def _run_impl(self, query: str) -> dict: + """Full pipeline: semaphore -> start -> validate -> query -> wait -> extract. + + Called only from `run()`, which wraps this entire method in the + research_queue FIFO slot. `self._run_id` (stamped by `run()` + before this method starts) is threaded into `self._query_inst` + and the returned `results` dict below, so + `instrumentation-query.jsonl` / `runs.jsonl` share the same + run_id used in the central `perplexity-activity.jsonl`. + """ start_time = time.time() self._init_artifact_dir(query) self._semaphore = SessionSemaphore() @@ -2862,6 +3004,7 @@ async def run(self, query: str) -> dict: # emit happens at every exit path (early returns + bottom finally). self._query_inst: dict = { "ts": time.strftime("%Y-%m-%dT%H:%M:%S%z"), + "run_id": getattr(self, "_run_id", None), "query_chars": len(query) if query else 0, "perplexity_mode": getattr(self, "perplexity_mode", None), "chrome_path_used": None, @@ -2874,6 +3017,8 @@ async def run(self, query: str) -> dict: "extracted_synthesis_chars": 0, "peak_prose_chars": 0, "result_validation": "ok", + "min_critical_ttl_s": None, # pre-guard min critical-cookie TTL (calibration #3) + "elapsed_wall_s": None, # submit->final wall time (calibration #3) "exit_reason": None, "inst_emitted": False, } @@ -2979,7 +3124,12 @@ async def run(self, query: str) -> dict: # that was causing "browsers close each other out". # Release happens immediately after submit_query returns so # wait_for_completion + extract_results run OUTSIDE the lock - # (fully parallel across sessions). + # (fully parallel across sessions) -- THIS IS THE DEFAULT + # (RESEARCH_QUEUE_STOPGAP unset) BEHAVIOR ONLY. Under + # RESEARCH_QUEUE_STOPGAP, that early release is skipped + # (see the guard below) and submit_lock stays held all the + # way through wait_for_completion + extract_results, + # released only in the outer `finally`. _log(f"Activating {self.perplexity_mode} mode...") if not await self.activate_mode(page): await self._save_artifact(page, "activate_failure") @@ -2992,12 +3142,26 @@ async def run(self, query: str) -> dict: # appeared inside submit_query). Defensive release in the # outer finally covers any exception path that bypasses # this explicit release. - try: - submit_lock.release() - submit_lock_released = True - _log("submit_lock released") - except Exception as e: - _log(f"submit_lock release error={e!r}") + # + # Phase 0 stopgap (RESEARCH_QUEUE_STOPGAP): when set, skip + # this early release so submit_lock stays held for the + # WHOLE run — the existing defensive release in the outer + # `finally` below (guarded by `submit_lock_released`) + # becomes the sole release point, serializing entire runs + # instead of just the submit window. Default (flag unset) + # behavior is unchanged. + if not _flag_enabled("RESEARCH_QUEUE_STOPGAP"): + try: + submit_lock.release() + submit_lock_released = True + _log("submit_lock released") + except Exception as e: + _log(f"submit_lock release error={e!r}") + finally: + # No-op when the flag is off (heartbeat is only + # ever started under RESEARCH_QUEUE_STOPGAP in + # _acquire_submit_lock), kept here for symmetry. + self._stop_submit_lock_heartbeat() _log("Waiting for completion...") completed = await self.wait_for_completion(page, self.timeout) @@ -3013,6 +3177,7 @@ async def run(self, query: str) -> dict: results["mode"] = "browser" results["completed"] = completed results["execution_time_ms"] = elapsed + results["run_id"] = getattr(self, "_run_id", None) _log(f"Done in {elapsed/1000:.1f}s") return results @@ -3056,6 +3221,14 @@ async def run(self, query: str) -> dict: _log("submit_lock released (defensive)") except Exception: pass + finally: + # Under RESEARCH_QUEUE_STOPGAP this is the ONLY + # release point (the mid-run release above is + # skipped under the flag), so it must also be where + # the heartbeat thread started in + # _acquire_submit_lock() gets stopped. No-op when + # the flag is off / heartbeat was never started. + self._stop_submit_lock_heartbeat() # Phase 3 (2026-05-29): emit per-query instrumentation once per # run() invocation regardless of exit path (normal return, raised # exception, mid-pipeline failure). Idempotent via _query_inst_emitted. @@ -3063,6 +3236,7 @@ async def run(self, query: str) -> dict: try: if self._query_inst.get("exit_reason") is None: self._query_inst["exit_reason"] = "completed" + self._query_inst["elapsed_wall_s"] = round(time.time() - start_time, 1) _emit_query_instrumentation(self._query_inst) self._query_inst_emitted = True except Exception: diff --git a/council-automation/install_bridge_keeper_task.ps1 b/council-automation/install_bridge_keeper_task.ps1 new file mode 100644 index 0000000..25dbafc --- /dev/null +++ b/council-automation/install_bridge_keeper_task.ps1 @@ -0,0 +1,133 @@ +# install_bridge_keeper_task.ps1 — Register browser_bridge_keeper.py as a Windows Task Scheduler task. +# +# Why: the browser-bridge MCP (remote Claude's browser automation) needs a Chrome +# with the "Claude Browser Bridge" MV3 extension to be running at all times so its +# WebSocket client can connect to the MCP server on ws://127.0.0.1:8765. This task +# keeps a DEDICATED, minimized bridge Chrome alive — launched at logon and +# re-launched by a periodic watchdog if it ever dies. Sibling of the +# PerplexitySessionKeeper task (install_keeper_task.ps1). +# +# Task Scheduler (not a long-lived daemon) is used for the same reasons as the +# Perplexity keeper: it invokes pythonw.exe with sane stdio, auto-restarts on +# failure, runs at logon, and runs as the logged-in interactive user so Chrome +# has a GUI session to render in. The keeper itself is ONE-SHOT (check → launch +# if dead → exit); the task repetition drives the watchdog. +# +# Run ONCE from an elevated PowerShell (Run as Administrator) the first time. +# Re-running is idempotent (updates the task in place). +# +# Usage: +# PowerShell -ExecutionPolicy Bypass -File install_bridge_keeper_task.ps1 +# PowerShell -ExecutionPolicy Bypass -File install_bridge_keeper_task.ps1 -Uninstall + +param( + [switch]$Uninstall, + [string]$TaskName = "BrowserBridgeKeeper", + [string]$PythonW = "" # auto-detect if empty +) + +$ErrorActionPreference = "Stop" + +$keeperPath = "$HOME\.claude\council-automation\browser_bridge_keeper.py" +$logDir = "$HOME\.claude\logs" + +if ($Uninstall) { + if (Get-ScheduledTask -TaskName $TaskName -ErrorAction SilentlyContinue) { + Write-Host "Removing scheduled task '$TaskName'..." + Unregister-ScheduledTask -TaskName $TaskName -Confirm:$false + Write-Host "Done. Bridge Chrome will no longer auto-start at logon." + Write-Host "Run 'python `"$keeperPath`" --stop' to close the current bridge Chrome." + } else { + Write-Host "Task '$TaskName' not registered. Nothing to remove." + } + return +} + +# Validate keeper script exists +if (-not (Test-Path $keeperPath)) { + Write-Error "browser_bridge_keeper.py not found at: $keeperPath" + exit 1 +} + +# Find pythonw.exe (no-console Python interpreter) +if (-not $PythonW) { + $pythonExe = (Get-Command python -ErrorAction SilentlyContinue).Source + if (-not $pythonExe) { + Write-Error "python not found on PATH. Pass -PythonW explicitly." + exit 1 + } + $PythonW = Join-Path (Split-Path $pythonExe -Parent) "pythonw.exe" + if (-not (Test-Path $PythonW)) { + Write-Error "pythonw.exe not found next to python ($pythonExe). Pass -PythonW ." + exit 1 + } +} +Write-Host "pythonw.exe: $PythonW" +Write-Host "keeper: $keeperPath" + +# Create log directory +New-Item -ItemType Directory -Path $logDir -Force | Out-Null + +# Build the action: pythonw.exe -u browser_bridge_keeper.py +$action = New-ScheduledTaskAction ` + -Execute $PythonW ` + -Argument "-u `"$keeperPath`"" ` + -WorkingDirectory (Split-Path $keeperPath -Parent) + +# Triggers: at logon (start when the user signs in) + every 5 minutes (watchdog). +# The bridge Chrome rarely dies, so 5 min is ample — and the reuse path is just a +# ~1s process scan with NO relaunch. (Contrast: PerplexitySessionKeeper uses 8 min +# because it is driven by the ~10-min pplx.session-id cookie TTL; this keeper has +# no cookies to refresh, only process liveness to guard.) +$logonTrigger = New-ScheduledTaskTrigger -AtLogOn -User "$env:USERNAME" +$periodicTrigger = New-ScheduledTaskTrigger -Once -At (Get-Date).AddMinutes(2) ` + -RepetitionInterval (New-TimeSpan -Minutes 5) ` + -RepetitionDuration (New-TimeSpan -Days 365) + +# Run as the current user, "only when logged on" (Interactive). This is MANDATORY +# for a GUI Chrome launch: "run whether user is logged on or not" would start +# Chrome in a non-interactive window station where it won't render. A disconnected- +# but-logged-in RDP session keeps Chrome + its service worker alive and the periodic +# task still fires; only a full logoff kills Chrome, recovered by the AtLogOn trigger. +$principal = New-ScheduledTaskPrincipal ` + -UserId "$env:USERDOMAIN\$env:USERNAME" ` + -LogonType Interactive ` + -RunLevel Limited + +# Settings: restart on failure, no time limit, allow on battery +$settings = New-ScheduledTaskSettingsSet ` + -AllowStartIfOnBatteries ` + -DontStopIfGoingOnBatteries ` + -StartWhenAvailable ` + -RestartCount 5 ` + -RestartInterval (New-TimeSpan -Minutes 1) ` + -ExecutionTimeLimit (New-TimeSpan -Days 0) # 0 = no time limit + +# Remove existing task if present (idempotent install) +if (Get-ScheduledTask -TaskName $TaskName -ErrorAction SilentlyContinue) { + Write-Host "Removing existing task '$TaskName' before re-registering..." + Unregister-ScheduledTask -TaskName $TaskName -Confirm:$false +} + +Register-ScheduledTask ` + -TaskName $TaskName ` + -Description "Keeps the user's default-profile Chrome (which hosts the Claude Browser Bridge extension) running so the browser-bridge MCP is always connectable." ` + -Action $action ` + -Trigger @($logonTrigger, $periodicTrigger) ` + -Principal $principal ` + -Settings $settings | Out-Null + +Write-Host "" +Write-Host "[OK] Task '$TaskName' registered." +Write-Host "" +Write-Host "Next steps:" +Write-Host " 1. Start the task now (one-time):" +Write-Host " Start-ScheduledTask -TaskName $TaskName" +Write-Host " 2. Verify it's running:" +Write-Host " Get-ScheduledTaskInfo -TaskName $TaskName" +Write-Host " python `"$keeperPath`" --status" +Write-Host " 3. Watch the logs:" +Write-Host " Get-Content `"$logDir\browser_bridge_keeper.log`" -Wait -Tail 20" +Write-Host "" +Write-Host "Uninstall later with:" +Write-Host " PowerShell -ExecutionPolicy Bypass -File `"$PSCommandPath`" -Uninstall" diff --git a/council-automation/queue_monitor.py b/council-automation/queue_monitor.py new file mode 100644 index 0000000..e593968 --- /dev/null +++ b/council-automation/queue_monitor.py @@ -0,0 +1,522 @@ +"""queue_monitor.py -- active monitoring sidecar for the Perplexity research +FIFO queue (`research_queue.py`). + +Watches the central queue snapshot (`perplexity-queue.json`) and activity log +(`perplexity-activity.jsonl`) that `research_queue.py` publishes, and alerts +on failures/stalls so the queue can be actively monitored while serializing +research runs across up to 9 concurrent local Claude Code sessions. + +Design contract (mirrors research_monitor.py): +- **Fail-open.** Missing/torn snapshot or activity-log files never crash the + poll loop -- they are treated as "no data this tick" and logged at debug. +- **Read-only.** This module never mutates queue state (tickets, locks, + snapshot, activity log) -- it only reads research_queue.py's published + outputs and (optionally) fires Pushover notifications / triggers the + session keeper as a best-effort remediation. +- **REUSE, don't reimplement.** Pushover delivery and keeper-triggering are + imported directly from research_monitor.py rather than duplicated. + +Usage: + python queue_monitor.py [--interval N] [--once] [--no-pushover] + +``--once`` performs a single evaluation pass and exits (used by the unit +tests and for cron-style invocation); the default mode polls forever. +""" +from __future__ import annotations + +import argparse +import json +import logging +import re +import sys +import time +from dataclasses import dataclass +from pathlib import Path +from typing import Any, Dict, List, Optional, Sequence, Set, Tuple + +import research_queue + +logger = logging.getLogger(__name__) + +# -------------------------------------------------------------------------- +# Paths (monkeypatchable module globals -- resolved by name at call time so +# tests can safely do `monkeypatch.setattr(queue_monitor, "SNAPSHOT_PATH", +# tmp_path / "snapshot.json")` etc. without ever touching the real live +# queue state). +# -------------------------------------------------------------------------- +SNAPSHOT_PATH: Path = research_queue.SNAPSHOT +ACTIVITY_LOG_PATH: Path = research_queue.ACTIVITY_LOG +LOG_WORKDIR: Path = Path.home() / ".claude" / "council-logs" / "queue-monitor" + +# -------------------------------------------------------------------------- +# Thresholds (monkeypatchable module globals -- see evaluate()). +# -------------------------------------------------------------------------- +STALL_TTL_S = 120 # active.heartbeat_age_s past this -> holder may be dead/hung +DEEP_QUEUE_N = 6 # stats.depth (or len(queued)) past this -> congestion +LONG_RUN_S = 600 # active.elapsed_s past this -> stuck well past normal +SELF_HEAL_COOLDOWN_S = 300.0 # minimum gap between best-effort keeper triggers +# Stalled-near-empty detector (Jul 12-14 empirical failure mode): a run that +# burned a long wall-clock but returned almost nothing = a session/synthesis +# stall, NOT a legitimately short answer (those return fast). Both legs required +# so a fast "443" reply (<300s) never trips it. Perplexity-verified 2026-07-14. +STALL_EMPTY_S = 300 # elapsed_wall_s past this AND ... +STALL_EMPTY_CHARS = 300 # ... extracted_synthesis_chars below this -> stalled-empty + +# Per-query instrumentation JSONL emitted by council_browser (carries +# elapsed_wall_s / extracted_synthesis_chars / exit_reason / min_critical_ttl_s, +# which the activity log does not). Monkeypatchable for tests. +INSTRUMENTATION_LOG_PATH: Path = ( + Path.home() / ".claude" / "council-cache" / "instrumentation-query.jsonl" +) + +_COOKIE_FAILURE_SIGNATURE_RE = re.compile( + r"cookie|session[-_ ]?(expired|stale)|unauthorized|re-?login|auth", re.IGNORECASE +) + +# -------------------------------------------------------------------------- +# Best-effort reuse of research_monitor's Pushover + keeper helpers. If +# research_monitor is unavailable (missing module, import error), degrade +# gracefully: log once and disable notifications/self-heal rather than +# crashing the queue monitor. +# -------------------------------------------------------------------------- +try: + import research_monitor as _rm + + _send_pushover = _rm._send_pushover + _trigger_keeper = _rm._trigger_keeper +except Exception as exc: # noqa: BLE001 -- must never block queue_monitor from running + logger.warning( + "queue_monitor: research_monitor unavailable, pushover/self-heal disabled (%s)", exc + ) + _send_pushover = None + _trigger_keeper = None + + +@dataclass(frozen=True) +class Alert: + """One monitoring finding. + + `key` is stable across ticks for the same underlying condition/event, so + callers can dedupe notifications without re-alerting on every poll. + """ + + key: str + severity: str # "info" | "warning" | "critical" + message: str + + +# -------------------------------------------------------------------------- +# Pure evaluation +# -------------------------------------------------------------------------- +def evaluate( + snapshot: Optional[Dict[str, Any]], + recent_events: Sequence[Dict[str, Any]], + recent_instrumentation: Sequence[Dict[str, Any]] = (), +) -> List[Alert]: + """Compute alerts from a queue snapshot + a batch of activity-log events. + + `recent_events` is expected to be the events *new since the caller's last + poll* (see `_tail_new_activity`) -- that is how cross-poll dedup of + error/timeout alerts is achieved in `run_loop` without this function + needing to hold any state itself. Within a single call, a duplicate + run_id+event pair in `recent_events` is collapsed to one alert (this + function stays a pure, stateless computation). + + Threshold globals (STALL_TTL_S, DEEP_QUEUE_N, LONG_RUN_S) are read by + name at call time (never captured as default-arg values), so tests can + `monkeypatch.setattr(queue_monitor, "STALL_TTL_S", ...)` and have it + take effect immediately. + """ + alerts: List[Alert] = [] + + if snapshot: + active = snapshot.get("active") + if isinstance(active, dict): + run_id = active.get("run_id", "?") + session = active.get("session", "?") + hb_age = active.get("heartbeat_age_s") + if isinstance(hb_age, (int, float)) and hb_age > STALL_TTL_S: + alerts.append( + Alert( + key=f"stalled:{run_id}", + severity="critical", + message=( + f"active run {run_id} (session={session}) heartbeat stale " + f"{hb_age}s > {STALL_TTL_S}s -- holder may be dead/hung" + ), + ) + ) + elapsed = active.get("elapsed_s") + if isinstance(elapsed, (int, float)) and elapsed > LONG_RUN_S: + alerts.append( + Alert( + key=f"long_run:{run_id}", + severity="warning", + message=( + f"active run {run_id} (session={session}) elapsed {elapsed}s " + f"> {LONG_RUN_S}s -- stuck well past normal" + ), + ) + ) + + stats = snapshot.get("stats") or {} + depth = stats.get("depth") + if not isinstance(depth, (int, float)): + depth = len(snapshot.get("queued") or []) + if isinstance(depth, (int, float)) and depth > DEEP_QUEUE_N: + alerts.append( + Alert( + key="deep_queue", + severity="warning", + message=f"queue depth {depth} > {DEEP_QUEUE_N} -- congestion", + ) + ) + + seen_in_batch: Set[str] = set() + for ev in recent_events or []: + event = ev.get("event") + if event not in ("error", "timeout"): + continue + run_id = ev.get("run_id", "?") + dedupe_key = f"{run_id}:{event}" + if dedupe_key in seen_in_batch: + continue + seen_in_batch.add(dedupe_key) + session = ev.get("session", "?") + detail = ev.get("error") or ev.get("query_preview") or "" + severity = "critical" if event == "error" else "warning" + alerts.append( + Alert( + key=f"event:{dedupe_key}", + severity=severity, + message=f"{event} run_id={run_id} session={session} {detail}".strip(), + ) + ) + + # Stalled-near-empty runs: completed but burned a long wall-clock for almost + # no output = a session/synthesis stall (the Jul 12-14 real failure mode), + # distinct from a legitimately short answer (which returns fast). The + # `stalled:` key prefix makes _should_self_heal() trigger a keeper cookie + # refresh for the NEXT run (the stalls correlate with low session-cookie TTL). + seen_stall: Set[str] = set() + for rec in recent_instrumentation or []: + if rec.get("exit_reason") != "completed": + continue + elapsed = rec.get("elapsed_wall_s") + chars = rec.get("extracted_synthesis_chars") + if not isinstance(elapsed, (int, float)) or not isinstance(chars, (int, float)): + continue + if elapsed <= STALL_EMPTY_S or chars >= STALL_EMPTY_CHARS: + continue + run_id = rec.get("run_id", "?") + if run_id in seen_stall: + continue + seen_stall.add(run_id) + ttl = rec.get("min_critical_ttl_s") + ttl_hint = ( + f", low session-cookie TTL {ttl:.0f}s at run" + if isinstance(ttl, (int, float)) and ttl < 200 + else "" + ) + alerts.append( + Alert( + key=f"stalled:empty:{run_id}", + severity="critical", + message=( + f"Perplexity stalled near-empty: run {run_id} took " + f"{elapsed:.0f}s but returned only {int(chars)} chars" + f"{ttl_hint} -- likely a session stall; refreshing cookies " + f"for the next run." + ), + ) + ) + + return alerts + + +# -------------------------------------------------------------------------- +# I/O helpers (fail-open) +# -------------------------------------------------------------------------- +def _read_snapshot() -> Optional[Dict[str, Any]]: + """Read + parse SNAPSHOT_PATH. Tolerates a missing or torn (partially + written) file by returning None -- never raises into the poll loop. + """ + try: + text = SNAPSHOT_PATH.read_text(encoding="utf-8") + except OSError as exc: + logger.debug("_read_snapshot: %s unavailable (%s)", SNAPSHOT_PATH, exc) + return None + try: + data = json.loads(text) + except json.JSONDecodeError as exc: + logger.debug("_read_snapshot: %s is torn/invalid JSON, skipping this poll (%s)", + SNAPSHOT_PATH, exc) + return None + return data if isinstance(data, dict) else None + + +def _tail_new_activity(offset: int) -> Tuple[List[Dict[str, Any]], int]: + """Read JSONL activity records appended to ACTIVITY_LOG_PATH since byte + `offset`. Returns `(records, new_offset)`. A trailing partial line is + left unconsumed (offset only advances past the last complete newline). + Fail-open: returns `([], offset)` on any I/O error, and restarts from 0 + if the file shrank (rotated/truncated) since the last poll. + """ + try: + if not ACTIVITY_LOG_PATH.exists(): + return [], offset + size = ACTIVITY_LOG_PATH.stat().st_size + if size < offset: + offset = 0 + if size == offset: + return [], offset + with ACTIVITY_LOG_PATH.open("rb") as f: + f.seek(offset) + data = f.read() + except OSError as exc: + logger.debug("_tail_new_activity: could not read %s (%s)", ACTIVITY_LOG_PATH, exc) + return [], offset + + last_nl = data.rfind(b"\n") + if last_nl == -1: + return [], offset # no complete line yet + complete = data[: last_nl + 1] + new_offset = offset + len(complete) + + records: List[Dict[str, Any]] = [] + for raw in complete.decode("utf-8", errors="replace").splitlines(): + raw = raw.strip() + if not raw: + continue + try: + obj = json.loads(raw) + except json.JSONDecodeError: + continue + if isinstance(obj, dict): + records.append(obj) + return records, new_offset + + +def _tail_new_jsonl(path: Path, offset: int) -> Tuple[List[Dict[str, Any]], int]: + """Generic sibling of `_tail_new_activity` for an arbitrary JSONL `path`. + Same fail-open, shrink-detect, partial-final-line semantics. Used to tail + the per-query instrumentation log without touching the activity-log reader. + """ + try: + if not path.exists(): + return [], offset + size = path.stat().st_size + if size < offset: + offset = 0 + if size == offset: + return [], offset + with path.open("rb") as f: + f.seek(offset) + data = f.read() + except OSError as exc: + logger.debug("_tail_new_jsonl: %s unavailable (%s)", path, exc) + return [], offset + last_nl = data.rfind(b"\n") + if last_nl == -1: + return [], offset # no complete line yet + complete = data[: last_nl + 1] + new_offset = offset + len(complete) + records: List[Dict[str, Any]] = [] + for raw in complete.decode("utf-8", errors="replace").splitlines(): + raw = raw.strip() + if not raw: + continue + try: + obj = json.loads(raw) + except json.JSONDecodeError: + continue + if isinstance(obj, dict): + records.append(obj) + return records, new_offset + + +def _tail_new_instrumentation(offset: int) -> Tuple[List[Dict[str, Any]], int]: + """Tail new per-query instrumentation records since byte `offset`.""" + return _tail_new_jsonl(INSTRUMENTATION_LOG_PATH, offset) + + +# -------------------------------------------------------------------------- +# Display +# -------------------------------------------------------------------------- +def _format_table(snapshot: Optional[Dict[str, Any]], alerts: Sequence[Alert]) -> str: + """Render a compact, human-readable live status table as a string.""" + lines = [f"--- queue_monitor {time.strftime('%Y-%m-%d %H:%M:%S')} ---"] + if not snapshot: + lines.append(" (no snapshot available)") + else: + active = snapshot.get("active") + if isinstance(active, dict): + lines.append( + f" ACTIVE run={str(active.get('run_id', '?'))[:8]} " + f"session={active.get('session', '?')} " + f"elapsed={active.get('elapsed_s', '?')}s " + f"hb_age={active.get('heartbeat_age_s', '?')}s " + f"query={active.get('query_preview', '')!r}" + ) + else: + lines.append(" ACTIVE (none)") + + queued = snapshot.get("queued") or [] + if queued: + for q in queued[:5]: + lines.append( + f" QUEUED #{q.get('position')} session={q.get('session', '?')} " + f"wait={q.get('wait_s', '?')}s query={q.get('query_preview', '')!r}" + ) + if len(queued) > 5: + lines.append(f" ... and {len(queued) - 5} more queued") + else: + lines.append(" QUEUED (empty)") + + stats = snapshot.get("stats") or {} + lines.append( + f" STATS depth={stats.get('depth', '?')} " + f"total_today={stats.get('total_today', '?')} " + f"errors_today={stats.get('errors_today', '?')}" + ) + + recent = snapshot.get("recent") or [] + for r in recent[-3:]: + lines.append( + f" RECENT {str(r.get('event', '?')):9s} " + f"run={str(r.get('run_id', '?'))[:8]} session={r.get('session', '?')}" + ) + + for a in alerts: + lines.append(f" ALERT [{a.severity}] {a.message}") + + return "\n".join(lines) + + +# -------------------------------------------------------------------------- +# Notification + self-heal +# -------------------------------------------------------------------------- +def _fire_alert(alert: Alert) -> None: + """Send one Pushover notification for `alert`. Best-effort: logs and + returns on any failure, never raises. + """ + if _send_pushover is None: + logger.info("queue_monitor: pushover unavailable, alert not sent: %s", alert.message) + return + priority = 1 if alert.severity == "critical" else 0 + try: + ok = _send_pushover( + LOG_WORKDIR, f"[queue_monitor] {alert.severity.upper()}", alert.message, priority + ) + except Exception as exc: # noqa: BLE001 -- notification failures must never crash the loop + logger.warning("queue_monitor: _send_pushover raised for key=%s (%s)", alert.key, exc) + return + if not ok: + logger.debug("queue_monitor: pushover send returned falsy for key=%s", alert.key) + + +def _should_self_heal(alerts: Sequence[Alert]) -> bool: + """True if any current alert looks like a stalled-holder or a + cookie/session-failure signature -- the two conditions a keeper refresh + can plausibly help with. + """ + for a in alerts: + if a.key.startswith("stalled:"): + return True + if a.key.startswith("event:") and _COOKIE_FAILURE_SIGNATURE_RE.search(a.message): + return True + return False + + +def _maybe_self_heal(alerts: Sequence[Alert], last_fired_ts: float) -> float: + """Best-effort keeper trigger, rate-limited by SELF_HEAL_COOLDOWN_S. + Returns the (possibly updated) last-fired timestamp. + """ + if _trigger_keeper is None: + return last_fired_ts + if not _should_self_heal(alerts): + return last_fired_ts + if (time.time() - last_fired_ts) <= SELF_HEAL_COOLDOWN_S: + return last_fired_ts + try: + _trigger_keeper(LOG_WORKDIR) + except Exception as exc: # noqa: BLE001 -- self-heal must never crash the loop + logger.warning("queue_monitor: _trigger_keeper raised (%s)", exc) + return time.time() + + +# -------------------------------------------------------------------------- +# Poll loop +# -------------------------------------------------------------------------- +def run_loop(interval_s: float = 10.0, once: bool = False, use_pushover: bool = True) -> None: + """Poll SNAPSHOT_PATH/ACTIVITY_LOG_PATH, evaluate, print, and notify. + + `once=True` performs a single pass and returns (used by tests and + cron-style invocation). Notifications are deduped per alert `key`: a + condition that stays active across polls only notifies once, but if it + resolves (key drops out of the current alert set) and later recurs, it + notifies again -- mirroring research_monitor.maybe_notify's + reset-to-current-set pattern. + """ + offset = 0 + # Seed the instrumentation tail at the CURRENT end-of-file so a freshly + # started monitor alerts only on stalls that occur WHILE it is watching, + # instead of replaying every historical stall in the log on startup. + try: + inst_offset = INSTRUMENTATION_LOG_PATH.stat().st_size + except OSError: + inst_offset = 0 + previously_active_keys: Set[str] = set() + last_self_heal_ts = 0.0 + + while True: + snapshot = _read_snapshot() + new_events, offset = _tail_new_activity(offset) + new_inst, inst_offset = _tail_new_instrumentation(inst_offset) + alerts = evaluate(snapshot, new_events, new_inst) + + print(_format_table(snapshot, alerts)) + + current_keys = {a.key for a in alerts} + new_keys = current_keys - previously_active_keys + if new_keys: + for a in alerts: + if a.key in new_keys: + if use_pushover: + _fire_alert(a) + else: + logger.info( + "queue_monitor: alert suppressed (--no-pushover): [%s] %s", + a.severity, a.message, + ) + previously_active_keys = current_keys + + last_self_heal_ts = _maybe_self_heal(alerts, last_self_heal_ts) + + if once: + return + time.sleep(interval_s) + + +# -------------------------------------------------------------------------- +# CLI +# -------------------------------------------------------------------------- +def main(argv: Optional[List[str]] = None) -> int: + parser = argparse.ArgumentParser( + description="Monitor the Perplexity research FIFO queue for stalls/errors/congestion." + ) + parser.add_argument("--interval", type=float, default=10.0, + help="Poll interval in seconds (default: 10).") + parser.add_argument("--once", action="store_true", + help="Perform a single evaluation pass and exit.") + parser.add_argument("--no-pushover", action="store_true", + help="Disable Pushover notifications (still prints + logs).") + args = parser.parse_args(argv) + + logging.basicConfig(level=logging.INFO, format="%(asctime)s %(levelname)s %(message)s") + run_loop(interval_s=args.interval, once=args.once, use_pushover=not args.no_pushover) + return 0 + + +if __name__ == "__main__": + sys.exit(main(sys.argv[1:])) diff --git a/council-automation/research_queue.py b/council-automation/research_queue.py new file mode 100644 index 0000000..c5a9a90 --- /dev/null +++ b/council-automation/research_queue.py @@ -0,0 +1,719 @@ +"""Crash-safe, cross-process FIFO queue for serializing Perplexity research +runs across concurrent local Claude Code sessions. + +Design: `~/.claude/docs/plans/2026-07-11-perplexity-research-queue-design.md` +Plan: `~/.claude/docs/plans/2026-07-11-perplexity-research-queue.md` + +Two layers, so the queue is both simple and bulletproof: + + ORDERING -- atomic ticket files under `QUEUE_DIR/tickets/`, named + `-.ticket`, seq allocated by `atomic_next_seq()`. + Tickets decide *who gets to try* and provide FIFO visibility. + + CORRECTNESS -- one shared `active.lock` (py-filelock). A process attempts + it, non-blocking, ONLY when it is the head (lowest-seq live + ticket). Whoever holds `active.lock` is the single active run. + The FileLock is authoritative for mutual exclusion; two + waiters can never both hold it even if the head-selection + logic has a bug. On Windows the OS frees the lock handle when + the holding process dies, so a crash mid-run self-heals the + queue without any explicit cleanup. + +This module is standalone -- nothing imports it yet (wiring into +`CouncilBrowser.run()` is a separate, later task). All paths are exposed as +plain module-level globals and re-read from the module namespace on every +call (never cached into a local at import time), so tests can safely do +`monkeypatch.setattr(research_queue, "QUEUE_DIR", tmp_path)` etc. +""" +from __future__ import annotations + +import json +import logging +import os +import tempfile +import threading +import time +import uuid +from contextlib import contextmanager +from pathlib import Path +from typing import Any, Dict, Iterator, List, Optional, Tuple + +from filelock import FileLock, Timeout + +logger = logging.getLogger(__name__) + +# -------------------------------------------------------------------------- +# Paths (monkeypatchable module globals -- functions below always resolve +# these by name at call time, never by capturing a local alias at import +# time, so reassigning them in a test takes effect immediately). +# -------------------------------------------------------------------------- +QUEUE_DIR: Path = Path.home() / ".claude" / "config" / "research-queue" +ACTIVITY_LOG: Path = Path.home() / ".claude" / "council-logs" / "perplexity-activity.jsonl" +SNAPSHOT: Path = Path.home() / ".claude" / "council-logs" / "perplexity-queue.json" + +# -------------------------------------------------------------------------- +# Constants +# -------------------------------------------------------------------------- +TTL_S = 120 # heartbeat-staleness backstop (holder touches every 10s -> 12x margin). + # PID-liveness (see pid_alive()) is the PRIMARY reclaim signal; + # this TTL only guards against a live process whose heartbeat + # thread has wedged/died without the process itself dying. +HEARTBEAT_INTERVAL_S = 10 +POLL_S = 1.5 +MAX_WAIT_S = int(os.environ.get("RESEARCH_QUEUE_MAX_WAIT", "1200")) +ACTIVITY_LOG_LOCK_TIMEOUT_S = 10 # exposed for tests (monkeypatchable) +SNAPSHOT_LOCK_TIMEOUT_S = 5 # exposed for tests (monkeypatchable) +STATS_LOOKBACK_LINES = 5000 # tail bound for today's-stats scan (see _compute_today_stats) + +# Windows OpenProcess() access right sufficient only to query existence -- +# never modify/terminate the target process. +_PROCESS_QUERY_LIMITED_INFORMATION = 0x1000 +_ERROR_ACCESS_DENIED = 5 +_KERNEL32 = None # lazy-initialized ctypes.WinDLL handle, Windows only + + +class QueueTimeout(RuntimeError): + """Raised when a caller waits longer than MAX_WAIT_S for a queue slot.""" + + +# -------------------------------------------------------------------------- +# Path helpers -- always recompute from the current QUEUE_DIR/ACTIVITY_LOG +# globals so monkeypatching those in tests is honored everywhere. +# -------------------------------------------------------------------------- +def _tickets_dir() -> Path: + return QUEUE_DIR / "tickets" + + +def _counter_path() -> Path: + return QUEUE_DIR / "counter" + + +def _counter_lock_path() -> Path: + return QUEUE_DIR / "counter.lock" + + +def _active_lock_path() -> Path: + return QUEUE_DIR / "active.lock" + + +def _ticket_path(seq: int, pid: int) -> Path: + return _tickets_dir() / f"{seq:08d}-{pid}.ticket" + + +def _activity_lock_path() -> Path: + return ACTIVITY_LOG.parent / (ACTIVITY_LOG.name + ".lock") + + +def _snapshot_lock_path() -> Path: + return SNAPSHOT.parent / (SNAPSHOT.name + ".lock") + + +def ensure_dirs() -> None: + """Create QUEUE_DIR/tickets and the parent dirs of ACTIVITY_LOG/SNAPSHOT.""" + _tickets_dir().mkdir(parents=True, exist_ok=True) + ACTIVITY_LOG.parent.mkdir(parents=True, exist_ok=True) + SNAPSHOT.parent.mkdir(parents=True, exist_ok=True) + + +# -------------------------------------------------------------------------- +# Low-level atomic I/O +# -------------------------------------------------------------------------- +def _atomic_write(path: Path, text: str) -> None: + """Write `text` to `path` via tmp-file-in-same-dir + os.replace. + + os.replace is atomic on both POSIX and Windows (unlike a bare + open(path, "w"), which can leave a torn/partial file visible to a + concurrent reader on Windows if the writer is interrupted). + """ + path.parent.mkdir(parents=True, exist_ok=True) + fd, tmp_name = tempfile.mkstemp(dir=str(path.parent), prefix=".tmp_", suffix=".part") + try: + with os.fdopen(fd, "w", encoding="utf-8") as fh: + fh.write(text) + os.replace(tmp_name, path) + except Exception: + try: + os.unlink(tmp_name) + except OSError as exc: + logger.debug("_atomic_write: could not clean up tmp file %s (%s)", tmp_name, exc) + raise + + +def _get_kernel32() -> Any: + """Lazily construct and cache a properly-typed ctypes handle to + kernel32.dll (Windows only). Caching avoids re-resolving the DLL/ + function pointers on every pid_alive() call (called every POLL_S, + ~1.5s, across up to 9 concurrent sessions). + + `restype`/`argtypes` are set explicitly to `wintypes.HANDLE` -- + without them, ctypes assumes a 32-bit `c_int` return value for + OpenProcess, but a Win64 HANDLE is a 64-bit pointer. On 64-bit + Windows that mismatch can truncate the handle value, causing + CloseHandle() to silently fail on a bad handle -- a slow handle + leak (one per pid_alive() call that never gets freed). + `use_last_error=True` makes ctypes.get_last_error() reflect the + real Win32 GetLastError() value after each call through this DLL + instance. + """ + global _KERNEL32 + if _KERNEL32 is None: + import ctypes + from ctypes import wintypes + + k32 = ctypes.WinDLL("kernel32", use_last_error=True) + k32.OpenProcess.restype = wintypes.HANDLE + k32.OpenProcess.argtypes = [wintypes.DWORD, wintypes.BOOL, wintypes.DWORD] + k32.CloseHandle.restype = wintypes.BOOL + k32.CloseHandle.argtypes = [wintypes.HANDLE] + _KERNEL32 = k32 + return _KERNEL32 + + +def pid_alive(pid: int) -> bool: + """Return True if a process with the given PID is currently running. + + WINDOWS SAFETY NOTE: `os.kill(pid, 0)` is NOT a safe existence probe on + Windows the way it is on POSIX. CPython's Windows implementation of + os.kill() does not special-case signal 0 -- for any non-console-event + signal value it opens the process and calls + `TerminateProcess(handle, sig)`, i.e. `os.kill(pid, 0)` actually KILLS + the target process (with exit code 0) instead of merely checking it + exists. Ticket PIDs here can belong to sibling Claude Code sessions + (including ones actively mid-research), so using os.kill(pid, 0) for + liveness checking would be destructive. We instead call + OpenProcess(PROCESS_QUERY_LIMITED_INFORMATION) on Windows, which only + queries -- it never touches the target process -- and close the handle + immediately. On POSIX, `os.kill(pid, 0)` is the standard, safe, + side-effect-free existence probe and is used unchanged. + + If OpenProcess fails with ERROR_ACCESS_DENIED (5), the process DOES + exist but this caller lacks rights to query it (e.g. a differently- + privileged sibling session) -- that must be reported as alive, never + as dead, or a live holder's ticket could be wrongly reclaimed out + from under it. + """ + if os.name == "nt": + import ctypes + + kernel32 = _get_kernel32() + handle = kernel32.OpenProcess(_PROCESS_QUERY_LIMITED_INFORMATION, False, int(pid)) + if handle: + if not kernel32.CloseHandle(handle): + logger.warning( + "pid_alive: CloseHandle failed for pid=%s (possible handle leak)", pid + ) + return True + err = ctypes.get_last_error() + if err == _ERROR_ACCESS_DENIED: + return True + return False + try: + os.kill(pid, 0) + except OSError: + return False + except OverflowError: + return False + return True + + +# -------------------------------------------------------------------------- +# Ticket lifecycle +# -------------------------------------------------------------------------- +def write_ticket( + seq: int, + pid: int, + run_id: str, + session: str, + state: str, + query_preview: str, + mode: str = "research", +) -> Path: + """Write a new ticket file and return its path. + + Ticket schema: {seq, pid, run_id, session, state ("waiting"/"active"), + query_preview (truncated to 80 chars), mode, enqueued_at, heartbeat_at}. + """ + ensure_dirs() + now = time.time() + data: Dict[str, Any] = { + "seq": seq, + "pid": pid, + "run_id": run_id, + "session": session, + "state": state, + "query_preview": (query_preview or "")[:80], + "mode": mode, + "enqueued_at": now, + "heartbeat_at": now, + } + path = _ticket_path(seq, pid) + _atomic_write(path, json.dumps(data)) + return path + + +def touch_heartbeat(path: Path) -> None: + """Refresh a ticket's heartbeat_at timestamp. Best-effort; a ticket that + has already been removed (e.g. by a concurrent GC) is silently skipped. + """ + try: + data = json.loads(path.read_text(encoding="utf-8")) + except (OSError, json.JSONDecodeError) as exc: + logger.debug("touch_heartbeat: ticket %s unreadable (%s), skipping", path, exc) + return + data["heartbeat_at"] = time.time() + try: + _atomic_write(path, json.dumps(data)) + except OSError as exc: + logger.debug("touch_heartbeat: failed to write ticket %s (%s)", path, exc) + + +def read_tickets() -> List[Tuple[Path, Dict[str, Any]]]: + """Return all currently-on-disk tickets, sorted by seq ascending. + Does NOT garbage-collect -- see live_tickets() for that. + + A ticket file that is valid JSON but missing (or has a non-int) + `seq` is skipped rather than propagating a KeyError out of the sort + -- an uncaught KeyError here would crash every waiter's poll loop + (`live_tickets()` / `_wait_for_promotion()`), taking down the whole + queue over a single malformed/torn ticket. + """ + tickets_dir = _tickets_dir() + if not tickets_dir.exists(): + return [] + out: List[Tuple[Path, Dict[str, Any]]] = [] + for f in tickets_dir.glob("*.ticket"): + try: + data = json.loads(f.read_text(encoding="utf-8")) + except (OSError, json.JSONDecodeError) as exc: + logger.debug("read_tickets: skipping unreadable ticket %s (%s)", f, exc) + continue + if not isinstance(data.get("seq"), int): + logger.warning("read_tickets: skipping ticket %s with missing/invalid seq", f) + continue + out.append((f, data)) + out.sort(key=lambda t: t[1].get("seq", 0)) + return out + + +def gc_dead_tickets() -> None: + """Reclaim (delete) tickets whose owning process is dead, or whose + heartbeat has gone stale past TTL_S. PID-liveness is the PRIMARY + signal (fast, unambiguous); heartbeat staleness is a backstop only, + so a long GC/scheduler pause never wrongly reclaims a live holder's + ticket while it may still hold active.lock. + """ + now = time.time() + for f, d in read_tickets(): + try: + alive = pid_alive(d["pid"]) + stale = (now - d.get("heartbeat_at", 0)) > TTL_S + except Exception as exc: + # Malformed ticket data -- treat as reclaimable. + logger.warning("gc_dead_tickets: malformed ticket %s (%s), reclaiming", f, exc) + alive, stale = False, True + if not alive or stale: + try: + f.unlink() + except OSError as exc: + logger.debug("gc_dead_tickets: could not unlink %s (%s)", f, exc) + + +def live_tickets() -> List[Tuple[Path, Dict[str, Any]]]: + """GC dead tickets, then return the remaining ones sorted by seq.""" + gc_dead_tickets() + return read_tickets() + + +# -------------------------------------------------------------------------- +# Sequence allocator +# -------------------------------------------------------------------------- +def atomic_next_seq() -> int: + """Allocate the next monotonic sequence number, race-free across + processes via a brief FileLock around a read-increment-write of the + `counter` file. + """ + ensure_dirs() + with FileLock(str(_counter_lock_path()), timeout=10): + counter_path = _counter_path() + n = 0 + if counter_path.exists(): + try: + n = int(counter_path.read_text(encoding="utf-8").strip() or "0") + except ValueError: + n = 0 + n += 1 + _atomic_write(counter_path, str(n)) + return n + + +# -------------------------------------------------------------------------- +# Central activity log + live snapshot +# -------------------------------------------------------------------------- +def log_event( + event: str, + run_id: str, + session: str, + seq: int, + query_preview: str, + mode: str, + **extra: Any, +) -> None: + """Append one JSON line describing a queue transition to ACTIVITY_LOG. + + Events: enqueued | started | completed | error | timeout. Extra + keyword args (wait_s, duration_s, status, error, ...) are merged + directly into the record. + """ + ACTIVITY_LOG.parent.mkdir(parents=True, exist_ok=True) + record: Dict[str, Any] = { + "ts": time.time(), + "run_id": run_id, + "event": event, + "session": session, + "seq": seq, + "query_preview": (query_preview or "")[:80], + "mode": mode, + **extra, + } + line = json.dumps(record) + # Best-effort: a busy activity-log lock must never break the caller's + # actual queue flow (enqueue/promote/release). Losing one log line to + # contention is acceptable; raising Timeout out of an unguarded + # enqueued/started/completed call site is not. + try: + with FileLock(str(_activity_lock_path()), timeout=ACTIVITY_LOG_LOCK_TIMEOUT_S): + with open(ACTIVITY_LOG, "a", encoding="utf-8") as fh: + fh.write(line + "\n") + except Timeout: + logger.warning( + "log_event: activity log lock busy past %ss, dropping event=%s run_id=%s", + ACTIVITY_LOG_LOCK_TIMEOUT_S, event, run_id, + ) + + +def _read_activity_events(limit: Optional[int] = None) -> List[Dict[str, Any]]: + """Read parsed JSONL records from ACTIVITY_LOG, optionally limited to the + last `limit` lines. Malformed lines are skipped, not fatal. + """ + if not ACTIVITY_LOG.exists(): + return [] + try: + lines = ACTIVITY_LOG.read_text(encoding="utf-8").splitlines() + except OSError as exc: + logger.debug("_read_activity_events: could not read %s (%s)", ACTIVITY_LOG, exc) + return [] + if limit is not None: + lines = lines[-limit:] + out: List[Dict[str, Any]] = [] + for line in lines: + line = line.strip() + if not line: + continue + try: + out.append(json.loads(line)) + except json.JSONDecodeError as exc: + logger.debug("_read_activity_events: skipping malformed line (%s)", exc) + continue + return out + + +def _read_recent_activity(limit: int = 20) -> List[Dict[str, Any]]: + return _read_activity_events(limit=limit) + + +def _is_same_local_day(ts: float, now: float) -> bool: + """True if `ts` falls on the same local calendar day as `now`.""" + a = time.localtime(ts) + b = time.localtime(now) + return (a.tm_year, a.tm_yday) == (b.tm_year, b.tm_yday) + + +def _compute_today_stats(now: float) -> Tuple[int, int]: + """Compute (total_today, errors_today) from the activity log. + + `total_today` counts DISTINCT RUNS (not raw events) that started today, + identified by a `started` event's run_id. `errors_today` counts `error` + and `timeout` events logged today. Bounded to the last + STATS_LOOKBACK_LINES lines of the activity log for performance (this is + read on every publish_snapshot() call, which can fire every ~1.5s per + waiting session) -- more than sufficient to cover a single day's events + under normal usage. + """ + events = _read_activity_events(limit=STATS_LOOKBACK_LINES) + started_run_ids_today: set[str] = set() + errors_today = 0 + for e in events: + ts = e.get("ts") + if not isinstance(ts, (int, float)) or not _is_same_local_day(ts, now): + continue + event = e.get("event") + if event == "started": + run_id = e.get("run_id") + if run_id: + started_run_ids_today.add(run_id) + elif event in ("error", "timeout"): + errors_today += 1 + return len(started_run_ids_today), errors_today + + +def publish_snapshot(my_seq: Optional[int] = None) -> None: + """Regenerate SNAPSHOT from live_tickets() plus a bounded tail of the + activity log. Atomic tmp+os.replace write. Carries a monotonic + `version` (wall-clock nanoseconds -- comparable across processes, + unlike time.monotonic_ns() whose reference point is undefined across + interpreters) plus `updated_at`, so a reader can discard an + out-of-order last-writer-wins snapshot write. + + `my_seq` is accepted for API symmetry with the polling loop in + acquire_slot (every caller's own ticket is already reflected via + live_tickets(), so it is not otherwise consulted) -- kept as a + parameter so a future caller-relative optimization (e.g. only + recomputing this caller's position) doesn't need a signature change. + """ + ensure_dirs() + tickets = live_tickets() + now = time.time() + + active: Optional[Dict[str, Any]] = None + queued: List[Dict[str, Any]] = [] + for _, d in tickets: + if d.get("state") == "active": + # active_since is stamped on the ticket at promotion time (see + # acquire_slot). Fall back to enqueued_at only for tickets + # written before that field existed, so elapsed_s reflects + # time-since-promotion, not time-since-enqueue (which double- + # counts the wait already reported via the "started" wait_s + # log event). + started_at = d.get("active_since", d["enqueued_at"]) + active = { + "run_id": d["run_id"], + "session": d["session"], + "query_preview": d["query_preview"], + "started_at": started_at, + "elapsed_s": round(now - started_at, 1), + "heartbeat_age_s": round(now - d["heartbeat_at"], 1), + } + else: + queued.append( + { + "run_id": d["run_id"], + "session": d["session"], + "position": 0, # filled below, 1-indexed + "query_preview": d["query_preview"], + "wait_s": round(now - d["enqueued_at"], 1), + } + ) + for i, item in enumerate(queued, start=1): + item["position"] = i + + recent = _read_recent_activity(limit=20) + total_today, errors_today = _compute_today_stats(now) + + snapshot = { + "version": time.time_ns(), + "updated_at": now, + "active": active, + "queued": queued, + "recent": recent, + "stats": { + "depth": len(queued) + (1 if active else 0), + "total_today": total_today, + "errors_today": errors_today, + }, + } + text = json.dumps(snapshot) + # Many processes can regenerate this snapshot concurrently while + # polling. A short FileLock serializes the replace so concurrent + # os.replace() calls onto the same destination never race into a + # transient Windows ERROR_ACCESS_DENIED. Best-effort only: the + # ticket dir remains the true source of truth, so a rare lock + # timeout here must never block the caller's actual queue progress. + try: + with FileLock(str(_snapshot_lock_path()), timeout=SNAPSHOT_LOCK_TIMEOUT_S): + _atomic_write(SNAPSHOT, text) + except Timeout: + logger.warning( + "publish_snapshot: snapshot lock busy past %ss, skipping this write " + "(ticket dir remains source of truth)", SNAPSHOT_LOCK_TIMEOUT_S, + ) + + +# -------------------------------------------------------------------------- +# Heartbeat thread +# -------------------------------------------------------------------------- +class _HeartbeatThread: + """Daemon thread that periodically touches a ticket's heartbeat_at. + + Started for BOTH waiting and active tickets so a crashed *waiter* is + also reclaimable via TTL_S, not just a crashed active holder. + """ + + def __init__(self, ticket_path: Path, interval_s: float = HEARTBEAT_INTERVAL_S) -> None: + self._ticket_path = ticket_path + self._interval_s = interval_s + self._stop_event = threading.Event() + self._thread = threading.Thread( + target=self._run, name="research-queue-heartbeat", daemon=True + ) + self._thread.start() + + def _run(self) -> None: + while not self._stop_event.wait(self._interval_s): + touch_heartbeat(self._ticket_path) + + def stop(self) -> None: + """Signal the heartbeat thread to stop and wait for it to exit.""" + self._stop_event.set() + self._thread.join(timeout=5.0) + + +# -------------------------------------------------------------------------- +# The core primitive +# -------------------------------------------------------------------------- +@contextmanager +def acquire_slot(session: str, query_preview: str, mode: str = "research") -> Iterator[Dict[str, Any]]: + """Block (cross-process, FIFO) until this caller is the sole active + Perplexity run, then yield a slot descriptor `{run_id, queued, + waited_s, seq}` for the duration of the `with` block. + + If RESEARCH_QUEUE_ENABLED=="0", this is a no-op context manager that + yields `{"run_id": , "queued": False}` immediately (today's + unserialized behavior). + + Raises QueueTimeout if MAX_WAIT_S elapses before promotion to active. + """ + if os.environ.get("RESEARCH_QUEUE_ENABLED", "1") == "0": + yield {"run_id": str(uuid.uuid4()), "queued": False} + return + + ensure_dirs() + run_id = str(uuid.uuid4()) + pid = os.getpid() + seq = atomic_next_seq() + ticket_path = write_ticket(seq, pid, run_id, session, "waiting", query_preview, mode) + log_event("enqueued", run_id, session, seq, query_preview, mode) + + heartbeat = _HeartbeatThread(ticket_path) + lock = FileLock(str(_active_lock_path()), thread_local=False) + lock_acquired = False + t0 = time.time() + + def _wait_for_promotion() -> float: + """Block until this ticket is promoted to active; return wait_s.""" + nonlocal lock_acquired + while True: + tickets = live_tickets() + head = tickets[0][1] if tickets else None + + if head is not None and head["seq"] == seq: + try: + lock.acquire(timeout=0) + lock_acquired = True + except Timeout: + # A failed non-blocking acquire here is NORMAL -- a + # crashed holder's OS lock handle can lag a moment + # before it's actually released. Never fatal: back + # off and retry. Only a genuine filelock/OS error + # (permissions/FS -- NOT Timeout) should propagate. + lock_acquired = False + + if lock_acquired: + # Strict-FIFO belt-and-suspenders (mutex is already + # safe without this -- it only tightens fairness): + # re-confirm we're still the lowest-seq live ticket + # now that we hold active.lock. + recheck = live_tickets() + recheck_head = recheck[0][1] if recheck else None + if recheck_head is None or recheck_head["seq"] != seq: + lock.release() + lock_acquired = False + time.sleep(POLL_S) + continue + return round(time.time() - t0, 1) + + if time.time() - t0 > MAX_WAIT_S: + waited_s = round(time.time() - t0, 1) + log_event( + "timeout", run_id, session, seq, query_preview, mode, + wait_s=waited_s, + ) + raise QueueTimeout( + f"research_queue: wait exceeded MAX_WAIT_S={MAX_WAIT_S}s " + f"(run_id={run_id}, seq={seq})" + ) + + touch_heartbeat(ticket_path) + publish_snapshot(my_seq=seq) + time.sleep(POLL_S) + + try: + waited_s = _wait_for_promotion() + except QueueTimeout: + # Already logged its own "timeout" event above -- avoid a + # duplicate "error" log for the same failure. + heartbeat.stop() + try: + ticket_path.unlink() + except OSError as exc: + logger.debug("acquire_slot: could not unlink ticket %s after timeout (%s)", ticket_path, exc) + publish_snapshot() + raise + except BaseException as exc: + log_event( + "error", run_id, session, seq, query_preview, mode, + error=str(exc), wait_s=round(time.time() - t0, 1), + ) + heartbeat.stop() + try: + ticket_path.unlink() + except OSError as unlink_exc: + logger.debug("acquire_slot: could not unlink ticket %s after error (%s)", ticket_path, unlink_exc) + publish_snapshot() + raise + + # Promoted to active. + active_since = time.time() + try: + data = json.loads(ticket_path.read_text(encoding="utf-8")) + data["state"] = "active" + data["active_since"] = active_since + _atomic_write(ticket_path, json.dumps(data)) + except (OSError, json.JSONDecodeError) as exc: + logger.warning( + "acquire_slot: failed to stamp ticket %s as active (run_id=%s): %s", + ticket_path, run_id, exc, + ) + log_event("started", run_id, session, seq, query_preview, mode, wait_s=waited_s) + publish_snapshot() + + try: + yield {"run_id": run_id, "queued": True, "waited_s": waited_s, "seq": seq} + except BaseException as exc: + duration_s = round(time.time() - active_since, 1) + log_event( + "error", run_id, session, seq, query_preview, mode, + error=str(exc), duration_s=duration_s, + ) + raise + else: + duration_s = round(time.time() - active_since, 1) + log_event( + "completed", run_id, session, seq, query_preview, mode, + duration_s=duration_s, + ) + finally: + if lock_acquired: + try: + lock.release() + except Exception as exc: + # Notable (not routine-best-effort): a failed release of + # the active-run mutex is worth surfacing even though we + # still proceed with cleanup -- the OS frees the handle + # on process exit regardless, so this is not fatal. + logger.warning("acquire_slot: active.lock release failed (run_id=%s): %s", run_id, exc) + heartbeat.stop() + try: + ticket_path.unlink() + except OSError as exc: + logger.debug("acquire_slot: could not unlink ticket %s on cleanup (%s)", ticket_path, exc) + publish_snapshot() diff --git a/council-automation/submission_lock.py b/council-automation/submission_lock.py index 6533fdc..561f1e9 100644 --- a/council-automation/submission_lock.py +++ b/council-automation/submission_lock.py @@ -33,6 +33,8 @@ """ from __future__ import annotations +import os +import threading import time from pathlib import Path @@ -95,3 +97,74 @@ def get_submit_lock(timeout: float | None = None) -> FileLock: # With thread_local=False, the counter is shared across threads in the # process and release correctly closes the fd / releases the OS lock. return FileLock(str(LOCK_PATH), timeout=timeout, thread_local=False) + + +HEARTBEAT_INTERVAL_S = 60.0 # default mtime-refresh cadence for long holds + + +class LockHeartbeat: + """Background thread that periodically refreshes a held lock file's mtime. + + The stale-reclaim check in `get_submit_lock()` treats any lock file + older than `STALE_AGE_S` (180s) as abandoned by a crashed holder and + unlinks it so a new caller can proceed. That assumption is correct + for the lock's original design (10-25s submit-window holds), but + breaks if a caller legitimately holds the lock for minutes (e.g. the + RESEARCH_QUEUE_STOPGAP whole-run widening in council_browser.py) -- + a second session would reclaim and acquire the "stale" lock out from + under a still-running holder, causing the exact overlap the widening + was meant to prevent. + + LockHeartbeat only opts a caller INTO this behavior when explicitly + started (see `start_lock_heartbeat`); nothing here runs unless a + caller creates one. A live holder's heartbeat thread keeps touching + the lock file's mtime every `interval_s`, so `age > STALE_AGE_S` + never trips while the holder is alive. If the holder process + crashes, its heartbeat thread dies with it -- the mtime stops + advancing, ages past `STALE_AGE_S`, and the existing reclaim logic + in `get_submit_lock()` fires exactly as it does today. + """ + + def __init__(self, lock_path: Path, interval_s: float = HEARTBEAT_INTERVAL_S) -> None: + self._lock_path = lock_path + self._interval_s = interval_s + self._stop_event = threading.Event() + self._thread = threading.Thread( + target=self._run, name="submit-lock-heartbeat", daemon=True + ) + self._thread.start() + + def _run(self) -> None: + # wait() returns True only when stop_event is set before the + # timeout elapses, so this loop refreshes mtime once per + # interval and exits promptly (no extra sleep) once stopped. + while not self._stop_event.wait(self._interval_s): + try: + os.utime(self._lock_path, None) + except OSError: + # Lock file briefly missing/replaced -- best-effort only; + # the next tick will retry. + pass + + def stop(self) -> None: + """Signal the heartbeat thread to stop and wait for it to exit.""" + self._stop_event.set() + self._thread.join(timeout=5.0) + + +def start_lock_heartbeat( + lock: FileLock, interval_s: float = HEARTBEAT_INTERVAL_S +) -> LockHeartbeat: + """Start a background heartbeat that keeps `lock`'s file mtime fresh. + + Only call this for a lock intended to be held far longer than + `STALE_AGE_S` (180s) -- e.g. under RESEARCH_QUEUE_STOPGAP, where + submit_lock spans a whole Perplexity run instead of just the submit + window. Callers MUST call `.stop()` on the returned LockHeartbeat + once the lock is released (or before releasing it) so the thread + doesn't keep touching a file the caller no longer owns. + + Not called anywhere by default -- opt-in only, so default (no + heartbeat) behavior is unaffected. + """ + return LockHeartbeat(Path(lock.lock_file), interval_s=interval_s) diff --git a/council-automation/tests/test_council_browser_queue_wiring.py b/council-automation/tests/test_council_browser_queue_wiring.py new file mode 100644 index 0000000..4f8b3f9 --- /dev/null +++ b/council-automation/tests/test_council_browser_queue_wiring.py @@ -0,0 +1,315 @@ +"""Tests for the research_queue <-> PerplexityCouncil.run() wiring +(Task 1.5, coordinator fresh-eyes review 2026-07-11). + +TESTING-STRATEGY NOTE (deviation from the literal "stub start/ +activate_mode/submit_query/extract_results" suggestion, documented per +"adapt to real code"): `run()`'s new wrapper calls exactly one thing -- +`self._run_impl(query)`. Stubbing the 4 individual Playwright methods +would ALSO require working around `SessionSemaphore()` (a real +file-based semaphore over the LIVE shared `~/.claude/config/ +browser-sessions/` dir), `_acquire_submit_lock()` (a real LIVE shared +`.perplexity_submit.lock` file), `validate_session()` (needs a real +Playwright page), `wait_for_completion()` (same), and +`_init_artifact_dir()` (writes into the LIVE `~/.claude/council-logs/ +runs/` dir unconditionally) -- none of which this wiring touches or +changes, and all of which are real shared resources live Perplexity +sessions on this machine may be using concurrently. Monkeypatching +`_run_impl` wholesale is the precise, minimal seam for testing exactly +what changed (the new `run()` wrapper) in full isolation from all of +that. + +ISOLATION (CRITICAL): every test monkeypatches `research_queue.QUEUE_DIR` +/ `ACTIVITY_LOG` / `SNAPSHOT` and `council_browser._QUERY_INST_LOG` to +tmp-based paths (directly, or via env vars for the subprocess test). +NONE of these tests ever touch the real `~/.claude/config/ +research-queue`, `~/.claude/council-logs/perplexity-*`, or +`~/.claude/council-cache/instrumentation-query.jsonl`. + +Run with (from council-automation/): + python -m pytest tests/test_council_browser_queue_wiring.py -v +""" +from __future__ import annotations + +import inspect +import json +import os +import subprocess +import sys +import time +from pathlib import Path + +import pytest + +import council_browser +import research_queue + + +@pytest.fixture(autouse=True) +def isolated_paths(tmp_path: Path, monkeypatch: pytest.MonkeyPatch) -> Path: + """Point every research_queue path global + council_browser's + instrumentation log at tmp_path locations for this test. autouse=True + so no test can forget this and accidentally touch live coordination + state while real Perplexity sessions may be running on this machine. + """ + monkeypatch.setattr(research_queue, "QUEUE_DIR", tmp_path / "research-queue") + monkeypatch.setattr(research_queue, "ACTIVITY_LOG", tmp_path / "perplexity-activity.jsonl") + monkeypatch.setattr(research_queue, "SNAPSHOT", tmp_path / "perplexity-queue.json") + monkeypatch.setattr(council_browser, "_QUERY_INST_LOG", tmp_path / "instrumentation-query.jsonl") + return tmp_path + + +# -------------------------------------------------------------------------- +# Test 4 first (cheap, no I/O): getsource guard against event-loop-blocking +# regressions -- acquire_slot's __enter__/__exit__ MUST be entered/exited +# via asyncio.to_thread, never called directly (which would block the +# event loop for up to research_queue.MAX_WAIT_S). +# -------------------------------------------------------------------------- +def test_run_wraps_body_in_acquire_slot_via_to_thread() -> None: + src = inspect.getsource(council_browser.PerplexityCouncil.run) + assert "research_queue.acquire_slot(" in src, ( + "run() must acquire a research_queue slot as the outermost layer" + ) + assert "await asyncio.to_thread(slot_cm.__enter__)" in src, ( + "acquire_slot's blocking __enter__ (poll-wait up to MAX_WAIT_S) " + "must run via asyncio.to_thread, not be awaited/called directly " + "on the event loop" + ) + assert "await asyncio.to_thread(lambda: slot_cm.__exit__(*_exc_info))" in src, ( + "acquire_slot's __exit__ must also run via asyncio.to_thread" + ) + # run() must delegate to a separate method (the existing pipeline), + # not inline Playwright logic directly inside the queue-wrapped try -- + # confirms the extract-method refactor actually happened. + assert "await self._run_impl(query)" in src + + +# -------------------------------------------------------------------------- +# Test 2: kill-switch neutrality. RESEARCH_QUEUE_ENABLED=0 -> run() creates +# zero queue/central artifacts and the returned dict is passed through +# unchanged (today's behavior, byte-identical). +# -------------------------------------------------------------------------- +@pytest.mark.asyncio +async def test_kill_switch_neutrality( + monkeypatch: pytest.MonkeyPatch, tmp_path: Path +) -> None: + monkeypatch.setenv("RESEARCH_QUEUE_ENABLED", "0") + + council = council_browser.PerplexityCouncil(perplexity_mode="research") + + stub_result = { + "query": "hello world", + "mode": "browser", + "completed": True, + "execution_time_ms": 42, + } + + async def fake_run_impl(query: str) -> dict: + assert query == "hello world" + return dict(stub_result) + + council._run_impl = fake_run_impl # type: ignore[method-assign] + + result = await council.run("hello world") + + # Results shape unchanged -- the wrapper is transparent when disabled. + assert result == stub_result + + # Zero queue/central artifacts created at all. + assert not research_queue.QUEUE_DIR.exists() + assert not research_queue.ACTIVITY_LOG.exists() + assert not research_queue.SNAPSHOT.exists() + + +# -------------------------------------------------------------------------- +# Test 3: error path. Enabled (default), stubbed body signals failure -> +# perplexity-activity.jsonl records "error" (not "completed"). Covers +# BOTH ways _run_impl can signal failure: (a) the dominant real-world +# path, an {"error": ...} dict returned without raising (that's what +# _run_impl's own internal `except Exception` block does for nearly +# every real failure mode -- see run()'s docstring), and (b) a genuine +# raised exception escaping _run_impl entirely. +# -------------------------------------------------------------------------- +@pytest.mark.asyncio +async def test_error_path_dict_result_records_error_not_completed( + monkeypatch: pytest.MonkeyPatch, +) -> None: + monkeypatch.delenv("RESEARCH_QUEUE_ENABLED", raising=False) # default: enabled + + council = council_browser.PerplexityCouncil(perplexity_mode="research") + + async def fake_run_impl_error_dict(query: str) -> dict: + return {"error": "synthetic failure for test", "step": "test"} + + council._run_impl = fake_run_impl_error_dict # type: ignore[method-assign] + + result = await council.run("bad query") + + # Public contract unchanged: run() still returns the error dict, does + # NOT raise, for this (dominant) logical-failure path. + assert result.get("error") == "synthetic failure for test" + + events = [ + json.loads(line)["event"] + for line in research_queue.ACTIVITY_LOG.read_text(encoding="utf-8").strip().splitlines() + ] + assert "enqueued" in events + assert "started" in events + assert "error" in events + assert "completed" not in events + + +@pytest.mark.asyncio +async def test_error_path_raised_exception_records_error_not_completed( + monkeypatch: pytest.MonkeyPatch, +) -> None: + monkeypatch.delenv("RESEARCH_QUEUE_ENABLED", raising=False) # default: enabled + + council = council_browser.PerplexityCouncil(perplexity_mode="research") + + async def fake_run_impl_raises(query: str) -> dict: + raise RuntimeError("boom") + + council._run_impl = fake_run_impl_raises # type: ignore[method-assign] + + with pytest.raises(RuntimeError, match="boom"): + await council.run("bad query") + + events = [ + json.loads(line)["event"] + for line in research_queue.ACTIVITY_LOG.read_text(encoding="utf-8").strip().splitlines() + ] + assert "error" in events + assert "completed" not in events + + +# -------------------------------------------------------------------------- +# Test 1: N=5 concurrent run() calls serialize strictly (active-counter +# never exceeds 1) and complete in arrival (FIFO) order. +# +# Deliberately implemented with real SUBPROCESSES, not asyncio.gather() +# within one process. acquire_slot's blocking wait runs via +# asyncio.to_thread -- gathering 5 concurrent run() calls in ONE process +# would put 5 WORKER THREADS of the SAME process racing to +# lock.acquire(timeout=0) on the same active.lock file. research_queue's +# own test suite found exactly this pattern (two threads, independent +# FileLock objects, same process) to be an unreliable proxy for true +# mutual exclusion on Windows -- same-process multi-handle file locking +# can be more permissive than genuine cross-process locking. Production +# never hits this: each council_query.py subprocess runs exactly one +# run() call, so asyncio.to_thread there only ever has a single worker +# thread touching active.lock per process. Real subprocesses (matching +# production) are the only trustworthy way to prove serialization here. +# -------------------------------------------------------------------------- +_RUN_WIRING_WORKER_SCRIPT = r""" +import asyncio, json, os, random, sys, time +from pathlib import Path + +sys.path.insert(0, os.environ["RQ_MODPATH"]) +import research_queue +import council_browser + +research_queue.QUEUE_DIR = Path(os.environ["RQ_QDIR"]) +research_queue.ACTIVITY_LOG = Path(os.environ["RQ_ACTIVITY_LOG"]) +research_queue.SNAPSHOT = Path(os.environ["RQ_SNAPSHOT"]) +council_browser._QUERY_INST_LOG = Path(os.environ["RQ_INST_LOG"]) + +count_file = Path(os.environ["RQ_COUNT_FILE"]) +max_file = Path(os.environ["RQ_MAX_FILE"]) +worker_index = os.environ["RQ_WORKER_INDEX"] +pid_map_dir = Path(os.environ["RQ_PID_MAP_DIR"]) +pid_map_dir.mkdir(parents=True, exist_ok=True) +(pid_map_dir / f"{os.getpid()}.pid").write_text(worker_index) + +council = council_browser.PerplexityCouncil(perplexity_mode="research") + +async def _fake_run_impl(query): + n = int(count_file.read_text()) if count_file.exists() else 0 + n += 1 + count_file.write_text(str(n)) + # Deterministic breach detection (F6 pattern): assert INSIDE the + # critical section, immediately after the increment. + assert n == 1, f"CRITICAL: observed count={n} inside exclusive section (pid={os.getpid()})" + cur_max = int(max_file.read_text()) if max_file.exists() else 0 + if n > cur_max: + max_file.write_text(str(n)) + await asyncio.sleep(random.uniform(0.1, 0.25)) + n = int(count_file.read_text()) + n -= 1 + count_file.write_text(str(n)) + return {"query": query, "mode": "browser", "completed": True, "execution_time_ms": 1} + +council._run_impl = _fake_run_impl + +asyncio.run(council.run(f"wiring test query {worker_index}")) +""" + + +def test_run_serializes_across_processes_fifo(tmp_path: Path) -> None: + qdir = tmp_path / "rq" + activity_log = tmp_path / "activity.jsonl" + snapshot = tmp_path / "snapshot.json" + inst_log = tmp_path / "inst.jsonl" + count_file = tmp_path / "count.txt" + max_file = tmp_path / "max.txt" + pid_map_dir = tmp_path / "pidmap" + count_file.write_text("0") + max_file.write_text("0") + + modpath = str(Path(research_queue.__file__).resolve().parent) + + base_env = os.environ.copy() + base_env["RQ_MODPATH"] = modpath + base_env["RQ_QDIR"] = str(qdir) + base_env["RQ_ACTIVITY_LOG"] = str(activity_log) + base_env["RQ_SNAPSHOT"] = str(snapshot) + base_env["RQ_INST_LOG"] = str(inst_log) + base_env["RQ_COUNT_FILE"] = str(count_file) + base_env["RQ_MAX_FILE"] = str(max_file) + base_env["RQ_PID_MAP_DIR"] = str(pid_map_dir) + base_env["RESEARCH_QUEUE_ENABLED"] = "1" + + n_workers = 5 + procs = [] + for i in range(n_workers): + env = base_env.copy() + env["RQ_WORKER_INDEX"] = str(i) + p = subprocess.Popen([sys.executable, "-c", _RUN_WIRING_WORKER_SCRIPT], env=env) + procs.append(p) + time.sleep(0.05) # stagger launches so arrival order is unambiguous + + for i, p in enumerate(procs): + rc = p.wait(timeout=60) + assert rc == 0, f"worker {i} exited with code {rc}" + + assert max_file.read_text().strip() == "1", ( + "expected max concurrent active runs across processes == 1, got " + f"{max_file.read_text().strip()}" + ) + assert count_file.read_text().strip() == "0" + + # Derive ground-truth arrival order and completion order from the + # actual production artifact (perplexity-activity.jsonl) rather than + # from Python-side launch-timing assumptions -- map each event's + # `session` field (ends with ":", stamped by run()'s + # `f"{Path.cwd().name}:{os.getpid()}"`) back to a worker index via + # the pid->index files each child wrote at startup. + pid_to_index = {f.stem: f.read_text().strip() for f in pid_map_dir.glob("*.pid")} + + lines = [ + json.loads(line) + for line in activity_log.read_text(encoding="utf-8").strip().splitlines() + ] + + def _worker_index_for(event: dict) -> str: + pid = event["session"].rsplit(":", 1)[-1] + return pid_to_index[pid] + + arrival_order = [_worker_index_for(e) for e in lines if e["event"] == "enqueued"] + completion_order = [_worker_index_for(e) for e in lines if e["event"] == "completed"] + + assert len(arrival_order) == n_workers + assert len(completion_order) == n_workers + assert arrival_order == completion_order, ( + "expected strict FIFO (completion order == arrival order), got " + f"arrival={arrival_order} completion={completion_order}" + ) diff --git a/council-automation/tests/test_queue_monitor.py b/council-automation/tests/test_queue_monitor.py new file mode 100644 index 0000000..e2c43cc --- /dev/null +++ b/council-automation/tests/test_queue_monitor.py @@ -0,0 +1,352 @@ +"""Tests for queue_monitor.py -- the FIFO research-queue monitoring sidecar. + +ISOLATION (CRITICAL): every test monkeypatches `queue_monitor.SNAPSHOT_PATH` +and `queue_monitor.ACTIVITY_LOG_PATH` to tmp_path locations, and monkeypatches +`queue_monitor._send_pushover` / `queue_monitor._trigger_keeper` to no-op +recorders. NONE of these tests ever send a real Pushover notification, fire +the real PerplexitySessionKeeper scheduled task, or read/write the real +`~/.claude/council-logs/perplexity-queue.json` / +`~/.claude/council-logs/perplexity-activity.jsonl` -- real Perplexity +research sessions may be running on this machine concurrently with this test +run, and those real paths are their live coordination state. + +Run with (from council-automation/): + python -m pytest tests/test_queue_monitor.py -v +""" +from __future__ import annotations + +import json +import time +from pathlib import Path +from typing import Any, Dict, List, Tuple + +import pytest + +import queue_monitor as qm + + +@pytest.fixture(autouse=True) +def isolated_paths(tmp_path: Path, monkeypatch: pytest.MonkeyPatch) -> Path: + """Point every queue_monitor path global at a tmp_path location, and + stub out notification/self-heal side effects so no test can accidentally + send a real Pushover message or fire the real scheduled task. + """ + monkeypatch.setattr(qm, "SNAPSHOT_PATH", tmp_path / "perplexity-queue.json") + monkeypatch.setattr(qm, "ACTIVITY_LOG_PATH", tmp_path / "perplexity-activity.jsonl") + monkeypatch.setattr(qm, "LOG_WORKDIR", tmp_path / "queue-monitor-logs") + return tmp_path + + +def _write_json(path: Path, data: Dict[str, Any]) -> None: + path.parent.mkdir(parents=True, exist_ok=True) + path.write_text(json.dumps(data), encoding="utf-8") + + +def _write_jsonl(path: Path, records: List[Dict[str, Any]]) -> None: + path.parent.mkdir(parents=True, exist_ok=True) + with path.open("w", encoding="utf-8") as f: + for rec in records: + f.write(json.dumps(rec) + "\n") + + +def _healthy_snapshot(**overrides: Any) -> Dict[str, Any]: + base: Dict[str, Any] = { + "version": 1, + "updated_at": time.time(), + "active": { + "run_id": "r1", + "session": "s1", + "query_preview": "hello", + "started_at": time.time() - 5, + "elapsed_s": 5.0, + "heartbeat_age_s": 2.0, + }, + "queued": [], + "recent": [], + "stats": {"depth": 1, "total_today": 1, "errors_today": 0}, + } + base.update(overrides) + return base + + +# -------------------------------------------------------------------------- +# 1. evaluate: stalled active +# -------------------------------------------------------------------------- +def test_evaluate_flags_stalled_active_when_heartbeat_stale( + monkeypatch: pytest.MonkeyPatch, +) -> None: + monkeypatch.setattr(qm, "STALL_TTL_S", 120) + snapshot = _healthy_snapshot(active={ + "run_id": "r1", "session": "s1", "query_preview": "q", + "started_at": time.time() - 300, "elapsed_s": 300.0, "heartbeat_age_s": 500.0, + }) + alerts = qm.evaluate(snapshot, []) + keys = {a.key for a in alerts} + assert "stalled:r1" in keys + stalled = next(a for a in alerts if a.key == "stalled:r1") + assert stalled.severity == "critical" + + +def test_evaluate_no_alert_when_healthy() -> None: + snapshot = _healthy_snapshot() + alerts = qm.evaluate(snapshot, []) + assert alerts == [] + + +def test_evaluate_no_alert_when_active_is_none() -> None: + snapshot = _healthy_snapshot(active=None, stats={"depth": 0, "total_today": 0, "errors_today": 0}) + alerts = qm.evaluate(snapshot, []) + assert alerts == [] + + +def test_evaluate_handles_none_snapshot() -> None: + assert qm.evaluate(None, []) == [] + + +# -------------------------------------------------------------------------- +# 2. evaluate: error/timeout events + within-batch dedupe +# -------------------------------------------------------------------------- +def test_evaluate_flags_error_event() -> None: + event = {"event": "error", "run_id": "r9", "session": "s9", "error": "boom"} + alerts = qm.evaluate(None, [event]) + assert len(alerts) == 1 + assert alerts[0].key == "event:r9:error" + assert alerts[0].severity == "critical" + assert "boom" in alerts[0].message + + +def test_evaluate_flags_timeout_event_as_warning() -> None: + event = {"event": "timeout", "run_id": "r9", "session": "s9"} + alerts = qm.evaluate(None, [event]) + assert len(alerts) == 1 + assert alerts[0].key == "event:r9:timeout" + assert alerts[0].severity == "warning" + + +def test_evaluate_dedupes_same_run_id_event_within_batch() -> None: + event = {"event": "error", "run_id": "r9", "session": "s9", "error": "boom"} + # Same event appears twice (e.g. overlapping tail read) -- must collapse + # to a single alert, not two. + alerts = qm.evaluate(None, [event, dict(event)]) + keys = [a.key for a in alerts] + assert keys == ["event:r9:error"] + + +def test_evaluate_ignores_non_error_events() -> None: + events = [ + {"event": "enqueued", "run_id": "r1", "session": "s1"}, + {"event": "started", "run_id": "r1", "session": "s1"}, + {"event": "completed", "run_id": "r1", "session": "s1"}, + ] + assert qm.evaluate(None, events) == [] + + +# -------------------------------------------------------------------------- +# 3. deep-queue and long-active thresholds +# -------------------------------------------------------------------------- +def test_evaluate_flags_deep_queue(monkeypatch: pytest.MonkeyPatch) -> None: + monkeypatch.setattr(qm, "DEEP_QUEUE_N", 6) + snapshot = _healthy_snapshot( + active=None, + queued=[{"session": "s", "position": i, "query_preview": "q", "wait_s": 1.0} for i in range(1, 8)], + stats={"depth": 7, "total_today": 0, "errors_today": 0}, + ) + alerts = qm.evaluate(snapshot, []) + keys = {a.key for a in alerts} + assert "deep_queue" in keys + + +def test_evaluate_no_deep_queue_alert_at_or_below_threshold(monkeypatch: pytest.MonkeyPatch) -> None: + monkeypatch.setattr(qm, "DEEP_QUEUE_N", 6) + snapshot = _healthy_snapshot( + active=None, + queued=[{"session": "s", "position": i, "query_preview": "q", "wait_s": 1.0} for i in range(1, 7)], + stats={"depth": 6, "total_today": 0, "errors_today": 0}, + ) + alerts = qm.evaluate(snapshot, []) + assert "deep_queue" not in {a.key for a in alerts} + + +def test_evaluate_deep_queue_falls_back_to_len_queued_when_stats_missing( + monkeypatch: pytest.MonkeyPatch, +) -> None: + monkeypatch.setattr(qm, "DEEP_QUEUE_N", 2) + snapshot = { + "active": None, + "queued": [{"session": "s", "position": i} for i in range(1, 5)], + "stats": {}, + } + alerts = qm.evaluate(snapshot, []) + assert "deep_queue" in {a.key for a in alerts} + + +def test_evaluate_flags_long_active(monkeypatch: pytest.MonkeyPatch) -> None: + monkeypatch.setattr(qm, "LONG_RUN_S", 600) + snapshot = _healthy_snapshot(active={ + "run_id": "r1", "session": "s1", "query_preview": "q", + "started_at": time.time() - 900, "elapsed_s": 900.0, "heartbeat_age_s": 1.0, + }) + alerts = qm.evaluate(snapshot, []) + keys = {a.key for a in alerts} + assert "long_run:r1" in keys + long_run = next(a for a in alerts if a.key == "long_run:r1") + assert long_run.severity == "warning" + + +def test_evaluate_no_long_active_alert_under_threshold(monkeypatch: pytest.MonkeyPatch) -> None: + monkeypatch.setattr(qm, "LONG_RUN_S", 600) + snapshot = _healthy_snapshot(active={ + "run_id": "r1", "session": "s1", "query_preview": "q", + "started_at": time.time() - 60, "elapsed_s": 60.0, "heartbeat_age_s": 1.0, + }) + alerts = qm.evaluate(snapshot, []) + assert "long_run:r1" not in {a.key for a in alerts} + + +# -------------------------------------------------------------------------- +# 4. run_loop(once=True) +# -------------------------------------------------------------------------- +def test_run_loop_once_fires_expected_alerts( + tmp_path: Path, monkeypatch: pytest.MonkeyPatch, capsys: pytest.CaptureFixture[str] +) -> None: + sent: List[Tuple[str, str, int]] = [] + + def fake_send_pushover(workdir: Path, title: str, body: str, priority: int) -> bool: + sent.append((title, body, priority)) + return True + + monkeypatch.setattr(qm, "_send_pushover", fake_send_pushover) + monkeypatch.setattr(qm, "_trigger_keeper", None) # disable self-heal side effects + monkeypatch.setattr(qm, "STALL_TTL_S", 120) + + snapshot = _healthy_snapshot(active={ + "run_id": "rstall", "session": "s1", "query_preview": "q", + "started_at": time.time() - 300, "elapsed_s": 300.0, "heartbeat_age_s": 500.0, + }) + _write_json(qm.SNAPSHOT_PATH, snapshot) + _write_jsonl(qm.ACTIVITY_LOG_PATH, [ + {"ts": time.time(), "event": "error", "run_id": "rerr", "session": "s1", + "error": "boom", "seq": 1, "query_preview": "q", "mode": "research"}, + ]) + + qm.run_loop(once=True, use_pushover=True) + + out = capsys.readouterr().out + assert "ACTIVE" in out + assert "ALERT" in out + + titles_bodies = [f"{t} {b}" for t, b, _p in sent] + assert any("rstall" in tb for tb in titles_bodies), ( + f"expected a stalled-run alert to be sent, got {sent!r}" + ) + assert any("rerr" in tb for tb in titles_bodies), ( + f"expected an error-event alert to be sent, got {sent!r}" + ) + # One pushover per newly-active alert key this tick. + assert len(sent) == 2 + + +def test_run_loop_once_no_pushover_flag_suppresses_notifications( + tmp_path: Path, monkeypatch: pytest.MonkeyPatch +) -> None: + sent: List[Any] = [] + monkeypatch.setattr(qm, "_send_pushover", lambda *a, **k: sent.append(a) or True) + monkeypatch.setattr(qm, "_trigger_keeper", None) + monkeypatch.setattr(qm, "STALL_TTL_S", 120) + + snapshot = _healthy_snapshot(active={ + "run_id": "rstall", "session": "s1", "query_preview": "q", + "started_at": time.time() - 300, "elapsed_s": 300.0, "heartbeat_age_s": 500.0, + }) + _write_json(qm.SNAPSHOT_PATH, snapshot) + + qm.run_loop(once=True, use_pushover=False) + + assert sent == [] + + +def test_run_loop_once_does_not_raise_on_missing_snapshot(monkeypatch: pytest.MonkeyPatch) -> None: + monkeypatch.setattr(qm, "_send_pushover", lambda *a, **k: True) + monkeypatch.setattr(qm, "_trigger_keeper", None) + # SNAPSHOT_PATH points at a tmp_path location that was never written. + qm.run_loop(once=True, use_pushover=True) # must not raise + + +def test_run_loop_once_does_not_raise_on_torn_snapshot(monkeypatch: pytest.MonkeyPatch) -> None: + monkeypatch.setattr(qm, "_send_pushover", lambda *a, **k: True) + monkeypatch.setattr(qm, "_trigger_keeper", None) + qm.SNAPSHOT_PATH.parent.mkdir(parents=True, exist_ok=True) + qm.SNAPSHOT_PATH.write_text('{"active": {"run_id": "r1"', encoding="utf-8") # truncated JSON + qm.run_loop(once=True, use_pushover=True) # must not raise + + +def test_run_loop_dedupes_across_polls_same_condition(monkeypatch: pytest.MonkeyPatch) -> None: + """A persisting alert (same key across ticks) must only notify once + while it stays active; a genuinely new run_id is a different key and + must notify again. + """ + sent: List[Any] = [] + monkeypatch.setattr(qm, "_send_pushover", lambda *a, **k: sent.append(a[1]) or True) + monkeypatch.setattr(qm, "_trigger_keeper", None) + monkeypatch.setattr(qm, "STALL_TTL_S", 120) + + snapshot = _healthy_snapshot(active={ + "run_id": "rstall", "session": "s1", "query_preview": "q", + "started_at": time.time() - 300, "elapsed_s": 300.0, "heartbeat_age_s": 500.0, + }) + _write_json(qm.SNAPSHOT_PATH, snapshot) + + # Two consecutive single-pass ticks against the SAME persisting condition. + qm.run_loop(once=True, use_pushover=True) + first_count = len(sent) + qm.run_loop(once=True, use_pushover=True) + second_count = len(sent) + + # Each run_loop(once=True) call starts its own fresh dedupe state (no + # cross-call state is persisted by design -- run_loop's dedupe window is + # a single invocation's lifetime), so both calls independently notify: + # 1 send after the first call, 2 cumulative sends after the second. This + # documents that contract rather than asserting suppression across + # process-level once=True invocations -- see + # test_run_loop_no_dupe_notification_within_single_long_running_call for + # the in-process suppression guarantee. + assert first_count == 1 + assert second_count == 2 + + +def test_run_loop_no_dupe_notification_within_single_long_running_call( + monkeypatch: pytest.MonkeyPatch, +) -> None: + """Within one continuous run_loop invocation (once=False), a condition + that persists across multiple ticks must only fire Pushover on the tick + it first appears. + """ + sent: List[Any] = [] + monkeypatch.setattr(qm, "_send_pushover", lambda *a, **k: sent.append(a[1]) or True) + monkeypatch.setattr(qm, "_trigger_keeper", None) + monkeypatch.setattr(qm, "STALL_TTL_S", 120) + + snapshot = _healthy_snapshot(active={ + "run_id": "rstall", "session": "s1", "query_preview": "q", + "started_at": time.time() - 300, "elapsed_s": 300.0, "heartbeat_age_s": 500.0, + }) + _write_json(qm.SNAPSHOT_PATH, snapshot) + + # Drive the loop body directly (3 ticks) without sleeping, by monkeypatching + # time.sleep to raise StopIteration after N iterations. + calls = {"n": 0} + real_sleep = time.sleep + + def fake_sleep(_s: float) -> None: + calls["n"] += 1 + if calls["n"] >= 3: + raise StopIteration + real_sleep(0) + + monkeypatch.setattr(qm.time, "sleep", fake_sleep) + + with pytest.raises(StopIteration): + qm.run_loop(interval_s=0, once=False, use_pushover=True) + + # 3 ticks of the same persisting stalled condition -> exactly 1 notification. + assert len(sent) == 1 diff --git a/council-automation/tests/test_queue_monitor_stall.py b/council-automation/tests/test_queue_monitor_stall.py new file mode 100644 index 0000000..0f521e4 --- /dev/null +++ b/council-automation/tests/test_queue_monitor_stall.py @@ -0,0 +1,110 @@ +"""Unit tests for queue_monitor's stalled-near-empty detector (2026-07-14). + +The Jul 12-14 real failure mode: a run that COMPLETES but burns a long +wall-clock for almost no output = a session/synthesis stall (distinct from a +legitimately short answer, which returns fast). evaluate() now scans per-query +instrumentation for elapsed_wall_s > STALL_EMPTY_S AND +extracted_synthesis_chars < STALL_EMPTY_CHARS and emits a `stalled:empty:` +alert whose key prefix drives a keeper cookie-refresh via _should_self_heal. + +Run with: + python -m pytest tests/test_queue_monitor_stall.py -v +""" +from pathlib import Path + +import pytest + +import queue_monitor as qm + + +def _inst(**kw): + base = { + "run_id": "r1", + "exit_reason": "completed", + "elapsed_wall_s": 500.0, + "extracted_synthesis_chars": 100, + "min_critical_ttl_s": 500.0, + } + base.update(kw) + return base + + +def test_flags_stalled_near_empty() -> None: + alerts = qm.evaluate(None, [], [_inst()]) + assert len(alerts) == 1 + a = alerts[0] + assert a.key == "stalled:empty:r1" + assert a.severity == "critical" + assert "stalled near-empty" in a.message + + +def test_stalled_empty_key_triggers_self_heal() -> None: + # The whole point of the `stalled:` prefix: the keeper refresh fires. + alerts = qm.evaluate(None, [], [_inst()]) + assert qm._should_self_heal(alerts) is True + + +def test_low_cookie_ttl_annotated_in_message() -> None: + alerts = qm.evaluate(None, [], [_inst(min_critical_ttl_s=140.0)]) + assert "low session-cookie TTL" in alerts[0].message + + +def test_fast_short_answer_not_flagged() -> None: + # A "443" reply: 40s, 3 chars — short but FAST, must not trip (elapsed leg). + alerts = qm.evaluate(None, [], [_inst(elapsed_wall_s=40.0, extracted_synthesis_chars=3)]) + assert alerts == [] + + +def test_long_but_substantial_answer_not_flagged() -> None: + # A legitimately long research run with real output — must not trip. + alerts = qm.evaluate(None, [], [_inst(elapsed_wall_s=480.0, extracted_synthesis_chars=8000)]) + assert alerts == [] + + +def test_boundary_not_inclusive() -> None: + # Exactly at the thresholds should NOT fire (strict > / <). + alerts = qm.evaluate( + None, [], [_inst(elapsed_wall_s=qm.STALL_EMPTY_S, extracted_synthesis_chars=qm.STALL_EMPTY_CHARS)] + ) + assert alerts == [] + + +def test_non_completed_exit_reason_ignored() -> None: + # An empty_synthesis / browser_busy row is handled elsewhere; the stall rule + # only classifies runs that *completed* yet returned almost nothing. + alerts = qm.evaluate(None, [], [_inst(exit_reason="empty_synthesis")]) + assert alerts == [] + + +def test_missing_or_nonnumeric_fields_ignored() -> None: + assert qm.evaluate(None, [], [_inst(elapsed_wall_s=None)]) == [] + assert qm.evaluate(None, [], [_inst(extracted_synthesis_chars="nan")]) == [] + assert qm.evaluate(None, [], [{}]) == [] + + +def test_dedupes_same_run_id_within_batch() -> None: + alerts = qm.evaluate(None, [], [_inst(), _inst()]) + assert len(alerts) == 1 + + +def test_default_arg_keeps_old_signature_working() -> None: + # Backward-compat: existing callers pass only (snapshot, events). + assert qm.evaluate(None, []) == [] + + +def test_tail_new_instrumentation_reads_appended_rows( + tmp_path: Path, monkeypatch: pytest.MonkeyPatch +) -> None: + p = tmp_path / "instrumentation-query.jsonl" + monkeypatch.setattr(qm, "INSTRUMENTATION_LOG_PATH", p) + p.write_text('{"run_id": "a", "exit_reason": "completed"}\n', encoding="utf-8") + recs, off = qm._tail_new_instrumentation(0) + assert [r["run_id"] for r in recs] == ["a"] + # Nothing new since last offset. + recs2, off2 = qm._tail_new_instrumentation(off) + assert recs2 == [] and off2 == off + # A trailing partial line is not consumed until its newline arrives. + with p.open("a", encoding="utf-8") as f: + f.write('{"run_id": "b"') + recs3, off3 = qm._tail_new_instrumentation(off) + assert recs3 == [] and off3 == off diff --git a/council-automation/tests/test_research_queue.py b/council-automation/tests/test_research_queue.py new file mode 100644 index 0000000..0bcc9bd --- /dev/null +++ b/council-automation/tests/test_research_queue.py @@ -0,0 +1,433 @@ +"""Tests for research_queue.py -- the crash-safe cross-process FIFO queue. + +ISOLATION (CRITICAL): every test in this module monkeypatches +`research_queue.QUEUE_DIR`, `research_queue.ACTIVITY_LOG`, and +`research_queue.SNAPSHOT` to paths under pytest's `tmp_path` fixture (or, +for the cross-process tests, an explicit tmp-based dir passed to child +processes via environment variables). NONE of these tests ever touch the +real `~/.claude/config/research-queue`, `~/.claude/council-logs/ +perplexity-activity.jsonl`, or `~/.claude/council-logs/perplexity-queue.json` +-- real Perplexity research sessions may be running on this machine +concurrently with this test run, and those real paths are their live +coordination state. + +Run with (from council-automation/): + python -m pytest tests/test_research_queue.py -v +""" +from __future__ import annotations + +import json +import os +import subprocess +import sys +import time +from pathlib import Path + +import pytest +from filelock import Timeout + +import research_queue as rq + + +@pytest.fixture(autouse=True) +def isolated_paths(tmp_path: Path, monkeypatch: pytest.MonkeyPatch) -> Path: + """Point every research_queue path global at a tmp_path location for + this test. autouse=True so no test can forget this and accidentally + touch the real live queue/log paths. + """ + qdir = tmp_path / "research-queue" + monkeypatch.setattr(rq, "QUEUE_DIR", qdir) + monkeypatch.setattr(rq, "ACTIVITY_LOG", tmp_path / "council-logs" / "perplexity-activity.jsonl") + monkeypatch.setattr(rq, "SNAPSHOT", tmp_path / "council-logs" / "perplexity-queue.json") + return qdir + + +# -------------------------------------------------------------------------- +# 1. atomic_next_seq monotonic +# -------------------------------------------------------------------------- +def test_atomic_next_seq_monotonic() -> None: + rq.ensure_dirs() + a = rq.atomic_next_seq() + b = rq.atomic_next_seq() + c = rq.atomic_next_seq() + assert (a, b, c) == (1, 2, 3) + + +# -------------------------------------------------------------------------- +# 2. Dead-PID ticket reclaimed +# -------------------------------------------------------------------------- +def test_dead_ticket_reclaimed() -> None: + rq.ensure_dirs() + rq.write_ticket( + seq=1, pid=999999999, run_id="x", session="s", state="waiting", + query_preview="q", + ) + rq.gc_dead_tickets() + assert rq.live_tickets() == [] + + +# -------------------------------------------------------------------------- +# 3. Stale-heartbeat ticket reclaimed (own live PID, but heartbeat stale) +# -------------------------------------------------------------------------- +def test_stale_heartbeat_reclaimed(monkeypatch: pytest.MonkeyPatch) -> None: + monkeypatch.setattr(rq, "TTL_S", 1) + rq.ensure_dirs() + rq.write_ticket( + seq=1, pid=os.getpid(), run_id="x", session="s", state="waiting", + query_preview="q", + ) + time.sleep(1.2) + rq.gc_dead_tickets() + assert rq.live_tickets() == [] + + +# -------------------------------------------------------------------------- +# 4. Mutual exclusion across PROCESSES (the load-bearing test) +# -------------------------------------------------------------------------- +_MP_WORKER_SCRIPT = r""" +import os, sys, time, random +from pathlib import Path + +sys.path.insert(0, os.environ["RQ_MODPATH"]) +import research_queue as rq + +rq.QUEUE_DIR = Path(os.environ["RQ_QDIR"]) +rq.ACTIVITY_LOG = Path(os.environ["RQ_QDIR"]) / "activity.jsonl" +rq.SNAPSHOT = Path(os.environ["RQ_QDIR"]) / "snapshot.json" + +count_file = Path(os.environ["RQ_COUNT_FILE"]) +max_file = Path(os.environ["RQ_MAX_FILE"]) + +with rq.acquire_slot(session=os.environ.get("RQ_SESSION", "w"), query_preview="mp-test"): + n = int(count_file.read_text()) if count_file.exists() else 0 + n += 1 + count_file.write_text(str(n)) + # F6: assert INSIDE the critical section, immediately after the + # increment, so a genuine mutual-exclusion breach crashes this worker + # right at the point of violation (deterministic, diagnosable) rather + # than relying solely on the parent's after-the-fact max_file check. + assert n == 1, f"CRITICAL: observed count={n} inside exclusive section (pid={os.getpid()})" + cur_max = int(max_file.read_text()) if max_file.exists() else 0 + if n > cur_max: + max_file.write_text(str(n)) + time.sleep(random.uniform(0.1, 0.25)) + n = int(count_file.read_text()) + n -= 1 + count_file.write_text(str(n)) +""" + + +def test_only_one_active_at_a_time(tmp_path: Path) -> None: + """Spawn 5 real subprocesses, each acquiring a slot and bumping a + shared counter file inside the critical section. Since the shared + counter is only ever read/written from inside `acquire_slot`'s + critical section, if mutual exclusion holds the observed max + concurrent count can never exceed 1 -- proving cross-process (not + just cross-thread) serialization. + """ + qdir = tmp_path / "mp_qdir" + qdir.mkdir() + count_file = qdir / "count.txt" + max_file = qdir / "max.txt" + count_file.write_text("0") + max_file.write_text("0") + + modpath = str(Path(rq.__file__).resolve().parent) + + base_env = os.environ.copy() + base_env["RQ_MODPATH"] = modpath + base_env["RQ_QDIR"] = str(qdir) + base_env["RQ_COUNT_FILE"] = str(count_file) + base_env["RQ_MAX_FILE"] = str(max_file) + base_env["RESEARCH_QUEUE_ENABLED"] = "1" + + procs = [] + for i in range(5): + env = base_env.copy() + env["RQ_SESSION"] = f"w{i}" + p = subprocess.Popen([sys.executable, "-c", _MP_WORKER_SCRIPT], env=env) + procs.append(p) + + for p in procs: + rc = p.wait(timeout=60) + assert rc == 0, f"worker subprocess exited with code {rc}" + + assert max_file.read_text().strip() == "1", ( + "expected the shared counter to never exceed 1 concurrent holder " + f"across processes, observed max={max_file.read_text().strip()}" + ) + assert count_file.read_text().strip() == "0" + + +# -------------------------------------------------------------------------- +# 5. FIFO order +# -------------------------------------------------------------------------- +def test_fifo_order() -> None: + rq.ensure_dirs() + pid = os.getpid() + for seq in range(1, 6): + rq.write_ticket( + seq=seq, pid=pid, run_id=f"r{seq}", session="s", state="waiting", + query_preview="q", + ) + tickets = rq.live_tickets() + assert [d["seq"] for _, d in tickets] == [1, 2, 3, 4, 5] + + +# -------------------------------------------------------------------------- +# 6. Double-promotion race: two head-eligible waiters can never both win +# active.lock -- the FileLock is the true mutex. +# +# NOTE: this is deliberately implemented with two real SUBPROCESSES, not +# two threads with independent FileLock() instances. Same-process +# multi-handle file locking on Windows is not a reliable stand-in for +# true cross-process exclusion (two FileLock objects in one process can +# both succeed in acquiring the "same" lock via independent OS handles +# in some configurations), so a thread-based version of this test can +# give a false pass/fail. A rendezvous (both children signal "ready", +# parent then drops a "go" file) forces genuine overlap regardless of +# subprocess startup jitter. +# -------------------------------------------------------------------------- +_LOCK_RACE_SCRIPT = r""" +import sys, time +from pathlib import Path +from filelock import FileLock, Timeout + +lock_path, ready_path, go_path, result_path = sys.argv[1:5] +Path(ready_path).write_text("ready") +while not Path(go_path).exists(): + time.sleep(0.01) + +lock = FileLock(lock_path, thread_local=False) +try: + lock.acquire(timeout=0) + Path(result_path).write_text("acquired") + time.sleep(0.3) # hold briefly so a genuinely-overlapping second + # attempt (if any) reliably observes contention + lock.release() +except Timeout: + Path(result_path).write_text("timed_out") +""" + + +def test_double_promotion_race_only_one_wins(tmp_path: Path) -> None: + rq.ensure_dirs() + lock_path = str(rq._active_lock_path()) + + ready_a, ready_b = tmp_path / "readyA", tmp_path / "readyB" + go = tmp_path / "go" + result_a, result_b = tmp_path / "resultA", tmp_path / "resultB" + + p_a = subprocess.Popen( + [sys.executable, "-c", _LOCK_RACE_SCRIPT, lock_path, str(ready_a), str(go), str(result_a)] + ) + p_b = subprocess.Popen( + [sys.executable, "-c", _LOCK_RACE_SCRIPT, lock_path, str(ready_b), str(go), str(result_b)] + ) + + deadline = time.time() + 10 + while (not ready_a.exists() or not ready_b.exists()) and time.time() < deadline: + time.sleep(0.01) + go.write_text("go") + + assert p_a.wait(timeout=10) == 0 + assert p_b.wait(timeout=10) == 0 + + outcomes = sorted([result_a.read_text().strip(), result_b.read_text().strip()]) + assert outcomes == ["acquired", "timed_out"], ( + f"expected exactly one contender to acquire active.lock and the " + f"other to fail non-blocking, got A={result_a.read_text()!r} " + f"B={result_b.read_text()!r}" + ) + + +# -------------------------------------------------------------------------- +# 7. MAX_WAIT_S timeout raises QueueTimeout +# -------------------------------------------------------------------------- +def test_max_wait_timeout_raises(monkeypatch: pytest.MonkeyPatch) -> None: + monkeypatch.setattr(rq, "MAX_WAIT_S", 0.3) + monkeypatch.setattr(rq, "POLL_S", 0.05) + rq.ensure_dirs() + + # A permanently-alive, never-removed ticket occupies the head + # position forever, so our own ticket (allocated below via + # acquire_slot's internal atomic_next_seq()) can never be promoted. + # IMPORTANT: allocate the blocker's seq through atomic_next_seq() too + # (not a hardcoded seq=1) so it can't collide with the seq + # acquire_slot() allocates for itself -- a same-pid, same-seq + # collision would produce the identical ticket filename and silently + # overwrite this blocker instead of adding a second ticket. + blocker_seq = rq.atomic_next_seq() + rq.write_ticket( + seq=blocker_seq, pid=os.getpid(), run_id="blocker", session="s", + state="waiting", query_preview="blocker", + ) + + with pytest.raises(rq.QueueTimeout): + with rq.acquire_slot(session="me", query_preview="q"): + pytest.fail("should never be promoted -- head is permanently occupied") + + +# -------------------------------------------------------------------------- +# 8. log_event + publish_snapshot +# -------------------------------------------------------------------------- +def test_log_event_and_snapshot_versioning() -> None: + rq.ensure_dirs() + rq.log_event("started", "rid", "s", 1, "hello", "research", wait_s=2) + lines = rq.ACTIVITY_LOG.read_text(encoding="utf-8").strip().splitlines() + last = json.loads(lines[-1]) + assert last["event"] == "started" + assert last["run_id"] == "rid" + assert last["wait_s"] == 2 + + rq.publish_snapshot() + snap1 = json.loads(rq.SNAPSHOT.read_text(encoding="utf-8")) + assert "version" in snap1 and "updated_at" in snap1 + assert isinstance(snap1["active"], type(None)) + assert snap1["queued"] == [] + + time.sleep(0.01) # guarantee a distinguishable wall-clock tick + rq.publish_snapshot() + snap2 = json.loads(rq.SNAPSHOT.read_text(encoding="utf-8")) + assert snap2["version"] > snap1["version"] + + +# -------------------------------------------------------------------------- +# 9. Flag disabled -> no-op, no ticket files created +# -------------------------------------------------------------------------- +def test_flag_disabled_is_noop(monkeypatch: pytest.MonkeyPatch) -> None: + monkeypatch.setenv("RESEARCH_QUEUE_ENABLED", "0") + with rq.acquire_slot(session="s", query_preview="q") as slot: + assert slot["queued"] is False + assert "run_id" in slot + tickets_dir = rq._tickets_dir() + assert not tickets_dir.exists() or list(tickets_dir.glob("*.ticket")) == [] + + +# -------------------------------------------------------------------------- +# F1 (coordinator fresh-eyes review, 2026-07-11): pid_alive must use +# correctly-typed Windows HANDLE ctypes bindings (no truncation/leak) and +# must report True for its own live PID, False for a definitely-dead one, +# and survive a tight repeated-call loop without error (handle-leak smoke). +# -------------------------------------------------------------------------- +def test_pid_alive_correct_and_no_leak_smoke() -> None: + assert rq.pid_alive(os.getpid()) is True + assert rq.pid_alive(999999999) is False + # Tight loop: each call does OpenProcess+CloseHandle. If restype/ + # argtypes were wrong (F1's original bug), a 64-bit HANDLE could get + # truncated to a bad 32-bit value and CloseHandle would silently fail + # every time -- this doesn't assert on OS handle counts directly (no + # stdlib API for that), but it does prove 2000 consecutive probes + # complete without ctypes raising and keep reporting the correct, + # stable answer for a live PID. + for _ in range(2000): + assert rq.pid_alive(os.getpid()) is True + + +# -------------------------------------------------------------------------- +# F2 (coordinator fresh-eyes review, 2026-07-11): a ticket file that is +# valid JSON but missing `seq` must be skipped, not crash the sort inside +# read_tickets()/live_tickets(). +# -------------------------------------------------------------------------- +def test_malformed_ticket_missing_seq_is_ignored_not_fatal() -> None: + rq.ensure_dirs() + # A well-formed ticket so the directory isn't empty. + rq.write_ticket( + seq=1, pid=os.getpid(), run_id="ok", session="s", state="waiting", + query_preview="q", + ) + # A torn/malformed ticket: valid JSON, but no "seq" key at all. + bad_path = rq._tickets_dir() / "99999999-1.ticket" + bad_path.write_text(json.dumps({"pid": os.getpid(), "run_id": "bad", "state": "waiting"})) + + # Must not raise (this is exactly the KeyError crash vector F2 fixes). + tickets = rq.live_tickets() + assert [d["run_id"] for _, d in tickets] == ["ok"] + + +# -------------------------------------------------------------------------- +# F4 (coordinator fresh-eyes review, 2026-07-11): log_event must be +# best-effort -- a busy activity-log lock must never raise out of an +# unguarded enqueued/started/completed call site. +# -------------------------------------------------------------------------- +def test_log_event_best_effort_on_lock_timeout(monkeypatch: pytest.MonkeyPatch) -> None: + monkeypatch.setattr(rq, "ACTIVITY_LOG_LOCK_TIMEOUT_S", 0.1) + rq.ensure_dirs() + + blocking_lock = rq.FileLock(str(rq._activity_lock_path()), thread_local=False) + blocking_lock.acquire() + try: + # Must NOT raise filelock.Timeout -- best-effort swallow. + rq.log_event("started", "rid", "s", 1, "q", "research") + finally: + blocking_lock.release() + + +# -------------------------------------------------------------------------- +# F5 (coordinator fresh-eyes review, 2026-07-11): the active ticket's +# elapsed_s in the published snapshot must reflect time-since-promotion +# (active_since), not time-since-enqueue (enqueued_at) -- a long wait in +# queue must not inflate the reported run duration. +# -------------------------------------------------------------------------- +def test_snapshot_stats_total_today_counts_runs_not_events() -> None: + """total_today must count DISTINCT RUNS (via `started` events), not raw + activity-log lines -- a single run logs 3 events (enqueued/started/ + completed), which the pre-fix `len(recent)` counted as 3. + """ + rq.ensure_dirs() + # One full run: enqueued -> started -> completed (3 events, 1 run). + rq.log_event("enqueued", "run-a", "s", 1, "q", "research") + rq.log_event("started", "run-a", "s", 1, "q", "research", wait_s=1) + rq.log_event("completed", "run-a", "s", 1, "q", "research", duration_s=5) + # A second run that errored out (no "started" logged for it here would + # still be a valid run, but exercise the common enqueued->started->error + # path so it's counted once via its own "started" event). + rq.log_event("enqueued", "run-b", "s", 2, "q", "research") + rq.log_event("started", "run-b", "s", 2, "q", "research", wait_s=1) + rq.log_event("error", "run-b", "s", 2, "q", "research", error="boom") + + rq.publish_snapshot() + snap = json.loads(rq.SNAPSHOT.read_text(encoding="utf-8")) + assert snap["stats"]["total_today"] == 2, ( + f"expected 2 distinct runs today, got {snap['stats']['total_today']} " + f"(pre-fix bug counted raw event lines instead)" + ) + assert snap["stats"]["errors_today"] == 1 + + +def test_snapshot_stats_errors_today_counts_timeout_too() -> None: + rq.ensure_dirs() + rq.log_event("enqueued", "run-c", "s", 1, "q", "research") + rq.log_event("timeout", "run-c", "s", 1, "q", "research", wait_s=1200) + + rq.publish_snapshot() + snap = json.loads(rq.SNAPSHOT.read_text(encoding="utf-8")) + assert snap["stats"]["errors_today"] == 1 + # No "started" event was ever logged for run-c (it timed out while + # still queued), so it must not be counted as a completed/started run. + assert snap["stats"]["total_today"] == 0 + + +def test_snapshot_elapsed_s_uses_active_since_not_enqueued_at() -> None: + rq.ensure_dirs() + now = time.time() + pid = os.getpid() + # Simulate a ticket that waited 50s in queue but has only been + # actively running for 5s. + ticket_path = rq.write_ticket( + seq=1, pid=pid, run_id="r1", session="s", state="active", + query_preview="q", + ) + data = json.loads(ticket_path.read_text(encoding="utf-8")) + data["enqueued_at"] = now - 50 + data["active_since"] = now - 5 + data["heartbeat_at"] = now + ticket_path.write_text(json.dumps(data)) + + rq.publish_snapshot() + snap = json.loads(rq.SNAPSHOT.read_text(encoding="utf-8")) + assert snap["active"] is not None + # Should be ~5s (active_since-based), nowhere near ~50s + # (enqueued_at-based, the pre-fix bug). + assert snap["active"]["elapsed_s"] < 10 + assert snap["active"]["started_at"] == data["active_since"] diff --git a/council-automation/tests/test_stopgap_serialization.py b/council-automation/tests/test_stopgap_serialization.py new file mode 100644 index 0000000..9af6d9a --- /dev/null +++ b/council-automation/tests/test_stopgap_serialization.py @@ -0,0 +1,252 @@ +"""Phase 0 Task 0.2 — integration tests for the whole-run lock hold. + +Covers: + - Two callers holding submission_lock.get_submit_lock() across a work + window (as run() does under RESEARCH_QUEUE_STOPGAP) never interleave, + and a long-timeout waiter eventually acquires once the first releases. + - The RESEARCH_QUEUE_STOPGAP guard in council_browser.PerplexityCouncil.run() + is present and correctly gates the mid-run early release (so inverting + or deleting the guard fails this test). + - The LockHeartbeat helper: refreshes a held lock file's mtime while + running (so the 180s stale-reclaim in get_submit_lock() never trips + on a live long-held lock), and stopping it lets stale-reclaim fire + again exactly as it does today. + +IMPORTANT (isolation): every test here monkeypatches +`submission_lock.LOCK_PATH` (and `STALE_AGE_S` where relevant) to a path +under `tmp_path`, so these tests NEVER touch the real, shared +`~/.claude/config/browser-sessions/.perplexity_submit.lock` file -- +running this suite must not block or interfere with a user's live +Perplexity session. + +Run with: + python -m pytest tests/test_stopgap_serialization.py -v +(from council-automation/, so `import submission_lock` / `import +council_browser` resolve via cwd on sys.path per `python -m pytest` +semantics). +""" +from __future__ import annotations + +import inspect +import threading +import time +from pathlib import Path + +import pytest + +import submission_lock + + +@pytest.fixture +def isolated_lock_path(tmp_path: Path, monkeypatch: pytest.MonkeyPatch) -> Path: + """Redirect submission_lock.LOCK_PATH to a tmp_path file for this test. + + Guarantees no test in this module can ever contend with, block, or + corrupt the real shared submit lock used by live Claude Code + sessions. + """ + lock_path = tmp_path / ".perplexity_submit.lock" + monkeypatch.setattr(submission_lock, "LOCK_PATH", lock_path) + return lock_path + + +def test_two_stopgap_runs_do_not_overlap(isolated_lock_path: Path) -> None: + """With the lock held across a whole work window (as run() does under + RESEARCH_QUEUE_STOPGAP), a second acquirer's work cannot start until + the first fully finishes and releases -- no interleave. Also proves + a long-timeout waiter (as under RESEARCH_QUEUE_MAX_WAIT) eventually + acquires once the first holder releases.""" + order: list[tuple[str, str]] = [] + order_guard = threading.Lock() + + def worker(name: str, hold: float) -> None: + with submission_lock.get_submit_lock(timeout=10): + with order_guard: + order.append(("start", name)) + time.sleep(hold) + with order_guard: + order.append(("end", name)) + + t1 = threading.Thread(target=worker, args=("A", 0.5)) + t2 = threading.Thread(target=worker, args=("B", 0.1)) + t1.start() + time.sleep(0.05) + t2.start() + t1.join(timeout=15) + t2.join(timeout=15) + + assert ("start", "A") in order + assert ("end", "A") in order + assert ("start", "B") in order + assert ("end", "B") in order + + # B must not start before A ends -- no interleave under whole-run hold, + # and B (the long-timeout waiter) does eventually acquire after A + # releases rather than erroring out. + assert order.index(("end", "A")) < order.index(("start", "B")), ( + f"expected A to fully finish before B started under a whole-run " + f"lock hold, got order={order!r}" + ) + + +def test_early_release_gated_by_stopgap_flag() -> None: + """getsource assertion: the mid-run early release block in run() is + gated by `_flag_enabled("RESEARCH_QUEUE_STOPGAP")`. Inverting the + condition (`if _flag_enabled(...)`) or deleting the guard entirely + would make this assertion fail.""" + import council_browser + from council_browser import PerplexityCouncil + + # Phase 1 wiring moved run()'s body into _run_impl(); inspect both so the + # guard is found wherever the mid-run early-release lives. + src = inspect.getsource(PerplexityCouncil.run) + _impl = getattr(PerplexityCouncil, "_run_impl", None) + if _impl is not None: + src += "\n" + inspect.getsource(_impl) + assert 'if not _flag_enabled("RESEARCH_QUEUE_STOPGAP"):' in src, ( + "expected the mid-run submit_lock release to be gated by " + '`if not _flag_enabled("RESEARCH_QUEUE_STOPGAP"):` so the ' + "release is SKIPPED (lock stays held) when the flag is on" + ) + # _flag_enabled itself must normalize truthiness (MINOR-4): only + # {"1","true","yes","on"} (case-insensitive) count as enabled. + assert council_browser._flag_enabled("RESEARCH_QUEUE_STOPGAP") is False + assert council_browser._flag_enabled("NON_EXISTENT_FLAG_XYZ") is False + + +class TestFlagTruthiness: + """MINOR-4: RESEARCH_QUEUE_STOPGAP=0 / =false must NOT enable the flag.""" + + @pytest.mark.parametrize("value", ["1", "true", "True", "YES", "on", "On"]) + def test_truthy_values_enable( + self, value: str, monkeypatch: pytest.MonkeyPatch + ) -> None: + import council_browser + + monkeypatch.setenv("RESEARCH_QUEUE_STOPGAP", value) + assert council_browser._flag_enabled("RESEARCH_QUEUE_STOPGAP") is True + + @pytest.mark.parametrize("value", ["0", "false", "False", "no", "off", ""]) + def test_falsy_values_do_not_enable( + self, value: str, monkeypatch: pytest.MonkeyPatch + ) -> None: + import council_browser + + monkeypatch.setenv("RESEARCH_QUEUE_STOPGAP", value) + assert council_browser._flag_enabled("RESEARCH_QUEUE_STOPGAP") is False + + def test_unset_does_not_enable(self, monkeypatch: pytest.MonkeyPatch) -> None: + import council_browser + + monkeypatch.delenv("RESEARCH_QUEUE_STOPGAP", raising=False) + assert council_browser._flag_enabled("RESEARCH_QUEUE_STOPGAP") is False + + +class TestLockHeartbeat: + """Unit tests for submission_lock.LockHeartbeat / start_lock_heartbeat.""" + + def test_heartbeat_refreshes_mtime( + self, isolated_lock_path: Path, monkeypatch: pytest.MonkeyPatch + ) -> None: + """A running heartbeat keeps touching the lock file's mtime.""" + lock = submission_lock.get_submit_lock(timeout=5) + lock.acquire() + try: + mtime_before = isolated_lock_path.stat().st_mtime + heartbeat = submission_lock.start_lock_heartbeat( + lock, interval_s=0.05 + ) + try: + time.sleep(0.3) # several heartbeat ticks + finally: + heartbeat.stop() + mtime_after = isolated_lock_path.stat().st_mtime + assert mtime_after > mtime_before, ( + "heartbeat should have refreshed the lock file's mtime " + "at least once" + ) + finally: + lock.release() + + def test_heartbeat_prevents_stale_reclaim_while_alive( + self, isolated_lock_path: Path, monkeypatch: pytest.MonkeyPatch + ) -> None: + """While a heartbeat is running, the lock file's mtime age never + exceeds STALE_AGE_S, so a live long-held lock is never mistaken + for a crashed holder's stale lock.""" + monkeypatch.setattr(submission_lock, "STALE_AGE_S", 0.2) + + lock = submission_lock.get_submit_lock(timeout=5) + lock.acquire() + try: + heartbeat = submission_lock.start_lock_heartbeat( + lock, interval_s=0.05 + ) + try: + # Sleep well past STALE_AGE_S -- without the heartbeat, + # the lock file would now look abandoned. + time.sleep(0.6) + age = time.time() - isolated_lock_path.stat().st_mtime + assert age < submission_lock.STALE_AGE_S, ( + f"expected heartbeat to keep mtime age ({age:.2f}s) " + f"below STALE_AGE_S ({submission_lock.STALE_AGE_S}s)" + ) + finally: + heartbeat.stop() + finally: + lock.release() + + def test_stopping_heartbeat_allows_stale_reclaim( + self, isolated_lock_path: Path, monkeypatch: pytest.MonkeyPatch + ) -> None: + """Once the heartbeat is stopped (simulating a crashed/finished + holder), the lock file's mtime stops advancing. After it ages + past STALE_AGE_S, get_submit_lock()'s existing reclaim logic + still unlinks it -- crash recovery is unaffected.""" + monkeypatch.setattr(submission_lock, "STALE_AGE_S", 0.2) + + lock = submission_lock.get_submit_lock(timeout=5) + lock.acquire() + heartbeat = submission_lock.start_lock_heartbeat(lock, interval_s=0.05) + time.sleep(0.1) # one tick, file gets touched + heartbeat.stop() + lock.release() # simulate the holder finishing/crashing + + # No heartbeat running now -- wait past STALE_AGE_S so the lock + # file looks abandoned by the (already-released) prior holder. + time.sleep(0.4) + + # get_submit_lock()'s reclaim runs synchronously inside the call, + # BEFORE the underlying file is recreated by .acquire(). If the + # stale file was unlinked, it will not exist yet at this point. + new_lock = submission_lock.get_submit_lock(timeout=5) + assert not isolated_lock_path.exists(), ( + "expected the stale lock file to have been unlinked by " + "get_submit_lock()'s existing reclaim logic once the " + "heartbeat stopped and STALE_AGE_S elapsed" + ) + new_lock.acquire() + try: + assert isolated_lock_path.exists() + finally: + new_lock.release() + + def test_start_lock_heartbeat_derives_path_from_lock_file( + self, isolated_lock_path: Path + ) -> None: + """start_lock_heartbeat() reads the path to heartbeat from the + FileLock's own `.lock_file` attribute (not a separate global), + so it stays correct even if LOCK_PATH is monkeypatched per-test.""" + lock = submission_lock.get_submit_lock(timeout=5) + lock.acquire() + try: + heartbeat = submission_lock.start_lock_heartbeat( + lock, interval_s=0.05 + ) + try: + assert heartbeat._lock_path == Path(lock.lock_file) + assert heartbeat._lock_path == isolated_lock_path + finally: + heartbeat.stop() + finally: + lock.release() diff --git a/council-automation/tests/test_submission_lock_scope.py b/council-automation/tests/test_submission_lock_scope.py new file mode 100644 index 0000000..d796aed --- /dev/null +++ b/council-automation/tests/test_submission_lock_scope.py @@ -0,0 +1,76 @@ +"""Phase 0 Task 0.1 — baseline characterization test. + +Documents (via inspect.getsource) that CouncilBrowser.run() uses the +cross-process submission_lock today. This is a baseline/characterization +test, not a behavior spec — it exists so future refactors of run() (e.g. +the Phase 0 RESEARCH_QUEUE_STOPGAP widening, or later the Phase 1 FIFO +queue) can be checked against a known-good starting contract: the lock is +acquired via submission_lock.get_submit_lock() (wrapped by +_acquire_submit_lock) and is released somewhere in run()'s body, with a +release-state flag guarding against double release. + +Run with: + python -m pytest tests/test_submission_lock_scope.py -v +(from council-automation/, so `import council_browser` resolves via cwd +on sys.path per `python -m pytest` semantics). +""" +import inspect + +import council_browser +from council_browser import PerplexityCouncil + + +def _run_source() -> str: + """Combined source of run() and (if present) _run_impl(). + + The Phase 1 FIFO-queue wiring extract-method-refactored run()'s body into + _run_impl(), leaving run() a thin queue wrapper. These characterization + checks care that the submit-lock contract exists in the run pipeline, not + which method holds it — so inspect both. + """ + src = inspect.getsource(PerplexityCouncil.run) + impl = getattr(PerplexityCouncil, "_run_impl", None) + if impl is not None: + src += "\n" + inspect.getsource(impl) + return src + + +def test_submit_lock_used_in_run() -> None: + """Baseline: run() acquires the cross-process submit lock. + + Today this happens via `await self._acquire_submit_lock()`, which + wraps `submission_lock.get_submit_lock()`. Mirrors the substring + check from the Phase 0 design doc (`"_submit_lock" in src`, which + matches via the `_acquire_submit_lock` method name). + """ + src = _run_source() + assert "_submit_lock" in src, "submission lock must be used in run()" + assert "_acquire_submit_lock" in src + + +def test_acquire_submit_lock_uses_submission_lock_module() -> None: + """_acquire_submit_lock() is backed by submission_lock.get_submit_lock.""" + src = inspect.getsource(PerplexityCouncil._acquire_submit_lock) + assert "get_submit_lock" in src + + +def test_run_releases_submit_lock() -> None: + """Baseline: run() releases the acquired submit_lock somewhere in its + body (either the mid-run explicit release, or the defensive release + in the outer finally).""" + src = _run_source() + assert "submit_lock.release()" in src + + +def test_run_tracks_submit_lock_release_state() -> None: + """Baseline: run() tracks whether submit_lock has already been + released via a `submit_lock_released` flag, so the mid-run release + and the defensive finally-block release can never both fire.""" + src = _run_source() + assert "submit_lock_released" in src + + +def test_council_browser_imports_get_submit_lock() -> None: + """Baseline: the module-level import wiring for the shared lock.""" + src = inspect.getsource(council_browser) + assert "from submission_lock import get_submit_lock" in src diff --git a/council-automation/tests/test_validate_result.py b/council-automation/tests/test_validate_result.py new file mode 100644 index 0000000..68e4aa0 --- /dev/null +++ b/council-automation/tests/test_validate_result.py @@ -0,0 +1,60 @@ +"""Unit tests for council_browser._validate_result — the post-extraction +truncation/emptiness classifier. + +Locks the 2026-07-14 fix: rule (d) (peak-length regression) is GATED to +non-substantial outputs so a complete 6-13K-char structured answer whose +streaming .prose peak was inflated by transient reasoning-trail text is NOT +false-flagged as truncated — while genuine near-empty stalls (<300 chars) and +structural cuts (unclosed fence / dangling token) are still caught at any size. + +Run with: + python -m pytest tests/test_validate_result.py -v +(from council-automation/, so `import council_browser` resolves via cwd.) +""" +import council_browser as cb + +V = cb._validate_result +SUB = cb.SUBSTANTIAL_SYNTHESIS_CHARS # 2500 + + +def test_empty_is_empty() -> None: + assert V("", 100) == "empty" + assert V(" ", 100) == "empty" + + +def test_large_answer_with_inflated_peak_is_ok_not_truncated() -> None: + # The core false-positive fix: 10K-char complete answer, streaming peak 12K + # (reasoning-trail inflation) => 15%+ regression, but must NOT flag. + big = "x" * 10000 + assert V(big, 12000) == "ok" + + +def test_genuine_tiny_stall_still_flagged() -> None: + # 197 chars after a peak of 292 = the real Jul-12 failure shape. + assert V("y" * 197, 292) == "suspect_truncated" + + +def test_short_complete_answer_is_ok() -> None: + # e.g. a "443" reply — short, no regression vs a small peak. + assert V("443", 3) == "ok" + assert V("443", None) == "ok" + + +def test_peak_regression_gate_boundary() -> None: + # Just below the substantial gate: regression still evaluated. + s = "z" * (SUB - 1) + assert V(s, int((SUB - 1) / 0.8)) == "suspect_truncated" # ~20% drop from peak + # At/above the gate: regression ignored. + s2 = "z" * SUB + assert V(s2, int(SUB / 0.5)) == "ok" # 50% "drop" from peak, but substantial => ok + + +def test_structural_rules_still_fire_on_large_output() -> None: + # (a) unclosed code fence must be caught even above the substantial gate. + assert V("a" * 3000 + "\n```code", 3100) == "suspect_truncated" + # (b) dangling terminal token must be caught even above the gate. + assert V("b" * 3000 + " and then:", 3100) == "suspect_truncated" + + +def test_large_clean_answer_ending_normally_is_ok() -> None: + assert V("word " * 700 + "final sentence.", 4000) == "ok" diff --git a/mcp-servers/browser-bridge/extension/background.js b/mcp-servers/browser-bridge/extension/background.js index 0c7ee64..489179e 100644 --- a/mcp-servers/browser-bridge/extension/background.js +++ b/mcp-servers/browser-bridge/extension/background.js @@ -235,6 +235,20 @@ function connect() { reconnectDelay = RECONNECT_BASE; lastServerMessage = Date.now(); + // Identify this client so the server can pick a single canonical target when + // more than one Chrome has the extension (e.g. the user's personal profile + // AND the always-on keeper Chrome). The keeper's copy carries "(Keeper)" in + // its manifest name; everything else reports role 'default'. Absence of this + // message (older extension builds) is treated as 'default' server-side, so + // this is fully backward-compatible. + try { + const mf = chrome.runtime.getManifest(); + const role = (mf.name || '').includes('Keeper') ? 'keeper' : 'default'; + ws.send(JSON.stringify({ type: 'hello', role, clientId: chrome.runtime.id, version: mf.version })); + } catch (e) { + // non-fatal — server defaults missing role to 'default' + } + // Layer 1: periodic ping clearInterval(pingTimer); pingTimer = setInterval(() => { @@ -309,6 +323,9 @@ async function handleServerMessage(msg) { case 'navigate': result = await handleNavigate(msg.payload); break; + case 'load_dynamic': + result = await handleLoadDynamic(msg.payload); + break; case 'get_context': result = await handleGetContext(msg.payload); break; @@ -424,10 +441,117 @@ async function getTargetTabId(payload) { return tab ? tab.id : null; } +// --------------------------------------------------------------------------- +// Dynamic content loader — foreground the tab, scroll lazy content, restore +// --------------------------------------------------------------------------- +// +// Facebook (and similar hardened sites) gate infinite-scroll content behind +// IntersectionObserver + lazy hydration. Chrome throttles BACKGROUND tabs — +// paint is paused and IntersectionObserver callbacks (bound to the frame +// rendering pipeline) never fire — so lazy lists never populate in the tabs the +// bridge opens with { active: false }. CDP visibility-spoofing does NOT flip +// document.visibilityState to 'visible', so the only reliable fix is to briefly +// FOREGROUND the tab, scroll, then restore the user's prior tab/window. + +/** + * Run `fn` with `tabId` foregrounded (active + its window focused), then restore + * whatever tab/window was active before. Always restores, even if `fn` throws. + */ +async function withForegroundTab(tabId, fn) { + let prevTabId = null; + let prevWindowId = null; + try { + const [prev] = await chrome.tabs.query({ active: true, lastFocusedWindow: true }); + if (prev) { + prevTabId = prev.id; + prevWindowId = prev.windowId; + } + } catch { /* best-effort — restore is optional */ } + + const target = await chrome.tabs.get(tabId); + try { + await chrome.tabs.update(tabId, { active: true }); + await chrome.windows.update(target.windowId, { focused: true }); + return await fn(); + } finally { + // Restore the user's context only if it differs from the target tab. + if (prevTabId && prevTabId !== tabId) { + await chrome.tabs.update(prevTabId, { active: true }).catch(() => {}); + if (prevWindowId) { + await chrome.windows.update(prevWindowId, { focused: true }).catch(() => {}); + } + } + } +} + +/** + * Navigate to (or reuse) a page, foreground it, and auto-scroll to force + * viewport-gated lazy content to load, then restore the user's prior tab. + */ +async function handleLoadDynamic(payload) { + // 1. Resolve the target tab — navigate first if a URL was supplied. + let tabId; + let url = payload.url || null; + if (url) { + const nav = await handleNavigate(payload); + tabId = nav.tabId; + url = nav.url || url; + } else { + tabId = await getTargetTabId(payload); + } + if (!tabId) throw new Error('No target tab for load_dynamic'); + + // 2. Ensure the content script is present (same probe as handleActionRequest). + try { + await chrome.scripting.executeScript({ + target: { tabId }, + func: () => typeof window.claudeHelpers !== 'undefined', + }); + } catch { + throw new Error('Cannot access this page (restricted URL)'); + } + + // 3. Foreground the tab so IntersectionObserver / lazy hydration actually run, + // scroll the lazy list to completion, then restore the prior tab/window. + const scrollResult = await withForegroundTab(tabId, async () => { + if (payload.waitForSelector) { + await chrome.tabs.sendMessage(tabId, { + source: 'claude-bridge', + action: 'waitForElement', + selector: payload.waitForSelector, + timeout: 15000, + }).catch(() => {}); + } + return chrome.tabs.sendMessage(tabId, { + source: 'claude-bridge', + action: 'autoScrollLoad', + containerSelector: payload.containerSelector, + itemSelector: payload.itemSelector, + maxScrolls: payload.maxScrolls, + stableMs: payload.stableMs, + minDelay: payload.minDelay, + maxDelay: payload.maxDelay, + timeout: payload.timeout, + }); + }); + + return { ...(scrollResult || {}), tabId, url }; +} + async function handleActionRequest(payload) { const tabId = await getTargetTabId(payload); if (!tabId) throw new Error('No active tab found'); + // Trusted directional scroll: JS window.scrollBy() produces isTrusted:false + // wheel/scroll events, which hardened infinite-scroll sites (Facebook friends + // list, etc.) ignore — the scrollbar moves but no lazy content loads. Route + // directional scrolls through CDP Input.dispatchMouseEvent(mouseWheel) so they + // arrive as trusted input and trigger lazy-load exactly like a human wheel. + // Selector-based scroll (scrollIntoView) still goes to the content script. + if (payload.action === 'scroll' && !payload.selector) { + return cdpWheelScroll(tabId, payload); + } + // Inject content script if not already present try { await chrome.scripting.executeScript({ @@ -447,6 +571,76 @@ async function handleActionRequest(payload) { return response; } +// --------------------------------------------------------------------------- +// Trusted wheel scroll via CDP +// --------------------------------------------------------------------------- +// +// JS window.scrollBy/scrollTo and new WheelEvent() are isTrusted:false. Hardened +// infinite-scroll (Facebook friends list, feeds, etc.) only fetches the next +// batch in response to a TRUSTED input event, so JS scrolling moves the scrollbar +// but never loads more content. CDP Input.dispatchMouseEvent(mouseWheel) events +// go through Chrome's real input pipeline (isTrusted:true) — the same mechanism +// Playwright's mouse.wheel() uses — so the page reacts as if a human scrolled. +async function cdpWheelScroll(tabId, payload) { + const amount = Math.max(1, Math.min(30000, payload.amount || 500)); + const dir = payload.direction || 'down'; + // [deltaY sign, deltaX sign] — CDP mouseWheel: +deltaY scrolls DOWN. + const sign = { up: [-1, 0], down: [1, 0], left: [0, -1], right: [0, 1] }; + const [vy, vx] = sign[dir] || [1, 0]; + + // Hardened sites (Facebook, feeds) pause IntersectionObserver / lazy hydration + // on hidden/background tabs, so a trusted wheel loads nothing while the tab is + // in the background. Foreground the tab (and focus its window) first so the + // scroll actually triggers content loading. Best-effort — never block on it. + try { + const tab = await chrome.tabs.get(tabId); + if (tab && !tab.active) await chrome.tabs.update(tabId, { active: true }); + if (tab && tab.windowId != null) { + await chrome.windows.update(tab.windowId, { focused: true }).catch(() => {}); + } + } catch { + // tab may be gone; the cdpCommand calls below will surface a clear error + } + + // Wheel events must originate from a point over the scrollable content. + // Resolve the viewport center via CDP Runtime.evaluate (defaults if it fails). + let x = 400; + let y = 400; + try { + const vp = await cdpCommand(tabId, 'Runtime.evaluate', { + expression: 'JSON.stringify({w:innerWidth,h:innerHeight})', + returnByValue: true, + }); + const dims = JSON.parse(vp?.result?.value || '{}'); + if (dims.w) x = Math.round(dims.w / 2); + if (dims.h) y = Math.round(dims.h / 2); + } catch { + // fall back to default coordinates + } + + // Position the pointer first — some wheel handlers require a prior mouseMoved. + await cdpCommand(tabId, 'Input.dispatchMouseEvent', { type: 'mouseMoved', x, y }); + + // Real wheel gestures arrive as a burst of small deltas; emulate that so the + // page's scroll / IntersectionObserver logic fires the same as a human scroll. + const TICK = 120; + const ticks = Math.max(1, Math.round(amount / TICK)); + let sent = 0; + for (let i = 0; i < ticks; i++) { + await cdpCommand(tabId, 'Input.dispatchMouseEvent', { + type: 'mouseWheel', + x, + y, + deltaX: vx * TICK, + deltaY: vy * TICK, + }); + sent += TICK; + await new Promise((r) => setTimeout(r, 16)); // ~1 frame between ticks + } + + return { success: true, direction: dir, amount: sent, trusted: true, via: 'cdp-mouseWheel' }; +} + async function handleNavigate(payload) { let tabId; diff --git a/mcp-servers/browser-bridge/extension/content.js b/mcp-servers/browser-bridge/extension/content.js index 5d89537..08afdee 100644 --- a/mcp-servers/browser-bridge/extension/content.js +++ b/mcp-servers/browser-bridge/extension/content.js @@ -103,6 +103,8 @@ async function handleAction(msg) { return actionInsertText(msg.selector, msg.text, msg.append); case 'waitForStable': return actionWaitForStable(msg.selector, msg.stableMs, msg.timeout, msg.pollInterval); + case 'autoScrollLoad': + return actionAutoScrollLoad(msg); default: throw new Error(`Unknown action: ${action}`); } @@ -250,6 +252,95 @@ function sleep(ms) { return new Promise((r) => setTimeout(r, ms)); } +// --------------------------------------------------------------------------- +// Auto-scroll loader — drives viewport-gated infinite-scroll / lazy content +// --------------------------------------------------------------------------- +// +// Scrolls a container (or the page) to the bottom in jittered increments until +// the amount of loaded content stops growing, then reports how much loaded. +// +// IMPORTANT: IntersectionObserver / lazy hydration only fire when the tab is +// actually foregrounded (Chrome throttles background tabs and pauses paint). +// The background service worker foregrounds the target tab before invoking this +// action and restores the prior tab afterwards (see handleLoadDynamic). + +async function actionAutoScrollLoad(msg) { + const containerSelector = msg.containerSelector || null; + const itemSelector = msg.itemSelector || null; + const maxScrolls = Math.max(1, Math.min(500, msg.maxScrolls || 60)); + const stableMs = Math.max(200, Math.min(20000, msg.stableMs || 1200)); + const minDelay = Math.max(100, Math.min(10000, msg.minDelay || 600)); + const maxDelay = Math.max(minDelay, Math.min(20000, msg.maxDelay || 1400)); + const timeout = Math.max(2000, Math.min(600000, msg.timeout || 90000)); + const stagnantLimit = 3; + + // Resolve the scroll target. When a container selector is given but not yet + // present, wait briefly for it (lazy layouts mount it after hydration). + let scrollTarget = null; + if (containerSelector) { + scrollTarget = await window.claudeHelpers.findElement(containerSelector, 5000); + if (!scrollTarget) { + return { success: false, error: `Scroll container not found: ${containerSelector}`, code: 'CONTAINER_NOT_FOUND' }; + } + } + + const measure = () => { + if (itemSelector) return document.querySelectorAll(itemSelector).length; + return scrollTarget + ? scrollTarget.scrollHeight + : (document.scrollingElement || document.documentElement).scrollHeight; + }; + + const scrollToBottom = () => { + if (scrollTarget) { + scrollTarget.scrollTo({ top: scrollTarget.scrollHeight, behavior: 'instant' }); + } else { + const el = document.scrollingElement || document.documentElement; + window.scrollTo({ top: el.scrollHeight, behavior: 'instant' }); + } + }; + + const startTime = Date.now(); + let prev = -1; + let stagnant = 0; + let scrolls = 0; + let timedOut = false; + + for (let i = 0; i < maxScrolls; i++) { + if (Date.now() - startTime >= timeout) { timedOut = true; break; } + + scrollToBottom(); + scrolls++; + + // Jittered, human-ish pause so lazy content can load between steps. + const delay = Math.round(minDelay + Math.random() * (maxDelay - minDelay)); + await sleep(delay); + + const current = measure(); + if (current <= prev) stagnant++; + else stagnant = 0; + prev = current; + + // Content stopped growing for several consecutive steps — fully loaded. + if (stagnant >= stagnantLimit) break; + } + + // Best-effort settle wait so the final batch finishes rendering before extraction. + if (itemSelector || containerSelector) { + await sleep(Math.min(stableMs, 2000)); + } + + return { + success: true, + loaded: itemSelector ? document.querySelectorAll(itemSelector).length : prev, + metric: itemSelector ? 'itemCount' : 'scrollHeight', + scrolls, + stagnant, + timedOut, + elapsed: Date.now() - startTime, + }; +} + // --------------------------------------------------------------------------- // Keyboard + Console actions // --------------------------------------------------------------------------- diff --git a/mcp-servers/browser-bridge/lib/websocket-bridge.js b/mcp-servers/browser-bridge/lib/websocket-bridge.js index d01da4a..17bf2a1 100644 --- a/mcp-servers/browser-bridge/lib/websocket-bridge.js +++ b/mcp-servers/browser-bridge/lib/websocket-bridge.js @@ -48,7 +48,7 @@ export class WebSocketBridge extends EventEmitter { _onConnection(ws) { const clientId = randomUUID(); - this.browserClients.set(ws, { id: clientId, lastPing: Date.now(), lastAppMsg: Date.now(), connectedAt: Date.now() }); + this.browserClients.set(ws, { id: clientId, lastPing: Date.now(), lastAppMsg: Date.now(), connectedAt: Date.now(), role: 'default' }); // Send connection init this._send(ws, { type: 'connection_init', clientId, serverVersion: '1.0.0' }); @@ -101,6 +101,20 @@ export class WebSocketBridge extends EventEmitter { info.lastAppMsg = Date.now(); } + // Browser client identification — record role so we can pick a single + // canonical target when more than one Chrome has the extension (e.g. the + // user's personal profile AND the always-on keeper). Backward-compatible: + // clients that never send 'hello' keep the default role. + if (msg.type === 'hello') { + const bi = this.browserClients.get(ws); + if (bi) { + bi.role = msg.role === 'keeper' ? 'keeper' : 'default'; + if (msg.clientId) bi.clientId = msg.clientId; + } + log.info('browser_hello', { clientId: bi?.id, role: bi?.role, browsers: this.browserClients.size }); + return; + } + // Handle relay client identification — move from browserClients to relayClients if (msg.type === 'relay_init') { const browserInfo = this.browserClients.get(ws); @@ -155,9 +169,14 @@ export class WebSocketBridge extends EventEmitter { timer, }); - for (const [clientWs] of this.browserClients) { - this._send(clientWs, envelope); + const relayTarget = this._selectTargetClient(); + if (!relayTarget) { + clearTimeout(timer); + this.pendingRequests.delete(browserRequestId); + this._send(ws, { requestId: relayRequestId, error: 'No browser extension connected' }); + return; } + this._send(relayTarget, envelope); return; } @@ -191,6 +210,34 @@ export class WebSocketBridge extends EventEmitter { this.emit('message', msg); } + /** + * Choose the SINGLE browser client that should execute a command when more + * than one is connected. Preference: role 'keeper' over 'default'; tiebreak + * most-recently-connected. Only OPEN sockets are eligible. Returns the chosen + * ws, or null if none are usable. + * + * This replaces the former send-to-ALL broadcast fan-out, which caused every + * connected extension to EXECUTE mutation commands (navigate/click/switch_tab) + * — a real bug once a dedicated keeper Chrome runs alongside the user's + * personal Chrome. With a single client this always returns that client, so + * behavior is unchanged. Failover is automatic and per-command: a dead + * primary is skipped (readyState) or already evicted, and the next command + * re-selects the surviving client. + */ + _selectTargetClient() { + let best = null; + let bestScore = -Infinity; + for (const [ws, info] of this.browserClients) { + if (ws.readyState !== 1 /* OPEN */) continue; + const score = (info.role === 'keeper' ? 1e13 : 0) + (info.connectedAt || 0); + if (score > bestScore) { + bestScore = score; + best = ws; + } + } + return best; + } + /** * Wait up to `timeoutMs` for at least one non-relay browser client to connect. * Resolves immediately if one is already present. @@ -244,9 +291,19 @@ export class WebSocketBridge extends EventEmitter { timer, }); - for (const [ws] of this.browserClients) { - this._send(ws, envelope); + // Single-target dispatch: send only to the elected client (keeper-first), + // never fan out to every connected extension (which double-executed + // mutations on multiple Chromes). + const target = this._selectTargetClient(); + if (!target) { + clearTimeout(timer); + this.pendingRequests.delete(requestId); + const err = new Error('No browser extension connected'); + err.code = 'NO_CLIENT'; + reject(err); + return; } + this._send(target, envelope); }); } diff --git a/mcp-servers/browser-bridge/server.js b/mcp-servers/browser-bridge/server.js index 41e806a..50cfe70 100644 --- a/mcp-servers/browser-bridge/server.js +++ b/mcp-servers/browser-bridge/server.js @@ -22,7 +22,7 @@ import { ReadResourceRequestSchema, } from '@modelcontextprotocol/sdk/types.js'; import { WebSocket } from 'ws'; -import { writeFileSync, mkdirSync, existsSync, unlinkSync } from 'node:fs'; +import { writeFileSync, mkdirSync, existsSync, unlinkSync, readFileSync } from 'node:fs'; import { basename, dirname, join, resolve as pathResolve } from 'node:path'; import { homedir } from 'node:os'; import { execFileSync, execFile } from 'node:child_process'; @@ -135,6 +135,22 @@ class BrowserBridgeServer { required: ['url'], }, }, + { + name: 'browser_load_dynamic', + description: 'Load viewport-gated infinite-scroll / lazy content (e.g. Facebook friends lists, feeds, search results) that will NOT render in a background tab. Briefly foregrounds the target tab, auto-scrolls until the list stops growing, then restores your previously-active tab/window. Optionally navigates first (pass url). After this returns, use browser_extract_data to read the hydrated content. CAUTION: on logged-in personal accounts, sites like Facebook detect automated traversal behaviorally — repeated/rapid list scraping risks security checkpoints or account lockout; use deliberately and sparingly.', + inputSchema: { + type: 'object', + properties: { + url: { type: 'string', description: 'URL to navigate to first (omit to scroll the current tab)' }, + tabId: { type: 'number', description: 'Target tab ID (uses session/active tab if omitted)' }, + containerSelector: { type: 'string', description: 'CSS selector of the scrollable container (omit to scroll the whole page)' }, + itemSelector: { type: 'string', description: 'CSS selector of the repeated list items — used to detect when loading is complete (falls back to scroll height)' }, + waitForSelector: { type: 'string', description: 'CSS selector to wait for before scrolling (e.g. the list container)' }, + maxScrolls: { type: 'number', description: 'Max scroll iterations (default 60, max 500)', default: 60 }, + stableMs: { type: 'number', description: 'Settle time in ms after loading stops (default 1200)', default: 1200 }, + }, + }, + }, { name: 'browser_get_context', description: 'Get the current page context (URL, title, selected text, meta)', @@ -504,6 +520,14 @@ class BrowserBridgeServer { required: ['task'], }, }, + { + name: 'research_queue_status', + description: 'Return the live Perplexity research FIFO queue snapshot (active run, ordered queue with positions, recent runs, stats) so a session can see cross-session serialization state. Reads ~/.claude/council-logs/perplexity-queue.json.', + inputSchema: { + type: 'object', + properties: {}, + }, + }, ], })); @@ -579,6 +603,23 @@ class BrowserBridgeServer { }); } + case 'browser_load_dynamic': { + const url = args.url ? Validator.url(args.url) : undefined; + const tabId = Validator.tabId(args.tabId); + const containerSelector = args.containerSelector ? Validator.selector(args.containerSelector) : undefined; + const itemSelector = args.itemSelector ? Validator.selector(args.itemSelector) : undefined; + const waitForSelector = args.waitForSelector ? Validator.selector(args.waitForSelector) : undefined; + const maxScrolls = args.maxScrolls !== undefined ? Validator.timeout(args.maxScrolls, 1, 500, 60) : undefined; + const stableMs = args.stableMs !== undefined ? Validator.timeout(args.stableMs, 200, 20_000, 1200) : undefined; + return this.bridge.broadcast( + { + type: 'load_dynamic', + payload: this._withSession({ url, tabId, containerSelector, itemSelector, waitForSelector, maxScrolls, stableMs }), + }, + CONFIG.timeouts.fullPage, + ); + } + case 'browser_get_context': { const tabId = Validator.tabId(args.tabId); try { @@ -1214,6 +1255,20 @@ class BrowserBridgeServer { }; } + case 'research_queue_status': { + const queuePath = join(homedir(), '.claude', 'council-logs', 'perplexity-queue.json'); + try { + if (!existsSync(queuePath)) { + return { empty: true, note: 'No research has run through the queue yet (perplexity-queue.json not found).' }; + } + const raw = readFileSync(queuePath, 'utf-8'); + return JSON.parse(raw); + } catch (queueErr) { + log.warn('research_queue_status_failed', { error: queueErr.message }); + return { error: 'snapshot temporarily unavailable, retry' }; + } + } + default: throw new Error(`Unknown tool: ${name}`); } diff --git a/mcp-servers/browser-bridge/test-target-selection.js b/mcp-servers/browser-bridge/test-target-selection.js new file mode 100644 index 0000000..6c1009c --- /dev/null +++ b/mcp-servers/browser-bridge/test-target-selection.js @@ -0,0 +1,98 @@ +/** + * test-target-selection.js — Unit tests for WebSocketBridge._selectTargetClient. + * + * The bridge used to fan every command out to ALL connected browser extensions, + * which meant mutation commands (navigate/click/switch_tab) executed on every + * connected Chrome. Once a dedicated keeper Chrome runs alongside the user's + * personal Chrome, that double-executes. _selectTargetClient() picks ONE target + * (keeper-first, tiebreak newest, OPEN-only). These tests lock that contract. + * + * Run with: node --test test-target-selection.js + */ + +import { describe, it } from 'node:test'; +import assert from 'node:assert/strict'; + +import { WebSocketBridge } from './lib/websocket-bridge.js'; + +const OPEN = 1; +const CLOSING = 2; + +/** Fake ws with a settable readyState. */ +function fakeWs(readyState = OPEN) { + return { readyState }; +} + +function bridgeWith(clients) { + const b = new WebSocketBridge(); + for (const { ws, info } of clients) b.browserClients.set(ws, info); + return b; +} + +describe('_selectTargetClient', () => { + it('returns the sole client when only one is connected (default)', () => { + const ws = fakeWs(); + const b = bridgeWith([{ ws, info: { role: 'default', connectedAt: 100 } }]); + assert.equal(b._selectTargetClient(), ws); + }); + + it('returns the sole client when only one is connected (keeper)', () => { + const ws = fakeWs(); + const b = bridgeWith([{ ws, info: { role: 'keeper', connectedAt: 100 } }]); + assert.equal(b._selectTargetClient(), ws); + }); + + it('prefers the keeper over the default when both are connected', () => { + const personal = fakeWs(); + const keeper = fakeWs(); + // personal connected LATER — keeper must still win on role, not recency. + const b = bridgeWith([ + { ws: personal, info: { role: 'default', connectedAt: 200 } }, + { ws: keeper, info: { role: 'keeper', connectedAt: 100 } }, + ]); + assert.equal(b._selectTargetClient(), keeper); + }); + + it('falls over to the default when the keeper socket is not OPEN', () => { + const personal = fakeWs(OPEN); + const keeper = fakeWs(CLOSING); + const b = bridgeWith([ + { ws: personal, info: { role: 'default', connectedAt: 200 } }, + { ws: keeper, info: { role: 'keeper', connectedAt: 100 } }, + ]); + assert.equal(b._selectTargetClient(), personal); + }); + + it('breaks ties between same-role clients by most-recent connection', () => { + const older = fakeWs(); + const newer = fakeWs(); + const b = bridgeWith([ + { ws: older, info: { role: 'default', connectedAt: 100 } }, + { ws: newer, info: { role: 'default', connectedAt: 300 } }, + ]); + assert.equal(b._selectTargetClient(), newer); + }); + + it('treats a missing role as default', () => { + const noRole = fakeWs(); + const keeper = fakeWs(); + const b = bridgeWith([ + { ws: noRole, info: { connectedAt: 500 } }, // no role field + { ws: keeper, info: { role: 'keeper', connectedAt: 100 } }, + ]); + assert.equal(b._selectTargetClient(), keeper); + }); + + it('returns null when there are no clients', () => { + const b = bridgeWith([]); + assert.equal(b._selectTargetClient(), null); + }); + + it('returns null when every client socket is non-OPEN', () => { + const b = bridgeWith([ + { ws: fakeWs(CLOSING), info: { role: 'keeper', connectedAt: 100 } }, + { ws: fakeWs(CLOSING), info: { role: 'default', connectedAt: 200 } }, + ]); + assert.equal(b._selectTargetClient(), null); + }); +});