新規に作成したログ監視が途中から読んでしまう 【MIRACLE ZBX 1.8, 2.0, 2.2】
新規に作成したログ監視が途中から読んでしまう
Zabbixで新規にログ監視のアイテムを作成すると、原則的にはログファイルの最初からチェックを始めます。ここで、「原則的」と表記しているのは、2.0.xからはskipオプションが追加されたからです。
タイトルのような問い合わせを受け、調査しました。原因としては、Zabbixエージェントがログ監視等のアクティブ監視の情報をメモリ上に保存しており、変更・新規追加されたキーと比較を行う際に、キーの文字列でしか比較を行っていないからです。
具体的な解説
以下は2.0.14を用いての解説となります。
Zabbixエージェントのアクティブ監視に関する処理は、src/zabbix_agent/active.c に記述されています。
最初にアクティブ監視用のプロセスが立ち上がると、init_active_metrics()がコールされて、監視情報を保存する変数(active_metrics)が初期化されます。
その後、定期的にrefresh_active_check()をコールすることによりサーバから監視情報を取得し、active_metricsを更新します。
1593 ZBX_THREAD_ENTRY(active_checks_thread, args)
1594 {
1595 ZBX_THREAD_ACTIVECHK_ARGS activechk_args;
...
1609 init_active_metrics();
1610
1611 while (ZBX_IS_RUNNING())
1612 {
...
1623 if (FAIL == refresh_active_checks(activechk_args.host,
activechk_args.port))
1624 {
1625 nextrefresh = (int)time(NULL) + 60;
1626 }
...
refresh_active_checks()から、受け取った情報をパーズするためにparse_list_of_checks()をコールし、active_metricsを更新するために、add_check()をコールします。parse_list_of_checks()の最初にdisable_all_metrics()をコールし、既存の監視情報を全てdisableにします。これにより、取得した情報のみを有効とし、キーが変更された監視を行わせなくすることができます。ですが、下記の処理にてdisableとして残されたままのキーは消されることがなく、問題の一因となります。(この辺りのソースコードは割愛します。)
次に、add_check()の処理を見ていきましょう。
126 static void add_check(const char *key, const char *key_orig, int refresh,
zbx_uint64_t lastlogsize, int m time)
127 {
128 const char *__function_name = "add_check";
129 int i;
130
131 zabbix_log(LOG_LEVEL_DEBUG, "In %s() key:'%s' refresh:%d lastlogsize:"
ZBX_FS_UI64 " mtime:%d",
132 __function_name, key, refresh, lastlogsize, mtime);
133
134 for (i = 0; NULL != active_metrics[i].key; i++)
135 {
136 if (0 != strcmp(active_metrics[i].key_orig, key_orig))
137 continue;
138
139 if (0 != strcmp(active_metrics[i].key, key))
140 {
141 int j;
142
143 zbx_free(active_metrics[i].key);
144 active_metrics[i].key = zbx_strdup(NULL, key);
145 active_metrics[i].lastlogsize = lastlogsize;
146 active_metrics[i].mtime = mtime;
147 active_metrics[i].big_rec = 0;
148 active_metrics[i].use_ino = 0;
149 active_metrics[i].error_count = 0;
150
151 for (j = 0; j < active_metrics[i].logfiles_num; j++)
152 zbx_free(active_metrics[i].logfiles[j].filename);
153
154 zbx_free(active_metrics[i].logfiles);
155 active_metrics[i].logfiles_num = 0;
156 }
...
164 active_metrics[i].status = ITEM_STATUS_ACTIVE;
134行目からのforループで、新規に取得した情報に対してそれぞれ処理を行っていきます。(key_orig, keyと二つ同じようなものがありますが、同じ内容が入っていると考えてください。)
136行目からの処理で、新しく取得した情報と既存の情報でkey_origが一致するものを抽出し、さらに、139行目でkeyが一致していないものを抽出しています。ただし、key_origとkeyは同じ内容が入っているため、ここの処理へ入ることがないと思います。ですので、lastlogsize, mtimeも更新されないと思います。
ここで、下記のケースを考えます。
- log[/tmp/foo.txt]で作成、監視。
- 上記のアイテムをlog[/tmp/foo.txt,.*]で作成、監視。
- log[/tmp/foo.txt]を新規に作成。
1.を受け取った後に監視をした状況で、エージェント内のactive_metricsは下記のようになります。
- key_orig=log[/tmp/foo.txt], key=log[/tmp/foo.txt], lastlogsize=200, enable
その後、2.を受け取った状況では、下記のように変化します。(一致したkey_origがないため、新規に加わります。)
- key_orig=log[/tmp/foo.txt], key=log[/tmp/foo.txt], lastlogsize=200, disable
- key_orig=log[/tmp/foo.txt,.*], key=log[/tmp/foo.txt,.*], lastlogsize=0, enable
当然、その後にlog[/tmp/foo.txt,.*]に対する監視が行われますので、下記のように変化します。
key_orig=log[/tmp/foo.txt], key=log[/tmp/foo.txt], lastlogsize=200, disable
key_orig=log[/tmp/foo.txt,.*], key=log[/tmp/foo.txt,.*], lastlogsize=200, enable
そして、/tmp/foo.txtへログ出力が行われるとさらに下記のように変化します。
- key_orig=log[/tmp/foo.txt], key=log[/tmp/foo.txt], lastlogsize=200, disable
- key_orig=log[/tmp/foo.txt,.*], key=log[/tmp/foo.txt,.*], lastlogsize=400, enable
ここで、さらに3.にあるように新規アイテムを1.と同じキーで作成します。
上述のように、keyとkey_origは同じものであるため、139行目の処理は行われず(つまり、サーバから取得したlastlogsize=0を用いない)、164行目の処理が行われステータスがactiveになるだけです。active_metricsの情報は下記となります。
- key_orig=log[/tmp/foo.txt], key=log[/tmp/foo.txt], lastlogsize=200, enable
- key_orig=log[/tmp/foo.txt,.*], key=log[/tmp/foo.txt,.*], lastlogsize=400, enable
この後、新規に追加されたlog[/tmp/foo.txt]に対する監視は、201バイト目から行われるので、ファイルの途中からの監視となってしまいます。
3.で新規にアイテムを作成しましたが、既存のアイテムを変更しても同様な問題が発生します。この問題を回避するためには、現状ではエージェントを再起動するしかありません。
そもそも、itemidというユニークな識別子があるのにもかかわらず、エージェントに送信していないことが実装不十分であると思っています。また、キーの変化を感知するためであろうkey_origという変数も有効に使用されているとは考えられません。
この問題に対するパッチも送付していますので、今後取り込まれるかもしれません。