2015年02月02日

第14回「 SystemTap ノススメ」が掲載されました。

今回は SystemTap を使って挙動を追跡するというお話です。

とあるシステムで、 Pacemaker を起動してから約70秒後にシステムが予期せぬ再起動をしてしまうというトラブルが発生していました。再起動する直前だけディスクI/Oが多いという傾向が見られたため、何らかのディスクI/Oに関するトラブルに巻き込まれた結果、 /dev/watchdog への書き込みが遅延して watchdog タイムアウトによるリセットが発生しているのではないかと疑ったのですが、原因を掴めませんでした。

そこで、再起動要求が発生した時点の kdump を取得することにより、誰が再起動要求を発生させているのか/どうして再起動要求を発生させることになったのかを調査するために、今回紹介した SystemTap スクリプトを仕掛けて事象を再現してもらいました。すると、何と sfex_daemon という監視プログラムが /proc/sysrq-trigger に b を書き込んだことによるリセットが発生していたことが判明したのです。これをきっかけに、設定の誤りが予期せぬ再起動の原因であったことが判明し、トラブルを解決することができました。

sfex_daemon のソースコードによると、普段はスリープしながら、定期的に update_lock() を呼び出してロックの状態を確認し、異常を検知した場合には failure_todo() を呼び出しているようです。 failure_todo() は cl_log() という関数の中から syslog() 関数を呼び出すことで syslog デーモンにログメッセージを送信後、 /proc/sysrq-trigger に b を書き込んでいるようです。では、何故 syslog() 関数を介して送信した筈のログメッセージが、 syslog ファイルに残っていなかったのでしょうか?実は、 syslog() 関数を介して syslog デーモンにログメッセージを出力する方法には、2つの落し穴があったのです。

1つ目の落し穴は、 rsyslog の version 3 からは、デフォルトで非同期書き込みを行うようになっている点です。そのため、非同期書き込み後すぐに再起動要求が発生してしまっては、ログに残すことができません。2つ目の落し穴は、 syslog() 関数を介して syslog デーモンにログメッセージを出力する方法では、 syslog デーモンがログメッセージを出力するよりも前に syslog() 関数が復帰してしまうため、たとえ同期書き込みを行うようになっていたとしても、同期書き込みの完了を待たずに再起動要求が発生してしまい、ログに残すことができません。

RHEL 7 の登場により、3つ目の落し穴も発見されました。 RHEL 7 の場合はデフォルトのファイルシステムが ext4 から xfs に変更されたため、 ext 系ファイルシステムで行われていた5秒毎の writeback も行われなくなっています。そのため、 RHEL 7 においては、明示的に sync() 関数などを呼ばないと、問題事象発生直前のログが残っていないという可能性が一層高くなっています。

再起動直前のログを確実に残したい場合、 syslog デーモンに頼っていては駄目なのかもしれません。今後 RHEL 7 のシステムが増えてくるに従い、問題事象発生時のログを如何に残すかという課題が出てきそうです。カーネルメッセージであればシリアルコンソールや netconsole 経由で取得するという方法が使えます。アプリケーションのメッセージについても自力でローカルとリモートの両方にログを出力するとかしたほうが良いのかなぁ?

明日は節分ですって? 幽霊は〜外〜。アップデートは〜内〜。(謎)

posted by 熊猫さくら at 22:00| Comment(0) | TrackBack(0) | Linux
この記事へのコメント
コメントを書く
お名前:

メールアドレス:

ホームページアドレス:

コメント:

※ブログオーナーが承認したコメントのみ表示されます。
この記事へのトラックバックURL
http://blog.sakura.ne.jp/tb/113064597
※ブログオーナーが承認したトラックバックのみ表示されます。

この記事へのトラックバック