vfs.file.regmatchで誤検知
いつもお世話になっております。
Zabbixのバージョン： 2.2.7
ZabbixサーバのOS： CentOS 5.4
ZabbixエージェントのOS：Windows2003
vfs.file.regmatchを使用してログ監視を行っているのですが、
監視対象のログファイルに検知条件の文字列が出力されていないにも関わらず検知されてしまうことがあります。
アイテム
vfs.file.regmatch[D:\Application\log\xxx.log,テスト,SHIFT_JIS]
アイテムのタイプ
Zabbixエージェント
更新間隔
60
トリガー
{test1:vfs.file.regmatch[D:\Application\log\xxx.log,テスト,SHIFT_JIS].last(0)}>0
毎回発生するわけではなく、発生しても次の更新タイミングでは正常になります。
何か原因など分かりますでしょうか。
以上、よろしくお願いいたします。
TNK - 投稿数: 4671
確認させて頂きたいのですが、そのxxx.logというファイルは、ロ
グの情報が1行1行追記されるようなログファイルではなく、毎回フ
ァイルの内容をすべて書き換えるような出力が行われるのですか？
ogata - 投稿数: 28
ログファイルは1行1行追記されていきます。
また、ログファイルには行の先頭にタイムスタンプが記載されているのですが、
検知した時刻には何も出力されていませんでした。
TNK - 投稿数: 4671
vfs.file.regmatch[]は、ファイルの最終行を検査するためのキー
ではありません。
ファイル内全体をみて、指定した文字列が含まれているかを検査す
るためのものです。
テキスト形式で、最終行に追記されていくようなのログファイルで、
最終行に該当する文字列が含まれるかを検査されたいのであれば、
log[]もしくはlogrt[]を利用することになると思います。
ogata - 投稿数: 28
回答ありがとうございます。
vfs.file.regmatch[]は更新周期のたびにファイルの先頭行から文字列が含まれているかという動作だと理解しています。
ただ、ログファイル内に該当文字列は出力されていないにもかかわらずvfs.file.regmatch[]の戻り値が1で返却されており、次のタイミングでは0が返却されているという動作を行っていました。
もし該当文字列が出力されている場合はファイルをクリアして文字列を消去するまでは正常に戻らないという認識なのですが違うのでしょうか。
TNK - 投稿数: 4671
ファイル内に含まれていなければ、0が返却されるはずです。
ファイルに含まれていなくても1が返却されたとのことですが、そ
れ以前に含まれていて、その値が残ったままであったのではありま
せんか？
最新データの画面等を利用して、再度、アイテムの値を取得したタ
イムスタンプと、ファイルの中にあったのかなかったのかとを照ら
し合わせてみてください。
例えば、何らかの原因でZabbixエージェントがそのファイルにアク
セスできない状態が発生していたりすると、そのアイテムの状態が
取得不可という状態になってしまう場合がありますのでご注意くだ
さい。
ogata - 投稿数: 28
最新データの情報などを見てみましたが、
グラフ上16:36以前は0で、16:36に1となり、16:37に0になっていました。
ログファイルのタイムスタンプを確認しましたが、16:30台に出力されたログはひとつもありませんでした。
1日1回ログファイルをローテーションしており、
15:13に条件には一致しない文字列が出力されていてその次に出力されているのは16:52で、
それも条件には一致していない文字列でした。
(15:13以前も条件に一致している文字列はありませんでした)
また、zabbix_server.logの16:36周りに関連するメッセージは出力されていませんでした。
4:45～8:37までログファイルが存在しないため取得不可になっていました。
TNK - 投稿数: 4671
正規表現に誤りがないかもご確認ください。
実際に指定されている正規表現は「テスト」という文字列ではない
ですよね？
もしかしたら、その設定内容が、ご自身が合致すると思われている
文字列とは一致していないのかもしれません。
ogata - 投稿数: 28
>実際に指定されている正規表現は「テスト」という文字列ではないですよね？
はい、実際は違う文字列になります。
再確認してみましたが、vfs.file.regmatch[]で指定した文字列はログファイル内に存在していませんでした。
TNK - 投稿数: 4671
後は、Zabbixのバージョンが古いことと、文字コードによる問題
くらいしか思いつきません。
可能であれば、具体的に指定されているキーの情報をお教え頂けれ
ば、再現の確認はできるかもしれません。
ogata - 投稿数: 28
回答ありがとうございます。
検知できないということであれば、文字コードの問題も考えたのですが
文字列が存在しないのに検知してしまうということなので文字コードではないと思います。
一度該当のアイテムとトリガーを削除して再度登録して様子をみています。
ogata - 投稿数: 28
一度アイテムとトリガーを削除した後、同じ内容で作成しましたが、
再びログに出力されていないにもかかわらずvfs.file.rematch[]で検知してしまう事象が発生していました。
別のサーバにも同じ内容のアイテムとトリガーを設定している(サーバ名が異なるだけで、検知文字列もファイルパスも同じ)のですが、そちらでは発生していません。
Zabbixエージェントを再起動などすることで改善されることはありますでしょうか。
TNK - 投稿数: 4671
もう少し具体的に出力されるログの内容と指定された正規表現を
ご提示頂けませんか？
私は、適切ではない正規表現が指定されている可能性をまだ拭い
きれていません。
あと、ログファイルを監視するのに最後の追記された行だけを見る
log[]やlogrt[]を利用するのではなく、vfs.file.regmatch[]を利
用されていることで、ファイルの全体として指定された正規表現
に合致している可能性も考えられるとまだ考えています。
あとは、Zabbix 2.2系ならサーバ側もエージェント側も最新の
バージョン(2.2.10)にバージョンアップした上で問題が発生する
のであれば、エージェントを再起動しても変わらないと思います。
ogata - 投稿数: 28
回答ありがとうございます。
出力される文字列、検知条件の文字列の提示は難しいのですが、
ログの内容として、正常終了を表す文字列か、異常終了を表す文字列のどちらが3分毎に出力されます。
検知条件として、2バイト文字のみが設定されており、正規表現は使用しておりません。
情報を収集するために、エージェントのデバックレベルを4に設定し、エージェントの再起動を行いました。
事象が再現されたタイミングのログを確認したところ、
事象が発生したタイミングの前回の精査では、22:46:01 までのログを精査しているようですが、
事象が発生したタイミングでは、18:58:00 までのログしか精査されていないように見えます。
また、デバックのログのなかに、検知条件を精査した旨のログは出力されていないように見えますが、
Sending back [1] が出力されてしまっています。
--事象発生前のログ--
2460:20151110:224826.633 Requested [vfs.file.regmatch[D:\Application\log\xxx.log,XXXXXXXXXXXXXXXXXXXX,SHIFT_JIS]]
2460:20151110:224826.633 convert_to_utf8() in_size:65 encoding:'SHIFT_JIS' codepage:932
2460:20151110:224826.649 convert_to_utf8() utf8_size:80 utf8_string:'[2015/11/10 8:37:00] XXXXXXXXXXXXXXXXXXXX。
'
～～～～～～～～～～～～～～～～～～～～
2460:20151110:224828.383 convert_to_utf8() in_size:66 encoding:'SHIFT_JIS' codepage:932
2460:20151110:224828.399 convert_to_utf8() utf8_size:81 utf8_string:'[2015/11/10 22:46:01] XXXXXXXXXXXXXXXXXXXX。
'
2460:20151110:224828.399 Sending back [0]
--事象発生時のログ--
2460:20151110:224926.055 Requested [vfs.file.regmatch[D:\Application\log\xxx.log,XXXXXXXXXXXXXXXXXXXX,SHIFT_JIS]]
2460:20151110:224926.055 convert_to_utf8() in_size:65 encoding:'SHIFT_JIS' codepage:932
2460:20151110:224926.055 convert_to_utf8() utf8_size:80 utf8_string:'[2015/11/10 8:37:00] XXXXXXXXXXXXXXXXXXXX。
'
～～～～～～～～～～～～～～～～～～～～
2460:20151110:224927.227 convert_to_utf8() in_size:66 encoding:'SHIFT_JIS' codepage:932
2460:20151110:224927.227 convert_to_utf8() utf8_size:81 utf8_string:'[2015/11/10 18:58:00] XXXXXXXXXXXXXXXXXXXX。
'
2460:20151110:224927.227 Sending back [1]
--事象発生後のログ--
2460:20151110:225026.493 Requested [vfs.file.regmatch[D:\Application\log\xxx.log,XXXXXXXXXXXXXXXXXXXX,SHIFT_JIS]]
2460:20151110:225026.493 convert_to_utf8() in_size:65 encoding:'SHIFT_JIS' codepage:932
2460:20151110:225026.493 convert_to_utf8() utf8_size:80 utf8_string:'[2015/11/10 8:37:00] XXXXXXXXXXXXXXXXXXXX。
'
～～～～～～～～～～～～～～～～～～～～
2460:20151110:225028.274 convert_to_utf8() in_size:66 encoding:'SHIFT_JIS' codepage:932
2460:20151110:225028.290 convert_to_utf8() utf8_size:81 utf8_string:'[2015/11/10 22:49:01] XXXXXXXXXXXXXXXXXXXX。
'
2460:20151110:225028.290 Sending back [0]
何か原因などわかりますでしょうか。
TNK - 投稿数: 4671
ログが3分毎に追記されるログファイルを指定されているんですよ
ね？
そうであるならば、vfs.file.regmatch[]を利用していたら、ファ
イルのどこかで条件に合致したら、それ以上読まないでしょうから、
ファイルの途中で止める場合もあるでしょう。
繰り返しになりますが、ログファイルに追記された部分のみで文字
列合致のチェックを行いたいのであれば、log[]またはlogrt[]を利
用すべきです。
これ以上は情報を提供頂けていないので、問題点を推測することが
不可能です。
fripper - 投稿数: 495
> 事象が発生したタイミングでは、18:58:00 までのログしか精査されていないように見えます。
> Sending back [1] が出力されてしまっています。
18:58:00 時点までのログ部分照合で「見つかった」と判定されたため、それ以降のファイル内容チェックが
スキップされてしまっただけだと思います
vfs.file.regmatch は「見つかったと判定した時点で１を返す」挙動なので、「見つかった」と判断されてしまえば
それ以降のチェックはスキップされます
なぜ、ある時点では「見つかった」判定にならなかった部分が、別の時点では「見つかった」と判定されてしまうか、
については、正直なところ不明です
誤検知した際の最終行（18:58:00）の文字列で「見つかった」と判定されているようなので、そこに何らかのヒントが
あると思います
vfs.file.regmatch は正規表現でのマッチングを行っているため
固定文字列のつもりで指定している文字列が正規表現として解釈されていたりする可能性はあると思います
また、ファイル側のエンコード（SJIS）と、マッチング内部処理時のエンコード（UTF8）との変換で、
意図しないデータに化けてしまっていて、マッチングで誤検知‥ということも可能性はあると思います
詳細な設定文字列と、デバッグログの内容、実際に対象としたファイルの該当部分の生文字列が無いと
これ以上は難しい気がします
ogata - 投稿数: 28
回答ありがとうございます。
実際の検知文字列は下記になります。
{ホスト名:vfs.file.regmatch[D:\Application\log\chk_receive_check.log,受信処理が行われていない注文が存在します,SHIFT_JIS].last(0)}>0
対象ログには下記の文字列が3分おきに出力されています。
下記以外の文字列は出力されていません。
[yyyy/mm/dd h:mm:ss] CHK_I_INFO 受信遅延監視 正常終了しました。
対象ログを確認しましたが、文字コードはSJISで改行コードはCRLFでした。
また、下記内容がマスクしていないエージェントのデバッグログになります。
--事象発生前のログ--
2460:20151110:224826.633 Requested [vfs.file.regmatch[D:\Application\log\chk_receive_check.log,受信処理が行われていない注文が存在します,SHIFT_JIS]]
2460:20151110:224826.633 convert_to_utf8() in_size:65 encoding:'SHIFT_JIS' codepage:932
2460:20151110:224826.649 convert_to_utf8() utf8_size:80 utf8_string:'[2015/11/10 8:37:00] CHK_I_INFO 受信遅延監視 正常終了しました。
'
～～～～～～～～～～～～～～～～～～～～
2460:20151110:224828.383 convert_to_utf8() in_size:66 encoding:'SHIFT_JIS' codepage:932
2460:20151110:224828.399 convert_to_utf8() utf8_size:81 utf8_string:'[2015/11/10 22:46:01] CHK_I_INFO 受信遅延監視 正常終了しました。
'
2460:20151110:224828.399 Sending back [0]
--事象発生時のログ--
2460:20151110:224926.055 Requested [vfs.file.regmatch[D:\Application\log\chk_receive_check.log,受信処理が行われていない注文が存在します,SHIFT_JIS]]
2460:20151110:224926.055 convert_to_utf8() in_size:65 encoding:'SHIFT_JIS' codepage:932
2460:20151110:224926.055 convert_to_utf8() utf8_size:80 utf8_string:'[2015/11/10 8:37:00] CHK_I_INFO 受信遅延監視 正常終了しました。
'
～～～～～～～～～～～～～～～～～～～～
2460:20151110:224927.227 convert_to_utf8() in_size:66 encoding:'SHIFT_JIS' codepage:932
2460:20151110:224927.227 convert_to_utf8() utf8_size:81 utf8_string:'[2015/11/10 18:58:00] CHK_I_INFO 受信遅延監視 正常終了しました。
'
2460:20151110:224927.227 Sending back [1]
--事象発生後のログ--
2460:20151110:225026.493 Requested [vfs.file.regmatch[D:\Application\log\chk_receive_check.log,受信処理が行われていない注文が存在します,SHIFT_JIS]]
2460:20151110:225026.493 convert_to_utf8() in_size:65 encoding:'SHIFT_JIS' codepage:932
2460:20151110:225026.493 convert_to_utf8() utf8_size:80 utf8_string:'[2015/11/10 8:37:00] CHK_I_INFO 受信遅延監視 正常終了しました。
'
～～～～～～～～～～～～～～～～～～～～
2460:20151110:225028.274 convert_to_utf8() in_size:66 encoding:'SHIFT_JIS' codepage:932
2460:20151110:225028.290 convert_to_utf8() utf8_size:81 utf8_string:'[2015/11/10 22:49:01] CHK_I_INFO 受信遅延監視 正常終了しました。
'
2460:20151110:225028.290 Sending back [0]
TNK - 投稿数: 4671
Windows Server 2003 SP1の環境は用意できていないので、Linux上
のZabbix 2.2.9で確認しましたが、
[2015/11/10 18:58:00] CHK_I_INFO 受信遅延監視 正常終了しました。
というようなログの出力と
受信処理が行われていない注文が存在します
という文字列パターンでの誤った文字列一致の判断はされないよう
です。
具体的なログファイルの内容をご提示いただけていないので、頂い
た情報の範囲で勝手に推測していますが、正常時は、
[2015/11/10 18:58:00] CHK_I_INFO 受信遅延監視 正常終了しました。
障害発生時は、
[2015/11/10 18:58:00] CHK_E_ERRO 受信遅延監視 受信処理が行われていない注文が存在します。
というようなログが追記されると仮定して確認しました。
やはり、追記されるログであるならば、ファイル内に合致する文字
列が残っていて、それを判断してしまっている可能性が高いと思わ
れます。
例えば、アイテムにはlog[]を利用し、トリガーの条件式には、str()
を利用するような形式に変更してみることをお勧めします。