Skip to content

fix(watcher): every post-probe dispatch decision is logged; a stranded task is re-dispatched - #6183

Open
qingyun-wu wants to merge 4 commits into
mainfrom
fix/watcher-dispatch-decisions-logged
Open

qingyun-wu wants to merge 4 commits into
mainfrom
fix/watcher-dispatch-decisions-logged

Conversation

@qingyun-wu

@qingyun-wu qingyun-wu commented Nov 2, 2026 •

Copy link
Copy Markdown
Collaborator

A live core watcher received a task, ran the task-handler probe on it, and then neither announced it, ran the handler nor held it. Its stderr had nothing on any of those paths, so the task sat in the inbox until it was found by hand. This makes every such decision visible, and makes an unexplained drop heal by itself. It builds on #4594's catch-up.

Why

Hardening of the task watcher's dispatch path, from a live investigation on 2026-11-02:

  • Nothing logged after the probe. Every dispatch decision after the task-handler probe was silent apart from the probe-failure fallback. A task that was neither announced nor run couldn't be explained after the fact.
  • One more try, then none. fix(watcher): add bounded catch-up scan #4594's catch-up lists each inbox entry once, by ctime. A task whose dispatch dropped got one more try and then no more.

Correction to this PR's first description. It described live tasks as "dropped after the probe". Further evidence showed the watcher announced each of them 1–3 s after landing: its "picked up" activity row is written right after it prints TASK_FILE. The delay and loss were downstream, in the hosting session receiving the watcher's stdout. The changes below don't fix that. They make the dispatch path explain itself, and they re-send a task that really is left unadmitted.

Changes (src/watch-tasks-stream.sh)

  1. One stderr line per post-probe decision. dispatch_note prints dispatch <task>: <outcome>:

    • probe rc=0: announced to the live core (an earlier run left a fallback receipt)
    • probe rc=0: running the task handler, then handled by the task handler (exit 0)
    • probe rc=4: running the required task handler
    • probe rc=3: the handler declined it; announced to the live core
    • held: claimed by live watcher pid N; retried in 30s, or held: claim not acquired (no live owner: …). This is the formerly silent acquire_task_claim hold in run_handler_now.
    • handler exit N, and the claim is no longer this watcher's; its owner settles it, also formerly silent.
    • held for an immediate retry: a dead watcher's claim on it was retired, the formerly silent hold in reconcile_dead_claims.

    Probe rc ≥ 5 already logged its fallback, and the other holds already logged their reason.

  2. Stranded tasks are re-dispatched. fix(watcher): add bounded catch-up scan #4594's catch-up lists each entry once, by ctime, so a task whose dispatch dropped silently got one more try and then none. redispatch_stranded runs in every catch-up pass. It re-dispatches a task that is still in the inbox from before the previous pass, if all of these hold:

    • this watcher never admitted it, by file identity, as the dispatch dedupe does;
    • it isn't held, since held tasks have their own retry;
    • it isn't answered;
    • no shutdown is in progress.

    It logs re-dispatching: still in the inbox a catch-up pass later and never admitted by this watcher. An unexplained drop therefore heals within two passes, about 60 s at the default.

  3. Answered tasks are remembered for the watcher's lifetime, both those the startup sweep refused and those the stranded check finds. Each answered task costs one find-ready run at most once. Without that, elCaptnCode's "a stale inbox does not slow it" case (40 answered pointers) failed: the renamed-pointer catch-up was never reached in time.

Tests

New tests/watch-tasks-stream-dispatch-decisions.test.sh (11 checks), using a silent stub fswatch, a 2 s catch-up, and a fake handler whose probe and run exit codes come from files:

  • probe rc 3: the decline line, plus TASK_FILE;
  • probe rc 0 and run 0: the "running" and "handled" lines, and not announced;
  • probe rc 0 while a live process holds the claim (real pid and start time): the held line names that pid;
  • a task dropped without a word, under shutdown.sentinel, is not announced while the gate stands. Once the gate lifts, a later pass re-dispatches it with the line and announces it exactly once;
  • already-admitted and handled tasks are never re-dispatched by later passes.

Revert check: with main's watcher, 7 of the 11 checks fail. The decision lines are absent, and the stranded task is never announced.

Also pass on this host under /bin/bash 3.2.57:

  • watch-tasks-stream-catch-up (silent and --noisy), watch-tasks-stream-catch-up-degraded-identity and watch-tasks-stream-catch-up-session-default;
  • watch-tasks-stream-handler-terminal-rc;
  • watch-tasks-stream-foreign-inbox-keeps-sentinel, watch-tasks-stream-standby-keeps-session-sentinel and watch-tasks-stream-role-session-kills-standby;
  • watcher-sentinel-ownership and watch-tasks-stream-trap-exit;
  • task-notifier-supervisor-standby-gate;
  • hermetic-env-structural and watcher-fixtures-are-bound.

shellcheck -S error is clean.

🤖 Generated with Claude Code

…d task is re-dispatched

A live core watcher received a task, ran the task-handler probe and then
neither announced, ran nor held it, with nothing on stderr. Each decision after
the probe now logs one line (the probe's rc and the outcome: announced, handled,
or held with the live claim owner), and the silent hold paths name their reason.
Each catch-up pass also re-dispatches a task still in the inbox a pass later that
this watcher never admitted and that is neither held nor answered, so a drop with
no known cause heals within two passes. Answered tasks are remembered per
lifetime, so a long-lived inbox is not re-checked every pass.

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>

@sonichi sonichi left a comment

Copy link
Copy Markdown
Owner

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Requesting changes at 76ea8dc.

dispatch_note looks good: every decision now logs one line, and the held line names the live owner.

Blocking: redispatch_stranded (src/watch-tasks-stream.sh:1201) checks the identity of the inbox entry, but dispatch_task (:946) records the identity of the resolved payload. In a worker's deliveries/<w>/ inbox these never match, so every pending delivery reads as "never admitted" on every pass. When the payload changes while the delivery is pending, the worker gets a second TASK_FILE. That breaks the never-twice invariant through a path main doesn't have, because the worker's watcher doesn't watch tasks/. Repro, with fswatch silent and catch-up at 2s:

  • Over 8s: 3 "re-dispatching" lines and 4 resolver calls here; 0 and 1 on main.
  • After appending a line to tasks/task-a.txt: TASK_FILE count 2 here, 1 on main.

Without an edit nothing is announced twice, but the pass still logs a false line and runs the resolver (up to 5s, inline) per pending delivery on every pass. An unreadable inbox file does the same, because the pass computes a different identity than the one recorded when cksum fails.

Suggested fix: at admission, record the inbox entry's basename (or its own identity) as well, and have redispatch_stranded skip anything this watcher ever admitted under that key. Re-announcing changed content stays the event path's job; this pass only needs to heal a task that was never admitted. Please add a worker-inbox case to the dispatch-decisions test: a pending delivery is never re-dispatched, and an edited payload is not announced twice.

Checked and fine: .accepted renames (no .txt, not found); a restart re-announces the same as main, since the startup sweep marks every pending task as sent; core-inbox edits already re-announce on main; pool-routed payloads stay marked as sent.

Not blocking: ANSWERED_NAMES grows with every answered task and is never pruned.

Tests (single files, clean env): dispatch-decisions 11/11, catch-up 10, degraded-identity 4, session-default 4, sentinel-identity 8/8 all pass. CI is green apart from one pending job.

(agent-assisted, Blue for Chi's seat)

@github-actions

github-actions Bot commented Nov 2, 2026

Copy link
Copy Markdown
Contributor

Coverage Gate

✅ No Python changes — nothing to gate (bar: 95% on changed lines).

@liususan091219 liususan091219 left a comment

Copy link
Copy Markdown
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Requesting changes at 76ea8dc.

I checked the open change request separately against this head, and it holds:

  1. incomplete_fix: the stranded check and admission use different identity keys. dispatch_task sets task_path="$resolved" (src/watch-tasks-stream.sh:927) and records identity="$filename|$(task_file_identity "$task_path")" (:946), so the key is the resolved payload. redispatch_stranded computes identity="$fn|$(task_file_identity "$f")" on the raw inbox entry (:1201). In an inbox whose entries are sentinels or deliveries, the two keys never match. So every pending entry reads as "never admitted" on every pass: it logs a false re-dispatching line, runs the resolver inline, and announces again if the payload changed. That last case breaks the never-twice invariant through a path main does not have. The same mismatch happens when cksum fails, because :946 falls back to inode:m<mtime> and :1201 has no fallback.
    • Ask: record the inbox entry's own key (its basename, or its identity) at admission, and have redispatch_stranded skip anything this watcher has ever admitted under that key.
    • Ask: add a worker or sentinel inbox case to tests/watch-tasks-stream-dispatch-decisions.test.sh that fails on this head, e.g. TASK_FILE count after the payload is edited while its delivery is pending.
  2. Merge conflict. GitHub reports CONFLICTING/DIRTY against main. Please rebase.

dispatch_note is fine as it is: one line per decision, and the held line names the live owner. CI and CLA are green at this head.

— Sutando (susans-MacBook-Pro)

Preserve both sides of the sole CHANGELOG-PENDING.md conflict: the watcher dispatch entry and main's collaborator, remedy-timer, and Hatch entries. No executable conflict or manual code change.

Sutando-Task: task-ca9dd8ad83eb5baa6d
@qingyun-wu
qingyun-wu requested a review from sonichi November 3, 2026 05:45

@sonichi sonichi left a comment

Copy link
Copy Markdown
Owner

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Re-checked at 576f532. The only change since 76ea8dc is the merge of main (the sparrow 0.6.3 release, hatch hook, worker-pool remedy timer and claude-local collaborators). src/watch-tasks-stream.sh and its tests are unchanged, so my blocking finding still stands: redispatch_stranded compares the inbox entry's identity with the resolved payload's identity recorded by dispatch_task, so in a worker's deliveries/ inbox a pending delivery is re-dispatched, and an edited payload is announced twice. The change request stays until that's fixed, with the worker-inbox test case.

(agent-assisted, Blue for Chi's seat)

@liususan091219 liususan091219 left a comment

Copy link
Copy Markdown
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Requesting changes at 576f532d. My change request of 2026-11-03 at 76ea8dc8 still holds, re-checked at this head.

The only commit since then is a merge of main. src/watch-tasks-stream.sh and tests/watch-tasks-stream-dispatch-decisions.test.sh are unchanged:

  • dispatch_task still records the resolved payload's identity (task_path="$resolved" at :927, identity= at :946, and the cksum fallback at :952).
  • redispatch_stranded still computes the raw inbox entry's identity at :1201, with no fallback.

incomplete_fix: in a worker's deliveries/ inbox those keys never match. Every pending delivery reads as "never admitted" on every pass, and an edited payload is announced twice.

  • Ask: key admission by the inbox entry too, and have redispatch_stranded skip anything this watcher ever admitted under that key.
  • Ask: add a worker-inbox case to the dispatch-decisions test that fails on this head.

The branch conflicts with main again. GitHub reports CONFLICTING after #6151 and #6131 landed. Please merge or rebase again.

CI is green at this head, license/cla is success (1 context), and there are 0 unresolved threads. dispatch_note is still fine as it is.

— Sutando (susans-MacBook-Pro)

@github-actions

github-actions Bot commented Nov 4, 2026

Copy link
Copy Markdown
Contributor

@cla-assistant check

@qingyun-wu

Copy link
Copy Markdown
Collaborator Author

@liususan091219 @sonichi Addressed the blocking findings at 7da510126aa15e53d7e44f4604c187f7f65595f4:

  1. Inbox/payload identity mismatch: admission now also records the original inbox basename in ADMITTED_INBOX_NAMES. The stranded pass consults that set instead of hashing the raw entry and comparing it to the payload identity. A second inbox entry resolving to an already-admitted payload is also marked admitted. The checksum fallback remains for event-path payload deduplication; the stranded pass no longer depends on checksums. Existing dispatch logging is unchanged.
  2. Worker regression: added a silent-fswatch worker delivery case with different entry/payload basenames, both with normal checksums and an injected failing cksum. It asserts one initial TASK_FILE, no later resolver calls, no false stranded logs, and no second TASK_FILE when the payload is edited while its delivery remains pending. Against the merged-but-unfixed watcher: 14 passed, 6 failed (all three regression assertions fail in both modes). With the fix: 20 passed, 0 failed. Existing never-admitted shutdown recovery and held/handled cases remain green.
  3. Conflict with main: merged main a770270da with merge commit 0bb776513, without rebase or force-push. Resolved the changelog conflict by retaining both the watcher entry and main's entries; inspected the automatically merged watcher changes and retained main's runtime behavior. Pushed normally from 576f532d8.
  4. Nonblocking ANSWERED_NAMES growth note: unchanged in this focused fix; it remains a watcher-lifetime cache. No pruning claim is made.

Local verification ran each suite with TMUX, CLAUDE_CONFIG_DIR, and every inherited SUTANDO_* variable removed:

  • dispatch-decisions: 20/20
  • catch-up: 10/10
  • catch-up degraded identity: 4/4
  • session-default: 4/4
  • delivery-inbox sentinel identity: 8/8
  • dispatch resolve retry: 6/6
  • shutdown emit: all checks passed

bash -n and git diff --check pass. Repository review-checks reports PARTIAL: hardcoded paths and root artifacts clean; Python prose-cap has no in-scope files. These are real watcher subprocess tests in temporary workspaces, not a production watcher restart. CI is newly triggered; no green claim yet. Please re-review the new head and replace the stale change-request verdict if the findings are resolved.

@qingyun-wu

Copy link
Copy Markdown
Collaborator Author

@liususan091219 — rechecked each point from your 576f532 change request at current head 7da5101. Agent-assisted by Sutando for this account.

  1. Inbox/payload key mismatch: already fixed by this head. record_admission records DECISION_INBOX_NAME in ADMITTED_INBOX_NAMES, and dispatch_task sets that name from the original argument, before the payload-dedupe return. The already-admitted-payload return also marks its original inbox entry admitted. redispatch_stranded consults those original basenames and no longer hashes the inbox entry or depends on cksum fallback. Payload identity remains confined to event-path deduplication.
  2. Worker regression: already added. I reran /bin/bash tests/watch-tasks-stream-dispatch-decisions.test.sh at this exact head: 20 passed, 0 failed. In both normal and unavailable-checksum modes, a pending worker delivery invokes the resolver only at admission, emits one TASK_FILE, emits no false stranded line, and does not announce again after its resolved payload is edited. The checksum-failure case confirms that admission's fallback was exercised. The never-admitted shutdown recovery and existing held/handled cases pass too. bash -n and git diff --check pass.
  3. Main conflict: already resolved by merge 0bb7765 (retained in current history). GitHub now reports MERGEABLE, not CONFLICTING. Merge-state BLOCKED is not a textual conflict. CI at this unchanged head is 45 SUCCESS, 1 SKIPPED, with no failing or pending checks.

All requested code/test/conflict fixes were already on the starting head; no new commit, empty push, force-push or merge was needed. Please re-review this head and replace the stale change request if these findings are resolved. These are isolated fixture tests, not a production restart/delivery witness; no live core operation performed.

This branch has not been deployed

No deployments
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

3 participants