ログ監視におけるトリガーのステータス変化について
はじめまして。takaiと申します。
ZABBIXのログ監視を利用しているのですが、トリガーのステータス変化について自分の想定とは異なる挙動をしている為、質問をさせていただきます。
環境：
Red Hat Enterprise Linux ES release 4 (Nahant Update 6)
ZABBIX v1.4.5 (ソースからコンパイル)
現象：
ログ監視にて、以下のようなトリガーを設定しています。
({test_tp:vfs.file.cksum[/var/log/test.log].diff(0)}>0)&({test_tp:log[/var/log/test.log].str(error)}=1)
アイテムの更新間隔は全て5分に設定しています。
この状態で、以下のコマンドにて、ログファイルに文字列を書き込みます。
# echo -e "hogehoge \n error \n 12312\nsdffegs\nsadgagwg\nhoahgfiwoagh\nerror\naksfjkshah
g\nkhjrih23ioorhoq\n 3 error\nhgklasgklwh\nafjaofj\nerro\nafkweflkf\nerror \ninfo" >> /var/log/test.log
この場合、ZABBIX上で以下のようにトリガーのステータスが変化すると想定していたのですが、想定通りの挙動となりません。
＜想定したトリガーステータスの変化＞<pre>
ログ書き込み文字列 トリガーステータス変化
hogehoge
error ← "障害"に変化
12312 ← "正常"に変化
sdffegs
sadgagwg
hoahgfiwoagh
error ← "障害"に変化
aksfjkshahg ← "正常"に変化
khjrih23ioorhoq
3 error ← "障害"に変化
hgklasgklwh ← "正常"に変化
afjaofj
erro
afkweflkf
error ← "障害"に変化
info ← "正常"に変化
</pre>
実際の挙動としては、上記4回全てでトリガーのステータスが障害となる場合もありますし、逆に、一度も障害とならない場合もあります。数回のみ障害を検知する場合もあります。
エージェントからログが(全て)転送されている事は、アイテムのヒストリにて確認しています。
ZABBIXのログ監視(アイテム値の転送)とトリガーの判定プロセスについて良く分かっていないのですが、上記のような挙動はそもそも仕様なのでしょうか。別スレッドになりますが、ふりっぱぁさんが以下のような投稿をされていたので、関連があるのかもしれないとも思うのですが、良く分かりませんでした。
<blockquote>＜２＞
また、ログがある程度の頻度で出力されていることと、エラー以外の情報も多数含んでいるため、
・エラー文字列を含む行が送られてきていても、トリガーの判定時には、それが最新行ではなくなって
しまっていて、判定に引っかからないことがある
</blockquote>
http://www.zabbix.jp/modules/newbb/viewtopic.php?topic_id=264&forum=6
上記ご存じの方、心当たりがある方がいらっしゃいましたら、教えていただけますでしょうか。(ソースコードのこの辺り、という情報ももしあればお願いします。)
長文申し訳ございません。何か情報がありましたら、よろしくお願い致します。
ysato - 投稿数: 6
takai さん、おはようございます。
佐藤と申します。
＃まだ試していませんが・・・
一度状況整理のために、監視条件を絞って頂けませんでしょうか？
今回の検索要求を満たすために、「{test_tp:log[/var/log/test.log].str(error)}=1」の条件式のみ、設定した場合の挙動はどうなりますか？
お手数をおかけしますが、宜しくお願い致します。
ysato - 投稿数: 6
動作確認をしてみました。
ZABBIX 監視ロジックの関係で、takai さんの検証方法ですと、まとめて障害検出されるようですね。
監視待機間隔を例えば 60 秒とした場合、監視開始直後のログ状態をひとまず確認して、error 文字列が対象ログに出力されていたら、「異常通知」を出力します。その後、60 秒間監視自体は停止 (ログは保存しつづける) しています。
60 秒経過後、再度監視して、前回の error を検出した、次の行以降に error があれば、「異常通知」します。error がなければ、「正常」とします。
今回の takai さんのケースですと、error 文字列が 1 以上出力された場合、「障害通知」をする設定ですから、echo コマンドで出力された error 4 回分が「障害通知」されていたのだと思います。
takei さんの期待されるような、障害検知試験をされる場合、以下のようなやり方をする必要があるかと思います。
1. error 出力 ( $ echo "error" > /var/log/test.log" )
2. ZABBIX 監視開始→「障害検知」
3. error 出力 ( $ echo "error" >> /var/log/test.log" )
4. ZABBIX 監視開始→「障害検知」
5. error 出力 ( $ echo "error" >> /var/log/test.log" )
6. ZABBIX 監視開始→「障害検知」
7. error 出力 ( $ echo "error" >> /var/log/test.log" )
8. ZABBIX 監視開始→「障害検知」
過不足あれば、どなたかご教示を・・・ :-?
takai - 投稿数: 20
返信ありがとうございます。
すいません。まだ試していませんのでこれからテストしてみます。
ご説明ありがとうございます。ただ今回良く分からないのは、初回投稿時に記載したテストケースで、『4回障害を検知する』場合もあれば、『2回障害を検知する』『一度も障害を検知しない』場合もあるというところです。
cksum が影響しているのか、他の部分で ZABBIX のトリガーチェックタイミングが上手くあっていないのか、良く分からないですが…。
例えば、ZABBIX の挙動として、Agent から転送されたログの保存ロジックとトリガーのチェックロジックが並列に動いていたりするのでしょうか。もし並列に(同期せずに)動いていると、以下のタイミングで上手く検知できない可能性があるかもしれない…？とも思っています。
1. 文字列 "error \n info" が Agent から転送される。
2. 保存ロジックが "error" を DB (MySQL) に保存。
3. トリガーチェックのロジックが起動される。
4. トリガーチェックのロジックが文字列を取得する前に、保存ロジックが "info" を DB に保存。
5. トリガーチェックのロジックが文字列を取得。この時点では "info" が最新の文字列となる為、『障害』にならない。
全て想像で描いているので、実際どうなのかを確認したいのですが、C言語はあまり得意ではない為、何か情報をお持ちの方がいれば、ご教示いただければ幸いです。(ソースコードのこの辺り、等。)
引き続き、何か情報をお持ちの方がいらっしゃいましたら、ご返信いただけると幸いです。
kodai - 投稿数: 1341
こんにちは。
私もテストできてないのですが、ひとつ気になる点があります。ysatoさんも書かれていますが、トリガーの
{test_tp:vfs.file.cksum[/var/log/test.log].diff(0)}>0
の部分は何か意図or目的があって設定されているのでしょうか？本来、ログのトリガー設定は
{test_tp:log[/var/log/test.log].str(error)}=1
だけでも問題なく動作するはずです。
また、アイテムの設定は以下のようになっているでしょうか？念のためご確認ください。
タイプ: ZABBIXエージェント(アクティブ)
キー: log[/var/log/test.log]
データ型: ログ
takai - 投稿数: 20
返信ありがとうございます。
こちらは、トリガーの条件にマッチする文字列が連続で書き込まれたときに、アラート(障害)を複数回発生させる為に設定しています。
現在、アイテムの取得間隔を5分に設定していますので、5分以内に連続して "error" が出力された場合は一度しか障害として検知されませんが、5分以上間隔を空けて "error" が連続して出力された場合は、それぞれを個別に検知する事が出来ます。(できると考えており、実際にそれっぽい挙動をしています。)
再度、確認致しました。正しく設定されているようです。
また、ysatoさんよりいただいていた
について、スクリプトを作って半日ほどテスト(試行回数で約110回)してみたところ、全てのケースで意図したとおりにトリガーのステータスが変化していました。
やはりcksumが怪しそうですが、前述の目的の為にcksumを条件に追加しているため、単純に条件から外すことは避けたいと考えています。
引き続き情報がありましたらお願い致します。また、cksumを利用せず、かつ上記の挙動(5分以上の間隔で "error" が連続して出力された場合は、それぞれ障害として検知したい)を満たせるトリガーの書き方等もありましたら、ご教授いただけると幸いです。
kodai - 投稿数: 1341
なるほど、そういうことでしたか。
上記の条件式ですと、cksumの値が前回値から変わっていない限り、ログにerrorの文字列があっても検知しないことになります。
ZABBIXの監視は各アイテムの収集タイミングにずれがありますので、ログ監視とcksumの監視が実行される時差でトリガーが動作していないのではないかと思います。
たとえば、ログ監視を5分ごとに行っているのであれば以下のトリガー設定では解決しないでしょうか？
({test_tp:log[/var/log/test.log].nodata(60)}=0)&({test_tp:log[/var/log/test.log].str(error)}=1)
上記の条件式ですと1回のログ監視が終了して60秒たったタイミングでトリガーは正常に戻るはずなので、次回のログチェックのタイミングでは必ずerror文字列が障害として検知されるはずです。
takai - 投稿数: 20
ご返信ありがとうございます。
なるほど。確かにこちらの方が複数アイテムを利用しない分、動作が安定する(意図通りの設定となりやすい)かもしれません。少し試したところ問題がなさそうでしたので、こちらの設定も本格的にテストしようと思います。
# 少し話がそれますが、nodata(60)はどのタイミングでチェックされるのでしょうか？log[/var/log/test.log]の値は最短で5分おきにしか更新されないと思うのですが、トリガー式で利用されている値を新規に受信した場合以外にも、トリガーの再計算が実施されているということでしょうか？(「トリガー再計算」のトリガーとなるものが良く分かりません…。)
皆様からいろいろと情報をいただき、状況を整理した結果、初めに投稿させていただいた問題は、実は2つの問題を含んでいるような気がしてきました。
1つ目は、kodaiさんよりご指摘いただいている「ログ監視とcksumの監視が実行される時差」によるものです。
前述のテストケースの場合、「echoによるログ書き込み(a)」→「cksumのアイテム値取得(b)」→「Agentによるサーバへのログ転送(c)」の順で処理が行われれば障害を検知しますが、(a)→(c)→(b)の順で処理された場合、(c)の段階ではcksumの更新を認識できないため障害にならず、かつ(b)のタイミングではログの最終文字列が"info"である為やはり障害を検知しないということになります。
# ということでよろしかったでしょうか？誤認しておりましたら、ご指摘お願い致します。
2つ目は「1つ目の原因以外によるもの」です。初回投稿時に「数回のみ障害を検知する場合もある」旨を書かせていただきましたが、具体的には前述のテストケースにて "3 error" (投入文字列の中で3番目にトリガーに引っかかる文字列) のみ障害を検知せず、その他(他3回の "error")は検知するという事がありました。
この場合、cksumのアイテム取得間隔はログと同じ5分なので、1つ目の問題(ケース)では説明ができないと考えています。
2つ目の問題については、サーバ側のログレベルを上げて、さらに調査を行う予定です。
色々と情報ありがとうございます。引き続き、何か情報がありましたらよろしくお願い致します。
takai - 投稿数: 20
ご連絡が遅くなり申し訳ありません。
上記のトリガーで400回ほど投入テストを実施して、一度も検知漏れが無い事を確認しました。こちらの設定で実際の監視を行おうと考えています。
ysatoさん、kodaiさん、ご返信いただきありがとうございました。