障害へのカウントダウン

お初にお目にかかります。基幹システムグループの桑原です。
システム開発に携わっていれば、多くの方が大なり小なり障害に遭遇しているかと思います。
私も長年開発・運用業務をやっており、システム障害や運用ミスなど、いろんな障害に携わってきました。自分が起こしたり、巻き込まれたりなどなど。
その中から最近発生した、そんなところに原因が・・と思ったもののお話しをします。

障害の概要

ある日お客様への通知物関連の処理にて、お客様の元へ届かないという障害が発生しました。
原因となった該当の処理自体は単純なもので、ファイルをリネームして移動するだけのものでバグが入り込む余地がないほどの処理です。
登場するサーバは下記の2台。

• サーバA：ファイルをリネーム・移動する処理が実行されるサーバ
  • 0:30にcron実行される
• サーバB：移動後のファイルを使用する後続処理が動くサーバ
  • 1:30にcron実行される
• オマケ情報
  • サーバAとサーバBは同じNASをマウントしている

時を遡ること約1年、サーバAの処理の終了時間が少しずつ遅れはじめました。
ここからカウントダウンが開始されたのでした。
移動されたファイルのタイムスタンプが今までは0:30だったのが、最終的にリミットの1:30を越えて後続処理に間に合わなくなり、障害の発生。
先に記述したとおり、ファイルをリネーム・移動するだけの処理がなぜこんなに時間がかかるのかまったく理由がわかりませんでした。

調べてみる

まずは、サーバAで遅れていった処理のログを見てみました。単純な処理過ぎて使えるログはほぼ出力しておらずまったく役に立ちません。
参考になったのは、ログのタイムスタンプで、0:30となっていたことで、処理自体は時間通りに開始しているらしい点。

移動先のファイルのタイムスタンプを確認してみると、やっぱり開始時間とはかなりかけ離れていることがわかりました。

なぜこの処理でこんなに時間がかかるのか、ソースを見ても時間のかかるところなんてありませんでした。
ファイルサイズは0～100byte前後がほとんどで普通に考えれば一瞬で終わります。
そしてさらに謎なことに、10日程度でこれがおさまったことです。
ちなみに3月15、16日はなにもしていません。

その後また少しずつ遅れ始めていて、このままではまた1年後くらいに同じことが起こってしまう可能性がありました。
調査に行き詰まり、チームでの障害共有のときに何かとっかかりになるような観点ないか相談をしてみました。

解決

結果からいうと、処理に時間がかかっていたわけではなく、サーバAの時計が遅れていました。
約1年前から少しずつ時計が遅れていき、後続処理までの1時間を超えてしまったというオチでした。
相談したときにNTPでは？と言われ、確認してみたら

と出てきました。時刻同期が無効だった・・・
そのときのファイルのタイムスタンプと実際の時刻のズレもほぼ同じでしたので、これかと。

なるほど、サーバAではズレている時刻どおり0:30に実行し終わっているので、ログのタイムスタンプは0:30になり、サーバBから見たらファイルは遅れて置かれた時間がタイムスタンプになるわけです。

サーバAで時刻同期を行って対応は終わりました。

他にも時刻同期が無効になっているサーバがないか確認したら数台見つかりました。
しかし、数分のズレで済んでおり、ここまで遅れていったのはサーバAのみでした。なぜこいつだけ・・

それなりに古いシステムで、構築時を思い返しても時刻同期をどうするみたいな細かいところまで手順にはなかった気がします。
約1年前なにがトリガーになって時計遅れ始めたのか、何もしてないのに正しい時刻になおったことなど気になる点はまだありますが、syslog見ても影響していそうなのもなく謎は残りますが、この件は一旦これで終わり。

障害原因の調査をするときは、該当システムばかり調査しがちになりますが、今回のように他のところに問題があることもあるのだなと。
今後の教訓として、迷ったら少しそっちに目を向けた調査も考慮しようと思った一件でした。