|
| 1 | +# Supervised IPC: submit_job ACK タイムアウト (非対話) |
| 2 | + |
| 3 | +ステータス: 解決済み (supervised IPC における socket transport) |
| 4 | +(stdio 側の根本原因は環境依存のまま) |
| 5 | + |
| 6 | +## 問題 |
| 7 | + |
| 8 | +`--supervised` モード(Supervisor -> Core IPC -> Worker)でワークフローを実行すると、一部の非対話実行で最初のステップ(`bootstrap`)で |
| 9 | +`submit_job` の ACK 待機中に IPC タイムアウトが発生して失敗します。 |
| 10 | + |
| 11 | +観測された失敗: |
| 12 | + |
| 13 | +``` |
| 14 | +Core IPC submit_job timed out after <N>ms (jobId=... requestId=...) |
| 15 | +``` |
| 16 | + |
| 17 | +IPC トレースで見えた主な症状: |
| 18 | + |
| 19 | +- Runner のログに `tx submit_job` が出る |
| 20 | +- Core が起動し、stderr に起動ログを出力する |
| 21 | +- Core 側で `rx submit_job` が出ず、ACK を送信しない |
| 22 | + |
| 23 | +つまり壊れているのは Runner -> Core の stdin 経路(Core 側でメッセージが見えない)です。 |
| 24 | + |
| 25 | +対処: socket ベースの supervised IPC transport(`AGENTCORE_SUPERVISED_IPC_TRANSPORT=socket`)を使い、stdio パイプを完全に迂回します。 |
| 26 | + |
| 27 | +## 再現 |
| 28 | + |
| 29 | +典型的な再現手順(stdio を強制。影響を受ける環境では失敗する可能性あり): |
| 30 | + |
| 31 | +```bash |
| 32 | +AGENTCORE_SUPERVISED_IPC_TRANSPORT=stdio \ |
| 33 | + AGENTCORE_IPC_TRACE=1 AGENTCORE_IPC_REQUEST_TIMEOUT=45s VERBOSE=0 \ |
| 34 | + bash examples/agent-pr-loop-demo/run-in-tmp.sh |
| 35 | +``` |
| 36 | + |
| 37 | +Socket transport(成功を想定): |
| 38 | + |
| 39 | +```bash |
| 40 | +AGENTCORE_SUPERVISED_IPC_TRANSPORT=socket \ |
| 41 | + AGENTCORE_IPC_TRACE=1 AGENTCORE_IPC_REQUEST_TIMEOUT=2m VERBOSE=0 \ |
| 42 | + bash examples/agent-pr-loop-demo/run-in-tmp.sh |
| 43 | +``` |
| 44 | + |
| 45 | +注記: `src/workflow/run.ts` では非対話の `--supervised` 実行時に |
| 46 | +`AGENTCORE_SUPERVISED_IPC_TRANSPORT=socket` がデフォルトになっています。 |
| 47 | + |
| 48 | +補足: |
| 49 | + |
| 50 | +- この問題はワークフロー YAML の `timeout` ではなく、IPC の request/response に関するものです。 |
| 51 | +- Keepalive 出力は「無出力監視による強制終了」を防ぐことはできますが、IPC のリクエストタイムアウトを修正するものではありません。 |
| 52 | + |
| 53 | +## 調査サマリ |
| 54 | + |
| 55 | +1) Keepalive とタイムアウト |
| 56 | + |
| 57 | +- `src/workflow/run.ts` に keepalive 出力を追加し、無出力でプロセスを kill される環境を回避。 |
| 58 | +- 非 supervised 実行では keepalive が有効なことを確認。 |
| 59 | +- supervised 実行では、失敗の原因が IPC リクエストタイムアウトであり、watchdog SIGTERM ではないことを確認。 |
| 60 | + |
| 61 | +2) IPC リクエストタイムアウト |
| 62 | + |
| 63 | +- デフォルトの IPC リクエストタイムアウトが 30 秒(`DEFAULT_REQUEST_TIMEOUT_MS = 30_000`)であることを確認。 |
| 64 | +- IPC リクエストタイムアウトを設定可能にし、supervised runner の既定値を `2m` に引き上げ: |
| 65 | + - CLI: `--ipc-request-timeout <DurationString>` |
| 66 | + - 環境変数: `AGENTCORE_IPC_REQUEST_TIMEOUT` / `AGENTCORE_IPC_REQUEST_TIMEOUT_MS` |
| 67 | + |
| 68 | +3) ステップタイムアウトとの関係 |
| 69 | + |
| 70 | +- `bootstrap: timeout: 2m` などのステップレベルタイムアウトが、長めの IPC タイムアウトより先に発火していた事例を確認。 |
| 71 | +- supervised runner の step timeout が Core の起動/ACK 待ちではなく、*Worker 実行時間*(ACK 取得後)に適用されるよう調整。 |
| 72 | + |
| 73 | +4) 停止した IPC 操作の特定 |
| 74 | + |
| 75 | +- タイムアウトした操作を `submit_job` / `request_permit` / `cancel_job` で識別できるようエラー情報を強化。 |
| 76 | +- 失敗経路では一貫して `submit_job` の ACK タイムアウトでした。 |
| 77 | + |
| 78 | +5) IPC トレース機能 |
| 79 | + |
| 80 | +- `src/ipc/json-lines-transport.ts` に `AGENTCORE_IPC_TRACE=1` のサポートを追加: |
| 81 | + - `tx` / `rx` を `pid` / `type` / `requestId` / `jobId` と共に出力。 |
| 82 | +- デモトレース補助を追加: |
| 83 | + - `examples/agent-pr-loop-demo/run-in-tmp.sh` が `AGENTCORE_ROOT` と git SHA を表示。 |
| 84 | + |
| 85 | +6) トランスポートレベルのエラー |
| 86 | + |
| 87 | +- `src/ipc/protocol.ts` で切断時に保留中リクエストが即座に失敗するよう close/error 処理を追加。 |
| 88 | +- 失敗例では、トランスポートのパース失敗/切断エラーは観測されませんでした。 |
| 89 | + |
| 90 | +7) Core 起動 / stdio ブリッジ |
| 91 | + |
| 92 | +- `src/scheduler/supervisor.ts` を `node:child_process.spawn` を使うよう変更。 |
| 93 | +- Core の stderr を親の stderr にパイプ接続して可視化。 |
| 94 | +- child の環境変数を明示的に引き継ぎ(Bun.spawn では更新済み `process.env` が継承されないため)。 |
| 95 | +- Core への stdin 書き込みを常にコールバックベース `write()` に変更し、完了待機を追加。 |
| 96 | +- Core IPC の stdin 取得元を調整: |
| 97 | + - `src/index.ts` では Core IPC 入力に `Bun.stdin.stream()` を優先使用(必要に応じて `process.stdin` にフォールバック)。 |
| 98 | + |
| 99 | +これらの変更で多くの環境で supervised IPC は改善しましたが、一部の環境では stdio メッセージが完全に消失します(Runner `tx` だけ発生し Core `rx` なし)。 |
| 100 | + |
| 101 | +8) socket ベースの supervised IPC transport |
| 102 | + |
| 103 | +- supervised IPC に Unix socket transport を追加し、stdio パイプを回避: `AGENTCORE_SUPERVISED_IPC_TRANSPORT=socket`。 |
| 104 | +- `src/workflow/run.ts` は非対話の `--supervised` 実行で既定値を `socket` に設定(`AGENTCORE_SUPERVISED_IPC_TRANSPORT=stdio|socket` で上書き可)。 |
| 105 | +- Core は Supervisor がセットする `AGENTCORE_IPC_SOCKET_PATH` へ接続します。 |
| 106 | + |
| 107 | +## 関連作業(Agent PR Loop デモ) |
| 108 | + |
| 109 | +調査中に agent PR loop のデモ/ワークフローも強化: |
| 110 | + |
| 111 | +- `examples/agent-pr-loop.yaml`: review 結果に応じて `implement`(Claude Code)をループするよう変更し、`completion_check` を使用。 |
| 112 | +- `completion_check` の判断を `decision_file` によるファイルベース判定へ対応し、stdout マーカー依存を排除。 |
| 113 | +- `scripts/agent-pr-loop/review-inputs.sh`: `.agentcore-loop/review.untracked.diff` を生成し、レビューに未追跡差分を含める。 |
| 114 | +- `examples/agent-pr-loop-demo/request.md`: 具体的な境界ケースを追加して品質基準を引き上げ。 |
| 115 | +- `examples/agent-pr-loop-demo/run-in-tmp.sh`: ワークフロー完了後の検証を追加(ブラックボックス確認)。 |
| 116 | + |
| 117 | +## 現在の状況 / 次のステップ |
| 118 | + |
| 119 | +- 根本原因: supervised stdio パイプで、特定の非対話環境で Runner -> Core 方向のメッセージが落ちて `submit_job` の ACK タイムアウトにつながる。 |
| 120 | +- 実装済み対策: supervised IPC を `AGENTCORE_SUPERVISED_IPC_TRANSPORT=socket` に変更。非対話 `--supervised` 実行では `src/workflow/run.ts` により既定で socket になります。 |
| 121 | +- 旧挙動が必要な場合、または元の問題を再現したい場合は次を指定: |
| 122 | + - `AGENTCORE_SUPERVISED_IPC_TRANSPORT=stdio` |
| 123 | + |
| 124 | +## 2026-02-14 フォローアップ |
| 125 | + |
| 126 | +非対話 supervised 起動で Supervisor -> Core stdin が黙って落ちる可能性をさらに下げるため、stdio の堅牢性を追加で向上しました。 |
| 127 | + |
| 128 | +### 変更内容 |
| 129 | + |
| 130 | +- `src/index.ts`: Core stdin 選択での互換フォールバックを追加。 |
| 131 | + - 利用可能なら `Bun.stdin.stream()` を使用。 |
| 132 | + - 利用不可時は `Readable.toWeb(process.stdin)` にフォールバック。 |
| 133 | +- `src/scheduler/supervisor.ts`: Core `stdin` トランスポート初期化を強化。 |
| 134 | + - `proc.stdin.setDefaultEncoding("utf8")` を best-effort で呼び出し。 |
| 135 | + - `proc.stdin.setNoDelay(true)` を best-effort で呼び出し。 |
| 136 | + - Core の stdin エラーをログ出力 (`[IPC][core-stdin-error]`)。 |
| 137 | + |
| 138 | +### stdio transport の残タスク |
| 139 | + |
| 140 | +- 再度再現コマンドを `AGENTCORE_IPC_TRACE=1` で実行。 |
| 141 | +- トレースに以下が含まれることを確認: |
| 142 | + - `tx submit_job`(Runner) |
| 143 | + - `rx submit_job`(Core) |
| 144 | + - `tx ack`(Core) |
| 145 | + - `rx ack`(Runner) |
| 146 | +- それでも欠落する場合、次は外部実行環境の子プロセスグループ/セッションラッピングを確認し、Core 起動前にラッピングを無効化。 |
| 147 | + |
| 148 | +### 2026-02-14 (stdio) 再実行結果 |
| 149 | + |
| 150 | +- 再現コマンド(stdio 強制): |
| 151 | + - `AGENTCORE_SUPERVISED_IPC_TRANSPORT=stdio AGENTCORE_IPC_TRACE=1 AGENTCORE_IPC_REQUEST_TIMEOUT=45s VERBOSE=0 bash examples/agent-pr-loop-demo/run-in-tmp.sh` |
| 152 | + - `AGENTCORE_SUPERVISED_IPC_TRANSPORT=stdio AGENTCORE_IPC_TRACE=1 AGENTCORE_IPC_REQUEST_TIMEOUT=20s bun run src/workflow/run.ts examples/hello-world.yaml --supervised` |
| 153 | +- 両方のコマンドで、いずれも以下を確認: |
| 154 | + - Runner `tx submit_job` |
| 155 | + - Core 起動ログ(`AgentCore starting`, `AgentCore started, awaiting IPC messages`) |
| 156 | + - Core 側の `[IPC][rx]` / `ack` は **未観測** |
| 157 | + - 20〜45 秒でタイムアウトし、ワークフロー失敗 |
| 158 | +- 追加の分離検証: |
| 159 | + - `AGENTCORE_IPC_TRACE=1 bun /home/reoring/roboppi/src/index.ts` をシェルパイプ経由(`printf ... | bun src/index.ts`)で実行すると `Core [IPC][rx] submit_job` と `ack` を確認。 |
| 160 | + - Bun runtime + `node:child_process` で子 bun プロセスへ書き込む supervisor 経路では、最小化した writer スクリプトでも Core の `[IPC][rx]` は得られない。 |
| 161 | +- stdio に関する最新仮説: |
| 162 | + - 本環境では Bun runtime のプロセス生成 + pipe transport が子 bun プロセスの stdin をトランスポート層で破棄する可能性。 |
| 163 | + - stdio は一部環境で依然不安定。タイムアウト再試行に費やすより、トランスポートの堅牢化まで待つべき。 |
| 164 | + |
| 165 | +### 2026-02-14 (socket) 再実行結果 |
| 166 | + |
| 167 | +- socket transport での問題解消を end-to-end で確認: |
| 168 | + - `AGENTCORE_SUPERVISED_IPC_TRANSPORT=socket AGENTCORE_IPC_REQUEST_TIMEOUT=2m VERBOSE=0 bash examples/agent-pr-loop-demo/run-in-tmp.sh` |
| 169 | + -> ワークフロー `SUCCEEDED`、デモの事後チェック完了 |
| 170 | + - `AGENTCORE_IPC_TRACE=1 bun run src/workflow/run.ts examples/hello-world.yaml --supervised` |
| 171 | + -> Core `[IPC][rx] submit_job` と `ack` を確認、ワークフロー `SUCCEEDED` |
| 172 | +- 全テスト通過: `bun test`(949 件) |
| 173 | +- 結論: 非対話 supervised 実行では socket transport を利用。stdio はフォールバック / デバッグ用。 |
0 commit comments