この記事では、自動化処理のログに「対象なし」とだけ書いていたために、3日間まったく処理できていない状態に気づけなかった実例と、そこから変えた3つのログ設計を書きます。エラーが出ない故障をどう可視化するかの話です。
「対象なし」と書いていたら、故障が見えなくなった
自動化した処理のログで、処理対象が0件だったときに『対象なし』とだけ出力していました。文字としては間違っていません。実際に対象は0件です。
ところが、これで3日連続で1件も処理できていない状態に、画面から気づけませんでした。「対象なし」は正常な日にも出る文字列なので、それが3日続いていても異常として目に入ってこないのです。
原因：ボタンは押せるが、状態が変わっていなかった
原因は、操作先の外部サービスのUI変更でした。ボタンは押せる状態にあり、クリック自体は成功します。しかしその後、状態が変わっていませんでした。
この手の失敗はエラーを出しません。クリックが例外を投げるわけではないので、ログ上は最後まで走って正常終了したように見えます。つまり、
- 例外なし
- ログは最後まで出ている
- 「対象なし」と書いてある
という三点が揃うと、外から見て健康な自動化と区別がつきません。ここが一番怖い部分でした。
対策1：0件でも必ず数字で書く
まず、0件のときに文章で逃げるのをやめました。件数を必ず数字として出します。
解除 0件 / 保護 41件
数字で書くと、0という値が記録として残ります。「対象なし」は文字なので比較も集計もできませんが、0件は他の日の数字と並べられます。0が3日並んでいれば、それは並べた時点で異常として見えます。文章にすると消えてしまう情報が、数字にすると残るという違いです。
ポイントは「異常だったから数字を出す」のではなく、「正常でも常に同じ形式で数字を出す」ことです。形式が揃っていないと、そもそも並べられません。
対策2：押せた≠変わった、を確認する
2つ目は、操作した後に状態が変わったかどうかを確認することです。今回の故障は、まさに「押せたこと」を成功の判定に使っていたために見逃しました。
ボタンが押せることと、対象の状態が変わることは別の事象です。押せたのは手前の話で、目的は状態の変化です。だから操作の後にもう一度状態を読み、変わっているかを見る。変わっていなければ、押せていても失敗として扱う。
ここを分けておかないと、外部サービスのUIが変わったときに「操作は通っているのに何も起きない」という状態が、そのまま正常終了として記録されてしまいます。
対策3：手動実行も、cronと同じ経路で通す
3つ目は運用側の話です。手動で動かしたいときも、cronやタスクと同じ経路、つまりログに残る形で実行するようにしました。
直接叩くと記録が残りません。記録が残らない実行が混ざると、集計したグラフが嘘をつきます。実際には動かしていた日が「動いていない日」として並び、逆に手動で処理してしまった件数がどこにも計上されない、といったズレが出ます。故障の判断材料として使うつもりのログなら、抜け道を作ってはいけないと考えるようになりました。
まだ分かっていないこと
今回は外部サービスのUI変更が原因でしたが、UIが変わることを事前に検知する方法は持っていません。次のUI変更でまた壊れる可能性は残っています。今できているのは「壊れたときに、それを数字として見えるようにする」ところまでで、壊れないようにする手立てはありません。ここは正直に、分かっていない部分です。
まとめ
- 0件のときに「対象なし」とだけ書くと、正常な日と区別できず、3日連続の停止に気づけなかった
- 原因は外部サービスのUI変更で、ボタンは押せるが状態が変わらない状態だった
- エラーが出ないため、ログ上は正常終了に見えていた
- 0件でも数字で書く（例：解除 0件 / 保護 41件）。数字なら並べて比較できる
- 操作後に状態が変わったかを確認する。押せた≠変わった
- 手動実行もcronやタスクと同じ経路でログに残す。直接叩くとグラフが嘘をつく
- UI変更そのものを事前に検知する方法は、まだ持っていない
