Zabbix 3.2以降の新機能解説（Zabbix 4.0を見据えて）その13 - copytruncate タイプローテーション

こんにちは、MIRACLE ZBX サポートを担当している花島タケシです。今回は、logrt[] キーでの copytruncate タイプローテーションが Zabbix4.0 でサポートされますので、このことについて解説します。

logrt[] キーでの copytruncate タイプローテーションサポート

ようやく copytruncate タイプのログ群がサポートされました。
かねてより logrt[] キーにてローテーションされるログファイル群のサポートはされていましたが、ようやく copytruncate タイプでローテーションされるファイル群もサポートされることになりました。

copytruncate とは ?

そもそも copytruncate タイプのローテーションとはどういうものなのでしょう ?

Asianux 6 上で、'man logrotate' としてマニュアルを確認します。

引用

copytruncate

Truncate the original log file in place after creating a copy, instead of moving the old log file and optionally creating a new one. It can be used when some program cannot be told to close its logfile and thus might continue writing (appending) to the previous log.

file forever. Note that there is a very small time slice between copying the file and truncating it, so some logging data might be lost. When this option is used, the create option will have no effect, as the old log file stays in place.

つまり、「オリジナルのファイルをコピーした後に、オリジナルのファイルを切り詰める。
したがって、ほんの少しだけ欠落することもあるよ。」ということです。

なぜ、こういった実装が必要か ? ということも記述されていて、「単に移動しただけだと、移動した先に書き込み続けてしまうタイプのアプリケーションがあるからです。

これは簡単にテストプログラムを書けます。あるファイルに対して、FD を開いてからそのファイルを mv します。そして、元々のファイル名で touch してファイルを作成しても、FD を開いたままのアプリケーションは元の ( 移動した先の ) ファイルへ出力します。

以前の Zabbix にもこういったバグがありました。

実際に手元の Asianux 6 で強制的にローテーションをさせると下記のような状態遷移が発生します。

ローテーション前

-rw-------. 1 root root 72207 2 月 22 09:17 2018 libvirtd.log

ローテーション後

-rw-------. 1 root root 0 2 月 22 09:34 2018 libvirtd.log
-rw------- 1 root root 72207 2 月 22 09:34 2018 libvirtd.log-20180222

libvirtd.log が libvirtd.log-20180222 へ mtime を伴わないコピーが行われ、libvirtd.log が 0 バイトに切り詰められています。

従来の実装ではなぜダメだったのか ?

一見上記のローテーション前後の結果を見ると、従来の実装のままでも問題がないように思われます。

logrt[] キーでの読み込み対象のファイル群は抽出された後に、mtime が古い順に、そして mtime が同じものがある場合、名前の大きい順に並べられ、古い方から読み込み対象とします。
ここが上記の「問題がないように思われる。」理由です。

しかし、オリジナルファイル ORG が、COPIED にコピーされている最中の状況を想像してみましょう。

COPIED は ORG より mtime が大きく、ファイルサイズは小さい状況です。このコピーしている最中に logrt[] キーでの監視が行われると、COPIED が新しく生成されたファイルであるため、ORG の残りの部分を読み取った後に ( 当然残りの部分がなければ読み取りませんが )、COPIED を先頭から読み込みます。

ということは、いわゆるファイルの読み返しが発生するわけです。

さらに、コピー中に ORG に新しくログが出力されると、タイミングによっては ORG も先頭から読み込むことになり、ここでも読み返しが発生してしまいます。

対策された実装を見ていこう

今回の解説には 4.0.0alpha3 を用います。

エージェントがログファイルを読み込むための実装は、src/zabbix_agentd/logfiles.c に記述されています。

ファイル読み込みに関する処理の入り口は process_logrt() となります。

これは、logrt 関連のキーだけでなく、log 関連のキーも同様です。
以前は分かれておりソースも読みやすかったのですが、今は一緒になった分読みづらくなっています。

2952 int process_logrt(
...
2959 int rotation_type)
2960 {
...
2972 if (SUCCEED != (res = make_logfile_list(flags, filename, *mtime, &logfiles, &logfiles_alloc, &logfiles_num,
2973 use_ino, err_msg)))
2974 {
...
2984 }
...
3007 if (0 < *logfiles_num_old && 0 < logfiles_num &&
3008 SUCCEED != update_new_list_from_old(rotation_type, *logfiles_old, *logfiles_num_old, logfiles,
3009 l logfiles_num, *use_ino, &seq, &start_idx, lastlogsize, err_msg))
3010 {
3011 destroy_logfile_list(&logfiles, &logfiles_alloc, &logfiles_num);
3012 goto out;
3013 }
3014
3015 if (ZBX_LOG_ROTATION_LOGCPT == rotation_type && 1 < logfiles_num)
3016 ensure_order_if_mtimes_equal(*logfiles_old, logfiles, logfiles_num, *use_ino, &start_idx);
...
3160 }

l.2972 にて、make_logfile_list() をコールし、logfiles にファイルリストを生成します。logrt 関連の場合は、前回の処理で最後に読んだファイルの mtime 以上のファイル群を、mtime が古い順に、mtime が同じものは名前の大きい順に並び替えたリストとなります。

次に、ll.3007-3013 の処理において、update_new_list_from_old() を用いて、前回処理時に生成したファイルのリストと直前の処理で生成したファイルのリストを比較します。
結果的には、どこまで読み込んだか ? やコピーされたファイルはどれか ? といった情報を反映させます。

内部的に copytruncate 形式かそうでないかが分かれた実装がされています。
というのも、上記のようにローテーションの仕組みが異なっており、ケアをする点も異なるからです。

copytruncate の場合は、ファイルサイズや i-node, 内部的な md5 値等を用いて判定をしています。

最終的には、旧ファイルリストと新ファイルリストをつき合わせるための二次元配列の表に対し、一致しているかやコピーされたものか ? という印をつけて、新ファイルリスト内の序列を決定します。

l.3016 において、mtime が同じファイルに対しての並び替えをします。
これには上記のコピーされたものか ? という印や、ファイル名、前回付けた序列等を元に判断しています。

3076 while (NULL != logfiles && i < logfiles_num)
3077 {
3078 if (0 == logfiles[i].incomplete &&
3079 (logfiles[i].size != logfiles[i].processed_size || 0 == logfiles[i].seq))
3080 {
...
3173 }
3174
3175 if (ZBX_LOG_ROTATION_LOGCPT == rotation_type && 1 < logfiles_num)
3176 {
3177 /* If logrt[] or logrt.count[] item is checked often but rotation by copying is slow it could happen */
3178 /* that the original file is completely processed but the copy with a newer timestamp is still in */
3179 /* progress. The original file goes out of the list of files and the copy is analyzed as new file, */
3180 /* so the matching lines are reported twice. To prevent this we manipulate our stored 'mtime' */
3181 /* and 'lastlogsize' to keep information about copies in the list as long as necessary to prevent */
3182 /* reporting twice. */
3183
3184 delay_update_if_copies(logfiles, logfiles_num, mtime, lastlogsize);
3185 }

ファイルリストの序列が完成すると ll.3076-3073 のブロックで、可能な限りファイルを読み込みます。

copytruncate の場合は最後に delay_update_if_copies() をコールして、リスト作成時にファイルがコピー中であった場合の処理を入れています。

コピー対象がある場合は読み込まないようになっており、全て読み込み完了した後に、元ファイルが大きくなっている場合に対するケアです。

終わりに

copytruncate に対する処理を読んで見ましたが、使えるようにはなっていますが、その判定アルゴリズムはかなり複雑です。

使用できるでしょうが、それが完全に問題なくとはまだ言いきれない感じもします。

実際に、下記のようにマニュアルにも記されているため、気をつけて使用してください。

Zabbix Documentation 4.0 - 6 LOG FILE MONITORING

The agent tries to handle all these situations reasonably well, but good results cannot be guaranteed in all circumstances.

注意事項

本ドキュメントの内容は、予告なしに変更される場合があります。
本ドキュメントは、限られた評価環境における検証結果をもとに作成しており、全ての環境での動作を保証するものではありません。
本ドキュメントの内容に基づき、導入、設定、運用を行なったことにより損害が生じた場合でも、当社はその損害についての責任を負いません。あくまでお客さまのご判断にてご使用ください。