From d5a191c47c3d225f1ec865df2c218d46157477bd Mon Sep 17 00:00:00 2001 From: Godopu Date: Sun, 13 Sep 2026 00:49:44 +0900 Subject: [PATCH] fix(issue-14): keep a job open on fresh disk heartbeats after the subscriber idles out The R1 grace after a subscriber idle timeout only continued while herdr reported `working` or the pane showed a busy token, and gave up the moment that evidence vanished. Two live jobs in the v4.4.2 review loop were closed as deadline_timeout that way: a grok review whose heartbeat gap was 147 s, and the creator running the full suite in a background shell (idle to herdr, no busy token) while publishing progress every 45 s. Both later published `completed`, which the terminal record refused. - `_recent_disk_heartbeat`: publish_event appends every event to the job's events.log before the wire publish, so a heartbeat the subscriber never saw is still on disk; treat one at most IDLE_TIMEOUT old as liveness - R1 loop: any evidence (herdr working, pane busy token, disk heartbeat) opens a new IDLE_TIMEOUT window; a job with no evidence for a whole window is closed as before, still inside the wall clock - test: a human-agent job whose subscriber idles out stays open across five disk heartbeats and picks up the out-of-band completion (rc 0) - VERSIONS.md v4.4.2 item 6 and test count updated Refs #14 Co-Authored-By: Claude Fable 5.1 Claude-Session: https://claude.ai/code/session_01VCgu9Fa9iT7TbJUSzdq4Ff --- .../multi-agent-mux-delegate-job | 95 ++++++++++++------- VERSIONS.md | 4 +- tests/test_issue14_delivery_ack.py | 64 +++++++++++++ 3 files changed, 126 insertions(+), 37 deletions(-) diff --git a/.agents/skills/multi-agent-mux-delegate-job/multi-agent-mux-delegate-job b/.agents/skills/multi-agent-mux-delegate-job/multi-agent-mux-delegate-job index 4f4e445..4b923bd 100755 --- a/.agents/skills/multi-agent-mux-delegate-job/multi-agent-mux-delegate-job +++ b/.agents/skills/multi-agent-mux-delegate-job/multi-agent-mux-delegate-job @@ -599,6 +599,32 @@ _agent_still_working() { _pane_tail "$sess" 8 2>/dev/null | grep -Fq "esc to interrupt" } +# ISSUE-14: agent-agnostic liveness. publish_event appends every event to the +# job's on-disk events.log before the wire publish, so a `progress` heartbeat +# that the subscriber never saw (it had already idled out, or the broker +# dropped it) is still visible here. An agent running its tests in a +# background shell looks idle to herdr and shows no busy token, yet keeps +# heartbeating - this is the only evidence that covers that case. +_recent_disk_heartbeat() { + local job_id="$1" window="$2" f="$REGISTRY_DIR/$job_id.events.log" + [ -f "$f" ] || return 1 + "$PY" - "$f" "$window" <<'PYEOF' +import calendar, json, sys, time +path, window = sys.argv[1], float(sys.argv[2]) +last = "" +with open(path) as fh: + for line in fh: + if line.strip(): + last = line +try: + stamp = json.loads(last)["timestamp"] + seen = calendar.timegm(time.strptime(stamp, "%Y-%m-%dT%H:%M:%SZ")) +except Exception: + sys.exit(1) +sys.exit(0 if time.time() - seen <= window else 1) +PYEOF +} + _map_sub_rc() { local sub_rc="$1" job_id="$2" local job_status="running" @@ -675,42 +701,41 @@ finalize_unfinished() { local sess="${target_sess#herdr:}" local target_agent target_agent=$(_sanitize_herdr_agent_name "$sess") - local still_working=0 - if [ "$sess" != "human" ] && [ -n "$sess" ]; then - _agent_still_working "$sess" "$target_agent" && still_working=1 - fi - if [ "$still_working" = "1" ]; then - local now elapsed remaining - now=$(date +%s) - elapsed=$(( now - ${START_TIME:-now} )) - remaining=$(( TIMEOUT - elapsed )) - [ $remaining -lt 0 ] && remaining=0 - while [ $remaining -gt 0 ]; do - local disk_st - disk_st="$(_disk_status "$job_id")" - if [ "$disk_st" = "completed" ] || [ "$disk_st" = "error" ] || [ "$disk_st" = "cancelled" ]; then - job_status="$disk_st" - FINAL_JOB_STATUS="$disk_st" - [ "$disk_st" = "completed" ] && return 0 - break - fi - if ! _agent_still_working "$sess" "$target_agent"; then - sleep 1 - disk_st="$(_disk_status "$job_id")" - if [ "$disk_st" = "completed" ] || [ "$disk_st" = "error" ] || [ "$disk_st" = "cancelled" ]; then - job_status="$disk_st" - FINAL_JOB_STATUS="$disk_st" - [ "$disk_st" = "completed" ] && return 0 - fi - break - fi - local wait_interval=1 - [ $remaining -lt $wait_interval ] && wait_interval=$remaining - sleep "$wait_interval" - remaining=$(( remaining - wait_interval )) - done - fi + # ISSUE-14: the subscriber's idle clock only counts events it received over + # the wire. Keep re-observing the disk while ANY liveness evidence is at + # most IDLE_TIMEOUT old - herdr `working`, the pane busy token, or a fresh + # heartbeat in events.log (see _recent_disk_heartbeat). Each sighting opens + # a new idle window; an agent that leaves no evidence for a whole window is + # closed, still inside the wall clock. Before this, one heartbeat gap + # longer than the idle timeout closed a live review as deadline_timeout + # and its later `completed` was refused. + local now elapsed remaining evidence_until + now=$(date +%s) + elapsed=$(( now - ${START_TIME:-now} )) + remaining=$(( TIMEOUT - elapsed )) + [ $remaining -lt 0 ] && remaining=0 + evidence_until=$(( now + IDLE_TIMEOUT )) + while [ $remaining -gt 0 ]; do + local disk_st + disk_st="$(_disk_status "$job_id")" + if [ "$disk_st" = "completed" ] || [ "$disk_st" = "error" ] || [ "$disk_st" = "cancelled" ]; then + job_status="$disk_st" + FINAL_JOB_STATUS="$disk_st" + [ "$disk_st" = "completed" ] && return 0 + break + fi + if { [ "$sess" != "human" ] && [ -n "$sess" ] && _agent_still_working "$sess" "$target_agent"; } \ + || _recent_disk_heartbeat "$job_id" "$IDLE_TIMEOUT"; then + evidence_until=$(( $(date +%s) + IDLE_TIMEOUT )) + elif [ "$(date +%s)" -ge "$evidence_until" ]; then + break + fi + local wait_interval=1 + [ $remaining -lt $wait_interval ] && wait_interval=$remaining + sleep "$wait_interval" + remaining=$(( remaining - wait_interval )) + done fi local close_req="deadline_timeout" diff --git a/VERSIONS.md b/VERSIONS.md index 0cbd818..1bd4fc2 100644 --- a/VERSIONS.md +++ b/VERSIONS.md @@ -47,11 +47,11 @@ 3. **쉼 `ls` 의 "no server running" 번역 (Issue #9)**: 서버가 내려가 있으면 쉼의 `ls` 가 `no server running (herdr session )` 으로 보고하고, `reconcile.sh` 는 이를 빈 서버로 판정해 `herdr_confirmed` 를 유지한다(파싱 실패로 모든 서버의 drift 감지가 멈추는 회귀 방지). 번역은 `agent list` 가 **실패**하고 그 오류 봉투의 `error.code` 가 정확히 `server_not_running` 일 때만 적용한다. 성공한 목록에 같은 문자열이 들어 있거나(예: 에이전트 이름 `server_not_running-codex`) 다른 실패인 경우는 번역하지 않으므로, 살아 있는 서버가 빈 서버로 오판되어 drift A 로 전 세션이 종료 처리되지 않고 그 밖의 실패는 종전대로 unknown(`herdr_confirmed=False`)으로 남는다. 4. **accepted 제출의 전달 확인 `SKS_DELIVERY_GRACE_S` (Issue #14, `send_keys_safe`)**: `agent prompt --wait` 결과가 `timeout`/`agent_prompt_stalled` 이면 herdr 가 입력을 이미 수락한 것으로 보고, `SKS_DELIVERY_GRACE_S`(기본 15초) 동안 `agent_status` working, 제출 전 화면에 없던 busy 토큰(`esc to interrupt`), 제출 전 스냅샷 대비 pane 변화 중 하나를 전달 확인 신호로 인정한다. 신호가 없으면 종전대로 rc 4 로 fail-closed 하고, 그 밖의 오류(`transport_error` 등)는 accepted 로 취급하지 않는다. 단일 주입 계약(재전송 없음)은 유지된다. 5. **래퍼 레지스트리 ack 유예 `MAM_INJECT_ACK_GRACE_S` (Issue #14, `multi-agent-mux-delegate-job`)**: `send_keys_safe` 가 전달을 확인하지 못해도 잡을 `agent_blocked` 로 닫기 전에 `MAM_INJECT_ACK_GRACE_S`(기본 10초) 동안 레지스트리를 관측하고, `pending` 이 아닌 상태(에이전트의 `started` 등)가 보이면 전달된 것으로 보고 진행한다(`_inject_acknowledged`). -6. **R1 유예의 pane busy 토큰 인정 (Issue #14, `_agent_still_working`)**: 구독자 idle 타임아웃 후 R1 유예가 herdr `working` 외에 pane 최근 8줄의 `esc to interrupt` 토큰도 작업 중 근거로 받아들인다. idle 타임아웃보다 긴 codex 리뷰가 턴 도중 `deadline_timeout` 으로 닫히고 이후 `completed` 가 거부되던 문제를 방지. +6. **R1 유예의 pane busy 토큰·디스크 heartbeat 인정 (Issue #14, `_agent_still_working`, `_recent_disk_heartbeat`)**: 구독자 idle 타임아웃 후 R1 유예가 herdr `working` 외에 pane 최근 8줄의 `esc to interrupt` 토큰, 그리고 잡 `events.log` 의 최근 이벤트(`publish_event` 가 와이어 발행 전에 로컬에 기록하는 `progress` heartbeat)도 작업 중 근거로 받아들인다. 근거가 관측될 때마다 `IDLE_TIMEOUT` 만큼의 새 창이 열리고, 한 창 내내 아무 근거도 없으면 종전대로 닫는다(벽시계 `TIMEOUT` 내). idle 타임아웃보다 긴 codex 리뷰, heartbeat 간격이 한 번 idle 창을 넘긴 리뷰, 백그라운드 셸로 테스트를 돌려 herdr 에 idle 로 보이는 creator 가 턴 도중 `deadline_timeout` 으로 닫히고 이후 `completed` 가 거부되던 문제를 방지. #### ✅ 품질 검증 - **T1-7 트리거 변경** (`tests/test_issue6_fail_closed.py`): 주입 실패 유발값을 `prompt_wait_result=timeout` → `transport_error` 로 변경(Issue #14 이후 `timeout` 은 accepted 제출이므로 더 이상 확정 실패가 아님)하고 `MAM_INJECT_ACK_GRACE_S=1` 로 대기를 단축. -- **신규 테스트 16개**: `tests/test_issue9_server_env.py` 8개(마커 제거, `MAM_NO_AUTOSTART` 부트스트랩 생략·호출 전달, status 조회 무기동, 정적 opt-out, `ls` 번역(최소·herdr 0.9 실제 오류 봉투), 성공 목록 속 `server_not_running` 문자열 비오판, 그 밖의 실패 unknown 유지, reconcile drift A 비발생), `tests/test_issue14_delivery_ack.py` 8개(busy 토큰·pane 변화 확인, 무신호 fail-closed, 선행 busy 토큰 배제, `transport_error` 비수용, mock herdr timeout 확인, 래퍼 레지스트리 ack, idle 타임아웃 pane busy 유예). +- **신규 테스트 17개**: `tests/test_issue9_server_env.py` 8개(마커 제거, `MAM_NO_AUTOSTART` 부트스트랩 생략·호출 전달, status 조회 무기동, 정적 opt-out, `ls` 번역(최소·herdr 0.9 실제 오류 봉투), 성공 목록 속 `server_not_running` 문자열 비오판, 그 밖의 실패 unknown 유지, reconcile drift A 비발생), `tests/test_issue14_delivery_ack.py` 9개(busy 토큰·pane 변화 확인, 무신호 fail-closed, 선행 busy 토큰 배제, `transport_error` 비수용, mock herdr timeout 확인, 래퍼 레지스트리 ack, idle 타임아웃 pane busy 유예, idle 타임아웃 디스크 heartbeat 유예). - **테스트 기대값 정정**: `tests/test_a4_adapter_contract.py` 가 `4d444ce` 의 agy `exit_key=/exit` 변경을 반영하도록 수정(그동안 전체 스위트에서 1건 실패하던 문제 해소). - **실측 (커밋 `497633f` 기록)**: 새로 부트스트랩한 서버에 마커가 없고 claude pane 의 transcript 저장이 복구됨, codex 잡 `d04ebcb5` 의 `started`/`completed` 가 `agent_blocked` 없이 수락됨. diff --git a/tests/test_issue14_delivery_ack.py b/tests/test_issue14_delivery_ack.py index 48ff0d1..874b838 100644 --- a/tests/test_issue14_delivery_ack.py +++ b/tests/test_issue14_delivery_ack.py @@ -302,3 +302,67 @@ def test_wrapper_idle_timeout_grace_accepts_pane_busy_token(tmp_path, mock_herdr job_data = json.loads((reg_dir / f"{jid}.json").read_text()) assert job_data.get("status") == "completed", f"status={job_data.get('status')}\n{stdout}\n{stderr}" assert proc.returncode == 0, f"expected rc=0 after the working grace, got {proc.returncode}\n{stdout}\n{stderr}" + + +# --------------------------------------------------------------------------- +# wrapper: idle-timeout grace (R1) must honour on-disk progress heartbeats +# --------------------------------------------------------------------------- +PUBLISH_PY = SKILLS / "multi-agent-mux-delegate-job" / "scripts" / "publish_event.py" + + +def test_wrapper_idle_timeout_grace_accepts_disk_heartbeat(tmp_path): + """No herdr evidence at all (a human agent, or an agent running its tests + in a background shell): once the subscriber has idled out, the wrapper + must keep the job open as long as fresh `progress` heartbeats keep landing + in events.log, and pick up the eventual completion. Each heartbeat here + arrives after the previous idle window would have expired.""" + reg_dir = tmp_path / "jobs" + reg_dir.mkdir(parents=True, exist_ok=True) + env = _base_env(tmp_path) + proc = subprocess.Popen( + [ + "bash", str(WRAPPER), "submit", + "--agent", "human", + "--prompt", "issue 14 disk heartbeat", + "--registry-dir", str(reg_dir), + "--workdir", str(tmp_path), + "--timeout", "60", + "--idle-timeout", "6", + ], + cwd=str(tmp_path), env=env, stdout=subprocess.PIPE, stderr=subprocess.PIPE, text=True, + ) + + jid = "" + for _ in range(100): + job_files = list(reg_dir.glob("*.json")) + if job_files: + jid = job_files[0].stem + break + time.sleep(0.1) + assert jid, "job was not registered" + + def heartbeat(detail: str): + subprocess.run( + [sys.executable, str(PUBLISH_PY), "--registry-dir", str(reg_dir), + "--job", jid, "--event", "progress", "--detail", detail], + capture_output=True, text=True, cwd=str(tmp_path), env=env, + ) + + # Subscriber idles out at ~6 s (plus broker connect); heartbeats then keep + # arriving 2 s apart, well inside the 6 s window each one re-opens (the + # wrapper's poll iteration costs ~2 s of herdr RPCs, so the ratio matters). + time.sleep(9) + for i in range(5): + heartbeat(f"still working {i}") + time.sleep(2) + done = subprocess.run( + [sys.executable, str(REGISTRY_PY), "--registry-dir", str(reg_dir), + "update", "--job", jid, "--status", "completed"], + capture_output=True, text=True, cwd=str(tmp_path), env=env, + ) + assert done.returncode == 0, done.stderr + + stdout, stderr = proc.communicate(timeout=90) + job_data = json.loads((reg_dir / f"{jid}.json").read_text()) + assert job_data.get("status") == "completed", f"status={job_data.get('status')}\n{stdout}\n{stderr}" + assert proc.returncode == 0, f"expected rc=0 while heartbeats kept landing, got {proc.returncode}\n{stdout}\n{stderr}"