以前、月に数回だけ夜間バッチが止まる不具合を調査したことがあります。
毎日止まるわけではなく、正常に終わる日の方が多い。ログを見ても「ここが原因だ」と言えるものがなく、最初は実行時刻やサーバー負荷、処理するデータ件数などを疑いました。
でも、それだけでは原因を絞れませんでした。
そこで途中から、正常終了したケースと停止したケースを並べ、何が違うのかを一つずつ比較する方法に変えました。
この記事では、月に数回しか起きない不具合を調べた経験をもとに、条件を絞り、過去の変更まで遡って原因を探す手順を書いています。
再現しにくい障害で、どこから調べればよいか迷ったときの参考になりましたら嬉しいです。
月に数回だけ止まる夜間バッチで手がかりがなかった
問題になったのは、夜間に動くバッチ処理でした。
月に数回だけ停止するものの、それ以外の日は何事もなかったように正常終了します。
最初は、
「処理する時間帯に何かあるのか」
「負荷が高い日に止まっているのか」
「データ件数が多いのではないか」
と考えました。
ログも確認しましたが、原因を直接示すような情報は見つかりません。
毎回再現する不具合なら条件を変えながら確認できますが、月に数回となると次にいつ起きるかも分かりません。
「たぶん負荷だろう」「この処理が怪しい」と考えるだけでは、なかなか前へ進みませんでした。
正常終了したケースと停止したケースを比較した
そこで、停止した日のログだけを見るのをやめ、正常に終わった日のデータも並べて比較することにしました。
原因を当てにいくのではなく、正常なケースと何が違うのかを見ることにしました。
実行時刻・負荷・データ件数では差が見えなかった
まず疑ったのは、実行環境でした。
実行時刻、処理時の負荷、対象になったデータ件数などを比べました。ところが、「この条件の日だけ止まる」と言えるほどの差がありません。
負荷が高くても正常に終わる日があり、データ件数が多くても問題なく処理されています。
深夜まで調査することもあったので、この頃は「確認したこと」と「分かったこと」を残すようにしていました。何を除外できたかが分かる方が、次の確認へ進みやすかったからです。
データ項目を比べると特定の条件が浮かんだ
次に、停止したときに処理していたデータと、正常に処理できたデータを項目ごとに比べました。
確認したのは、
- 文字数
- 空欄になっている項目
- 日付
- コード値
など。すると、停止したデータにだけ特徴のある項目が見つかりました。
「もしかすると、この項目が関係しているのでは？」
ここでようやく、調べる範囲が狭くなりました。
ところが、現在の仕様を確認しても、そのデータで処理が止まる理由をうまく説明できません。そこで、その項目がいつ追加され、どんな変更を受けてきたのかを調べることにしました。
現在の仕様では説明できず5年前まで遡った
改修履歴を確認すると、対象の項目は5年ほど前に追加されたものだと分かり、その当時の仕様書まで戻って確認しました。
すると、その項目は追加当初、データ移行の期間だけ空欄を許す仕様になっていたんですね。
通常であれば値が入る。ただし、移行期間中に作られた一部のデータでは、空欄のままでも登録できる。
さらに確認すると、その古い条件で作られたデータが現在も残っていました。
「これかもしれない」
正常に終わるデータと停止するデータの違いが、ここで過去の仕様変更とつながりました。
この段階では、再現条件、コード、テストを並行して確認しました。今回の障害調査を進めるために、それぞれで確認した結果を持ち寄る形です。
NULLチェックをすり抜ける条件分岐が残っていた
古いデータ条件が分かったことで、そのデータがコード上でどう扱われているかを追いました。最終的に見つかったのは、NULLチェックをすり抜ける条件分岐です。
通常のデータでは問題になりません。
ところが、5年前の移行期間中に作られた一部の古いデータがその条件に入ると、想定していない処理へ進み、夜間バッチが停止していました。
月に数回しか起きなかったのも、その条件を持つ古いデータが処理対象になったときだけ発生していたからです。
今回の調査では、正常ケースとの差を見たことで調べる条件を狭め、その差が今の仕様では説明できなかったため、過去の仕様まで遡ることができました。
まとめ
正常終了したケースと停止したケースを比較し、データの違いを追ったことで、5年前の仕様変更と古いデータ条件までたどれました。
原因が見えないときは、まず正常ケースとの差を見て、今の仕様で説明できなければ過去の変更まで戻る。今回の調査では、その順番が原因を絞る手がかりになりました。
再現しにくい不具合の調査が進まず、どこから手を付ければよいか迷っているときの、一つの参考になればと思います。
コメント