イベントログの監視
Windowsのイベントログを監視していますが、意図したように障害検知されません。
環境：
○CentOS 6.2、Zabbix Server 1.8.16
○Windows Server 2008、Zabbix Agent 1.8.15
Windowsのイベント（application、system、security）のエラーログを監視するように設定しました。
→エラーレベルと情報レベルの２つのイベントログを作成して、エラーのログのみ障害検知できることは確認しました。
しかし、Windowsサーバを再起動をしたり、このサーバを監視外（ステータスを無効）に設定後に監視状態（ステータスを有効）に設定すると、それまでたまっていたイベントログが一気に読み込まれるため？か情報レベルのログが障害として検知されます。もちろんエラーログは障害として検知されます。
監視設定は以下の通りです。
○アイテム
タイプ：Zabbixエージェント（アクティブ）
キー：eventlog[application]
データ型：ログ
更新間隔：300s
○トリガー
イベント生成：ノーマル
条件式：({Template_Windows:eventlog[application].logseverity()}=4)&({Template_Windows:eventlog[application].nodata(60)}=0)
原因の説明が出来ずに困っています。設定が間違っているのでしょうか？
よろしくお願い致します。
TNK - 投稿数: 4744
Zabbixサーバを稼働させているサーバと、監視対象のWindowsとで
時刻が合っていて、対象となる監視アイテムの情報を変更していな
ければ、Windowsを再起動してもイベントログを再読み込みしてし
まうようなことは発生しないはずです。
再度、時刻が合っているか、アイテムを変更したりしていないか、
本当に再読み込みして最初から処理されているのかをご確認くださ
い。
あと、気になるのは、アイテムの更新間隔が300秒となっているの
に、トリガーのnodata()の引数が60秒にされている点です。
アイテムは、300秒間隔でしか確認しないものに対して、60秒間デ
ータがなかったかを判定するのは不自然ではないでしょうか。
300秒経たなければ状態が変化しないのですから、無駄な判定処理
を行っていることになってしまっていると思います。
恐らく、nodata()を利用して、新たなログが指定された時間出力さ
れなければ、障害の状態を元に戻したいと考えられて設定されたと
思うのですが、nodata()を利用する場合は、確か30秒ごとに式の評
価処理が動くので、記載頂いたようなトリガーの式で、設定によっ
ては複数回同じ障害に対して通知してしまう場合があるかもしれま
せん。
アイテムの更新間隔よりもnodata()の引数を大きくしてみてはいか
がでしょうか。
katosai - 投稿数: 36
回答ありがとうございます。返信が遅くなりすみません。
以下を確認しました。
・サーバとWindowsの時刻は合っていた
・nodata()の引数をアイテム更新間隔（300）より大きく350にしてみたが、現象は変わらない
>エラーレベルと情報レベルの２つのイベントログを作成して、エラーのログのみ障害検知できることは確認しました。
このようなログのケース（エラーログ１の後に情報ログ１）でイベントを生成して、再度以下を確認してみました。
○nodata()の引数を60、250、350で変える
→どの引数の場合もエラーログ１を障害検知
○nodata()の引数を60、250、350で変える。サーバを監視外（ステータスを無効）に設定後に監視状態（ステータスを有効）にする。
→どの引数の場合もエラーログ１を障害検知
上記のログと少し変えて、情報ログ１→エラーログ１→情報ログ２というケースのイベントを生成して、同じ条件で確認してみました。
○nodata()の引数を60、250、350で変える
→どの引数の場合も情報ログ２を障害検知
→最新のログを検知してしまう
○nodata()の引数を60、250、350で変える。サーバを監視外（ステータスを無効）に設定後に監視状態（ステータスを有効）にする。
→どの引数の場合も情報ログ２を障害検知
→最新のログを検知してしまう
上記のような結果になりまして、nodata()の引数を変えても情報やエラーに関係なく最新のログが取得されました。
なお、障害検知といっているのは、メールによる障害通知を指しています。
アクションで以下のようにメールの内容を設定しています。
-----------------------------------------------------
Trigger: {TRIGGER.NAME}
Event date: {EVENT.DATE}
Event time: {EVENT.TIME}
Trigger status: {TRIGGER.STATUS}
Trigger severity: {TRIGGER.SEVERITY}
Item values:
{ITEM.NAME1} ({HOSTNAME1}:{TRIGGER.KEY1}): {ITEM.VALUE1}
-----------------------------------------------------
メールの設定が悪いのでしょうか？
よろしくお願いいたします。
TNK - 投稿数: 4744
トリガーなどを変更されたのであれば、きちんとその内容をご提示
ください。
以前、サーバを再起動したときにログを最初から再読み込みされて
いるという質問であったのかと思いますが、今回は、複数イベント
を発生させた際の動作の質問に質問内容が変わっています。
申し訳ありませんが、
・実現したいことは何なのか？
・どう設定したのか？
・想定していた動きと実際に発生した現象はどのような違いで、
どうしたいのか？
を再度ご提示いただけませんでしょうか？
あと、送られたメールがどのサーバで、どのタイミングで発生させ
たイベントであるかもきちんと照らし合わせてみてください。
katosai - 投稿数: 36
申し訳ありません。下記に整理します。
■実現したいこと
Windowsのイベントログ監視で、エラーログだけを障害検知して、メール通知したい。
さらに、現在の運用ではホストを監視除外にしたり監視にしたりしているが、監視を再開させた時もエラーログだけを検知したい。
■現状
Windowsのイベントログ監視で単発のエラーログは障害として検知でき、エラーログだけがメール通知できる。
しかし、対象となるWindowsホストのステータスを「無効」から「有効」に変更して監視を再開すると、前回の監視以降たまっていたイベントログの内、（エラー、情報に関係なく）最新のログがメールによって通知される。
■現在の設定
○環境：
・CentOS 6.2、Zabbix Server 1.8.16
・Windows Server 2008、Zabbix Agent 1.8.15
○アイテム
・タイプ：Zabbixエージェント（アクティブ）
・キー：eventlog[application]
・データ型：ログ
・更新間隔：300s
○トリガー
・イベント生成：ノーマル
・深刻度：軽度の障害
・条件式：({Template_Windows:eventlog[application].logseverity()}=4)&({Template_Windows:eventlog[application].nodata(60)}=0)
○アクション
・イベントソース：トリガー
・アクションのコンディション：「トリガーの値＝障害」&「トリガーの深刻度＝軽度の障害」
・メッセージ：
-----------------------------------------------------
Trigger: {TRIGGER.NAME}
Event date: {EVENT.DATE}
Event time: {EVENT.TIME}
Trigger status: {TRIGGER.STATUS}
Trigger severity: {TRIGGER.SEVERITY}
Item values:
{ITEM.NAME1} ({HOSTNAME1}:{TRIGGER.KEY1}): {ITEM.VALUE1}
-----------------------------------------------------
TNK様の「アイテムの更新間隔よりもnodata()の引数を大きく」という助言通り、トリガーの条件のnodata()を以下のように変えてみました。
({Template_Windows:eventlog[application].logseverity()}=4)&({Template_Windows:eventlog[application].nodata(350)}=0)
しかし、ホストのスタータスを無効から有効に変えると、監視無効中に発生したログがエラー、情報ログを含めて22件あり、その内2件がエラーログでしたが、メールによって通知されたのは22件目（22件のうち最新）の情報ログでした。
情報ログが全て読み込まれるというのは漠然としているため、現象のスコープを小さくしようと思い複数イベントを発生させて現象を確認しようとした次第です。
よろしくお願いいたします。
fripper - 投稿数: 495
この挙動は仕様となってしまいます
まず、ホストを無効にしていたこと。
その間に発生していたログは、zabbixサーバ宛には通知されていません
ホストを有効にした時点で、前回の監視以降に発生した追加ログがすべてサーバへ向けて送信されます
この時点で、エラー判定される行が見つかったため、トリガーが発動し、
アクションが発動してメールが送信される流れになります
メール本文に書かれる値「ITEM.VALUE1」ですが、
>The latest value of the Nth item in the trigger expression if used for displaying triggers.
>Historical (when event happened) value of Nth item of the trigger expression
>if used for displaying events and notifications.
トリガーが発動し、アクションが発動した時点で、対象となるアイテム「eventlog[application]」に対して
zabbix側のDBに保存されている値は、最後に届いた値ですので、たまたまそれの serverity は「情報」レベルかもしれません
この値がメールに表示されてしまっているのが現状となります
対策ですが‥
zabbix 側で、serverity に関わらず、全てのイベントログを収集する必要がある場合や、
このアイテムに対して、別のトリガーを仕掛けている場合などには難しいかもしれませんが、
アイテムの定義そのものを「eventlog[application,,"Error"]」のように、
そもそもエラーのもの、今回のトリガーの対象になるべきもの、しか
収集しないようにしてしまうことで、対策が可能です
もちろん、この場合には、トリガー側の定義も変更が必要となり、serverity での条件判定は不要となります
{Template_Windows:eventlog[application,,"Error"].nodata(60)}=0
katosai - 投稿数: 36
回答ありがとうございます。
eventlog[application]では全てのイベントログ（情報やエラーなど）が対象になるんですね。
それをeventlog[application,,"Error"]とすることで、エラーのイベントログのみが対象になるわけですね。
教えていただいた通り下記のようにアイテム、トリガーを設定し、ステータスを無効から有効にしたところ確かにエラーログのみが検知され、エラーログのみがメールで通知されるようになりました。
{Template_Windows:eventlog[application,,"Error"].nodata(60)}=0
ありがとうございました。
また、nodata()の動きがまだ理解できておりません。
TNK様から指摘がありましたが、監視間隔が300なのでnodata()は300より大きく設定した方がよろしいのでしょうか？
よろしくお願いします。
fripper - 投稿数: 495
マニュアル（https://www.zabbix.com/documentation/jp/1.8/manual/config/triggers）にもありますが、
nodata を利用したトリガーは、関係するアイテムのデータ更新がなくても 30sec に１度評価されます
仮に、nodata の閾値間隔を 500、eventlog のチェック間隔を 300 とした場合には
00:00:00. 定期処理としての nodata のチェックが行われる
00:00:20 エージェントがチェック、新規ログの中に error は見つからなかった
00:00:20. データは届いていないので、トリガーの評価は行われない
00:00:30. 定期処理としての nodata のチェックが行われる
00:01:00. 定期処理としての nodata のチェックが行われる
・・以下30秒おきに定期チェック
00:04:30. 定期処理としての nodata のチェックが行われる
00:05:00. 定期処理としての nodata のチェックが行われる
00:05:20 エージェントがチェック、新規ログの中に error が見つかって、データを送ってくる
00:05:20. データが届いたので、トリガーの評価が行われる → 500 sec 以内にデータがあるのでトリガー発動
00:05:30. 定期処理としての nodata のチェックが行われる → 500 sec 以内にデータがあるのでトリガー発動したまま
00:06:00. 定期処理としての nodata のチェックが行われる → 500 sec 以内にデータがあるのでトリガー発動したまま
・・以下30秒おきに定期チェック
00:09:30. 定期処理としての nodata のチェックが行われる → 500 sec 以内にデータがあるのでトリガー発動したまま
00:10:00. 定期処理としての nodata のチェックが行われる → 500 sec 以内にデータがあるのでトリガー発動したまま
00:10:20 エージェントがチェック、新規ログの中に error は見つからなかった
00:10:20. データは届いていないので、トリガーの評価は行われない
00:10:30. 定期処理としての nodata のチェックが行われる → 500 sec 以内にデータがあるのでトリガー発動したまま
00:11:00. 定期処理としての nodata のチェックが行われる → 500 sec 以内にデータがあるのでトリガー発動したまま
・・以下30秒おきに定期チェック
00:13:30. 定期処理としての nodata のチェックが行われる → 500 sec 以内にデータがあるのでトリガー発動したまま
00:14:00. 定期処理としての nodata のチェックが行われる → 500 sec 以内にデータがなくなったのでトリガーが戻る
00:14:30. 定期処理としての nodata のチェックが行われる
といったようになります
仮に、nodata の閾値間隔を 60、eventlog のチェック間隔を 300 とした場合には
00:00:00. 定期処理としての nodata のチェックが行われる
00:00:20 エージェントがチェック、新規ログの中に error は見つからなかった
00:00:20. データは届いていないので、トリガーの評価は行われない
00:00:30. 定期処理としての nodata のチェックが行われる
00:01:00. 定期処理としての nodata のチェックが行われる
・・以下30秒おきに定期チェック
00:04:30. 定期処理としての nodata のチェックが行われる
00:05:00. 定期処理としての nodata のチェックが行われる
00:05:20 エージェントがチェック、新規ログの中に error が見つかって、データを送ってくる
00:05:20. データが届いたので、トリガーの評価が行われる → 60 sec 以内にデータがあるのでトリガー発動
00:05:30. 定期処理としての nodata のチェックが行われる → 60 sec 以内にデータがあるのでトリガー発動したまま
00:06:00. 定期処理としての nodata のチェックが行われる → 60 sec 以内にデータがあるのでトリガー発動したまま
00:06:30. 定期処理としての nodata のチェックが行われる → 60 sec 以内にデータがなくなったのでトリガーが戻る
00:07:00. 定期処理としての nodata のチェックが行われる
・・以下30秒おきに定期チェック
00:10:00. 定期処理としての nodata のチェックが行われる
00:10:20 エージェントがチェック、新規ログの中に error は見つからなかった
00:10:20. データは届いていないので、トリガーの評価は行われない
00:10:30. 定期処理としての nodata のチェックが行われる
といったようになります
監視データの到着と、nodata の定期評価タイミングは、必ずしも同期しないため、こうなります
今回の事例では、トリガーが戻るタイミングが変わるだけになります
TNK さんが指摘なさっているのは、通常、定期的にデータが届くはずのアイテム（zabbixエージェント型など）を
利用したトリガーでの問題です
300 秒おきにデータが届くはずのアイテムで、900 秒間 nodata ならばエラー、とするならば良いのですが、
300 秒おきにデータが届くはずのアイテムで、60 秒間 nodata ならばエラー、としてしまうと、
正常時にも、トリガーが発動してしまうことになります
よって、一般的に nodata を利用する場合には、アイテムの監視間隔に指定した時間間隔よりも
長い期間を指定すべき、との指摘です
＃TNK さん、もし誤解でしたら申し訳ありません
通常のエージェントタイプのアイテムで、nodata を活用する利点としては、
ネットワーク途絶や、エージェント側モジュールのダウンなどで、意図しないデータ到着の
途絶が発生したことが検知できるようになることです
先に書きましたとおり、（マニュアルにある記述です）
常時30秒おきに、トリガーの評価処理が動作することになります。
よって、nodata を使ったトリガーを多用すると、サーバ側の負荷が上がることにつながります
監視台数や、トリガー数、サーバのスペックやDBのパフォーマンスにもよりますが、
この点には注意が必要です
katosai - 投稿数: 36
ようやくnodata()の動きが理解できました。
詳しい説明をありがとうございました。
katosai - 投稿数: 36
教えていただいてから時間がたってしまいましたが、追加で質問させていただきます。
以前はトリガーを以下のように設定しており、多くのイベントログ（情報、エラーが混在）が出力されると、エラーではないログがメールによって通知されました。
---------------------------------------------------
イベント生成：ノーマル
条件式：({Template_Windows:eventlog[application].logseverity()}=4)&({Template_Windows:eventlog[application].nodata(60)}=0)
---------------------------------------------------
この場合、例えば、10件のログ中5件のエラーログがあった場合はメールが5件送信されていました。
トリガーの条件式を教えていただいたように設定したところ、多くのイベントログが出力されても、エラーログのみが検知されてエラーログのみがメールで通知されるようになりました。
---------------------------------------------------
{Template_Windows:eventlog[application,,"Error"].nodata(60)}=0
---------------------------------------------------
しかし、例えば、10件のログ中5件のエラーログがあったとしてもメールは1件しか送信されなくなりました。
ヒストリ画面上では5件のエラーログが表示されてます。
質問１）
トリガーを以下のように設定した上で、メールをエラーの件数分送信することは可能でしょうか？
---------------------------------------------------
{Template_Windows:eventlog[application,,"Error"].nodata(60)}=0
---------------------------------------------------
質問２）
トリガーを以下のように設定し、
---------------------------------------------------
{Template_Windows:eventlog[application,,"Error"].nodata(60)}=0
---------------------------------------------------
ヒストリ画面上では以下のようにエラーが表示されています
---------------------------------------------------
エラー5 ←①今回の監視で検出されたエラー
エラー4 ←②今回の監視で検出されたエラー
エラー3 ←③今回の監視で検出されたエラー
エラー2 ←④今回の監視で検出されたエラー
エラー1 ←⑤今回の監視で検出されたエラー
エラー10 ←⑥前回の監視で検出されたエラー
エラー9 ←⑦前回の監視で検出されたエラー
エラー8 ←⑧前回の監視で検出されたエラー
エラー7 ←⑨前回の監視で検出されたエラー
エラー6 ←⑩前回の監視で検出されたエラー
エラー5 ←⑪前回の監視で検出されたエラー
エラー4 ←⑫前回の監視で検出されたエラー
エラー3 ←⑬前回の監視で検出されたエラー
エラー2 ←⑭前回の監視で検出されたエラー
エラー1 ←⑮前回の監視で検出されたエラー
---------------------------------------------------
その結果、送信されてきたメールは以下でした。
---------------------------------------------------
エラー1
エラー10
エラー9
エラー8
エラー7
エラー6
エラー5
エラー4
エラー3
エラー2
---------------------------------------------------
アクションは以下のように設定しました。
---------------------------------------------------
{{HOSTNAME1}:{TRIGGER.KEY1}.last(#1)}
{{HOSTNAME1}:{TRIGGER.KEY1}.last(#2)}
{{HOSTNAME1}:{TRIGGER.KEY1}.last(#3)}
{{HOSTNAME1}:{TRIGGER.KEY1}.last(#4)}
{{HOSTNAME1}:{TRIGGER.KEY1}.last(#5)}
{{HOSTNAME1}:{TRIGGER.KEY1}.last(#6)}
{{HOSTNAME1}:{TRIGGER.KEY1}.last(#7)}
{{HOSTNAME1}:{TRIGGER.KEY1}.last(#8)}
{{HOSTNAME1}:{TRIGGER.KEY1}.last(#9)}
{{HOSTNAME1}:{TRIGGER.KEY1}.last(#10)}
---------------------------------------------------
メールが1件のみ送信の場合、メールの文面に今回検出したエラーを表示したいのですが、どのようにアクションに設定すればよいでしょうか？
メールを見ると、ヒストリ画面上の⑤～⑭のエラーが送信されたように見えますが、今回検出した①～⑤のエラーを送信させたいです。
エラー件数分のように動的に変えるのは難しいと思いますので、10件固定でよいです。
お忙しいところすみません。教えていただけないでしょうか。
TNK - 投稿数: 4744
ログを1行毎に処理してメールを送信させるには、トリガーのイベ
ント生成を「障害イベントを継続して生成」にする必要があります。
ただし、Zabbix 1.8系を利用されている場合、1秒間に多数のエラー
発生があった場合に、メールに記載される内容が、イベントが発生
したものと一致しない場合があります。
この不具合は、バージョン2.0で解消されていますので、大量のエ
ラーログを処理するような場合は、Zabbix 2.0系にバージョンアッ
プされることをお勧めします。
katosai - 投稿数: 36
TNK様 回答ありがとうございます。
>ログを1行毎に処理してメールを送信させるには、トリガーのイベ
>ント生成を「障害イベントを継続して生成」にする必要があります。
質問１に対する対応ですね。
自分で質問していて何ですが、このようにすると100件エラーが発生したら100件のメールが送信されるのでした。
質問２の1通のメールに今回発生したエラーを表示する方法は何かございますでしょうか？
last(#n)では、今回検出した1件目のエラーから過去に遡ってしまいました。
{ITEM.LASTVALUE＜n＞}は「ITEM.LASTVALUE1」は今回検出した1件目のエラーで、それ以外は「*UNKNOWN*」となりました。
>ただし、Zabbix 1.8系を利用されている場合、1秒間に多数のエラー
>発生があった場合に、メールに記載される内容が、イベントが発生
>したものと一致しない場合があります。
また、この部分をもう少し詳しく教えていただけないでしょうか？
以下を拝見させていただきましたが、顧客から原因説明を求められて困っております。
http://www.zabbix.jp/node/1827
http://www.zabbix.jp/node/745
お忙しいところすみません。よろしくお願いいたします。
heya - 投稿数: 319
こんにちは。
> >ただし、Zabbix 1.8系を利用されている場合、1秒間に多数のエラー
> >発生があった場合に、メールに記載される内容が、イベントが発生
> >したものと一致しない場合があります。
> また、この部分をもう少し詳しく教えていただけないでしょうか？
1.8では時間を秒までしか保持していません。1秒未満の違いは分からないので、時間順にソートしたときに秒が同じなら、その同じ秒のデータについては順番が保証されません。
2.0では時間をナノ秒まで保持しています。なので、時間順にソートしたときは秒が同じでもナノ秒は違うので、正確にソートされます。
例えば1.8では
－－－－－－－－－－－－－－－－－－－－－－－－－
実際に届いた時刻 データベースに保存される時刻
[1] 00:00:00.111111111 00:00:00
[2] 00:00:01.123456789 00:00:01
[3] 00:00:01.222333444 00:00:01
[4] 00:00:01.999999999 00:00:01
[5] 00:00:02.333333333 00:00:02
－－－－－－－－－－－－－－－－－－－－－－－－－
となるため、ソートしたときに最初が[1]で最後が[5]というのは保証されますが、[2][3][4]がこの順番になる保証はないということです。実際にどういう順番になるかはおそらくデータベースにどう格納されるかによるんでしょう（そしてそれはユーザーの関知するところではない）。
ところで、今は「障害イベントを継続して生成」はチェックしてない状態なんですよね？そうであれば、最初のエラーログが届いた時点で障害状態になり、二つ目以降のログが届いても障害状態は継続したままなのでアクションは実行されないと思います。そして、60秒後にnodata(60)が1になるので、トリガーの条件式を満たさなくなり、回復状態に戻ると思います。
> 質問２の1通のメールに今回発生したエラーを表示する方法は何かございますでしょうか？
というわけで、「一連のログが全部出終わった後にまとめて表示する」というのは難しいと思います。何かいい方法はあるんだろうか・・・？
> {ITEM.LASTVALUE＜n＞}は「ITEM.LASTVALUE1」は今回検出した1件目のエラーで、それ以外は「*UNKNOWN*」となりました。
LASTVALUEのnは、“トリガーの条件式のn番目のアイテム”の最新の値です。今回はトリガー内にアイテムは一つしか無いので、2以降だと「*UNKNOWN*」となるんでしょう。
katosai - 投稿数: 36
heya様
時間の持ち方の問題だったのですね。詳しい説明をありがとうございました。
>ところで、今は「障害イベントを継続して生成」はチェックしてない状態なんですよね？
はい、その通りです。
最初のエラーログ以降はアクションが実行されないため、メールは1件のみ送信されます。
ヒストリー画面上では一連のログが表示されているので、何とかならないかと思ったのですが。。。
お忙しいところ、ありがとうございました。