AIエージェントの最初の診断が間違っていたとき:ログが示した6件

AIコーディングエージェントが自信を持って間違えた6件。MySQLの接続上限、PHPのinclude階層、robots.txtの順序、CDN、スマホでの図、シェルのループ。それを示したログと計測の記録。

AIコーディングエージェントに本番の障害調査や修正を任せている、あるいは任せようとしている開発者向けの記事です。エージェントは間違えるとき、実際にはどう間違えるのか。本番サイトとアプリのAPIをAIエージェントと4日間運用するあいだに、最初の説明が自信たっぷりで、もっともらしく、しかも間違っていた例が6件集まりました。どれも同じ方法で捕まえています。コードを読み込むことではなく、ログ、パーサー、計測のどれかが反対の結果を出したことです。

AIコーディングエージェントに本番サーバーを触らせる:効いたガードレールで紹介した5つのミスとは別物です。あちらは生成物の誤りでした。今回は思い込みの誤りです。上限の数え方、ディレクトリの深さ、パーサーの読み方についての思い込みでした。各事例は「前提 → 確認 → 証拠 → 修正」の順で書きます。

ループ図。エージェントが原因を述べる。次に、その原因が間違いだと示せるチェック(ログの行、パーサー、スクリーンショットなど)を選ぶ。証拠が一致すれば修正し、チェックは残す。一致しなければ診断を見直して、もう一度チェックする。
以下のすべての事例がたどった流れ。診断は、ログか計測が裏づけて初めて修正になった。

事例1:「全員が1時間あたり1つの枠を共有している」

前提。 共用サーバー上のcronが、MySQLのエラー1226(max_connections_per_hour、上限500)で失敗しました。エージェントの診断はこうです。アプリのAPI、cron、旧ページはすべて同じDBユーザーでログインするので、1時間500回の枠を全員で分け合っている。APIの通信が多いせいでcronの分がなくなった。筋は通っていて、私たちはその説明で記事も公開しました。

確認。 誰が枠を使っているかを知るため、エージェントは共通のDB接続関数に1行のロガーを入れました。接続のたびに時刻、出どころ、クライアントの種類を書くだけで、応答の中身は変えていません。

証拠。 数時間でログが診断を否定しました。夜の2時間、アプリのAPIだけで1,557回と1,503回の接続があり、上限のおよそ3倍なのに、リクエストはすべて成功していました。共有の枠が500しかないなら失敗しているはずです。違いは接続経路でした。APIは localhost で接続し、失敗したcronはDBサーバーのリモートのホスト名で接続していました。外部のクローラーと同じ経路です。

修正。 MySQLのアカウントは user@host 単位で、上限はローカルではなくリモート経路のほうで数えられていました。cronはまずローカル接続を試すようにし、記事も同じ日の夜に、新しい計測で何が変わったかを書き足して訂正しました。詳しくはMySQL 1226 max_connections_per_hour:共用サーバーでの対処にあります。

教訓。 最初の診断はドキュメントと推論から組み立てたものでした。2つ目は数えた結果です。正しかったのは2つ目だけでした。

事例2:「5階層上がホームディレクトリ」

前提。 接続ロガーは、Web公開領域の外、アカウントのホーム下の非公開フォルダに置きました。旧PHPファイル10個からこれを読み込む必要があり、エージェントは @include_once(dirname(__FILE__, 5) . '/<private>/connlog.php') と書いて、「5階層上がホーム」とコメントしました。@ は意図的です。ロガーがなくてもページは動かなければならないからです。

確認。 デプロイ後、エージェントは「ページが表示される」で終わらせませんでした。その日のログをサーバーから取得し、出どころ別に行数を数えました。

証拠。

new-format lines: 22
[(('api', 'dart'), 22)]

22行すべてがアプリのAPIからで、旧ページからの行は0でした。直前にエージェント自身が旧ページを何度か開いていたにもかかわらずです。ページのバイト列はデプロイ前と同じでした。そこが問題でした。ページを守るための @ が、失敗まで隠していたのです。このパスは間違えやすいものです。同じ構造をダミーの名前で再現し、PHP 8.5で実行しました。

<?php
// A file inside the web root of a shared host (placeholder path)
$file = '/home/user/domains/example.com/www/app/lib/db.php';
foreach ([1, 5, 6] as $n) {
    printf("dirname(\$file, %d) = %s\n", $n, dirname($file, $n));
}
// What @include_once does with a missing file: nothing visible
$r = @include_once dirname($file, 5) . '/private/log.php';
var_dump($r);
dirname($file, 1) = /home/user/domains/example.com/www/app/lib
dirname($file, 5) = /home/user/domains
dirname($file, 6) = /home/user
bool(false)

エージェントは lib/ より上のフォルダを数えていましたが、dirname() はファイルから数えます。1階層目はファイル自身のフォルダなので、ホームに届くには5ではなく6階層必要でした。

修正。 10ファイルすべてを dirname(__FILE__, 6) にして再デプロイし、ログを読み直しました。旧ページの行が2行現れ、ページのバイト列は相変わらず同一でした。

教訓。 失敗が設計上「静か」なら、成功の証拠は期待した副作用しかありません。それを確かめること。

事例3:「まず全部許可して、例外を並べる」

前提。 スクレイパー対策で robots.txt にルールを足しました。一般向けのグループは、すでに Allow: / の後にAPIや旧アプリ画面の Disallow: が並ぶ形でした。全部許可してから例外を書く。自然に読めます。

確認。 デプロイ前に、エージェントはビルド済みのファイルをPythonの標準ライブラリ urllib.robotparser にかけ、(ボット, パス)の組と期待する答えを並べて確かめました。

証拠。 Googlebot /api/v1/x 허용 と出ました。허용は韓国語で「許可」です。ブロックしたはずのパスでした。Pythonのパーサーは最初に一致したルールを使い、Allow: / はすべてに一致します。Googleは最長一致の規則を公開しているので、Googlebot自身ならブロックしたはずです。ただ、すべてのクローラーがGoogleの規則に従うわけではありません。最小の再現です(Python 3.9)。

from urllib.robotparser import RobotFileParser

ALLOW_FIRST = """User-agent: *
Allow: /
Disallow: /api/
Disallow: /legacy-app/
"""
DISALLOW_FIRST = """User-agent: *
Disallow: /api/
Disallow: /legacy-app/
Allow: /
"""
for name, text in [("Allow first", ALLOW_FIRST), ("Disallow first", DISALLOW_FIRST)]:
    rp = RobotFileParser()
    rp.parse(text.splitlines())
    print(name)
    for path in ["/api/v1/list", "/legacy-app/page.php", "/en/some-post/"]:
        print(f"  {path:22} {'allowed' if rp.can_fetch('Googlebot', 'https://example.com' + path) else 'blocked'}")
Allow first
  /api/v1/list           allowed
  /legacy-app/page.php   allowed
  /en/some-post/         allowed
Disallow first
  /api/v1/list           blocked
  /legacy-app/page.php   blocked
  /en/some-post/         allowed

修正。 Disallow の行を Allow: / より前に移しました。この順なら、先勝ちのパーサーでも最長一致のパーサーでも答えが同じになります。パーサーでもう一度確認し、デプロイ後に公開中のファイルを取得して順序を確かめました。

図。Allow: / が Disallow: /api/ より前にあるグループで、ボットが /api/v1/list を求める。Python の urllib.robotparser のような先勝ちのパーサーは Allow: / で止まり、許可する。Google が説明している最長一致のパーサーは、より長い Disallow: /api/ を選んでブロックする。Disallow の行を先に置けば、どちらのパーサーでもブロックされる。
robots.txt の1つのグループ内で行の順序が効く理由。Allow: / が先頭にあると、先勝ちのパーサーは塞いだつもりのパスに入れてしまう。

教訓。 「Googleにとって正しい」と「正しい」は別の主張です。読み方の違うパーサーでも試すこと。

事例4:「GooglebotのUAを送れば、Googlebotの見え方が分かる」

前提。 同じ変更で、旧ページに来る行儀の悪いクローラーへ403を返す .htaccess のルールも足しました。検索エンジンは影響を受けてはいけません。エージェントはテストを1つ加えました。GooglebotのUser-Agentで旧ページを要求し、200を期待するものです。

確認。 いつもどおり、本番サーバー上の使い捨てフォルダでルール一式を試しました。

証拠。 そのケース以外はすべて合格でした(テストの表示は韓国語です。봇차단=ボット遮断、옛 화면=旧画面、앱=アプリ、안드로이드 웹뷰=AndroidのWebView)。

OK   403 GET  봇차단: AhrefsBot → 옛 화면 403
OK   200 GET  앱 Dart → API 200
OK   200 GET  안드로이드 웹뷰 → 옛 화면 200
FAIL 403 GET  Googlebot → 옛 화면 200

最初の見立ては「新しいルールが広く当たりすぎた」でした。エージェントは、ルールを直す前にその見立てを確かめました。同じGooglebotの文字列を、ルールの対象外のページ(ブログのトップと記事1本)に送ると、どちらも403でした。BingbotのUser-Agentでも403です。私たちのルールではあり得ません。ホスティングのCDNが、GooglebotやBingbotを名乗りながらそのネットワークから来ていないリクエストを、サイト全体で拒否していたのです。

修正。 問題はルールではなかったので、ルールはそのまま残しました。テストケースのほうを外し、偽のGooglebotでは外部からテストできない理由をコメントに残しました。本物のGooglebotからの見え方は、本物のGooglebotでリクエストを送るSearch ConsoleのURL検査でしか確認できません。

教訓。 失敗したテストは、自分が書いていない層も含めた経路全体についての証拠です。コードを直す前に、どの層が拒否したのかを突き止めること。

事例5:「図は問題ない」と思っていたら、スマホ幅では重なっていた

前提。 本文の図はYAMLから生成するSVGで、スマホ用に縦配置版も自動で作ります。縦配置の列の間隔は28pxでした。デスクトップでは問題なく見え、幅のチェックも警告0でした。

確認。 古い記事に図を追加するエージェントには、縦配置版も含めてPNGに描画し、目で見ることを義務づけていました。

証拠。 複数のエージェントが別々に同じことを報告しました。スマホ配置の横向きの矢印で、ラベル(「はい」「いいえ」や短い条件)が箱の枠線に重なる。ある報告は原因まで書いていました。「その列の間隔が28pxしかない」。幅のチェックでは見えません。広すぎるものはなく、ただ重なっていただけだからです。

修正。 描画コードの1行で間隔を28pxから54pxにしました。その時点の図41個をすべて再チェックしてエラー0・警告0、メインセッションがヘッドレスブラウザで2つの図を358px幅で撮って結果を確かめました。

OGカードの日本語でも同じ種類の失敗をしています。最初の改行処理は「本番」の「本」と「番」のあいだのように単語の途中で改行していて、描画されたカードを人が見るまで、どのチェックも通っていました。直し方はPillowでOG画像を自動生成:日本語タイトルの改行と禁則処理にあります。

教訓。 見た目に関わるものは、実際に使われる大きさのスクリーンショットまでがテストです。

事例6:「未使用画像75枚は全部移した」。この記事の執筆中に発覚

前提。 古い記事54本の改訂後、メインセッションはどの記事からも参照されない旧画像75枚を一覧にしてファイルに書き、シェルのループで1枚ずつローカルのバックアップへ移しました。その後、デプロイでサーバーからも削除しました。

確認。 当時はこれを確かめるチェックがありませんでした。見つけたのは、この記事のために数え直したときです。同じ未使用画像のスクリプトを今日実行した結果です。

29 files, 28 referenced, 1 unused
   /static/img/legacy/2021/07/st.jpg

証拠。 一覧に載っていたのに、なぜ残ったのか。一覧ファイルには75件ありましたが、最後の行の後ろに改行がなく、素の while read ループは改行のない最終行を読み落とします。当日のログにはすでに食い違いが出ていました。一覧の unused: 75 と、ドライランの prune would delete: 74 です。2つの数を比べた人がいなかっただけでした。zshでの再現です。

printf '/img/a.png\n/img/b.png\n/img/c.jpg' > list.txt
echo "lines by wc -l: $(wc -l < list.txt)   entries by grep -c: $(grep -c . list.txt)"
echo "-- while read"; while read u; do echo "move $u"; done < list.txt
echo "-- while read || [ -n ]"; while read -r u || [ -n "$u" ]; do echo "move $u"; done < list.txt
lines by wc -l:        2   entries by grep -c: 3
-- while read
move /img/a.png
move /img/b.png
-- while read || [ -n ]
move /img/a.png
move /img/b.png
move /img/c.jpg

漏れたのは第三者の商品写真でした。どの記事にも使われていないのに、古いURLでは公開されたままでした。この記事のために数えていて見つけたもので、この記事を公開するのと同じデプロイで削除しています。

修正。 while read -r u || [ -n "$u" ] を使うこと。そして、一覧の件数、移した件数、削除した件数が一致するまで、片づけを完了と呼ばないことです。

棒グラフ。未使用として一覧に出た画像は75件。それを移動するシェルのループが処理したのは74件。サーバー側で削除されたのも74件。1件は移動されず、公開されたまま残った。
同じ片づけ作業から出た、本来は一致するはずの3つの数。1件の差は当日のログに出ていたが、この記事のために数え直すまで誰も比べていなかった。

6件に共通すること

事例 エージェントの思い込み 反対の結果を出したチェック
MySQL 1226 全クライアントで1つの枠 接続ごとのログ:localhostで1時間約1,500回が成功
includeの階層 5階層上がホーム 出るはずのログ:旧ページからは0行
robots.txt Allowが先でも問題ない 先勝ちの標準パーサー:塞いだパスが許可
偽のGooglebot テストは自分のルールを見ている ルールの対象外のページでも同じ403
スマホの図 幅の警告がなければ問題ない 縦配置を描画したPNG
画像の片づけ 75枚の一覧なら75枚移した 一覧75、ドライラン74、ファイルは配信中

どれも特殊な話ではありません。経験のある開発者でも同じ思い込みをするでしょう。エージェントに必要だったのは賢さではなく、自分の間違いを示せるチェックと、完了と言う前にそれを実行することでした。

チェックリスト:エージェントに証明させる

AIエージェントの「直しました」を受け取る前に、主張に合った証拠を求めます。

  1. 「原因はXです」:Xが偽なら違って見えるはずの計測を出させる。文章ではなく、件数、ログ、時間で。
  2. 「変更は動いています」:それを示す副作用(ログの行、ヘッダー、DBの行)を名指しさせ、デプロイ後に見せさせる。「エラーなし」だけで済ませない。
  3. 「安全のためにエラーは抑えています」:それなら、コードが実際に動いたという積極的な証拠を出させる。エラーは何も教えてくれないので。
  4. 「このファイルは正しいです」:気にしているものとは読み方の違う標準パーサーにかけさせる。
  5. 「テストが落ちたのは今回の変更のせいです」:変更が効かない場所で同じリクエストを繰り返させる。それでも落ちるなら、原因は別にある。
  6. 「見た目は問題ありません」:利用者が見る大きさで、改行の仕方が違う言語ごとにスクリーンショットを出させる。
  7. 「N件すべて処理しました」:入力N件、処理N件、出力N件を並べて比べさせる。
  8. チェックは残す。 上のチェックはすべてスクリプトかメモに残してあるので、同じ思い込みは次にもっと早く捕まります。

エージェントの速さはコードを書く力から来ています。信頼性はこうしたチェックから来ていて、求めるのに大した手間はかかりません。

よくある質問

これはハルシネーションだった?

いいえ。どれも筋の通った前提が、このサーバーではたまたま偽だったケースです。上限の数え方、パスの階層数、パーサーの読み方、CDNのユーザーエージェントの扱い。だからコードを読み直しても見つからず、ログや計測で見つかりました。

こうした誤りを一番安く捕まえる方法は?

主張が間違いだと示せるチェックを求め、完了と言う前に実行させることです。今回なら、出るはずのログの行、実ファイルにかけた標準パーサー、スマホ幅のスクリーンショット、一致するはずの2つの件数でした。

利用者に影響したものは?

短期間ですが1件あります。MySQLのエラー原因を誤って説明した記事が、同じ日の夜に新しい計測で訂正されるまで公開されていました。また、片づけの後も未使用の画像が1枚公開されたままで、この記事を書く途中で見つかりました。残りはデプロイ前か直後に捕まえ、目に見える影響はありませんでした。

  • #AIエージェント
  • #Claude Code
  • #デバッグ
  • #ログ
  • #検証
  • #運用

t.laboratory

実際に作って運用しているアプリ・サーバー・サービスで起きた問題と、その解決に使ったコードを記録する技術ブログです。

運営者情報 · アプリ

↑