--- slug: echo-gate-poll-exit-sentinel-triad status: partially-resolved created: 2026-05-24T10:49:18Z updated: 2026-05-25T18:00:00Z trigger: user-report goal: find_and_fix tdd_mode: false --- # Debug Session: ECHO gate / poll-exit / sentinel detection triad ## Symptoms User reports three related symptoms in the echo-commune / ECHO gate / poll-exit machinery. All evidence is in real log files (lines quoted exact in user report). ### Symptom 1 — ECHO gate opens but Psyche never awoken with commune output - **Log:** `C:\Users\decid\AppData\Local\spt\logs_latest\ling.log` - **Bad cases:** line 127, line 152 — ECHO gate fires, no Psyche wake follows - **Good case for comparison:** line 68 — ECHO gate fires AND Psyche IS awoken ### Symptom 2 — poll-exit error path: 3 loops then wrapper self-terminates - **Log A:** `C:\Users\decid\AppData\Local\spt\logs_latest\ling.log` line 164 - **Log B:** `C:\Users\decid\AppData\Local\spt\logs_latest\todlando.log` line 300 ### Symptom 3 — ECHO gate repeatedly reports "no sentinel" during active session - **Log:** `C:\Users\decid\AppData\Local\spt\logs_latest\todlando.log` - **Range:** line 232 to end of file (~80+ minutes wall time) ## Evidence ### Symptom 1 — bad vs good frame headers GOOD (ling.log:63 → wake at line 68): ``` ECHO_COMMUNE ... self_session=0690a7a8-9b1d-... exit=0 stdout_bytes=2768 excerpt_bytes=43967 excerpt_lines=21 ... ``` → next poll: `poll returned 1957 bytes` → `[MSG] from=}` info.json instead of the full `InfoJson`. Stripping `session_id` / `owl_id` / `parent_pid` / `state` stops the cross-session `OWL_SESSION_ID` inheritance leak documented in `src/owl/cleanup.rs::run` (lines 76-86). `src/common/types.rs::get_pid_from_info` and `get_parent_pid_from_info` were migrated from typed `InfoJson` deserialization to `serde_json::Value::get(...)` so the new minimal shape parses cleanly. Legacy full-shape info.json files continue to parse identically. ### Cycle-3 conclusion on Symptom 1 / Bug 1 user-directed wrong-perch fix **No code change applied for the user-directed "wrong perch read/write" hypothesis** — neither the grep audit (`grep -rn "info_file" src/owl src/live src/common`) nor the on-disk evidence supports a regression where one perch's info.json is read / written in place of another's. Every production reader of `info_file(self_id)` resolves to the FLAT Self path; every production reader of psyche info.json resolves through `resolve_info_file` with `ParentHint::Explicit(self_id)` to the NESTED path. Each is correct. The observed `self_session` UUID flap is best explained by two foreground Claude windows racing `refresh_info_json_session_id`, not by a wrong-perch bug. A possible follow-up fix lives at `src/common/hook_output.rs::find_perch_by_session` — its parent_pid fallback unconditionally `patch_session_id`s any matching perch, which makes Self's `info.session_id` non-monotonic across concurrent Claude windows. Fixing it would require either (a) refusing to patch when the existing session_id is still active in another Claude window, or (b) widening Self's session_id field to a set of "currently-attached sessions." Either is structural and out of scope for this debug session. **Important secondary effect of Bug 2 fix:** with the psyche perch's info.json now carrying no session_id, the cleanup.rs `state == Psyche` skip becomes redundant-but-harmless (the `session_id` substring search the function uses can no longer match a wrapper-owned psyche perch). Bug 3 (signoff stamp) is structurally moot for the same reason. ### Sub-question from user > "Why would it be checking for psyche's PID presence during a point in > time where it has no business spawning the psyche?" Answer: the wrapper is NOT spawning the psyche LLM here — the inner `owl poll listen --psyche --parent --once` subprocess is spawned EVERY wrapper iteration as the message-listener for the psyche perch, completely independent of whether the psyche claude session itself is being resumed. The "psyche respawning" framing is wrong — this is just the wrapper's normal per-iteration message-drain cycle, which happens to re-enter `poll::run` and therefore re-run the DUPLICATE guard each time. The fix (skip DUPLICATE guard for own psyche) closes the symptom by removing the spurious guard rather than by suppressing the per-iteration spawn (which is structurally required for message delivery). ### Symptom 3 status post-Bug-2 fix S3 (sentinel-absent loop) was NOT directly addressed by the Bug 2 fix. Per cycle-2 hypothesis H3-v2, the most likely cause was tied to S1 (Self session_id drift) — and since the structural source of that drift (concurrent Claude windows patching info.json) was not addressed, S3 remains possible in future sessions. However, Bug 2's wrapper-survival fix means the wrapper no longer dies after ~95 minutes of sentinel-absent loops, so even if S3 recurs the wrapper will continue to fire on the next legitimate Stop event. ## Resolution | Bug | Status | Commit | |---|---|---| | Bug 1 (wrong-perch read/write) | NOT REPRODUCED — see Cycle-3 conclusion above | — | | Bug 2 (DUPLICATE storm + schema-shrink) | FIXED | `fix(poll): wrapper-owned psyche skips DUPLICATE guard + writes minimal info.json` | | Bug 3 (signoff stamp) | STRUCTURALLY MOOT post-Bug-2 | — (covered by Bug 2) | Session status set to `partially-resolved`: Bug 2 ships; Bug 1's structural follow-up (multi-Claude-window race on `patch_session_id`) is documented above and deferred per user instruction (no version bump, no deploy this round). ## Cycle 4 — "fix did not work" re-report (2026-05-25): DEPLOY GAP, not regression **User re-report:** `doyle.log:75` — wrapper hit the identical DUPLICATE storm and self-terminated. "Previous fix apparently did not work." **Verdict: the Bug-2 fix is correct and was never the problem in Cycle 4 — doyle ran a binary built two hours BEFORE the fix commit.** Pure deploy timing artifact. No code change required. ### Evidence Source confirmed correct (fix present, not regressed): - `src/owl/poll.rs:140` — `let wrapper_owned_psyche = psyche && parent.is_some();` and line 141 guard excludes it. Intact. - `src/live/wrapper/mod.rs:1527-1540` — inner poll argv passes `poll listen --psyche --parent ...`, so at the failing call site `psyche=true && parent=Some` → `wrapper_owned_psyche=true` → guard bypassed. Unit test `poll_psyche_argv_contains_once_flag` (mod.rs:2372) asserts `--parent` at args[4]. (H2 "argv missing --parent" REJECTED.) Binary timeline (the actual root cause): | Artifact | Built / committed | Contains Bug-2 fix? | |---|---|---| | fix commit `6342852` | 2026-05-24 **05:47:51** | — (source of fix) | | deployed `spt/1.11.15/owl.exe` | 2026-05-24 **03:36:32** | **NO** — 2h older than fix | | deployed `spt/1.11.16/owl.exe` | 2026-05-25 **19:04:18** | YES (`6342852` is ancestor of HEAD) | doyle gen=7 launched 2026-05-25 **17:15:58**, stormed + died **17:40:44** — both BEFORE 1.11.16 was built (19:04). So doyle ran **1.11.15**, whose binary predates the fix by two hours. The fix had been committed but the binary was not rebuilt/redeployed until 1.11.16 today, *after* doyle was already dead. Active version now (`installed_plugins.json`) = **1.11.16** → the next doyle launch picks up the guard-bypass. Bug 2 is closed in the running binary as of the 1.11.16 deploy. ### Cycle-4 conclusion on Symptom 2 / Bug 2 | Bug | Status | Resolution | |---|---|---| | Bug 2 (DUPLICATE storm) | RESOLVED IN DEPLOYED BINARY | Fix `6342852` correct; reached the runtime only via the 1.11.16 deploy (2026-05-25 19:04). 1.11.15 (doyle's binary) predated the fix. | **No further code change.** Empirical confirmation pending: relaunch a live agent on 1.11.16 and confirm the wrapper survives a DUPLICATE-pid poll exit without incrementing `consecutive_empty`.