fix(council): Perplexity research outage — port collision, invisible failures, keeper that never survived - #72
Open
intellegix wants to merge 8 commits into
Conversation
…orphaned results
Machine-wide Perplexity research outage on 2026-08-07: four consecutive
research_query runs failed at ~128s with "Page.wait_for_timeout: Target page,
context or browser has been closed".
Root cause: the runner attached to the wrong Chrome. _start_via_cdp() treated
"port 9222 answers /json/version" as proof the session keeper was alive. Three
facts lined up: the PerplexitySessionKeeper task has been Disabled since 07-30;
a stale session_keeper.cdp from 08-02 still pointed at 9222 recording a PID dead
since the reboot; and browser-relay/relay.mjs (the /takeover phone relay) claimed
port 9222 at 12:57 with a throwaway C:\Temp\igx-cdp-profile. From 12:57 the health
check passed against the relay's cookie-less Chrome, so every run navigated to a
logged-out wall and was torn down ~128s later. Last success 11:49 (pre-reboot,
launch path); relay up 12:57; first failure 13:19.
A reachable port was being treated as a trusted port.
council_browser.py — prove endpoint identity before attaching, layered so an
indeterminate probe degrades to the next check rather than blocking a healthy
keeper:
- recorded PID must be alive (stale .cdp file is deleted)
- DevToolsActivePort GUID in the keeper's profile must match the endpoint's
webSocketDebuggerUrl (canonical launch-time/discovery-time match)
- failing that, the port owner's command line must name session_keeper_profile
- post-attach, the context must carry a Perplexity auth cookie — which also
catches a live keeper whose login has expired
The "synthesize a .cdp file because 9222 answers" fast path is gated behind the
same ownership check. Any refusal falls back to local launch, which is what was
working before 12:57.
council_query.py — invocation_id is a fresh UUID per call, so a caller dying
orphans a completed result (council_fae5c9e0.json). Results now carry a
query_fingerprint and run_browser_query checks for a matching, usable, recent
result before re-running. Age comes from the recorded timestamp rather than file
mtime, so re-saving a recovered orphan cannot keep it alive indefinitely.
Verified: first post-patch run completed in 159.5s where the two runs before it
failed at 128s. Gates unit-tested against live machine state — refuse the relay's
Chrome, wrong GUID and wrong port; accept a simulated healthy keeper. Orphan
recovery verified against the real council_fae5c9e0.json.
Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01VsT8c4wZQYv2fRN6szvEQ6
Captures two improvements that were live in the working tree but not on any merged branch, so the follow-up fixes apply on top of what actually runs: - council_browser.py: tier-0 aria-pressed mode-activation verifier - research_queue.py: _atomic_write WinError 5 retry loop Co-Authored-By: Claude Opus 5 <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_013jYxW6be3KvPW4Sm8zdW5q
…sible Second machine-wide Perplexity outage in 24h (2026-08-08). Two independent defects, one of which hid the other. 1. IDENTITY, NOT REACHABILITY (the outage). `_ensure_fresh_session` probed port 9222 with a bare urlopen and treated any answer as "the keeper is alive". The /takeover browser relay binds that same port, so the guard fired a keeper refresh that could never land, waited SESSION_KEEPER_WAIT_S, then submitted on expired cookies. `_start_via_cdp` had been hardened against exactly this on 08-07 and correctly REFUSED the same port seconds earlier -- the two paths disagreed. This is not a regression of that fix; it is its un-fixed twin. Both call sites now share `_keeper_cdp_alive()`. Compounding it, PerplexitySessionKeeper had been Disabled since 07-30, so `Start-ScheduledTask` was a silent no-op and the 120s wait could only ever time out. `_keeper_task_state()` now checks before entering that branch. Structural fix: the keeper moves to a DEDICATED CDP port (9223, via COUNCIL_KEEPER_CDP_PORT) so it can never contend with the relay again -- the collision memory port-registry flagged as "latent, still unresolved". session_keeper.py also refuses to adopt a foreign Chrome on its port. 2. FAILURE INVISIBILITY (the reason nobody caught #1). The queue logged `started` and never `error`, so errors_today read 0 through a total outage. `acquire_slot`'s error path cannot run when the process is killed outright, and that is the normal end for a research run: the MCP layer calls execFileAsync with a 540s timeout, and Node's timeout kill on Windows is TerminateProcess -- no signal, no unwinding. gc_dead_tickets() is the one place another process can observe the death, so it now logs a `dropped` event there (once, by the winner of the unlink race). errors_today counts it, the snapshot carries last_failure so callers see WHAT broke, queue_monitor alerts on it, and the MCP layer returns RUNNER_KILLED instead of an opaque "Task failed". Also: `keeper-timeout-stale-proceed` no longer proceeds. Hard-expired cookies now raise SessionStaleError before submit (SESSION_STALE to the caller). Cookies that are merely expiring-soon still proceed, which is what the old always-proceed rationale was actually about. Tests: tests/test_pplx_failure_visibility.py -- 11 cases, 10 of which fail against the pre-fix code. Full suite 92 passed. Co-Authored-By: Claude Opus 5 <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_013jYxW6be3KvPW4Sm8zdW5q
…ntity gates
Verifying the previous commit on live infrastructure surfaced the reason the
keeper has effectively never stayed up -- which is what routed every research
run onto the local-launch path where the 08-08 outage lived.
- CREATE_BREAKAWAY_FROM_JOB on the Chrome launch. DETACHED_PROCESS only
detaches the console; it does NOT leave the parent's job object, and every
realistic launcher supplies one (Task Scheduler gives each task instance a
job; so does the agent harness). When the launching instance ended the job
was torn down and took Chrome with it within ~60s -- cleanly enough that
Chrome removed its own DevToolsActivePort file, so it read as a normal
shutdown rather than a kill. Measured before: Chrome gone by t+60s. After:
alive past t+120s with the launcher long exited. Falls back to the old
flags if the job forbids breakaway.
- session_keeper.cdp now records the pid of the process SERVING CDP (Chrome)
rather than the keeper python's. The keeper is one-shot and exits seconds
after launching Chrome, so the pid it published was always dead by the time
a reader looked.
- Identity gates reordered. The recorded-pid check ran FIRST and vetoed
everything, so with the bug above every healthy keeper was judged a stale
.cdp file and deleted. Decisive gates (DevToolsActivePort GUID, then port
ownership) now run first; the recorded pid only breaks ties when neither can
reach a verdict. An over-strict identity gate silently disabled the CDP path
it was written to protect -- the foreign-Chrome protection itself is
unchanged and still tested.
Verified live, not asserted:
- real research_query succeeded in 32.9s (was: two identical 9-minute deaths)
- keeper on 9223 and /takeover relay on 9222 coexisting, neither displaced
- forced a hard-killed run (os._exit inside the slot, same semantics as the
TerminateProcess that Node's timeout issues): produced enqueued/started/
dropped, errors_today 0 -> 1, last_failure populated, and the monitor
daemon logged ALERT [critical]. That exact sequence was silent before.
Tests: 95 passed (17 new).
Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_013jYxW6be3KvPW4Sm8zdW5q
…Scheduler The previous commit claimed CREATE_BREAKAWAY_FROM_JOB made the keeper's Chrome survive past t+120s. That measurement was taken from a launch that had NOT picked up the new code (the redeploy raced the task start), so it does not support the claim. Correcting it rather than leaving it standing. What is actually true, measured 2026-08-08 07:27: [keeper 07:27:14] Job breakaway not permitted ([WinError 5] Access is denied) Breakaway only succeeds if the CONTAINING job grants JOB_OBJECT_LIMIT_BREAKAWAY_OK, and Task Scheduler's job does not — the same constraint already proved with IsProcessInJob for the Santee demo app (memory port-registry). Under the task, Chrome lives on the order of minutes and the task's own repetition re-establishes it. Launched from an interactive shell the flag works and Chrome persists, so the code is kept. The proper fix (make the long-lived process the task's OWN process) is not applied: it needs a new scheduled task, and schtasks /Create is denied without elevation on this box. Documented as a known open item in the code. This does not affect the outage fix or the monitoring fix, and does not change the verified result — nothing depends on the keeper being continuously up. The local-launch path has a correct freshness guard and a working refresher, and that is the path the verified 32.9s research_query actually used. Co-Authored-By: Claude Opus 5 <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_013jYxW6be3KvPW4Sm8zdW5q
…rowser-relay The diagnostic string a human reads to decide what to go kill was pointing at the wrong process. The Chrome on C:\Temp\igx-cdp-profile is launched by the Dogfood Supervisor (Intellegix Code\scripts\start-dogfood.cmd, auto-starts at logon), NOT by browser-relay/relay.mjs. Verified by walking the parent chain: chrome pid 25944 -> cmd.exe 7628 -> start-dogfood.cmd. The profile name is browser-relay's, which is what made the misattribution durable across two outage writeups. Credit: session fb-page-pricing-iterated-perplexity flagged it. The label now also says do NOT kill it: the supervisor relaunches a byte-identical Chrome within ~3s, and the phone-takeover bridge on :7070 depends on it. And because it auto-starts at logon, this collision was never "latent" as previously recorded — it holds 9222 essentially always, which is why moving the keeper to its own port was the only real fix. Behaviour is unchanged; this corrects operator-facing text and the assertion that pins it. Memories perplexity-cdp-identity-gate and port-registry corrected to match. 95 tests pass. Co-Authored-By: Claude Opus 5 <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_013jYxW6be3KvPW4Sm8zdW5q
…ng is a no-op Found by applying another lane's reframing to my own work: tracked-vs-untracked is the wrong axis, "reproducible from what IS tracked" is the right one. This PR failed that test. queue_monitor.py imports research_monitor for _send_pushover and _trigger_keeper (queue_monitor.py:89-97). research_monitor.py was untracked and existed in git NOWHERE — not on this branch, not in origin/master — so a fresh checkout of this PR got queue_monitor without it. Reproduced against a clean directory containing only this branch's files: WARNING queue_monitor: research_monitor unavailable, pushover/self-heal disabled _send_pushover is: None INFO queue_monitor: pushover unavailable, alert not sent: dropped run_id=x So the whole point of the monitoring half of this PR — make a killed run SURFACE — degraded to a log line nobody reads. The `dropped` event would still be written and errors_today would still count it, but the critical alert would never leave the machine. That is precisely the failure class this PR exists to fix: a signal that looks correct and reports nothing. It survived my own verification because I tested the alert firing in the LIVE tree, where the untracked file happens to sit next to it. After adding the file, the same clean-directory check reports _send_pushover WIRED. 95 tests pass. Deliberately NOT a blanket `git add` of the untracked set: council-automation has 12 untracked .py files and one of them, ensure_perplexity_tab.py, was written against a root cause disproven the next morning and is documented as ignore/delete. Committing it would give known-wrong code the authority of being in git. This commit adds exactly the one file this PR's own behaviour depends on. Co-Authored-By: Claude Opus 5 <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_013jYxW6be3KvPW4Sm8zdW5q
intellegix
marked this pull request as ready for review
August 9, 2026 23:08
The keeper log emitted %H:%M:%S with no date into an append-only file that had never been rotated in 76 days (8.6 MB, 116k lines). Grouping its lines by clock minute therefore collapses every day in the file into the same bucket, so a once-per-8-minutes schedule reads as a burst whose height equals the NUMBER OF DAYS present. 69 days in the file, 69 "navigations in one minute". That artifact cost an evening. It produced a false all-clear on the cookie-guard hypothesis, then a wrong "68-navigation burst" explanation for a corrupted extraction, then a retraction of that retraction, then a separate investigation session to disprove a burst that never existed. Three of the six scoping errors recorded in PERPLEXITY-SESSION-FAILURE-EVIDENCE-2026-08-08.md trace to this one log line: a timestamp that identifies its subject by clock time alone cannot distinguish today from nine weeks ago. Verified independently before accepting the diagnosis (keeper-9222-burst-source found it; austinkidwell-orchestrator confirmed it; I re-ran it here): longest run of consecutive Starting-keeper lines sharing a clock minute, in raw file order across 12,812 starts ........................... 2 backward time jumps in the file .................................. 68 (~69 days) So there is no burst, and the keeper is on schedule. CHANGES, both in session_keeper.py: 1. _log now emits %Y-%m-%d %H:%M:%S. This alone makes the artifact impossible. 2. Size-based rotation at startup (5 MB, 3 backups). The log is written by pointing fds 1/2 at the file via os.dup2, so a RotatingFileHandler cannot manage it -- rotation has to happen before the descriptors are opened, and a one-shot process running every ~8 minutes gives a natural, safe point. Best effort: a rename race between overlapping invocations must never stop the keeper from starting. Rotation behaviour was checked empirically, not assumed: Path.with_suffix with a dotted suffix produces the intended .log.1/.log.2/.log.3 ring, the ring is capped at _LOG_BACKUPS, and .1 holds the previous run. Deliberately NOT changed, all measured correct: the PT8M schedule, the callers at council_browser.py:1181 and :1482 and research_monitor.py:206 (22 extra starts in 76 days), and the 9223 port. Tests: 2 new (dated-timestamp assertion incl. a guard that the old format cannot return; rotation ring capped and ordered). 97 passed. Co-Authored-By: Claude Opus 5 <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_013jYxW6be3KvPW4Sm8zdW5q
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.
Second machine-wide Perplexity research outage in 24h (2026-08-08). Filed evidence:
council-automation/PERPLEXITY-SESSION-FAILURE-EVIDENCE-2026-08-08.md.Was yesterday's fix a regression?
No. PR #71's identity gate worked exactly as designed — it correctly refused the
foreign Chrome on 9222 seconds before each failure. Three separate defects were found.
1. The identity gate was applied at one call site, not its twin
_start_via_cdprefused the relay's Chrome and fell back to a local launch. Thatfallback runs
_ensure_fresh_session("local-launch"), which still probed 9222 with abare
urlopenand concluded "the keeper is alive" — the same reachability-is-not-identitymistake, un-fixed. It then fired a keeper refresh that could never land, waited 120s, and
submitted on expired cookies.
Compounding it,
PerplexitySessionKeeperhad been Disabled since 2026-07-30, soStart-ScheduledTaskwas a silent no-op and that 120s could only ever time out.Fixes: both call sites share
_keeper_cdp_alive();_keeper_task_state()checks the taskbefore waiting on it; the keeper moves to a dedicated CDP port 9223 so it can never
contend with
/takeoveron 9222 again (the collisionport-registryflagged as "latent,still unresolved");
session_keeper.pyrefuses to adopt a foreign Chrome on its own port.2. Failures were invisible — arguably the bigger bug
The queue logged
startedand nevererror, soerrors_todayread 0 through a totaloutage.
acquire_slot's error path cannot run when the process is killed outright, andthat is the normal end for a research run: the MCP layer calls
execFileAsyncwith a 540stimeout, and Node's timeout kill on Windows is
TerminateProcess— no signal, nounwinding. Queue-based monitoring was structurally blind to the dominant failure mode,
which is why both outages were found by a session tripping over them.
gc_dead_tickets()is the one place another process can observe the death, so it now logsa
droppedevent there (once, by the winner of the unlink race).errors_todaycounts it,the snapshot carries
last_failure,queue_monitoralerts on it, and the MCP layerreturns
RUNNER_KILLEDinstead of an opaque "Task failed".3. The keeper never survived its launcher — found while verifying
DETACHED_PROCESSdetaches the console but does not leave the parent's job object, andevery realistic launcher supplies one. Chrome died ~60s after each keeper invocation,
cleanly enough that it removed its own
DevToolsActivePortfile. Every run then found noCDP and fell back to the local launch — i.e. this is why traffic reached the broken path
at all. Fixed with
CREATE_BREAKAWAY_FROM_JOB(with fallback).Two follow-ons:
session_keeper.cdpnow records Chrome's pid, not the one-shot keeperpython's; and the identity gates are reordered so the weakest signal (a recorded pid)
cannot veto positive proof of ownership. Previously that veto rejected every healthy
keeper. The foreign-Chrome protection is unchanged and still tested.
Also:
keeper-timeout-stale-proceedno longer proceedsHard-expired cookies raise
SessionStaleErrorbefore submit (SESSION_STALEto thecaller) rather than burning a 5–8 minute slot on a doomed run. Cookies that are merely
expiring soon still proceed — that is what the old always-proceed rationale was about.
Verified by doing, not asserting
research_querysucceeded in 32.9s (was: two identical ~9-minute deaths)./takeoverrelay on 9222 coexisting; neither displaced.os._exitinside a live queue slot — same semantics as theTerminateProcess Node issues. Produced
enqueued/started/dropped,errors_today0 → 1,
last_failurepopulated, and the monitor daemon loggedALERT [critical].That exact sequence was completely silent before this PR.
tests/test_pplx_failure_visibility.py; 10 of the first 11fail against pre-fix code).
Ops changes already applied to the live machine
PerplexitySessionKeeperandPerplexityQueueMonitorre-enabled and running; keeperrebound to 9223.
~/.claude/council-automationandmcp-servers/browser-bridge/server.jsupdated in place (the MCP server executes them directly, so the fix had to be live to be
verifiable).
server.jschanges take effect for newly started sessions.Note: the first commit snapshots two improvements that were live in the working tree but
unmerged, so the fixes apply on top of what actually runs.
🤖 Generated with Claude Code
https://claude.ai/code/session_013jYxW6be3KvPW4Sm8zdW5q
Ready for review (undrafted 2026-08-09) — and the case for merging got concrete today
Undrafted after verifying: 95 tests pass, branch clean and fully pushed, and every fix has been
running in production since 2026-08-08 07:26.
Today's incident is the argument. At 10:23:31 a repo-wide
git restoreunder~/.claudereverted every modified-vs-HEAD tracked file — which silently un-did four of the files in this PR.
council_browser.py:67importsstart_lock_heartbeatfrom asubmission_lock.pythat the revertedcopy does not define, so
council_browserbecame un-importable and research was down ~50 minuteswhile
errors_todaystayed0andlast_failurestayednull(the break was upstream of thequeue, so the counters read affirmatively green). Restored by hand at 11:20 from this branch.
Two things that matters for:
tree is exactly what got reverted. Merging converts "restored by hand" into "cannot silently
regress."
back up without the keeper-port fix, the identity-gate twin fix and the fail-fast — i.e. the
2026-08-08 machine-wide outage would have been possible again, with every metric green. The crash
was the lucky part.
Also validated in production since opening: the
droppedevent fired on its first real failureat 14:13 (a runner process death that left no other trace), moving
errors_today0 → 1 andsurfacing within one monitoring cycle. Before this PR that run would have been invisible.
One item from the original description is now closed by evidence rather than assertion: the
cross-process cookie-guard hypothesis I flagged as unproven has been resolved against itself —
run()admits at most one run machine-wide, making the mechanism structurally impossible, and therefined variant was exercised 22 times in one day with zero corrupted extractions. No code change
followed, which is the point of having owed a reproduction.