自動化のログ設計：0件を数字で残さないと故障に気づけない

「対象なし」は情報がゼロに近い

私が動かしていた自動化スクリプトは、処理対象が0件だったときにログへ対象なしとだけ書いていました。動いた証拠にはなるし、エラーも出ていないので、当時はそれで十分だと思っていました。

ところが実際には、3日連続で1件も処理できていない状態に、画面から気づけませんでした。ログを開いても「対象なし」が並んでいるだけで、それが「今日はたまたま対象がなかった」のか「ずっと0件が続いている」のかを、目で区別できなかったからです。

原因：押せたけれど、変わっていなかった

原因は外部サービスのUI変更でした。ボタンは押せる状態にあり、スクリプトはクリック操作まで完走します。しかし押した結果として状態が変わっていませんでした。

この形の故障がやっかいなのは、例外が飛ばないことです。クリックに成功した時点で処理は「成功」として次に進み、最後まで走り切って終了します。ログ上は正常終了に見えていました。監視の側から見ると、失敗が1件も記録されない故障です。

対策1：0件でも必ず数字で書く

まず、ログの書き方を変えました。処理件数は、たとえ0でも必ず数字として出します。

解除 0件 / 保護 41件

この形にすると、0という数字がログに並ぶようになります。文字列の「対象なし」と違い、数字であれば時系列で並べたときに「ずっと0が続いている」ことが形として見えます。集計やグラフに乗せることもできます。

対策2：押せた ≠ 変わった

2つ目は、操作したあとに状態が変わったかどうかを確認することです。今回の故障は「ボタンは押せるが状態が変わらない」というものでした。つまり、操作の成否だけを見ていては絶対に検出できません。

• 操作が例外なく終わったこと … これは成功の証拠にならない
• 操作後に対象の状態が期待どおりに変わったこと … ここまで確認して初めて成功

自動化を書いているとき、私は無意識に「クリックが通った＝やった」と考えていました。そこが間違いでした。押せたことと、変わったことは別の事実です。

対策3：手動実行も、同じ経路を通す

3つ目は運用側の話です。動作確認のためにスクリプトを直接叩くと、cronやタスクスケジューラ経由で動いたときとは記録の残り方が変わります。直接叩いた分は記録に残らず、グラフが嘘をつきます。

「手動で試したときは動いた」という記憶だけが残り、ログには何も残らない。あとから履歴を見返したときに、実際の稼働状況と食い違います。なので手動で実行するときも、cronやタスクと同じ経路（ログに残る形）で実行するようにしました。

まだ分かっていないこと

正直に書くと、この対策で「同種の故障をすべて検出できる」とは言えません。今回分かったのは、ボタンは押せるが状態が変わらないという壊れ方が実在し、それがエラーとして表面化しないという1点です。他にどんな沈黙する故障の形があるのかは、私はまだ把握できていません。0件が続いたときに自動で知らせる仕組みをどう組むかも、まだ決めきれていません。

それでも、0を数字で残しておけば、少なくともあとから「おかしい」と気づく材料は手元に残ります。気づけなかった3日間の一番の問題は、故障そのものより、判断材料がログに存在しなかったことでした。