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

自動化のログに「対象なし」とだけ書いていたせいで、3日連続で1件も処理できていない状態に気づけませんでした。エラーが出ない故障をどう見つけるか、実際に踏んだ穴と、その後に変えた3つのログ設計を書きます。

「対象なし」は、何も言っていないのと同じでした

自動化を回していると、処理対象がゼロの日は普通にあります。私はそれを対象なしの一言でログに書いていました。短くて読みやすいし、実際その日は何もしなくていいわけですから、当時は何の疑問もありませんでした。

ところが、この書き方には決定的な欠陥がありました。「本当に対象がゼロだった」のか「対象を見つけられなくなっていた」のかが、ログから区別できないのです。どちらの場合も、画面には同じ「対象なし」が並びます。

失敗したこと

3日連続で1件も処理できていない状態に、画面から気づけませんでした。ログは3日とも「対象なし」。静かな日が続いているようにしか見えませんでした。

原因は、外部サービスのUI変更でした。厄介だったのは、ボタンは押せるという点です。押下自体は成功するので、処理は例外を投げずに最後まで走りきります。けれど、押した後の状態が変わっていない。目的は何ひとつ達成されていないのに、ログ上は正常終了に見えていました。

ここが今回いちばん学んだところです。監視というと、つい「エラーを検知する」方向に頭が向きます。でも今回のようにエラーが一度も出ない故障は、エラー監視では絶対に引っかかりません。落ちてくれたほうがまだ親切だった、というのが正直な感想です。

実測

3日連続で0件

エラーログはゼロ。すべて「正常終了」として記録されていました

まずログの書式を変えました。件数がゼロであっても、文章ではなく数字で残します。

解除 0件 / 保護 41件

「対象なし」と「解除 0件」は、人間が読むと同じ意味に見えます。でも運用上はまったく違います。数字で書いてあれば、日々の値を並べて比較できるからです。ゼロが1日だけなら偶然かもしれませんが、同じ数字が並び始めたら異常を疑えます。文章のままでは、この「並べる」という操作ができません。

もうひとつ効くのが、ゼロではない項目も同時に出すことです。上の例なら、解除が0件でも保護は41件動いています。片方だけがゼロなら、その処理だけが壊れている可能性が高い。両方ゼロなら、もっと手前が止まっている可能性が高い。数字を並べた瞬間に、切り分けの材料になります。

ポイント

ログは「読むもの」ではなく「並べて比べるもの」として設計する。だから0件も数字で書く。文章で書くと比較できなくなります。

今回の故障の本体はここでした。自動化のコードは「ボタンを押す」までを仕事だと思っていて、押した結果どうなったかを一切見ていませんでした。だから、押せた時点で成功とみなしてしまった。

操作が成功したかどうかは、操作の戻り値ではなく、状態が変わったかどうかで判定する。これを守るように書き換えました。押す前と押した後で対象の状態を確認し、変わっていなければ成功として数えません。

注意

外部サービスのUIは、こちらの都合と関係なく変わります。変わったこと自体は防げません。防げるのは「変わったのに気づかないまま動き続けること」だけです。

これは調査中に気づいた副次的な問題です。動作確認をするとき、私はスクリプトを直接叩いていました。そのほうが速いからです。でも直接叩くと、cronやタスクスケジューラ経由のときと経路が違うため、記録が残りません。

結果どうなるかというと、手で動かして確認した分がログに反映されず、あとから件数を並べたときにグラフが嘘をつきます。実際には手で動かしていた日が、記録上は何もしていない日に見える。逆に、手動では動いていたのに定期実行では動いていない、というズレも見えなくなります。

うまくいったこと

0件を数字で書くようにしてから、日々の値を並べて見られるようになりました。「同じ数字が続いている」という形で異常が目に入るようになったのが、いちばんの変化です。

正直に書いておくと、同じ種類の故障を今後どれだけ早く見つけられるかは、まだ検証できていません。今回入れたのは「気づける形にする」ための変更であって、自動で通知が飛ぶところまでは作っていません。数字が並んでいても、私が見に行かなければ気づけないという弱点は残ったままです。

また、状態の確認をどこまで細かくやるべきかも決めきれていません。確認を増やせば処理は重くなりますし、確認そのものがUI変更で壊れる可能性もあります。ここは運用しながら調整していく段階です。

まとめ