Linuxログローテート時のログ再検知について
お世話になります。
【環境】
Server：CentOS5.5 Zabbix1.8.5
Agent：CentOS5.5 Zabbix1.8.5
zabbixにてmessagesを監視しておりますが、messagesがローテートされると、ローテートされる前に検知したログを再度頭から読んでしまうという現象に悩まされています。
※messagesがmessages.1になる時にmessages.1を頭から読んでしまうという意味です
ログローテートはOSデフォルトのlogrotateで行っており、上記事象が発生するのはlogrotate時にsyslogプロセスをkill -HUPにより再起動する場合のみです。
zabbixのアイテムは以下のように登録しています。
logrt[/var/log/messages*,"[Ee][Rr][Rr][Oo][Rr]",UTF8,]
回避策等のノウハウがあれば教えて下さい。
kodai - 投稿数: 1341
念のため確認ですが、設定されているファイルの指定は
<code>logrt[/var/log/messages.*]</code>
でしょうか？(アスタリスクの前にドットが入る)
また、logrotate時にsyslogをkill -HUPされているというのは、logrotate.confのpostrotateに記載されているということでしょうか？
logrtのキーはmtimeを利用してどのファイルを読むべきか、という判断をします。
また、ファイルサイズが前回よりも小さくなった場合に、ファイルの先頭から読む動きをします。
syslogプロセスをkill -HUPした場合の動作は確認していませんが、何らかの原因でmessages.1のmtimeが変更されたか、前回よりもファイルサイズが小さくなったなどの原因が考えられます。
shiba-zab - 投稿数: 3
設定ですが、
logrt[/var/log/messages.*] ではなく
logrt[/var/log/messages*] です。
なぜならば、ログローテート時のログ取りこぼし防止の為、 /var/log/messages と /var/log/messages.1 を監視して欲しいからです。
また、kill -HUPはpostrotate内に記載しております。
なるほど。
ログローテート時の各ログファイルのmtimeを調べてみた所、ローテーション時にkill -HUPを行うと一瞬だけ messages と messages.1 のmtimeが全く同じになるタイミングがあります。
これによりzabbixがmessages.1のmtimeが変更されたと認識して、新たにログを頭から読み直す動きをしていると考えて良いでしょうか？
以下にmtimeのデータを貼り付けます。
※データは文字量が多くなるので一部加工しています。
▼kill -HUPを行うローテーションの場合
・ローテーション前
105136.703 In process_logrt() filename [/var/log/messages*] lastlogsize [197] mtime [1329270620]
105136.704 'messages.2' mtime:'1329220240'
105136.704 'messages.1' mtime:'1329270089'
105136.705 'messages' mtime:'1329270620'
105136.705 'messages.4' mtime:'1329219557'
105136.706 'messages.3' mtime:'1329219906'
・ローテーション後
105137.708 In process_logrt() filename [/var/log/messages*] lastlogsize [197] mtime [1329270620]
105137.709 'messages.2' mtime:'1329270089'
105137.710 'messages.1' mtime:'1329270697' ←mtimeが同じ
105137.711 'messages' mtime:'1329270697' ←mtimeが同じ
105137.711 'messages.4' mtime:'1329219906'
105137.711 'messages.3' mtime:'1329220240'
▼kill -HUPを行わずローテーションする場合
・ローテーション前
111404.877 In process_logrt() filename [/var/log/error.log*] lastlogsize [153] mtime [1329271956]
111404.877 'error.log.2' mtime:'1327649044'
111404.878 'error.log.4' mtime:'1314692025'
111404.878 'error.log' mtime:'1329271956'
111404.878 'error.log.1' mtime:'1329205809'
111404.878 'error.log.3' mtime:'1325033437'
・ローテーション後
111405.886 In process_logrt() filename [/var/log/error.log*] lastlogsize [153] mtime [1329271956]
111405.886 'error.log.2' mtime:'1329205809'
111405.887 'error.log.4' mtime:'1325033437'
111405.887 'error.log' mtime:'1329272045' ←mtime大
111405.887 'error.log.1' mtime:'1329271956' ←mtime小
111405.887 'error.log.3' mtime:'1327649044'
kodai - 投稿数: 1341
logrtのファイル名に利用できるのはシェルのワイルドカードではなく、正規表現です。今回の場合は問題ないと思うのですが、logrt[/var/log/messages*]だと/var/log/messageにもマッチしてしまうので注意してください。
正規表現 http://ja.wikipedia.org/wiki/正規表現
ログの動きについてまとめてみたので、こちらもご参考ください。
http://kodai74.blogspot.com/2012/02/zabbixloglogrt.html
messagesとmessages.1のmtimeが同じになってしまうということは、上記の記事でも書いている通り、logfiles配列の中ではアルファベット順に降順になることになります。
実際に試して確認はしていないのですが、ログローテート後にmtimeが同じ値で、かつその瞬間に監視処理が入った場合、messagesを先に読んで、messages.1を後に読むような動きになってしまっているのかもしれません。
可能であれば、messages.1を先頭から読んでしまう状態になったときのアイテムのヒストリを確認いただき、
- messages.1 (ログローテート前に読んでいたログ)
- messages (ログローテート後の最新ファイル)
- messages.1の先頭から
の順で読んでしまっていないか、確認してみていただけないでしょうか？
もしこの推測が正しいようなら、Zabbix側のファイル判別処理を修正しないと根本的には対応できないと思われます。
shiba-zab - 投稿数: 3
ご回答ありがとうございます。
完全にワイルドカードと勘違いしておりました。
ご指摘ありがとうございます。
アイテムのヒストリでログの読み方を確認してみた所以下のとおりでした。
１．messages
(ログローテート発生)
２．messages.1 (頭から読み込み)
３．messages (頭から読み込み)
ログファイルの内容を確認していて気づいたのですが、ログローテート時に以下のような動きをしていました。
１．ログローテート発生
２．syslog停止 ※停止時にmessages.1にsyslogが再起動する旨のメッセージを書き込み
３．syslog起動 ※起動時にmessagesに初期化された旨のメッセージを書き込み
ここで、２の時にmessages.1がmessagesに代わって最新ファイルとなってしまい、messages.1を頭から読んでいると考えられます。
なので、syslog再起動時にメッセージを出力しないようにできれば本件は解決するかなと推測しています。
kodai - 投稿数: 1341
ログファイルの順番は問題なさそうですね。
ソースコード上はログローテート後にmessages.1とmessagesの双方が更新されていた場合、通常はmessages.1の残りを読んでからmessagesに移るはずで、messages.1とmessagesのmtimeが同じなら、messages.1は飛ばされてmessagesを先頭から読むはずなので、messages.1を先頭から読んでしまうのは何か他に原因があるように見えるのですが...
とはいえ、ソースを読んだときの見落としがあるかもしれないので、可能であればsyslog再起動時にmessages.1を更新しないようにして試してみて頂けると助かります。