【質問】同時に複数ログを受信した場合の{ITEM.VALUE}の動作について

度々のご連絡となり、申し訳ありません。

ログ監視のアラートメールにて、本文に表示されているアイテムの値がトリガー条件と整合しないことから
状況を確認したところ、アラートメールの{ITEM.VALUE}で表示される監視データが
実際に検知したものではなく、より新しい行のログを表示することがわかりました。
Zabbix2.0系で修正された、とフォーラムのいくつかの内容から拝見しましたが、
3.0系でも発生する事象でしょうか。
恐れ入りますがご存知の方いましたら、ご教示くださいますようお願い致します。

詳細を以下に記載しますので、ご参考までにご覧ください。

◆環境
・Zabbix-Server
Version : 3.0.16-1.el6
OS : Amazon Linux AMI(2017.09)

・Zabbix-Agent
Version : 3.0.16-1+xenial_i386.deb
OS : Ubntu16.04.3 LTS (Xenial Xerus)

◆アイテム
・logrt[/dir/^system\.(log|log\.1)$,@LogLevel_error,,,skip]
取得間隔:5秒
・getLogTimeDiff.sh[xxxxx]
取得間隔:1秒

※getLogTimeDiff.sh[xxxxx]はZabbixデータベースの”history_logs”テーブルから、
アイテムIDを元に最新ログレコードのタイムスタンプとローカル時間の差分を算出し出力するシェルスクリプトです。
xxxxxにはアイテムIDが入ります。
当環境ではZabbixが不要な過去ログを取得してしまうため、このようなアイテムを作成しています。

◆トリガー
・{Template hoge:logrt[/dir/^system\.(log|log\.1)$,@LogLevel_error,,,skip].iregexp(".*E00000001.*",300)}<>0 and
{Template hoge:getLogTimeDiff.sh[xxxxx].last()}<=300

◆メール
Date :{EVENT.DATE} {EVENT.TIME}
Hostname   :{HOST.NAME}
Trigger     : {TRIGGER.NAME}
Trigger severity : {TRIGGER.SEVERITY}

1. {ITEM.NAME1} ({HOST.NAME1}:{ITEM.KEY1}): {ITEM.VALUE1}

◆検知したログ
{"time":"2018-06-24 12:00:00","level":"ERROR","code":"E00000001","message":"xxx"}
{"time":"2018-06-24 12:00:00","level":"ERROR","code":"E00000002","message":"yyy"}

◆実際のメールの{ITEM.VALUE}
{"time":"2018-06-24 12:00:00","level":"ERROR","code":"E00000002","message":"yyy"}

本来は"E00000001"の文言をログが表示すべきところ、上記のログが表示してしまう状態です。

以上です。宜しくお願い致します。

コメント表示オプション

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

広瀬です。

トリガー条件式の「障害イベントを継続して生成」はどう設定されていますか?
チェックが無い場合は、同時検知した場合は最初に検知した方、つまりメール通知された
ものが正解な動作だったはずなので、動作は正常に見えます。

ユーザー jusco0103 の写真

広瀬さん

ご連絡いただきありがとうございます。
「障害イベントを継続して生成」はチェックを入れておりません。
少し詳しくお伺いしたのですが、動作が正常に見えるという点について、
トリガーの発報については条件にマッチしたログで行われるのが正しいとは認識していますが、
アラートメールの{ITEM.VALUE}に、上記でマッチしたログとは異なるログ(より新しく出力したログ)の内容が表示する、というのが
正しい動作ということでしょうか。
そうなると同時間に複数のログが出た場合、メール通知の内容がずれてしまうのが正しい動作となりますが、
そのような認識で間違いございませんでしょうか。

ユーザー jusco0103 の写真

ログのタイムスタンプに不備があったため、修正しました。

ユーザー yk_taiko の写真

恐らく、"getLogTimeDiff.sh[xxxxx]" を使用している影響だと思います。

トリガー条件が長いので、それぞれ(a)、(b)と記載します。
(a) {Template hoge:logrt[/dir/^system\.(log|log\.1)$,@LogLevel_error,,,skip].iregexp(".*E00000001.*",300)}<>0
(b) {Template hoge:getLogTimeDiff.sh[xxxxx].last()}<=300

ログが出力されてからイベントが出力されるまでに、おそらく3回判定が走っています。

(1) 「{"time":"2018-06-24 12:00:00","level":"ERROR","code":"E00000001","message":"xxx"}」出力時
(2) 「{"time":"2018-06-24 12:00:00","level":"ERROR","code":"E00000002","message":"yyy"}」出力時
(3) "getLogTimeDiff.sh[xxxxx]" 更新時

それぞれのタイミングでトリガー判定と {ITEM.VALUE} がどうなるか想定すると...
-------------------------------
(1)
 トリガー判定:(a)真=過去300秒に該当ログが存在
        (b)偽=アイテム更新前の為
 {ITEM.VALUE}:{"time":"2018-06-24 12:00:00","level":"ERROR","code":"E00000001","message":"xxx"}

(2)
 トリガー判定:(a)真=過去300秒に該当ログが存在
        (b)偽=アイテム更新前の為
 {ITEM.VALUE}:{"time":"2018-06-24 12:00:00","level":"ERROR","code":"E00000002","message":"yyy"}

(3)
 トリガー判定:(a)真=過去300秒に該当ログが存在
        (b)真=アイテムが更新された為
 {ITEM.VALUE}:{"time":"2018-06-24 12:00:00","level":"ERROR","code":"E00000002","message":"yyy"}
-------------------------------
となり、(3) のタイミングで出力されたために出た気がします。

ユーザー jusco0103 の写真

yk_taiko 様

いつもご回答いただきありがとうございます。

(2)のトリガー判定で取得した{ITEM.VALUE}の状態から(3)のトリガー評価時の条件(b)が真となりトリガー発報した結果、
トリガーに整合しない{ITEM.VALUE}が表示されるということですね。
丁寧なご説明誠にありがとうございます。大変得心致しました。

確認のため、getLogTimeDiff.sh[xxxxx]の値が500秒より多い状態から、
同じ時刻にトリガーにマッチするもの、しないものを含めた
複数種類のログを出力させて動作検証してみます。