logrt[]で、ローテーション後、毎回旧ファイルの全内容を読み込んでしまう
zabbix server 2.2.2 〜 zabbix proxy 2.2.3 〜 zabbix agent 2.2.3 で、
logrtを設定して利用を開始したところ、標記のトラブルに遭遇しております。
アイテム：
logrt["/var/log/test/test.log(-[0-9]{8})?$",": (error|ERROR)",UTF-8]
トリガー：
({hostname:logrt["/var/log/test/test.log(-[0-9]{8})?$",": (error|ERROR)",UTF-8].iregexp(error)})#0 & {hostname:logrt["/var/log/test/test.log(-[0-9]{8})?$",": (error|ERROR)",UTF-8].nodata(30)}=0
インターバル：30秒
実際のログファイル：
/var/log/test/test.log
/var/log/test/test.log-yyyymmdd ※前日分
/var/log/test/test.log-yyyymmdd.gz ※前々日分以前
トラブル：
1) logrotate後、前日分ファイルを毎インターバル毎に再読み込みし、
該当するエントリに全てトリガーを発報してしまう。
2) 一旦アイテムの監視を停止し、同様の検知条件となる別アイテムを作成して
監視を開始しても、前日分を毎インターバル毎に再読み込みし、同様に発報してしまう。
以下の投稿やバグに該当するかの切り分けがつかず、
同様の事例に対処法などご存知の方がいらっしゃったらご教示ください。
http://www.zabbix.jp/node/2719
https://support.zabbix.com/browse/ZBX-7098
事象発生前後の挙動やログファイルのタイムスタンプなどは、
添付ファイルに記載させて頂きます。
現状はローテーション時の30秒の空白を許容して、
logrt[]ではなくlog[]で監視せざるを得ないかと考えております。
以上、よろしくお願いします。
- logrt_details.txt (2.53 KB)
KAZ - 投稿数: 1085
ローテート時にZabbixエージェントのログをDebugLevel=4で動作させることできますでしょうか？
そして、「再読み込み」が発生した時に「test.log already added」と言うログが出力されるか確認いただけますでしょうか？
Zabbix2.2.3のエージェント側のソースで怪しそうな箇所を見つけました。
下記はadd_logfile関数の抜粋
cmp = strcmp(filename, (*logfiles)[i].filename))ですが、i=0で*logfiles)[i].filenameが「test.log-20140517」、filenameが「test.log」の場合、
次のif分に流れて「test.log」が監視対象から漏れてしまい、結果過去ログを読んでしまう処理に流れそうで…
------- zabbix-2.2.3/src/zabbix_agent/logfiles.c 297-335行目 -----------
/************************************************************************************************/ /* (1) sort by ascending mtimes */ /* (2) if mtimes are equal, sort alphabetically by descending names */ /* the oldest is put first, the most current is at the end */ /* */ /* filename.log.3 mtime3, filename.log.2 mtime2, filename.log1 mtime1, filename.log mtime */ /* -------------------------------------------------------------------------------------- */ /* mtime3 <= mtime2 <= mtime1 <= mtime */ /* -------------------------------------------------------------------------------------- */ /* filename.log.3 > filename.log.2 > filename.log.1 > filename.log */ /* -------------------------------------------------------------------------------------- */ /* array[i=0] array[i=1] array[i=2] array[i=3] */ /* */ /* note: the application is writing into filename.log, mtimes are more important than filenames */ /************************************************************************************************/ for (; i < *logfiles_num; i++) { if (mtime > (*logfiles)[i].mtime) continue; /* (1) sort by ascending mtime */ if (mtime == (*logfiles)[i].mtime) { if (0 > (cmp = strcmp(filename, (*logfiles)[i].filename))) continue; /* (2) sort by descending name */ if (0 == cmp) { /* the file already exists, quite impossible branch */ zabbix_log(LOG_LEVEL_DEBUG, "%s() file '%s' already added", __function_name, filename); goto out; } /* filename is smaller, must insert here */ } /* the place is found, move all from the position forward by one struct */ break; }KAZ - 投稿数: 1085
macotomiiさん
すいません、間違ってました。
確認撮ったんですが、test.logとtest.log-20140517比較すると、-1が返ってきます。
strcmpは'\0'以降は比較しないとなっていたのですが、比較するようです。
下記の検証取りました。
-1 = strcmp("abc","abcd")
1 = strcmp("abcd","abc")
お騒がせしました。
macotomii - 投稿数: 4
コメントありがとうございます。
「DebugLevel=4」は検証してみたいとおもいます。
KAZ - 投稿数: 1085
macotomiiさん
ちょっと整理してみましたら、やはり「-1 = strcmp("test.log","test.log-20140517")」がまずいですね。A(^^;
すいません。m(__)m
1回目 test.log-20140517を読む
logfiles[0].filename に test.log-20140517
logfiles[0].mtime に 2014-05-17 03:06:02.239259781
2回目 test.logを読む
本来、配列のlogfiles[1].filenameとlogfiles[1].mtimeに積まなきゃいけないが
「-1 = strcmp("test.log","test.log-20140517")」なので、
ソート処理が走り下記となる。
logfiles[0].filename に test.log
logfiles[0].mtime に 2014-05-17 03:06:02.239259781
logfiles[1].filename に test.log-20140517
logfiles[1].mtime に 2014-05-17 03:06:02.239259781
本来、過去 logfiles[0] >>> 未来 logfiles[n]とならなきゃいけないのに
配列に逆転して情報が設定され、過去側の情報が読まれてしまった。
なので、ご指摘通り下記の件で対応されると思います。
https://support.zabbix.com/browse/ZBX-7098
zinten - 投稿数: 69
KAZさん
ファイル名の比較の前のmtimeの比較のところで引っかかるので関係ないのでは？
if (mtime > (*logfiles)[i].mtime) ←この条件のとこ
比較しているのはctimeではなくmtimeなのでModifyのところでの比較になると思います。
いただいてる情報を見る限り並び順がおかしくなったりはしないと思います。
# stat test.log
File: `test.log'
Modify: 2014-05-17 03:06:02.239259781 +0900
Change: 2014-05-17 03:06:02.239259781 +0900
# stat test.log-20140517
File: `test.log-20140517'
Modify: 2014-05-16 19:23:50.513700840 +0900
Change: 2014-05-17 03:06:02.239259781 +0900
KAZ - 投稿数: 1085
zintenさん
比較しているのはctimeではなくmtimeなのでModifyのところでの比較になると思います。
いただいてる情報を見る限り並び順がおかしくなったりはしないと思います。
なるほど…
確かにそうですね…
zinten - 投稿数: 69
なんとなくですが…
新手のバグで以下のループにやられている気が。。。
--------------------------------------------------
/* processing matched logfiles starting from the older one to the newer one */
for (; i < logfiles_num; i++)
{
logfile_candidate = zbx_dsprintf(logfile_candidate, "%s%s", directory, logfiles[i].filename);
if (SUCCEED != (ret = process_log(logfile_candidate, lastlogsize, mtime, skip_old_data, big_rec,
encoding, regexps, pattern, output_template, p_count, s_count, process_value, server,
port, hostname, key)) || 0 >= *p_count || 0 >= *s_count)
{
/* Do not make a logrt[] item NOTSUPPORTED if one of selected files is not accessible */
/* (can happen during a rotation). Maybe during the next check all will be well. */
ret = SUCCEED;
break;
}
if (i != logfiles_num - 1)
{
zbx_free(logfile_candidate);
*lastlogsize = 0; ←※ここがよくない気がする！
}
}
-----------------------------------------------------------------
動作確認してないので予想のうえ長いですが…
--ローテーション直後
lastlogsize=58652
mtime=5月 16 19:23
file[0]： name=test.log-20140517
logsize=586852
mtime=5月 16 19:23
file[1]： name=test.log
logsize=0
mtime=5月 17 03:06
--監視1回目
①process_log()
file[0]を読み込む
filesize=lastlogsizeでSUCCESSで返る
②※のところ
lastlogsizeが0にされる(mtimeは更新されない)
③process_log()
file[1]を読み込む
filesize=lastlogsizeでSUCCESSで返る
④ループを抜ける
lastlogsize=0 ←こっちだけ更新される
mtime=5月 16 19:23
--監視2回目
①process_log()
file[0]を読み込む
lastlogsizeが0なので全部読み直す
②※のところ
lastlogsizeが0にされる(mtimeは更新されない)
③process_log()
file[1]を読み込む
filesize=lastlogsizeでSUCCESSで返る
④ループを抜ける
lastlogsize=0 ←またしても0となる
mtime=5月 16 19:23
以下、最新のログファイルに何か書かれるまで無限ループ
③のところでmtimeを上書きしないとダメなんでしょうけどしてないのでずっと古いファイルを読み続けてるのかと思います。
以下の修正のどれかの影響かと思うので2.2.2のエージェントにしたほうがよさそうですね。。。
------------------------------------------
[ZBX-7740] fixed agent crash if logrt and log items are not supported
[ZBX-6731] faster processing of log files by agent on Unix
[ZBX-6729] faster processing of log files by agent on Microsoft Windows
------------------------------------------
macotomii - 投稿数: 4
zintenさん
貴重なコメントありがとうございます。
予想頂いたとおりだと、事象と一致します。
2.2.2で再現するかしないか検証してみます。
KAZ - 投稿数: 1085
macotomiiさん、zintenさん
zintenさんの指摘点を踏まえ追い直してみました。
尚、私はZabbix2.2.3のソースを追ってます。
process_logrt関数の535-566行目の処理に焦点を置いてローテートを考慮して考えると…
1)test.logのみ存在している場合
i = (1 == *skip_old_data && 0 < logfiles_num) ? logfiles_num - 1 : 0;
skip_old_dataは古いデータを読み飛ばす判定のフラグなのですが、デフォルト初回は0が設定されてます。
なので、iは0となり、file[0]にtest.logの情報が設定され…
process_log関数でtest.logが読まれ、lastlogsizeにはprocess_log関数で読んだサイズが設定されます。
iは0、logfiles_numは1なので、lastlogsizeはそのまま(!=なので)
2)ローテートしてtest.logとtest.log-20140517ができた後
i = (1 == *skip_old_data && 0 < logfiles_num) ? logfiles_num - 1 : 0;
skip_old_dataですが、2回めはlastlogsizeが真(0以外)だと0、偽だと1が設定されます。(active.cのadd_check関数で設定)
lastlogsizeが0以外なので、skip_old_dataは0となり、iは0となります。 <--ここがおかしい、skip_old_dataは1にならないといけないはず！
その為、process_log関数はfile[0]とfile[1]を読んでしまいます。
と言う訳でskip_old_dataのフラグの立て間違いかなと…A(^^;
zinten - 投稿数: 69
KAZさん
私も2.2.3のコードを追ってます。
実機での確認は時間がないので週末くらいになりそうですが...
>2)ローテートしてtest.logとtest.log-20140517ができた後
>i = (1 == *skip_old_data && 0 < logfiles_num) ? logfiles_num - 1 : 0;
>skip_old_dataですが、2回めはlastlogsizeが真(0以外)だと0、偽だと1が設定されます。(active.cのadd_check関数で設定)
>lastlogsizeが0以外なので、skip_old_dataは0となり、iは0となります。 <--ここがおかしい、skip_old_dataは1にならないといけないはず！
skipは初めてエージェントにキーが渡されたときだけ、機能すればよいので
二回目以降の監視では0（skipを行わない）で問題ないと思います。
そんなにちょくちょくskipされても困りますし…
また、add_checkの該当コードは同じキーで監視が行われている場合は「goto out;」で飛ばされているので対象の処理を通りません。
問題なのは最新のファイルが0byteの場合はmtimeが更新されないため、
毎回既に読み終わったひとつ前のファイルを抽出してしまうことだと思います。
KAZ - 投稿数: 1085
zintenさん
返信ありがとうございます。
skipは初めてエージェントにキーが渡されたときだけ、機能すればよいので
二回目以降の監視では0（skipを行わない）で問題ないと思います。
skipは複数ファイルが有る時に最新のファイル以外は読まないためのフラグと思ったのですが…
勘違い？A(^^;
また、add_checkの該当コードは同じキーで監視が行われている場合は「goto out;」で飛ばされているので対象の処理を通りません。
そうですね、ご指摘ありがとうございます。
なのですが、add_checkの処理通らなくてもデフォルトでskip_old_dataは0なので、file[0]から読む流れになってしまいます。
問題なのは最新のファイルが0byteの場合はmtimeが更新されないため、
毎回既に読み終わったひとつ前のファイルを抽出してしまうことだと思います。
ローテートした時ですよね？
ローテートした時間が入っているのでは…
# stat test.log
File: `test.log'
Size: 0 Blocks: 0 IO Block: 4096 通常の空ファイル
Device: ca01h/51713d Inode: 136196 Links: 1
Access: (0777/-rwxrwxrwx) Uid: ( 48/ apache) Gid: ( 48/ apache)
Access: 2014-05-17 03:06:02.239259781 +0900
Modify: 2014-05-17 03:06:02.239259781 +0900
Change: 2014-05-17 03:06:02.239259781 +0900
Birth: -
zinten - 投稿数: 69
>skipは複数ファイルが有る時に最新のファイル以外は読まないためのフラグと思ったのですが…
>勘違い？A(^^;
-------------------------------------
if (S_ISREG(file_buf.st_mode) &&
*mtime <= file_buf.st_mtime &&
0 == regexec(&re, d_ent->d_name, (size_t)0, NULL, 0))
-------------------------------------
上記のコード部分を見れば分かるとおり
対象のファイルを選択するのにmtimeとfilenameを使用しています。
対象のfilenameの中の最後に監視したmtime以降を監視対象として選択します。
初回はmtimeが0なのであればあった分だけ対象として選択されるため、
skipが動作する必要があるのですが
2回目以降はskipが動作した結果mtimeに最新のファイルのmtimeが入っているため
古いファイルは選択すらされないです。
そのためskipが動作する必要がないんです。
もしここでskipが動作してしまうとlog[]と同じ動作となってしまい、
最後に監視されてからローテーションするまでに書かれたログが捨てられてlogrt[]を使用する意味がないです。
>>問題なのは最新のファイルが0byteの場合はmtimeが更新されないため、
>>毎回既に読み終わったひとつ前のファイルを抽出してしまうことだと思います。
>ローテートした時ですよね？
>ローテートした時間が入っているのでは…
言葉が足りませんでした。
上記のmtimeはエージェントがキャッシュ上に保持しているmtimeになります。
本来なら0バイトでも読んだのならキャッシュ上のmtimeを0バイトのファイルのmtimeに更新するべきなのですが
更新していないため何度も古いファイルが選択され続けているために起こっているといいたかったんです。。。
------------------------------------------------------
File: `test.log'
Modify: 2014-05-17 03:06:02.239259781 +0900
File: `test.log-20140517'
Modify: 2014-05-16 19:23:50.513700840 +0900
------------------------------------------------------
KAZ - 投稿数: 1085
上記のコード部分を見れば分かるとおり 対象のファイルを選択するのにmtimeとfilenameを使用しています。 対象のfilenameの中の最後に監視したmtime以降を監視対象として選択します。
add_logfileするところの処理ですね？
前回監視タイミングがには2014-05-16 19:23:50より前で(mtime)
test.logに2014-05-16 19:23:50くらいにログが書かれて
2014-05-17 03:06:02にローテートして、test.log-20140517ができたと…
で、process_logでtest.log-20140517とtest.log読み…
test.logが0バイト、lastlogsizeが0なのでprocess_logの下記に引っかかってmtime更新されないと…
その為に毎回test.log-20140517を見に行くということですかね？
と言うことは、process_logで0バイトのログの更新確認時にmtime設定すれば良い？
if ((zbx_uint64_t)buf.st_size == *lastlogsize) { /* The file size has not changed. Nothing to do. Here we do not deal with a case of changing */ /* a logfile's content while keeping the same length. */ *mtime = (int)buf.st_mtime; <-- こレを追加するようなイメージ？ ret = SUCCEED; goto out; }zinten - 投稿数: 69
KAZさん
その通りです。
説明下手ですいません。
>と言うことは、process_logで0バイトのログの更新確認時にmtime設定すれば良い？
そのイメージです。
後は0バイトを判定する必要があるかどうかをちょっと迷ってます。
if ((zbx_uint64_t)buf.st_size == *lastlogsize)
{
/* The file size has not changed. Nothing to do. Here we do not deal with a case of changing */
/* a logfile's content while keeping the same length. */
if(0 == *lastlogsize) *mtime = (int)buf.st_mtime; <-- 0バイトか判定しなくていい？
ret = SUCCEED;
goto out;
}
KAZ - 投稿数: 1085
zintenさん
その通りです。
説明下手ですいません。
いえ、こちらこそ色々ご指摘ありがとうございます。m(__)m
後は0バイトを判定する必要があるかどうかをちょっと迷ってます。
そうですね。
lastlogsizeが0以外でbuf.st_sizeと同じということはmtimeにbuf.st_mtimeがすでに入っているはずなんですよね…
お作法的にはした方がいいような気もしますが…A(^^;
zinten - 投稿数: 69
macotomiiさん KAZさん
すごく拙い英語ですがバグ報告上げてみました。
https://support.zabbix.com/browse/ZBX-8238
同じ日に出されたZBX-7098の問題の対応で入ったパッチのおかげで
次のバージョンでは発生しなくなるようです。
TNK - 投稿数: 4719
ありがとうございました。
結局、ZBX-7098の対応はまだできていなかったのですね。
KAZ - 投稿数: 1085
zintenさん
ありがとうございます。m(__)m
ZBX-7098絡みの修正でlog[]とlogrt[]の処理かなり変わるみたいですね… A(^^;
macotomii - 投稿数: 4
zintenさん、KAZさん
ソースコードレベルでの解析、
https://support.zabbix.com/browse/ZBX-8238 の起票、ありがとうございます。
Known Issueもアップデートされましたが、2.2.2のagentでは再現しないことを検証しました。
暫くは、2.2.2で運用するようにします。
ご協力ありがとうございました！
気づいた点は、ユーザレベルの報告になってしまいますが、
これからもしていきたいと思います。