ログローテされた際に過去ログを読み込んでしまう
お世話になっております、広瀬です
・ZABBIX Ver.1.8.10
・JDK1.6.0.32
・監視対象ログはJavaのアプリログ
・ログローテーション方式は、log4jによる1世代ローテ(※log4jの使用Verは1.2.11)
Javaのアプリログを監視させており、一通りのアイテム・トリガ・アクション設定は
済ませており、正常にログ取得・監視は出来る状態にまで持っていきました。
しかし、掲題の通りですがローテーションされた過去ログに切り替わった直後に、
一世代前のログ(単純にalert.log/alert.log.1となるだけですが･･･)の中身を再読込し
てしまい、エラーが通知されてしまう現象が発生しました。
■アイテム
logrt[/usr/java/tomcat/logs/zabbix/alert.log.*,ERROR,,]
■トリガ
({hostname:logrt[/usr/java/tomcat/logs/zabbix/alert.log.*,ERROR,,].nodata(30)}=0)&({hostname:logrt[/usr/java/tomcat/logs/zabbix/alert.log.*,ERROR,,].regexp(E-XXXXX|E-XXXXX)}=1)
※イベント生成はノーマルにしています。
■試験してみた事
・mv alert.log alert.log.1 && echo "ERROR E-XXXXX" >> alert.log
・mv alert.log alert.log.1 && touch alert.log && echo "ERROR E-XXXXXX" >> alert.log
上記のように、適当なUNIXコマンドでローテーションさせた場合には、過去ログを読むよう
なことはおきませんでした(UNIXコマンドの場合、幾つかパターンあるので、何れも特に異常は無し)。
■気になる点としては
・logrt側のファイルパス部の正規表現
・log4jのバージョン
後者のlog4jバージョンについては、1.2.11が2005年のものであるため、古すぎることもありリリース
ノートなどを漁っているところです。
logrt側についてはzabbix_agentd.logでの挙動自体を追えなかったので、若干手詰まりな状況です。
かなり限定的な状況なので、どちらの問題ということではありませんがlogrtアイテムキーの記述等に
何か不備があるようでしたら、ご指摘頂ければと存じます。
以上、宜しくお願い致します。
kodai - 投稿数: 1341
log4jのログローテート処理がどのようになっているのか分からないのですが、アイテムで設定されているログファイルのパスがalert.log.*となっていますので、
alert.log.1
alert.log.2
alert.log.swp
alert.log123456789
alert.log....
alert.logabd
など、いずれにもマッチしてしまいます。log4jでログローテートの際に一時ファイルを作るなどの処理が行われていたりしないでしょうか？
また、ローテートされた後のログファイル名がある程度分かっているようでしたら、
alert.log.[1-9]
のように文字数を固定で指定されると想定外の動作を防ぐことができます。
KAZ - 投稿数: 1085
広瀬さん
kodaiさんの書かれている通り「alert.log.*」が問題かと。
監視したいのはalert.logでは無いですか？
それならばローテート後のalert.log.1は監視対象から外さないといけないかと。
↓これでどうでしょうか？
■アイテム
logrt[/usr/java/tomcat/logs/zabbix/alert.log,ERROR,,]
■トリガ
({hostname:logrt[/usr/java/tomcat/logs/zabbix/alert.log,ERROR,,].nodata(30)}=0)&({hostname:logrt[/usr/java/tomcat/logs/zabbix/alert.log,ERROR,,].regexp(E-20001|E-20404)}=1)
尚、log4jは設定で、出力方法が色々設定できますよね。
どういう出力をしているかも書いて頂けると助かります。A(^^;
使われているのはRollingFileAppdenderでしょうか？
それならlog4Jの設定は問題ないかと思います。
参考まで > kodaiさん
Log4J徹底解説
http://www.nurs.or.jp/~sug/soft/log4j/log4j5.htm
wakaba - 投稿数: 228
kodaiさん、KAZさん
さっそくのご返答ありがとうございます。広瀬です。
＞kodaiさん
alert.logは1世代のみローテーションさせていますので、
当世代：alert.log
1世代前：alert.log.1(サーバによってはalert.log.yyyymmddss)
としています。
>KAZさん
■アイテム
logrt[/usr/java/tomcat/logs/zabbix/alert.log,ERROR,,]
ご指摘の通り、上記であれば想定通りの動きをします。
自身の認識が間違っていたのかもしれませんが、上記の記述方法であってもローテする直前に書き込まれた
ログ内容はローテーションされた過去ログからは自動的に読み取られるのでしたでしょうか？(多分にこの認識
が間違っていたのかもしれません)
※1秒間隔でアイテム設定していますので、ミリ秒単位の書き込みがあること前提でのお話ですが･･･
RollingFileAppdenderはい以下の通りです。
＜appender name="alertLog" class="org.apache.log4j.RollingFileAppender"＞
＜param name="threshold" value="ERROR" /＞
＜param name="Append" value="true" /＞
＜param name="MaxBackupIndex" value="1" /＞
＜param name="MaxFileSize" value="100KB" /＞
＜param name="file" value="/usr/java/tomcat/logs/zabbix/alert.log" /＞
＜layout class="org.apache.log4j.PatternLayout"＞
＜param name="ConversionPattern" value="%d %-15t %-5p %m - (%c) (%F:%M:%L)%n" /＞
＜/layout＞
＜/appender＞
サイズ指定でのローテを行っています。log4jの動きとして一時ファイルを生成するかどうかまでは
詳細がすぐはわかりません(開発チームが行っているため･･･)。
KAZ - 投稿数: 1085
広瀬さん
>ご指摘の通り、上記であれば想定通りの動きをします。
>自身の認識が間違っていたのかもしれませんが、上記の記述方法であってもローテする直前に書き込まれた
>ログ内容はローテーションされた過去ログからは自動的に読み取られるのでしたでしょうか？(多分にこの認識
>が間違っていたのかもしれません)
監視タイミングとローテートタイミングの間のログと言う事ですよね？
確かにalert.logだけだと拾えないですね…
この話題は昔、1.8がでる時に話が上がってましたね。
どう言う仕組みになったんでしたっけ？ > kodaiさん
>※1秒間隔でアイテム設定していますので、ミリ秒単位の書き込みがあること前提でのお話ですが･･･
ミリ秒はありえますね。A(^^;
>サイズ指定でのローテを行っています。log4jの動きとして一時ファイルを生成するかどうかまでは
>詳細がすぐはわかりません(開発チームが行っているため･･･)。
確か作らないはずです…(と覚えてるんですが、少々自信ないです。)
wakaba - 投稿数: 228
KAZさん
広瀬です。
>監視タイミングとローテートタイミングの間のログと言う事ですよね？
>確かにalert.logだけだと拾えないですね…
>この話題は昔、1.8がでる時に話が上がってましたね。
はい、そのとおりです。私も以前にそのような話題を見たような記憶があり、若干、自分の記憶というか
認識が揺らいでいます（＾＾；
ただ、少々気になるのは一番最初に書いたとおりなのですが、logrtアイテムキーでalert.log.*と指定させ
ていてもですが、
>■試験してみた事
>
>・mv alert.log alert.log.1 && echo "ERROR E-XXXXX" >> alert.log
>・mv alert.log alert.log.1 && touch alert.log && echo "ERROR E-XXXXXX" >> alert.log
シェルなどでローテさせた場合、内容はともかくとしても、動き的には上記のようなものになるかと思います。
①リネームしてから、②新規ファイル生成or直接生成して、③次世代のログファイルに書き込み
この場合、log4jとは違い、幾ら試験しても「過去ログを読むという」挙動はしませんでした。
となると、log4j側かな・・・などと考えてはいたのですが、些か自信の程ありません。
この辺は、開発とも協力してlog4jのバージョン変更等も確認を急いでいます。
何かわかりましたら、再度ご教授いただけると幸いです。
TNK - 投稿数: 4671
Zabbix、Log4J両方のソースまでの再確認や実検証はしていません
が、考えられる可能性ということで書かせて頂きます。
Log4Jでログのローテーションを行う場合、以下のような処理にな
っていることが考えられます。
１．ローテーション条件になってローテーション処理開始
２．過去のローテーションしたファイルをリネーム
３．現在書き込んでいるログファイルをリネーム
４．新規に出力するログファイルを新規作成
５．新しく作成したログファイルに出力先切り替え
このような処理であった場合は、３．でリネームした後でも、５．
での出力先を切り替えるまでの間に前のログファイルに継続してロ
グが出力される場合が考えられます。
例示されていたような、コマンドラインでのmv、touch、echoのよ
うに、1つ1つの処理がファイルのオープンとクローズを行って終了
していれば、４．で新規作成され次第、その後は新しいファイルに
出力されるので、今回のような問題は発生しないかもしれません。
しかし、今回のようにLog4Jで継続的にログを出力していた場合、
Log4Jを利用しているプロセスがファイルをオープンしたままの状
態でファイルのリネームを行う状態となり、プロセスとしてはファ
イルをリネームしても自分がオープンしているファイルディスクリ
プタに書き込むので、リネームされたファイルに継続して出力して
しまうと思われます。
こういった状況が発生していたならば、alert.logよりもalert.log.1
の方がファイルの更新日付が新しいために、zabbixサーバが、
aleart.logを処理後に、再度処理済みのログが出力されている
alert.log.1を読み込んで処理してしまう状態が発生している可能
性があるのではないでしょうか？
しかも、アイテムの設定として1秒間隔で設定されているとのこと
ですので、より上記のような瞬間に処理を行ってしまって、問題が
発生しやすい状況になっていると思われます。
アイテムの更新間隔を、例えば30秒とか長い秒数に変更して試して
頂けませんでしょうか？
kodai - 投稿数: 1341
logrtはそういった場合のために用意されているので、wakabaさんの認識に間違いはないですよ。logrtを利用すればログローテートされた場合でも直前のファイルの末尾を読んでから次のファイルを読んでくれます。
logキーとlogrtキーの詳細な動きはこちらもご参考ください。logrtはファイルの更新時刻も見て最新のログファイルを探します。
http://kodai74.blogspot.com/2012/02/zabbixloglogrt.html
ログローテーションの動きはアプリ側の実装によってもかなり異なります。Zabbix側の動きは上記の記事に書いた通りなので、ファイルを先頭から読んでしまうのはZabbixの動きと相性の悪い「何か」があるのだと思います。
ちなみに、viなどでログファイルを開くと.alert.log.swpファイルが作成されるため、アイテム設定でalert.log.*としているとログを先頭から読む原因になりますのでご注意ください。
wakaba - 投稿数: 228
広瀬です。ご返信おそくなりました。
> こういった状況が発生していたならば、alert.logよりもalert.log.1の方がファイルの更新日付が新しいために、zabbixサーバが、
> aleart.logを処理後に、再度処理済みのログが出力されているalert.log.1を読み込んで処理してしまう状態が発生している可能
> 性があるのではないでしょうか？
はい、その可能性もいろいろ試した中で、ログファイルのオープン・クローズ処理に影響されている可能性があるのではという
節がちらほら見えていました。
ただ、loggerなどでログファイルに連続して書き込みしているところに対して、mv/touchなどの処理を行った場合と具体的にどの
ような差異があるのかが突き止められないので、困っていました。
色々確認していた中で、相違点を見つけました。
■問題が起きているシステムの場合
・常にTomcat(Java)のプロセスが動いており、そのプロセスがlog4jでログをローテーション処理している
・ログローテーションはサイズ指定で動作
■問題が起きていない(確認されていない)システムの場合(2種あります)
・単純にジョブとしてCron動作するJavaアプリケーションの定時処理にて何らかの処理がなされ、
Exceptionを起こした場合に吐かれるだけという違いがありました。
・log4jのサイズローテーション
・同じく、ジョブとしてCron動作するJavaアプリにて定時処理され、Exception起こした場合に吐かれます。
・こちらはlogback(log4jから分派した別のクラス)を使用しています。
・尚、このシステムだけ日付によるローテーションを使用しています。
上記のように、ログファイル自体をプロセス自体が常に掴んでいる(確証はありませんが・・・)可能性
がある、場合にはTNKさんの言われるようにファイルオープン・クローズ処理による何らかの影響が
絡んでくるのだろうというご指摘は、非常にごもっともなお話だと思います。
ご理解いただけるかわかりませんが、TNKさんから見て上記のパターンであれば当てはまりそうでし
ょうか？
> logキーとlogrtキーの詳細な動きはこちらもご参考ください。logrtはファイルの更新時刻も見て最新のログファイルを探します。
> http://kodai74.blogspot.com/2012/02/zabbixloglogrt.html
上記のサイトに関しては時折拝見させていたています。私もワイルドカードと正規表現の「＊」の意味
をまったく理解していませんでした。非常に参考させて頂いています。
尚、今ひとつ理解しきれていない点として
・lastlogsize
・mtime
ローテーションされたファイル(たとえば、/var/log/messages.1など)が、保存されている上記２つの値が、
前回と両方とも違う場合は、どのような挙動しますでしょうか？
※あくまでも当該のローテーションされたログはシステムが吐いたことが前提で、人為的に手は加えて
いないこととします。
長くなりましたが、よろしくお願いいたします。