日本人はログ監視好きらしいです。
しかし、正しくログ監視が設定されていない状況も多々あります。
そこで、ログ監視の歴史と仕様の遷移を解説したいと思います。
Zabbixのログ監視の根本仕様
根本仕様は以下の2つのみです。
- 同じファイルは続きから読む
- 異なるファイルは先頭から読む
簡単ですよね？
複雑なのは同じファイルか判定する処理なんです…
初期のログ監視
Zabbix1.8未満ではlogrtキーは提供されておらず、ログ監視はlogキーのみでした。10年以上前になりますが、新橋の居酒屋でZabbix SIAのAlexeiとZabbix日本ユーザ会の前身であるZABBIX-JP代表の寺島広大(現Zabbix Japan代表)と私と他のスタッフがlog監視のローテーション対応について酒を飲みながら語り合いました。その頃の私はZabbix1.6で色々不具合修正をZBXで投稿していました。
その後、1.7.3で現在のlogrtの元になるファイル名に正規表現が使用でき、ローテーションされたファイルを監視できるlog.regexpキーが実装されました。
- [DEV-369] added item check "log.regexp" with file log rotation, the parameter "fileformat" has a format [path][regexp] (Dmitry)
しかし、名前が良くないと1.7.4でlogrtに名称が変更されました。
- [DEV-369] item check "log.regexp" was renamed to "logrt" to specify "log rotation" (Dmitry)
logrtキーはアクティブに更新がある1つのログファイルとローテーションされた更新されないファイルを時系列に監視を行う機能です。
アクティブに更新がある複数ファイルは監視できません。
現在のログ監視の仕様の元になる大きな仕様変更
2.0.13 / 2.2.4未満のログ監視ではログの途中からの読み込みやログの読み直しの発生が報告されていました。
logrtキーはlogキーと違って複数のログファイルが読み込み対象となります。その為、前回読んだファイルと異なるファイルから読み始めると想定外の動作になってしまいます。
そこでログ監視で前回読んだファイルと今回読んだファイルが同じか判定するis_same_file関数を2.0.13 / 2.2.4で実装しました。
この大きな仕様変更の骨子は「is_same_file関数」になり、以下を元に前回読んだファイルと同じファイルか判定します。
- mtimeが前回監視したファイルと同じか未来になっている
- ファイルサイズが同じか増えている
- Iノード/ファイルインデックスが同じ
- 同じデバイス上に存在する(デバイス番号が同じ)
- 先頭512Byteのチェックサムが同じ
ファイルの更新方法と処理の違い
Zabbixは以下のファイルの更新方法に対応したログ監視を実装しています。
- 可変長追記書き更新ファイル
一般的なログファイルになり、同じファイルなら続きから読み、異なるファイル先頭から読み込みます。
例えば、ファイル"messages"がローテーションされると、今まで読んでいたファイルはmessages.1になり、新たにmessagesが作成され、新たなログはmessagesに記録されます。Zabbixはmessages.1がどこまで読んだか判定し、messages.1を全部読んでからmessagesを読み込みます。 - 固定長上書き更新ファイル
OK、NGを上書きするファイル監視の場合、Iノード/ファイルインデックスやファイルサイズは変わりません。OKからNGに変わると先頭512Byteのチェックサムとmtimeが変わりますが、OKにOKを上書きした場合、mtimeしか変わりません。
その為、mtimeのみ更新されたら「異なるファイル」と判断し、先頭から読み込みを行います。
mtimeのみ更新されたら「異なるファイル」と判断し、先頭から読むのは仕様です。
仕様変更後の問題
「固定長上書き更新ファイル」の仕様ですが色々と問題が発生しました。
OSがファイル情報を更新する順番
OSがファイル情報を更新する際にmtime、ファイルサイズの順で更新する可能性が報告されました。その為、OSがmitmeを更新した後、ファイルサイズを更新する前にログ監視が行われると、「固定長上書き更新ファイル」の判定で別ファイルと判定され先頭から読み直す可能性がありました。
- [ZBX-9290]: fixed log file reloading if its size is updated later than modification time
ログを出力するアプリケーションの問題
ログを出力するアプリケーションの出力方法によってはファイルサイズがかわらず、mtimeのみ更新される事象が報告されました。
- [ZBX-17891] changed log, log.count monitoring to ignore file modification time (wiper)
仕様変更後のその他の問題
ローテーションの問題
従来のZabbixはmv & createに対応していましたが、ローテーションでcopy & truncateを使用されるとローテーションの為にコピーしたファイルを別ファイルと判断し、先頭から読み込む事象が報告されました。
- [ZBXNEXT-4216] added 'copytruncate' log file rotation support for logrt[], logrt.count[] (Andris)
OS時刻同期により時刻戻りの問題
mtimeでファイルの読み込み順番の制御や更新があった読み込み対象のファイルか判定するので、基本的に回避できない事象になりますが、logキーはmtimeの処理を無視させる事対応で事象の抑止を実装しました。
- [ZBX-17891] changed log, log.count monitoring to ignore file modification time (wiper)
現在のlogキー、logrtキーでログ監視を想定通りの動作にするためには？
現在のlogキー、logrtキーでは監視対象のログファイルに適した<options>を設定する必要があります。
| ファイル更新 | ローテーション | mtimeのみ変わる | キー | <options> |
|---|---|---|---|---|
| 固定長上書き | なし | 別ファイル | log | rotate(デフォルト) |
| 可変長追記書き | mv & create | 別ファイル | logrt | rotate(デフォルト)、mtime-reread |
| 可変長追記書き | mv & create | 同じファイル | logrt | mtime-noreread |
| 可変長追記書き | copy & truncate | - | logrt | copytruncate |
<options>のrotate(デフォルト)とmtime-rereadはエイリアスで同じ処理になります。
何も考えないで選ぶなら、下の設定がベストです。
- ローテーションしてないログ監視
logキーを使いましょう。<options>は未設定でOK - ローテーション：mv & create
logrtキーで<options>はmtime-norereadを設定 - ローテーション：copy & truncate
logrtキーで<options>はcopytruncateを設定
最後に… 現在のログ監視で発生する事象
- <options>の設定のミスマッチによるログの読み直し
一番多いのではないでしょうか？ - OSの時刻同期による時刻戻りによるログの読み直し
次点に多いのがこの事象ではないかと思います。
特にWindows OSでは発生が多いです。
現時点では回避不能です。 - OSのイメージ戻しによるログの読み直し
監視対象ファイルが昔に戻りサイズが小さくなる、mtimeが過去に戻った後に、アプリがログを追記するとmtimeが更新され別ファイルと判断されてしまいます。
OSのイメージ戻しの際は既に読んでいるログを再度読まないようにログファイルを削除する等の運用回避が必要です。 - Zabbixの不具合によるログの読み直し
6.0以降ではログ監視固有の仕様的な不具合は特に報告ありません。
ようやく2.0.13/2.2.4で実装された仕様が落ち着いたようです。
<options>の設定は回避できる問題なので、ログ監視する際はローテーション方式とファイル出力方法を確認しましょう。