ログ監視にて、当日分の初回検知分のみ再度検知してしまう

以下現象が発生しております。
何か原因や知見などございましたら、ご教授願います。

[設定]
 同一ファイルに対して以下3つのアイテムを定義しています。
 アイテムの更新間隔は全て5秒です。

 アイテム1 : logrt[/var/log/messages.*,"MpJobsch: ERROR",utf8,100]
 トリガー1 : ({Template:logrt[/var/log/messages.*,"MpJobsch: ERROR",utf8,100].regexp("MpJobsch: ERROR")})<>0
         and
         ({Template:logrt[/var/log/messages.*,"MpJobsch: ERROR",utf8,100].nodata(60)})=0

 アイテム2 : logrt[/var/log/messages.*,"MpJobsch: WARNING",utf8,100]
 トリガー2 : ({Template:logrt[/var/log/messages.*,"MpJobsch: WARNING",utf8,100].regexp("MpJobsch: WARNING")})<>0
         and
         ({Template:logrt[/var/log/messages.*,"MpJobsch: WARNING",utf8,100].nodata(60)})=0

 アイテム3 : logrt[/var/log/messages.*,"FJSVoast: ERROR",utf8,100]
 トリガー3 : ({Template:logrt[/var/log/messages.*,"FJSVoast: ERROR",utf8,100].regexp("FJSVoast: ERROR")})<>0
         and
         ({Template:logrt[/var/log/messages.*,"FJSVoast: ERROR",utf8,100].nodata(60)})=0

 messagesファイルは別途logrotateにてローテーションさせています。
 (daily、create、nocompress)

[現象]
 16:10 その日で最初の警告メッセージ発生。アイテム2にて正常に検知
 18:29 特にアイテムに引っかかるログが発生していないが、アイテム2のトリガーが発動
     検知内容は16:10に一度検知した警告メッセージが再度通知される
 21:10 2回目の警告メッセージ発生。アイテム2にて正常に検知
 21:19 特にアイテムに引っかかるログが発生していないが、アイテム2のトリガーが発動
     検知内容は16:10に一度検知した警告メッセージのみが再度通知される
     (21:10の警告メッセージは再通知されず)

 上記の様に、その日の最初に検知したメッセージが何度か再検知される現象(契機は不明)
 となります。
 別の日でも同様な挙動となっています。

 また、その他のサーバやログ監視では発生しておりません。
 設定上の違いとしては、同じファイルに対して複数アイテムが定義されているかどうか
 となります。
 同じ設定を実施しているサーバが2台あり、2台とも同じ様な挙動となっております。
 
 なお、再検知されたタイミングで、zabbixエージェントの再起動や該当ログファイルのvi参照
 など特別な作業は実施していません。

以上です、よろしくお願い致します。

コメント表示オプション

お好みのコメント表示方法を選び「設定の保存」をクリックすると変更が反映されます。
ユーザー TNK の写真

まずは、Zabbixの詳細なバージョンをお教えください。
可能であれば、Zabbixを稼働させているプラットフォームの情報も
ご提供頂けませんでしょうか?

18:29と21:19の前後の対象のアイテムの最新データの値を確認して
みてください。
特にその時刻の少し前に何らかの値を取得していませんか?

あと、21:19に通知された内容が16:10のものであったと判断された
根拠をお教えください。
それに関連してくるのですが、アクション内のメッセージとして、
どのような設定を行っているのかも詳細をお教えください。

もう一つ、トリガーの設定で、障害イベントを継続して生成に関しては
どのように設定されていますか?

ユーザー namaroi の写真

返信ありがとうございます。
不足分の情報を追記します。

zabbixバージョン : 3.0.5
OSバージョン   : RedhatEnterpriseLinux 7.2(AWS上で稼働)
           zabbixサーバ、エージェント共に同じバージョンです。
トリガー     : 「障害イベントを継続して生成」はOFF
アクション    : ・メッセージ内容
             ステータス:障害
             発生日時:{DATE} {TIME}
             ホスト名:{HOST.NAME1}
             検知ログ:{ITEM.KEY1}
             検知内容:{ITEM.VALUE1}
           ・実行条件
             計算のタイプ:And
             実行条件  :A トリガーの値=障害
                    B トリガー=<トリガー2の名前>

>18:29と21:19の前後の対象のアイテムの最新データの値を確認してみてください。
>特にその時刻の少し前に何らかの値を取得していませんか?
一点書き漏れてましたので以下に書き直します。(18:25追記)
失礼致しました。

 16:10 その日で最初の警告メッセージ発生。アイテム2にて正常に検知
 18:25 2回目の警告メッセージ発生。アイテム2にて正常に検知
 18:29 特にアイテムに引っかかるログが発生していないが、アイテム2のトリガーが発動
     検知内容は16:10に一度検知した警告メッセージが再度通知される
 21:10 3回目の警告メッセージ発生。アイテム2にて正常に検知
 21:19 特にアイテムに引っかかるログが発生していないが、アイテム2のトリガーが発動
     検知内容は16:10に一度検知した警告メッセージのみが再度通知される
     (18:25、21:10の警告メッセージは再通知されず)

18:29、21:19共に、発生前10分程度以内に検知すべきメッセージが発生しています。
「監視データ」→「イベント」にて確認しています。

>あと、21:19に通知された内容が16:10のものであったと判断された根拠をお教えください。
通知されたメールの内容及び、「レポート」→「アクションログ」から判断しております。
メール内容の「{ITEM.VALUE1}」が16:10に出力されたメッセージとなっておりました。

以上です、よろしくお願い致します。

ユーザー namaroi の写真

補足情報です。

当サーバでは、rsyslog.confにて以下設定を実施してプライオリティ別に出力先ファイルを分けています。

*.info;mail.none;authpriv.none;cron.none /var/log/messages ←デフォルト設定
*.err /var/log/error.messages ←追加設定
*.=warn /var/log/warn.messages ←追加設定

上記のerrとwarnを別ファイルに分ける設定を削除すると、本現象は再現しなくなる事が分かりました。
zabbixの仕様や不具合などから、本現象に繋がる様な点、何かご存知でしたらご教授願います。

以上です、よろしくお願い致します。

広瀬です。

ログファイルの指定ですが、/var/log/messages.*ではなく、

/var/log/^messages.*$

     ↑mの前の「^」を絶対に忘れずに。最後の$は保険です

に変更してみてください。公式ドキュメントでもそのような記述になっています
最後のファイル名の指定の部分は、regexp扱いですので部分一致条件となります<たぶん

なので、/var/log/error.messagesでも、/var/log/messages.*でも反応してしまうのだと思います。
Agentのデバッグログを挙げて、現状の場合とアイテム変更した後の状況を見比べてみてください。
言わんとしてること解ると思います。

ユーザー namaroi の写真

広瀬さん

ご指摘の通り「^」を指定していなかったので、messagesだけでなくerror.messages、warn.messagesも
監視対象として扱われていました。
絶対パスで指定しているので、先頭は指定しなくても良いと勘違いしておりました。
助かりました、ありがとうございます。

ただ、これが今回の現象に繋がるロジックが理解出来ずにいます。
(デバッグログの見比べは環境制約上まだ実施出来ていません)
もしご存じでれば以下点もご教授頂けると助かります。

・logrtではファイルサイズ(lastlogsize)と更新日時(mtime)で監視対象や監視順序を決定する認識ですが、
 mtimeは秒までの判断となるか?
・logrtにて同じmtimeのファイルが複数存在する場合、ファイル名の降順で処理される認識でよいか?
・アイテム毎にlastlogsize、mtimeを保持する認識ですが、logrtにて複数ファイルが監視対象となった場合、
 ファイル毎にそれらの情報が管理されるのか?

この辺の仕様が分かると、その仕様とnodata(60)の絡みで今回の事象に繋がる流れが見えてきそうな気がしています。

以上です、よろしくお願い致します。

広瀬です

先に現状の回避策のみお伝えしていましたが、今回の事象に関しての説明は私も調査
しない事には理解出きない部分がありそうです。

> ・logrtではファイルサイズ(lastlogsize)と更新日時(mtime)で監視対象や監視順序を決定する認識ですが、
>  mtimeは秒までの判断となるか?
> ・logrtにて同じmtimeのファイルが複数存在する場合、ファイル名の降順で処理される認識でよいか?
> ・アイテム毎にlastlogsize、mtimeを保持する認識ですが、logrtにて複数ファイルが監視対象となった場合、
>  ファイル毎にそれらの情報が管理されるのか?

エージェントは基本はファイルサイズとmtimeを追いかけますが、Agent内部としてはさらに以下の情報も持っています

 ①iノード番号 (UNIX/GNU/Linux)、ファイルインデックス(Microsoft Windows)、
 ②ログファイルの最初の512バイトのMD5合計値

計4つの値を総合して、ファイルの変化をみています。Ver1.8のころには無かった機構ですね。Ver2.2の日本語マニュアル
見てもらえれば、言わんとしていることはおわかりになるかと思います。

尚、/var/log/messages、/var/log/error.messages、war.messagesはそれぞれ、内容、inode、ファイルサイズ、mtimeも
違いますので、今回の事象の説明をするにはデバッグログからも説明できません。おそらくはバグだろうと判断しています
本家に同種問題が無いか確認してみます。解答できればフィードバック出きたらとおもいます<期待はなさらないように

以上です

ユーザー namaroi の写真

広瀬さん

返信が遅れまして失礼致しました。

>本家に同種問題が無いか確認してみます。解答できればフィードバック出きたらとおもいます<期待はなさらないように
ありがとうございます。
こちらでも進展等ありましたら、またご連絡致します。

以上です、よろしくお願い致します。