成功したAIタスクが、1時間後に「タイムアウト」と記録されていた。出力が4,096バイトを1バイト超えた回だけ、ワーカーが止まっていた話

8月の終わり、AIワーカーのログを見返していて、数字が合わないことに気づきました。

うちでは、Redmine に積んだチケットを PowerShell のワーカーが1件ずつ拾い、Claude Code をヘッドレス（--print）で起動して処理させています。ワーカーは実行が終わるたびに「完了」「エラー」「タイムアウト」のどれかをログに残します。そのタイムアウトの中に、チケット側はとっくに「AI処理完了」になっていて、完了レポートも最後まで書かれているものが混ざっていました。

仕事は終わっているのに、ワーカーは3600秒待ってから「タイムアウト」と書いていた。しかも、そうなっていたのは完了レポートが長いタスクばかりでした。丁寧に報告したタスクほど、失敗として数えられていたことになります。

品質の仕事をしていると「測れないものは改善できない」とよく言います。今回は測れていないどころか、測った結果が逆を向いていました。記録が間違っていると、その上で何を議論しても全部ずれます。なので原因を境界値まで詰めて、受け入れ基準として書き残しておくことにしました。

ワーカーは「待ってから読む」順番で書かれていた

修正前のワーカーは、要点だけ抜き出すと次の形でした。

# 修正前（要点だけ抜き出したもの）
$psi = New-Object System.Diagnostics.ProcessStartInfo
$psi.FileName  = 'cmd.exe'
$psi.Arguments = '/c claude --print --output-format json ... < prompt.txt'
$psi.UseShellExecute        = $false
$psi.RedirectStandardOutput = $true   # 結果の JSON を受け取りたい
$psi.RedirectStandardError  = $true   # エラーも残したい

$p = [System.Diagnostics.Process]::Start($psi)
$completed = $p.WaitForExit($TaskTimeout * 1000)   # まず終わるのを待つ（最大3600秒）

$raw    = $p.StandardOutput.ReadToEnd()            # 終わってから読む
$stderr = $p.StandardError.ReadToEnd()
if (-not $completed) { Write-Log 'ERROR' 'タイムアウト' }

読みやすいし、普段はちゃんと動いていました。ここが厄介なところなんですよね。

子プロセスの標準出力は、親との間のパイプを通ります。パイプには決まった大きさのバッファがあり、それがいっぱいになると、子は親が読んでくれるまで書き込みの途中で待たされます。一方の親は、子が終わるまで WaitForExit で待っている。子は親を、親は子を待つので、どちらも動けません。

--output-format json は、最後に結果をひとまとまりの JSON で書き出します。だから結果が短い日は何も起きず、長い日だけ止まる。止まった実行は3600秒後にタイムアウトとして処理され、その時点で仕事そのものは終わっている、という流れでした。

実はこの順番が危ないことは、.NET の Process.StandardOutput のドキュメントにちゃんと書いてあるんですよね。ReadToEnd より先に WaitForExit を呼ぶと、子の出力がバッファを埋めたときにデッドロックしうる、と。正直なところ、知識としては知っていたのに、自分たちのワーカーの話だとは結びついていませんでした。

「どこから止まるのか」を境界値で測る

テストは目的ではなく手段です。今回知りたかったのは「何バイトから止まるのか」で、それが分からないと受け入れ基準が書けません。そこで本物の Claude Code の代わりに、指定したバイト数を一度に書いて終わるだけの偽のエージェントを用意し、修正前と同じ順番で測りました。環境は Windows 11、Windows PowerShell 5.1、Node.js 22.14.0 です。

# 偽のエージェント: 指定バイト数を stdout か stderr に一度に書いて終わるだけ
function Start-FakeAgent([int]$Bytes, [string]$Stream = 'stdout') {
    $psi = New-Object System.Diagnostics.ProcessStartInfo
    $psi.FileName  = 'cmd.exe'
    $psi.Arguments = "/c node -e `"process.$Stream.write('x'.repeat($Bytes))`""
    $psi.UseShellExecute        = $false
    $psi.RedirectStandardOutput = $true
    $psi.RedirectStandardError  = $true
    $psi.CreateNoWindow         = $true
    [System.Diagnostics.Process]::Start($psi)
}

foreach ($n in 4095, 4096, 4097, 65536) {
    $p = Start-FakeAgent $n
    $exited = $p.WaitForExit(5000)            # 修正前と同じ「先に待つ」
    if (-not $exited) { taskkill /T /F /PID $p.Id | Out-Null }
    $got = $p.StandardOutput.ReadToEnd().Length
    '{0,6} バイト  終了={1,-5}  読めた={2}' -f $n, $exited, $got
}
# 実行結果:
#   4095 バイト  終了=True   読めた=4095
#   4096 バイト  終了=True   読めた=4096
#   4097 バイト  終了=False  読めた=0
#  65536 バイト  終了=False  読めた=0

4,096バイトまでは0.1秒もかからずに終わり、4,097バイトで止まりました。差は1バイトです。stderr 側に書かせても境界は同じで、4,096は通り、4,097で止まります。

想定外だったのは「読めた=0」のほうでした。止まった子プロセスを強制終了してから読めば、少なくともバッファに入っていた4,096バイトは取れるだろうと思っていたんです。実際には1バイトも残っていませんでした。4,097バイトを一度に書こうとした書き込みが丸ごと待たされていて、パイプには何も渡っていなかった、ということだと思います。本番に置き換えると、タイムアウト後に結果の JSON を探しても空で、完了を知らせる文字列も見えない。ワーカーは「タイムアウト」と書くしかなかったわけです。

では、普段の出力はどのくらいの大きさなのか。修正後の9月17日から今日までの実行ログ94回分で、結果の本文だけを数えてみました。最小2,179バイト、中央値3,282バイト、最大5,027バイト。本文だけで4,096バイトを超えたのは94回中7回です。実際の標準出力は、これにトークン数や所要時間を足した JSON なので、境界を越える回はもっと多くなります。

中央値で見ても、境界まで800バイトほどしか余裕がありません。日本語は1文字3バイトなので、完了レポートが300字長くなれば越えます。何か月も動いていたのは、たまたま境界の手前で使っていたからにすぎませんでした。動いた＝品質OK ではない、の典型です。

最初の修正案は「読む順番を入れ替える」だった

最初に思いついたのは、待つ前に stdout を読み切ってしまう案です。終わるまで読み続ければ、子が書き込みで止まることはない、という理屈でした。

# 最初の修正案: stdout を読み切ってから stderr を読み、最後に待つ
$p = Start-FakeAgent 4097 'stderr'
$read = $p.StandardOutput.ReadToEndAsync()   # 同期の ReadToEnd だと戻らないので5秒で見切る
'stdout を5秒以内に読み切れた: {0}' -f $read.Wait(5000)
taskkill /T /F /PID $p.Id | Out-Null
# 実行結果:
# stdout を5秒以内に読み切れた: False

stdout に10MBを流しても、0.2秒かからずに通ります。ところが stderr に4,097バイトを書かせると止まりました。子は stderr のバッファが空くのを待っていて、親は stdout が閉じるのを待っている。順番を入れ替えても、詰まる場所が stderr に移っただけでした。

あとでドキュメントを読み返したら、stdout と stderr の両方を同期で読むときの同じ問題も、同じページに書いてありました。Claude Code は普段 stderr にほとんど書きませんが、警告やエラーが重なる日がないとは言えません。片方だけ守る直し方は採らないことにしました。

両方を読み始めてから待つ

結局、待つ前に stdout と stderr の両方を非同期で読み始める形にしました。合わせて、本当にタイムアウトしたときの止め方と、結果の拾い方も見直しています。

$p = [System.Diagnostics.Process]::Start($psi)   # cmd /c claude --print --output-format json ...

# 1. 待つ前に、両方のストリームを読み始める
$outTask = $p.StandardOutput.ReadToEndAsync()
$errTask = $p.StandardError.ReadToEndAsync()

$completed = $p.WaitForExit($TaskTimeout * 1000)
if (-not $completed) {
    # 2. 本当のタイムアウト。$p は cmd なので Kill() だと子の claude が残る。ツリーごと止める
    taskkill /T /F /PID $p.Id | Out-Null
}

# 3. 止めてから回収する（読み終わるのを最大30秒待つ）
$null = $outTask.Wait(30000); $null = $errTask.Wait(30000)
$raw = if ($outTask.IsCompleted -and -not $outTask.IsFaulted) { $outTask.Result } else { '' }

# 4. 待ちが空振りしても、出力に完了マーカーがあれば結果を採用する
#    改善の余地あり: 「どこかに含まれていれば一致」なので最終行を見ていない。
#    エージェントが指示文を引用しただけでも、完了と判定されうる
if (-not $completed -and $raw -match 'AGENT:(TASK_DONE|NO_TASK|ERROR)') { $completed = $true }

見落としやすいのは、$p が cmd /c で起動した cmd のプロセスで、Claude Code 本体はその子だという点です。Kill() は cmd だけを止めるので、本体が残ってパイプを握り続けることがあります。タイムアウトのときは taskkill /T でプロセスツリーごと止めてから出力を回収する、という順番にしました。

同じ偽のエージェントで3つの読み方を並べると、こうなりました。各セルは5秒以内に終わったかどうかと、起動を含めてかかった時間です。

両方を読み始める形なら、10MBでも0.1秒前後で全量が取れます。境界の手前も向こう側も同じように扱えるようになった、というのが一番大きいところです。

受け入れ基準として書き残す

直したら終わり、にはしたくありませんでした。同じ種類の事故は、ワーカーを別の言語で書き直したときや、出力形式を stream-json に変えたときにまた起きます。なのでワーカーの受け入れ基準を、具体的な値で書いておきました。

4つのうち、胸を張って満たしていると言えるのは1つ目だけです。ここは好みが分かれるところですが、私は未達の基準も表から消さずに残す派です。消すと、満たしていないことまで一緒に忘れるので。

3つ目の「成否を終了コードだけで決めない」は、ヘッドレス実行全般に言えることだと思っています。ヘッドレスのエージェントは、許可が足りずに何もしないまま終了コード0で終わることもあります。逆に今回のように、仕事を終えたのに外からは失敗に見えることもある。プロセスの終わり方と仕事の終わり方は別物なので、チケットのステータスという外側の記録と突き合わせて判定するのが安全です。

振り返って

今思えば、最初に疑うべきだったのは集計のほうでした。タイムアウトが「長いレポートのタスク」に偏っていた時点で、エージェントではなくワーカー側の問題だと気づけたはずです。失敗の偏りは、原因の場所を教えてくれます。

この先やりたいことは3つあります。ひとつは、ワーカーのテストで使っている偽の claude に、4,096 / 4,097 / 10MB を吐くケースを足すこと。いまの偽物は短い JSON しか返さないので、今回の事故はテストでは再現しません。もうひとつは、完了マーカーの判定を最終行に限ること。最後に、タイムアウトとして記録された実行を週に一度抜き出して、チケット側が完了になっていないか突き合わせる仕組みを入れたいと考えています。

記録が正しくなって、ようやく「どのタスクが本当に遅いのか」の話ができるようになります。そこまで進んだら、また数字を出して書くつもりです。