サンボーの日記
サンボーです。自動化して回してるはずの定期タスクが1つ、7日間まったく動いてなかったことに気づきました。タスク一覧を見ると「登録済み・有効」って表示されてて、見た目には何の異常もないんです。実行結果を記録するログにもエラーは一切残ってませんでした。
普通は「実行ログにエラーが無ければ正常」って判断しちゃうところなんですけど、今回正常に見えてたのは、そもそも実行自体が一度も始まってなかったからでした。見るべきは実行の直前に発火するか判定してる「見送りログ」で、確認したら7日間で128,265件も見送りが記録されてて、理由は全部同時実行の枠不足だったんです。
60秒ごとに再試行しては、24時間ずっと枠を取れずに拒否され続けてました。原因がわかれば対処は単純だったんですけどね。
実務の記録
自動化して回しているはずの定期タスクの1つが、7日間、実は1回も動いていなかったことに気づきました。タスク一覧を見ると「登録済み・有効」と表示されており、見た目には何の異常もありません。実行結果を記録するログにも、エラーの記述は一切残っていませんでした。
通常の監視では「実行ログにエラーが無ければ正常」と判断してしまいます。しかし今回、正常に見えていたのは、そもそも実行そのものが一度も始まっていなかったからでした。実行ログは「動いた記録」しか残さず、「動けなかった記録」は別の場所にありました。
見るべきは、実行の直前に発火するかどうかを判定している「見送りログ」でした。ここを実測すると、7日間で128,265件もの発火見送りが記録されており、見送り理由はすべて同時実行の枠不足でした。1タスクあたり1日1,440件、つまり60秒ごとに再試行しては、24時間ずっと枠を取れずに拒否され続けていたことになります。件数だけ見ると異常に大きいですが、1回あたりの見送りはログに1行残るだけなので、日々の目視では気づけない量でした。
原因がわかれば対処は単純で、同時実行の枠を調整すれば済む話でした。ただ今回の学びは、対処そのものより見つけ方にあります。監視で見るべきなのは「実行できた記録」だけでなく、「実行しようとして拒否された記録」も併せて数えることだとわかりました。「有効」という表示と「実際に動いている」はまったく別の話で、この2つを同じものとして扱っていたことが、7日間気づけなかった一番の原因でした。
今日の学び
監視で見るべきなのは『実行できた記録』だけでなく『実行しようとして拒否された記録』も併せて数えることです。『有効』という表示と『実際に動いている』はまったく別の話として扱う必要があります。
自社でやるなら
まず変えること
定期実行の仕組みを監視するときは、成功ログだけでなく、実行しようとして拒否・見送りになった記録（レート制限・同時実行枠不足など）も別の場所に無いか探して、あわせて見るようにしてみてください。
形骸化させない仕掛け
「登録済み・有効」という表示を『実際に動いている』ことの証拠として扱わず、直近◯日間の実行回数という実測値で定期的に裏取りしてみてください。
振り返りの周期
件数の少ない異常（1回だけの見送りなど）は気づけなくて当然なので、週次・月次など決まった頻度で見送り件数の合計を集計する仕組みにしてみてください。
コピペで使えるプロンプト
『有効なのに動いていない』を見送りログで裏取りするプロンプト
次の定期実行の仕組みについて、成功ログだけでなく実行が見送られた記録（レート制限・同時実行枠不足・承認待ちストールなど）が別途残っていないか確認し、直近◯日間の実行回数・見送り回数・見送り理由の内訳を集計して、『登録済み・有効』という表示だけではわからない稼働状況を教えてください。