logrotateでログが欠損することがあるらしいーー

そんな話を小耳に挟んだので、調べてみた。
これはその調査の記録だ。
さほど詳しくない人が調べた結果なので、ミスがあれば指摘は歓迎したい。

TL;DR

/var/log/anything/*.log {
    :
    nocopytruncate
    compress
    delaycompress
    sharedscripts
    postrotate
        /sbin/service httpd graceful # or anything else.
    endscript
}

環境

Debianベースのイメージを
- Dockerコンテナとして
- macOS上で動かしている
logrotate、gzipのバージョンは記事執筆時点の最新
- logrotate: 3.21.0
- gzip: v1.13

処理を追いかけてみる

まず各オプションの処理を各リポジトリのソースコード上で追いかけてみよう。

`copytruncate`

copytruncateはファイル名を変更せずに、新しいファイルを作成し、そこにまるごとコピーし、元のファイルを切り詰めるオプションだ。
つまり書き込み先のinodeの変更が発生しない。

だいたいのオプションはlogrotateのソースコード上ではLOG_FLAG_HOGEHOGEというフラグになっており、copytruncateもLOG_FLAG_COPYTRUNCATEというフラグに対応している。
そしてそのままcopyTruncateというメソッドと対応している。

`copytruncate` ありの場合

処理の流れとしては以下の通り。

ファイルロック等は行っていなさそうなので、新ログファイルへのコピーから旧ログファイルの切り詰めまでに隙間がありそうだ。

`copytruncate` なしの場合

処理の流れとしては以下の通り。

renameする

ここで気をつける必要があるのは、大抵のアプリケーションサーバーは自分が掴んでいるログファイルのリネームを検知しないという点だ。
アプリケーションサーバーを再起動するなどしてログファイルを掴み直すまでは旧ログファイルに書き込み続ける可能性が高い。

`compress`

compressを指定するとローテート後のファイルを圧縮できる。
圧縮にはgzipが使われる。
gzipコマンドでは通常、圧縮されたファイルが作られて、元のファイルは削除される。
gzipコマンドではファイルをロックしている箇所は無さそうなので、最後のほうの書き込みが欠損する可能性はありそうだ。

`compress` ありの場合

gzipコマンドを組み立てて実行

`compress` なしの場合

何もしない

動作検証してみる

それでは実際にログが欠損するのか軽く実験してみよう。
以下のようなログを延々と出力する簡単なプログラムを準備した。
私の手元のマシンスペックだと、0.0002秒ごとにログが出力される。
2つのファイルに出力し続け、片方のファイルだけをローテートさせるようにしておく。

[19:49:47.6774] 123 times loop in 1 proc.
:
[19:49:47.7864] 456 times loop in 1 proc.

強制的にローテートさせたいので、size 100で指定してある。
その他の基本オプションは以下のとおりとなっている。

    rotate 2
    size 100

手動でローテートさせるには、以下のコマンドを使う。

logrotate -fv /etc/logrotate.d/test

`copytruncate`あり+`compress`なし

以下のようなログが出力された。

旧ログファイル: 2325720 times loop in 1 proc. が最後
新ログファイル: 2326100 times loop in 1 proc. が最初

差分は0.0002秒を380回なので、およそ0.076秒ぶんのログが欠損している。
対象のログファイルは約200MBの状態だった。
copytruncateありの場合、ローテート時のinodeの変化は起こらず、旧ログファイル圧縮時の欠損は発生し得ないため、copytruncateあり+compressありのパターンは試さない。

`copytruncate`なし+`compress`なし

以下のようなログが出力された。

旧ログファイル: 128132 times loop in 1 proc. が最後
新ログファイル: なし
別のログファイル: 128132 times loop in 1 proc. が最後

ローテート後もrenameされたファイルに書き込み続けている。
そのため、ローテーション回数の上限に達すると、それ以降のログが欠損する。
これはrename後もプロセスが同じファイルのinodeを持ち続けているからだ。

`copytruncate`なし+`compress`あり

以下のようなログが出力された。

旧ログファイル: 52385 times loop in 1 proc. が最後
新ログファイル: なし
別のログファイル: 128132 times loop in 1 proc. 以降も続く

ローテート後の書き込みが欠損している。
旧ログファイルはgzipで圧縮後に無くなっているので、プロセスが掴んでいるinodeが迷子になってしまっているからだ。
迷子になったinodeの挙動はディストリビューションによって多少異なるようだが、見えないファイルとして膨れ上がってディスクスペースを圧迫することがあるので、注意が必要だ。

`gzip`のみ

compressの実際の中身の処理ということで、gzipで直接圧縮するだけの場合を試す。
するとfile size changed while zippingというログが出た。
これは時間の差で見るしかないが、直後にdate +%H:%M:%S.%3Nで出力してみたところ、0.0015秒ぶんのログが欠損している可能性が高そうだ。
なお対象のファイルは約200MBだ。

解決策

これまでに出てきた欠損するケースに対応する設定を検討してみよう。

ローテートしても古いファイルに書き込み続ける問題への対応

この問題を解決するには、postrotateを利用してプロセスを再起動するなどの対応が必要だ。
再起動すれば、通常はファイルが無いことを検知して、新しいログファイルを生成する。
例として、以下のようなかたちでhttpdをgracefulにrestartする。

/var/log/anything/*.log {
    :
    sharedscripts
    postrotate
        /sbin/service httpd graceful # or anything else.
    endscript
}

sharedscriptsも同時に指定しているのは、指定しないとログファイルごとにpostrotateの内容が実行されるからだ。

`compress`で欠損が発生する問題への対応

この問題はdelaycompressを指定することで解決可能なようだ。
このオプションを指定すると、ローテート後に1サイクル遅らせて圧縮する。
つまり、完全に書き込みが無くなった状態のログファイルを圧縮する。
そのため、圧縮されていないログファイル2世代分を保持するためのディスクスペースが必要な点には留意したい。
delaycompressはcompressオプションと同時に指定する必要がある点には注意が必要だ。

具体的には以下のような流れになる。

ローテート前

drwxr-xr-x  2 root root    4096 Oct 28 10:11 .
drwxrwxrwx 12 root root    4096 Aug 24 12:31 ..
-rw-r--r--  1 root root     387 Oct 28 10:11 hoge.log

1度目のローテート後

-rw-r--r--  1 root root     387 Oct 28 10:11 hoge.log
-rw-r--r--  1 root root     387 Oct 28 10:11 hoge.log.1

2度目のローテート後

-rw-r--r--  1 root root      387 Oct 28 10:13 hoge.log
-rw-r--r--  1 root root      387 Oct 28 10:12 hoge.log.1
-rw-r--r--  1 root root      185 Oct 28 10:11 hoge.log.2.gz

結論

上記を組み合わせると、欠損が出ない組み合わせとしては以下のような組み合わせとなりそうだ。

/var/log/anything/*.log {
    :
    nocopytruncate
    compress
    delaycompress
    sharedscripts
    postrotate
        /sbin/service httpd graceful # or anything else.
    endscript
}

挙動をテストしたい場合は、-dvオプションを指定すると良い。

logrotate -dv /etc/logrotate.d/test

ただ、delaycompressは二度目のローテート時にしか発動しないため、なるべく本番に近い小さな環境で実際に動かして確認することをお勧めする。