From 123dca47bb82ee1bde92ab10ecaff678dcb20cce Mon Sep 17 00:00:00 2001 From: Godopu Date: Tue, 22 Sep 2026 04:28:08 +0000 Subject: [PATCH] fix(issue-23): onboarding delivery is judged by the agent's own started event, and a rollback verifies the kill Plan commits 3 and 4 landed together: both rewrite the same region of create_session.sh and share one test file, and splitting them afterwards would have meant hunk-level surgery on already-verified code. Delivery verdict (item 3). create_session --onboard called a healthy agent a failure three seconds after registering the job: inject_instructions -> send_keys_safe returns rc 4 when `agent prompt --wait --until working` fails and the pane is still not working two seconds later, which is exactly where a TUI that is still starting up lands. It never got the ISSUE-18 confirmation the delegate-job wrapper has. rc 4 is a warning now and the agent's own `started` decides, within the job's own ack timeout; rc 1/2/3 stay hard failures, since they say the pane never quiesced, a dialog was blocking, or the text never appeared, and no later `started` repairs those. The self-published `started` had to go first. create_session published it on the agent's behalf right after injection, so the registry showed a started job whether or not the agent ever saw the prompt - with that line in place, no started-based verdict can mean anything. delegate_wait_started is lib.sh's counterpart to the wrapper's _wait_started (plan item D10-b). The wrapper's own `submit` was the first choice, but it blocks until the job reaches a terminal state, and create_session must return as soon as delivery is confirmed; the on-disk evidence it reads - registry status past `pending`, or a started line carrying this dispatch token - is written by publish_event before its wire publish, so no broker is involved. Rollback integrity (item 4). The trap ran `_herdr kill-session -t "$SESSION_NAME" 2>/dev/null || true`, so a kill that closed nothing still printed "rolling back" while the session kept running, and the row stayed `running` pointing at the job the same rollback had just failed (#23 symptom 5). With item 1 in place this check is finally trustworthy: the kill used to fail because the caller's workspace id hid the pane. The trap now reads the kill's rc, confirms with has-session, closes the onboarding job as `cancelled` (a terminal transition the registry knows, and the truthful one - the job was never dispatched), and marks the row. A session still alive exits 43 with the manual cleanup command, distinct from 42 (TUI never ready). The row keeps a schema-valid status rather than the plan's `error`, which atomic_yaml.py rejects: `terminated` once the session is really gone, and `running` when the kill failed, because it is still running. What makes that case legible is the note, the cleared delegate_job_id and exit 43 - not a status claiming the opposite of the truth. The row is never deleted; a deleted row takes the evidence with it. Co-Authored-By: Claude Opus 5 --- .agents/skills/lib.sh | 49 ++++ .../scripts/create_session.sh | 83 ++++++- tests/test_issue23_24_startup_path.py | 221 ++++++++++++++++++ 3 files changed, 346 insertions(+), 7 deletions(-) diff --git a/.agents/skills/lib.sh b/.agents/skills/lib.sh index d3b5920..63ced3d 100644 --- a/.agents/skills/lib.sh +++ b/.agents/skills/lib.sh @@ -2131,6 +2131,55 @@ delegate_publish_event() { _delegation_py publish --job "$job_id" --event "$event" --detail "$detail" ${extra[@]+"${extra[@]}"} || true } +# delegate_wait_started [ack_timeout_s] [dispatch_token] +# +# ISSUE-23 / ISSUE-18: delivery is confirmed by the protocol, not by the +# screen. `agent prompt --wait --until working` failing two seconds after the +# keys were handed over says nothing about a TUI that is still starting up - +# that is exactly what made create_session --onboard call a healthy agent a +# failure. The evidence is the agent's own `started`: the registry record +# leaves `pending` (publish_event syncs it on this host) or a matching started +# line lands in the job's events.log, which publish_event writes before its +# wire publish so a slow broker cannot delay the verdict. +# +# Returns 0 on that evidence, 1 if neither appeared within T. Never re-injects: +# the single-injection contract is fail-closed. +delegate_wait_started() { + local job_id="$1" ack_s="${2:-180}" tok="${3:-}" + [ -n "$job_id" ] || return 1 + local reg_dir="${MAM_JOBS_DIR:-${WORKSPACE_ROOT:-$PWD}/.mam/jobs}" + local rec="$reg_dir/$job_id.json" + local ev_log="$reg_dir/$job_id.events.log" + local started_re='"event": *"started"' + if [ -n "$tok" ]; then + started_re='"event": *"started".*"dispatch_token": *"'"$tok"'"' + fi + local deadline st + deadline=$(( $(date +%s) + ack_s )) + while :; do + st="" + if [ -f "$rec" ]; then + st=$(REC="$rec" python3 -c " +import json, os +try: + print(json.load(open(os.environ['REC'])).get('status', '') or '') +except Exception: + print('') +" 2>/dev/null || true) + fi + if [ -n "$st" ] && [ "$st" != "pending" ]; then + return 0 + fi + if [ -f "$ev_log" ] && grep -Eq "$started_re" "$ev_log" 2>/dev/null; then + return 0 + fi + if [ "$(date +%s)" -ge "$deadline" ]; then + return 1 + fi + sleep 1 + done +} + # ensure_subscriber_daemon [workdir] # Start the monitor subscriber for this workspace unless one is already running. # Prints the PID(s) on stdout, exactly as start_watchdog always did. diff --git a/.agents/skills/multi-agent-mux-create/scripts/create_session.sh b/.agents/skills/multi-agent-mux-create/scripts/create_session.sh index de59d5f..9d8360e 100755 --- a/.agents/skills/multi-agent-mux-create/scripts/create_session.sh +++ b/.agents/skills/multi-agent-mux-create/scripts/create_session.sh @@ -283,13 +283,63 @@ NOW_ISO=$(date -u +'%Y-%m-%dT%H:%M:%SZ') spawn +# _mark_row_rolled_back +# ISSUE-23: the YAML row and the job registration are both written before the +# prompt is injected, so a rollback that only kills the pane leaves a row that +# says `running` pointing at a failed job - which is what status.sh keeps +# reporting (symptom 5). Mark the row instead of deleting it: a deleted row +# takes the evidence with it. +# +# stays inside the schema's vocabulary (running/terminated/archived/ +# stopped - atomic_yaml.py rejects anything else): `terminated` when the +# session is really gone, and `running` when the kill failed, because it IS +# still running and saying otherwise would be the same lie in reverse. What +# makes the failed case legible is the note, the cleared job id and exit 43. +_mark_row_rolled_back() { + local status="$1" note="$2" + [ "${ROW_APPENDED:-0}" = "1" ] || return 0 + atomic_dump_yaml "$AGENT_SESSIONS_YAML" \ + SESSION_NAME="$SESSION_NAME" ROLLBACK_STATUS="$status" ROLLBACK_NOTE="$note" <<'PYEOF' || true +name = os.environ['SESSION_NAME'] +status = os.environ['ROLLBACK_STATUS'] +note = os.environ['ROLLBACK_NOTE'] +for s in d.get('herdr_sessions', []): + if s.get('name') == name: + s['status'] = status + s['last_visible_status'] = note + s['delegate_job_id'] = None + break +PYEOF +} + # Trap for rolling back/cleaning up herdr session if script exits due to error cleanup_herdr_on_error() { local exit_code=$? - if [ $exit_code -ne 0 ]; then - echo "⚠️ Error occurred during initialization (exit code $exit_code). Rolling back and killing herdr session '$SESSION_NAME'..." >&2 - _herdr kill-session -t "$SESSION_NAME" 2>/dev/null || true + [ $exit_code -eq 0 ] && return 0 + echo "⚠️ Error occurred during initialization (exit code $exit_code). Rolling back and killing herdr session '$SESSION_NAME'..." >&2 + + # ISSUE-23: the kill result used to be discarded (`2>/dev/null || true`), so + # a kill that closed nothing still printed "rolled back" while the session + # kept running. Check it, then confirm with has-session. + local kill_rc=0 + _herdr kill-session -t "$SESSION_NAME" || kill_rc=$? + local alive=0 + _herdr has-session -t "$SESSION_NAME" >/dev/null 2>&1 && alive=1 + + # Release the onboarding job: `cancelled` is a terminal transition the + # registry knows, and it says what happened - the job was never really + # dispatched. Best effort; a failure here must not stop the rollback. + if [ -n "${DELEGATE_JOB_ID:-}" ]; then + delegate_publish_event "$DELEGATE_JOB_ID" cancelled "rolled back by create_session" "${DELEGATE_JOB_TOKEN:-}" "${DELEGATE_JOB_ATTEMPT:-}" || true fi + + if [ "$alive" = "1" ]; then + _mark_row_rolled_back "running" "rollback-failed" + echo "ERROR: rollback could not kill herdr session '$SESSION_NAME' (kill rc=$kill_rc) - it is still running." >&2 + echo " Clean it up with: HERDR_SESSION_NAME=${HERDR_SESSION_NAME:-default} herdr kill-session -t $SESSION_NAME" >&2 + exit 43 + fi + _mark_row_rolled_back "terminated" "rolled-back" } trap cleanup_herdr_on_error EXIT @@ -390,6 +440,7 @@ if [ -n "$SUBMIT_JOB_PROMPT" ]; then echo "Submitted delegated job: $DELEGATE_JOB_ID" DELEGATE_JOB_TOKEN="" DELEGATE_JOB_ATTEMPT="" + DELEGATE_JOB_ACK_S="" if [ -n "$DELEGATE_JOB_ID" ]; then local_info=$(python3 -c " import sys, json, os @@ -402,13 +453,15 @@ if os.path.exists(p): d = json.load(f) tok = d.get('dispatch_token', '') att = d.get('attempt_id', d.get('iteration', 1)) - print(f'{tok} {att}') + ack = d.get('ack_timeout_sec', 180) + print(f'{tok} {att} {ack}') except Exception: pass " 2>/dev/null || true) if [ -n "$local_info" ]; then DELEGATE_JOB_TOKEN=$(echo "$local_info" | awk '{print $1}') DELEGATE_JOB_ATTEMPT=$(echo "$local_info" | awk '{print $2}') + DELEGATE_JOB_ACK_S=$(echo "$local_info" | awk '{print $3}') fi fi fi @@ -547,6 +600,7 @@ snap['taken_at'] = os.environ['NOW_ISO'] snap['cwd'] = os.environ['PANE_CWD'] print(f"appended: {name}", flush=True) PYEOF +ROW_APPENDED=1 echo echo "=== created ===" @@ -582,12 +636,27 @@ Task: $SUBMIT_JOB_PROMPT" # Inject instructions into the herdr pane rc=0 inject_instructions "$SESSION_NAME" "$instructions" "$DELEGATE_JOB_ID" || rc=$? - if [ "$rc" -ne 0 ]; then + # ISSUE-23: rc 4 is "Enter was not seen to be accepted within the send_keys + # window", which is where a TUI that is still finishing its start-up lands. + # It is a warning now; the agent's own `started` decides. rc 1/2/3 are still + # failures: they say the pane never quiesced, a dialog was blocking, or the + # text never appeared - none of which a later `started` can repair. + if [ "$rc" -ne 0 ] && [ "$rc" -ne 4 ]; then delegate_publish_event "$DELEGATE_JOB_ID" error "instruction injection failed (prompt-lock, rc=$rc)" "$DELEGATE_JOB_TOKEN" "$DELEGATE_JOB_ATTEMPT" exit 1 fi - - delegate_publish_event "$DELEGATE_JOB_ID" started "multi-agent-mux session created and instructions injected" "$DELEGATE_JOB_TOKEN" "$DELEGATE_JOB_ATTEMPT" + if [ "$rc" -eq 4 ]; then + echo "WARNING: Enter was not observed to be accepted for '$SESSION_NAME' (rc=4); waiting for the agent's own started event instead." >&2 + fi + + # ISSUE-23: this script no longer publishes `started` on the agent's behalf. + # It used to, which made the registry show a started job even when the agent + # never saw the prompt, and left any started-based verdict meaningless. + if ! delegate_wait_started "$DELEGATE_JOB_ID" "${DELEGATE_JOB_ACK_S:-180}" "$DELEGATE_JOB_TOKEN"; then + delegate_publish_event "$DELEGATE_JOB_ID" error "onboarding delivery unconfirmed: no started within ${DELEGATE_JOB_ACK_S:-180}s" "$DELEGATE_JOB_TOKEN" "$DELEGATE_JOB_ATTEMPT" + echo "ERROR: '$SESSION_NAME' did not acknowledge the onboarding prompt within ${DELEGATE_JOB_ACK_S:-180}s" >&2 + exit 1 + fi # Trigger immediate priority reconcile cycle asynchronously # Issue #21 phase 2 (A8): the control root's reconcile/watchdog, never the # (unreviewed) copy in a worktree --workspace; identical paths by default. diff --git a/tests/test_issue23_24_startup_path.py b/tests/test_issue23_24_startup_path.py index c73ec4c..ee8e02b 100644 --- a/tests/test_issue23_24_startup_path.py +++ b/tests/test_issue23_24_startup_path.py @@ -444,3 +444,224 @@ def test_s6b_create_session_no_longer_gates_dialogs_on_claude(mam_sandbox): assert call, "create_session no longer answers start-up dialogs at all" assert all('"$AGENT"' in l for l in call), call assert 'if [ "$AGENT" = "claude" ] && [ -z "$LAST_VISIBLE_STATUS_OVERRIDE" ]' not in src + + +# -------------------------------------------------------------------------- +# item 3 — onboarding delivery is judged by the agent's own `started` (#23) +# -------------------------------------------------------------------------- + +def _create_sh(tmp_path): + return tmp_path / ".agents" / "skills" / "multi-agent-mux-create" / "scripts" / "create_session.sh" + + +def _extract(path, start_marker, end_marker, close=None): + """Lift a block out of create_session.sh so the test runs the shipped code + rather than a paraphrase of it. A moved marker fails loudly here. + + `close` closes the construct the end marker opens: the block runs to the + first line equal to it after the end marker (e.g. the `fi` of an `if`).""" + lines = open(path).read().splitlines(True) + start = next((i for i, l in enumerate(lines) if start_marker in l), None) + assert start is not None, "start marker %r is gone from %s" % (start_marker, path) + end = next((i for i, l in enumerate(lines[start:], start) if end_marker in l), None) + assert end is not None, "end marker %r is gone from %s" % (end_marker, path) + if close is not None: + end = next((i for i, l in enumerate(lines[end:], end) if l.strip() == close), None) + assert end is not None, "block opened at %r is never closed with %r" % (end_marker, close) + return "".join(lines[start:end + 1]) + + +def _seed_job(tmp_path, job_id, status="pending", started_token=None): + jobs = tmp_path / ".mam" / "jobs" + jobs.mkdir(parents=True, exist_ok=True) + (jobs / ("%s.json" % job_id)).write_text(json.dumps( + {"job_id": job_id, "status": status, "dispatch_token": "tok-1", + "attempt_id": 1, "ack_timeout_sec": 2})) + ev = jobs / ("%s.events.log" % job_id) + if started_token is None: + if ev.exists(): + ev.unlink() + else: + ev.write_text(json.dumps( + {"job": job_id, "event": "started", "dispatch_token": started_token}) + "\n") + return jobs + + +def _run_delivery(tmp_path, inject_rc, job_id="job1", **seed): + """Run create_session.sh's own delivery block with a stubbed injection.""" + lib = tmp_path / ".agents" / "skills" / "lib.sh" + block = _extract(_create_sh(tmp_path), "# Inject instructions into the herdr pane", + "delegate_wait_started", close="fi") + _seed_job(tmp_path, job_id, **seed) + pub_log = tmp_path / "published.txt" + script = ''' +set -euo pipefail +source "%s" +SESSION_NAME=test-sess +DELEGATE_JOB_ID=%s +DELEGATE_JOB_TOKEN=tok-1 +DELEGATE_JOB_ATTEMPT=1 +DELEGATE_JOB_ACK_S=2 +instructions="hello" +inject_instructions() { return %d; } +delegate_publish_event() { printf '%%s\\n' "$2" >> "%s"; } +%s +echo DELIVERED +''' % (lib, job_id, inject_rc, pub_log, block) + env = dict(os.environ, MAM_JOBS_DIR=str(tmp_path / ".mam" / "jobs")) + res = subprocess.run(["bash", "-c", script], capture_output=True, text=True, + cwd=str(tmp_path), env=env) + published = pub_log.read_text().split() if pub_log.exists() else [] + return res, published + + +def test_s7_create_session_no_longer_publishes_started_for_the_agent(mam_sandbox): + """S7 (source): create_session used to publish `started` itself, so the + registry showed a started job even when the agent never saw the prompt. + With that line present no started-based verdict can mean anything.""" + src = open(_create_sh(mam_sandbox)).read() + assert 'delegate_publish_event "$DELEGATE_JOB_ID" started' not in src + assert "delegate_wait_started" in src + + +def test_s7b_delivery_succeeds_on_the_agents_own_started(mam_sandbox): + """S7b (real registry files, stubbed injection): a started line carrying + this dispatch token is the evidence.""" + res, published = _run_delivery(mam_sandbox, 0, started_token="tok-1") + assert "DELIVERED" in res.stdout, res.stdout + res.stderr + assert published == [], published + + +def test_s7c_delivery_succeeds_when_the_registry_left_pending(mam_sandbox): + """S7c: publish_event syncs the record on this host, so a status past + `pending` is the same evidence.""" + res, _ = _run_delivery(mam_sandbox, 0, status="running") + assert "DELIVERED" in res.stdout, res.stdout + res.stderr + + +def test_s7d_no_started_within_t_is_a_delivery_failure(mam_sandbox): + """S7d: fail closed, and say so on the job.""" + res, published = _run_delivery(mam_sandbox, 0) + assert res.returncode == 1, res.stdout + res.stderr + assert "DELIVERED" not in res.stdout + assert published == ["error"], published + + +def test_s7e_a_started_from_another_dispatch_is_not_evidence(mam_sandbox): + """S7e: a loop job keeps one events.log across attempts, so only a started + carrying THIS dispatch token counts.""" + res, _ = _run_delivery(mam_sandbox, 0, started_token="tok-OTHER") + assert res.returncode == 1, res.stdout + res.stderr + + +def test_s8_rc4_is_a_warning_and_the_started_wait_decides(mam_sandbox): + """S8 (stubbed injection): rc 4 is "Enter not seen accepted", which is + exactly where a still-starting TUI lands - #23's false failure. It must no + longer abort; the started wait decides both ways.""" + res, published = _run_delivery(mam_sandbox, 4, started_token="tok-1") + assert "DELIVERED" in res.stdout, res.stdout + res.stderr + assert "rc=4" in res.stderr, res.stderr + assert published == [], published + + res, published = _run_delivery(mam_sandbox, 4) + assert res.returncode == 1, res.stdout + res.stderr + assert published == ["error"], published + + +@pytest.mark.parametrize("rc", [1, 2, 3]) +def test_s8b_the_other_injection_failures_still_abort_at_once(mam_sandbox, rc): + """S8b: rc 1/2/3 say the pane never quiesced, a dialog was blocking, or the + text never appeared. No later `started` repairs those, so they stay hard + failures - only rc 4 was relaxed.""" + res, published = _run_delivery(mam_sandbox, rc, started_token="tok-1") + assert res.returncode == 1, res.stdout + res.stderr + assert "DELIVERED" not in res.stdout + assert published == ["error"], published + + +# -------------------------------------------------------------------------- +# item 4 — a rollback verifies the kill (#23) +# -------------------------------------------------------------------------- + +def _run_rollback(tmp_path, kill_rc, still_alive, row=True, job_id="job1"): + lib = tmp_path / ".agents" / "skills" / "lib.sh" + yaml_path = tmp_path / ".mam" / "agent-sessions.yaml" + if row: + yaml_path.write_text( + "herdr_sessions:\n" + "- name: test-sess\n" + " status: running\n" + " role: creator\n" + " delegate_job_id: %s\n" + " pane:\n" + " index: 0\n" + " pid: 111\n" + " cmd: claude\n" + " cwd: %s\n" % (job_id, tmp_path)) + else: + yaml_path.write_text("herdr_sessions: []\n") + _seed_job(tmp_path, job_id) + block = _extract(_create_sh(tmp_path), "# _mark_row_rolled_back ", + "trap cleanup_herdr_on_error EXIT") + pub_log = tmp_path / "published.txt" + # The trap is installed and fired the way create_session fires it: an + # errexit shell exiting non-zero. rc 9 through means "no exit 43". + script = ''' +set -euo pipefail +source "%s" +SESSION_NAME=test-sess +DELEGATE_JOB_ID=%s +DELEGATE_JOB_TOKEN=tok-1 +DELEGATE_JOB_ATTEMPT=1 +ROW_APPENDED=%d +AGENT_SESSIONS_YAML="%s" +delegate_publish_event() { printf '%%s\\n' "$2" >> "%s"; } +_herdr() { + case "${1:-}" in + kill-session) return %d ;; + has-session) return %d ;; + esac + return 0 +} +%s +exit 9 +''' % (lib, job_id, 1 if row else 0, yaml_path, pub_log, + kill_rc, 0 if still_alive else 1, block) + env = dict(os.environ, MAM_JOBS_DIR=str(tmp_path / ".mam" / "jobs"), + AGENT_SESSIONS_YAML=str(yaml_path)) + res = subprocess.run(["bash", "-c", script], capture_output=True, text=True, + cwd=str(tmp_path), env=env) + published = pub_log.read_text().split() if pub_log.exists() else [] + return res, published, yaml_path.read_text() + + +def test_s9_a_kill_that_left_the_session_alive_is_reported(mam_sandbox): + """S9 (stubbed herdr, real YAML + registry): the kill failed and the + session is still up. #23's rollback swallowed exactly this and printed + "rolled back" anyway, leaving a `running` row against a failed job.""" + res, published, yaml_text = _run_rollback(mam_sandbox, kill_rc=1, still_alive=True) + assert res.returncode == 43, res.stdout + res.stderr + assert "test-sess" in res.stderr and "kill-session" in res.stderr + assert "rollback-failed" in yaml_text, yaml_text + assert "status: running" in yaml_text, "a session that is still up must not be called gone" + assert "delegate_job_id: null" in yaml_text, yaml_text + assert published == ["cancelled"], published + + +def test_s10_a_successful_kill_keeps_the_previous_behaviour(mam_sandbox): + """S10: nothing is still running, so no exit 43 and no warning - but the + row and the job are still cleaned up, which is the other half of #23.""" + res, published, yaml_text = _run_rollback(mam_sandbox, kill_rc=0, still_alive=False) + assert res.returncode == 9, res.stdout + res.stderr + assert "rolled-back" in yaml_text, yaml_text + "\nSTDERR:" + res.stderr + assert "status: terminated" in yaml_text, yaml_text + assert "delegate_job_id: null" in yaml_text, yaml_text + assert published == ["cancelled"], published + + +def test_s10b_a_rollback_before_the_row_existed_touches_no_yaml(mam_sandbox): + """S10b: failing before the append must not invent a row.""" + res, published, yaml_text = _run_rollback(mam_sandbox, kill_rc=0, still_alive=False, + row=False) + assert res.returncode == 9, res.stdout + res.stderr + assert "herdr_sessions: []" in yaml_text, yaml_text