🙄

「Control request timeout: initialize」 の正体は SIGKILL だった話 (Claude Code C

に公開
AI
AWS
Python
Celery
Claude
tech

production の Celery task のログにこの文字列が出始めた時、最初に頭を抱えました。

ERROR analyze_code_specification failed:
Control request timeout: initialize

Codens Green では、リポジトリの内容を解析する analyze_code_specification という Celery task があって、その中で Claude Code CLI を subprocess として叩いています。staging では普通に通るのに、production だけ何回かに 1 回これが出る。完全に再現するわけでもなく、間欠的に落ちる。

「Control request timeout: initialize」 という文字列は、いかにも Claude Code の MCP 初期化ハンドシェイクが timeout したように読めるんですよね。実際、Claude Code Agent SDK の内部にはこういう init handshake のフェーズがあって、そこで stdio が詰まると似た文言が出ます。なので最初は完全に 「Claude Code 側の init bug を踏んだな」 と思い込んで、丸 1 日溶かしました。これが今回の本題です。結論を先に書くと、Claude Code は何も悪くなかったし、handshake も timeout していなかった。OS の OOM killer が CLI process を殺していて、外側から見ると init timeout に見えていただけ、というオチでした。

エラーメッセージに引っ張られた 1 日

最初の数時間は、エラー文字列を素直に信じて Claude Code 側を疑っていました。

順に手を動かしたのが以下です。

  • stdio が詰まっていないか: subprocess の stdout / stderr の pipe を PIPE から DEVNULL に変えたり、逆にバッファサイズを上げたり。変化なし。
  • protocol version mismatch: Agent SDK の version を 1 つ上げ下げしてみる。これも変化なし。
  • agent SDK の config: timeout 値 (init_timeout_ms 的なやつ) を 2 倍にしてみる。これは production のログに変化が出るかと思ったんですが、エラーが出る頻度はほぼ同じ。timeout が原因なら、引き伸ばせば確率は下がるはず。下がらない。
  • staging で再現させる: staging だと出ない。production だと出る。同じ image、同じ entrypoint、同じ Claude Code version。何が違う、と問い詰めること数時間。

この時点で 「Claude Code SDK が production の env var の何かで死んでいる」 みたいな仮説をいくつか立てて、env var を片っ端から binary search で staging と diff り始めていました。これがダメな方向に進んでいた典型例で、エラー文字列に意味を持たせすぎていたんですね。「Control request timeout: initialize」 という文字列を見ると、人間の脳が勝手に 「init phase の timeout」 という物語を作ってしまう。実際にはこの文字列は、SDK が 「子 process との通信が確立できないまま window が閉じた」 時の generic な文言でしかなくて、なぜ通信が確立できなかったのかは何も教えてくれていない。

ログを信じて深追いするのと、ログを疑って観測点を変えるのと、切り替えが遅かったというのが正直な反省です。

exit code を見るだけで終わる話だった

仮説が尽きてきたあたりで、ふと 「そもそも子 process はどう死んだんだ」 を確認していないことに気付きました。Python の subprocess.run は returncode を返してくれるので、これを wrapper の中で素直に出すだけです。

result = subprocess.run(
    claude_cli_cmd,
    capture_output=True,
    timeout=600,
)
logger.error(
    "claude code subprocess exited",
    returncode=result.returncode,
)

これを production に仕込んで再現を待ったら、出てきた値が -9 でした。

POSIX 上で subprocess の returncode が負の値の時、その絶対値は子 process を殺した signal の番号です。-9 は signal 9、つまり SIGKILL。

ここで頭の中の絵が一気に切り替わりました。SDK の handshake が timeout していたのではなく、Claude Code CLI が initialize の途中で OS に殺されていた。SDK 側から見ると 「子 process が応答せずに pipe が閉じた」 にしか見えないから、「Control request timeout: initialize」 とログに書く。文字列は嘘ではないけど、原因の手前で止まっている。

SIGKILL を 「外から誰でも送れる」 のは確かなんですが、Linux で身に覚えのない SIGKILL が飛んでくる代表選手は kernel の OOM killer です。ここからは Claude Code の話ではなく、OS の memory accounting の話になります。

OOM killer の犯人映像

dmesg を見たら一発でした。

Out of memory: Killed process 1842 (node) total-vm:2148364kB,
anon-rss:1456892kB, file-rss:0kB, shmem-rss:0kB, UID:1000

Claude Code CLI は内部的に Node ランタイムを起動して、そこで context を load して動きます。これがそこそこ重い。今回 production で実測したら、1 回の invocation で RSS が 500 MB 〜 1500 MB の間を動いていました。安定して 500 MB ではなくて、解析するリポジトリの大きさによって 1.5 GB まで膨らむ。

問題はこちら側の worker の sizing でした。analyze_code_specification を担当していた Celery worker は、もともと汎用の Python task 用に組まれていて、memory limit がそこまで大きくない。さらに Celery の default 通り、prefork で複数 task を 1 worker で並列に走らせていました。

つまり、production で何が起きていたかというと。

  1. ある時刻に analyze_code_specification が 2 つ enqueue される
  2. 同じ worker の別 child process が 2 つとも pickup する
  3. それぞれが Claude Code CLI を subprocess として起動する
  4. 2 つの CLI が並列で memory を膨らませ始める
  5. worker の memory ceiling を超える
  6. kernel OOM killer が起動して、一番でかい process (大抵 Claude Code の Node) を SIGKILL で落とす
  7. 親の Python から見ると、子の stdio が突然閉じて 「init handshake が応答しない」 となる
  8. SDK が 「Control request timeout: initialize」 を吐く

staging で出なかったのは単純で、staging では並列で analyze_code_specification が走るシナリオを踏んでいなかったからです。負荷を再現していないだけだった。

fix は 4 つの組み合わせ

直し方は分解すると 4 つあって、どれが欠けても再発します。

1. dedicated queue に分ける

まず Celery の task_routes を書き換えて、analyze_code_specification だけ analysis という新規 queue に流すようにしました。それ以外の task は今まで通り default や fixing、control_plane、plan_monitor に残します。

# celery_app.py
task_routes = {
    "tasks.analyze_code_specification": {"queue": "analysis"},
    "tasks.fix_issue":                   {"queue": "fixing"},
    "tasks.update_plan_state":           {"queue": "plan_monitor"},
    "tasks.sync_billing":                {"queue": "control_plane"},
    # ほかは default queue
}

queue を物理的に分けないと、次の 「専用 worker」 「concurrency=1」 がそもそも適用できないんですよね。「重い task は重い worker に」 を実現する前提条件です。

2. dedicated ECS Fargate worker tier を立てる

analysis queue だけを subscribe する worker を、専用の ECS Fargate task として動かすようにしました。memory は 8 GB (8,192 MB) 確保。汎用 worker の数倍です。

1 CLI invocation が peak 1.5 GB として、ヘッドルームを 5 GB 以上残す sizing。CLI の peak 自体が解析対象の repo size でブレるので、margin を厚めに取っています。Node の GC 挙動も含めると、tight に組むと結局また OOM を踏むので、ここは贅沢にしておきたいところでした。

3. concurrency = 1 で起動する

新 worker は明示的に --concurrency 1 で起動します。

celery -A app worker \
  -Q analysis \
  --concurrency 1 \
  --loglevel info \
  --max-tasks-per-child 50

ここが今回の事件で一番大事な部分です。memory を 8 GB に増やしたから 「2 並列くらいなら」 と concurrency を 2 にしたくなるんですが、それをやると 1.5 GB × 2 = 3 GB 前後で済まなさそうな日 (片方が 2 GB を超える日) が必ず来る。OOM killer は average ではなく peak で発動するので、 「大体大丈夫」 は成立しません。

加えて、Claude Code CLI を同一 instance で並列に走らせると、Node の起動コスト・file system cache の競合・stdout の混線、と別の問題も付いてきます。1 invocation 1 worker と割り切ると debug もずっと楽になる。

--max-tasks-per-child 50 は、長く動かすうちに Python 側の RSS がじわじわ伸びる病気の対策です。Claude Code 側というより、こちらの Celery worker プロセス自身の話。

4. メモリの算数を残しておく

最終的な配分はこの形に落ちました。

  • worker service: ECS Fargate 専用 tier (汎用 tier とは別 service)
  • memory: 8,192 MB
  • concurrency: 1
  • 1 invocation peak: 約 1,500 MB (worst case)
  • 同時実行数: 1
  • headroom: 6 GB 以上

ここの数字を README にも runbook にも書いておくのが重要で、半年後の自分が 「concurrency 1 は無駄だから 2 にしよう」 と思った時に止まれる。

テストとしては routing 周りに ピンポイント assertion を足しました。

  • analyze_code_specification は analysis queue に乗ること
  • control_plane 系 task は新 queue に rerouting されていないこと
  • plan_monitor の isolation が壊れていないこと

ここを test で固めないと、後から task_routes を弄った時にサイレントで戻る怖さがあります。

tradeoff の話

dedicated worker tier を立てると、見えやすいコストがいくつか付いてきます。

  • infra cost が単純に増える。専用 instance を常時起動するので、idle 時間ぶんは丸ごと無駄になる。
  • scale-out の応答が遅い。汎用 worker は既に warm な instance に task が積まれるだけだけど、analysis tier はもともと数が少ないので、burst で来た時の wait が出やすい。
  • 監視対象がもう 1 つ増える。alert ルール、metrics の dashboard、deploy pipeline、全部追加。
  • queue の死活も別個にケアが必要。analysis queue が詰まっていても default queue は健康、という状態が起きうる。

それでも分ける判断をしたのは、analyze_code_specification だけが memory profile も latency profile も他と全然別物だからです。これを汎用 worker に同居させ続けると、他の軽い task まで OOM の巻き添えで殺される。「重い neighbor が他の住人を巻き込む」 のを止めるのが、今回の routing の本当の目的でした。

最初から queue を分けておけば良かった、というのが正直なところです。

この debug から残った教訓

今回の件で 2 つだけ、自分の中に残しておくべき教訓があります。

1 つ目。AI CLI を subprocess で抱える Python service の memory accounting は、普通の Python task と完全に別世界。CLI 側は自前で JS runtime や Python runtime や ML model を抱え込むので、「親 worker から見えない巨大な子」 が必ず付いてくる。Celery の concurrency は Python 側の同時実行数しか見ていなくて、子 process の memory までは面倒を見てくれません。worker の sizing は、子 process の peak RSS を主役にして組む必要がある。

2 つ目。誤誘導する error string を見たら、まず exit code を見る。今回の場合、Control request timeout: initialize という文字列は技術的に間違いではないけど、「子 process が initialize 中に何かでコケた」 までしか言っていません。なぜコケたのかは、その文字列を出した SDK は知らない。OS が出した SIGKILL かもしれないし、子 process が assertion で落ちたのかもしれないし、segfault かもしれない。returncode を 1 行 log に足すだけで、その分岐がたいてい解決します。早めにやるほど時間が浮く。

このあたりは、AI CLI を自社サービスに組み込む時に毎回どこかで踏む地雷だと思うので、共有しておきます。

Codens (https://www.codens.ai/) では、こういう 「AI を production に載せた時の地味な OS レイヤの戦い」 を踏み抜いた分だけ harness として固めています。同じ穴に落ちる人を 1 人でも減らせれば、この記事の役目は終わりです。

Discussion