logrotateでログが欠損するケースとその対策

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

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

## TL;DR

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

## 環境

- Debianベースのイメージを
    - Dockerコンテナとして
    - macOS上で動かしている
- logrotate、gzipのバージョンは記事執筆時点の最新
    - [logrotate](https://github.com/logrotate/logrotate): 3.21.0
    - [gzip](https://git.savannah.gnu.org/cgit/gzip.git/): v1.13

## 処理を追いかけてみる

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

### `copytruncate`

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

だいたいのオプションは`logrotate`のソースコード上では`LOG_FLAG_HOGEHOGE`というフラグになっており、`copytruncate`も[`LOG_FLAG_COPYTRUNCATE`](https://github.com/logrotate/logrotate/blob/cb99cda639fb4b65810401878e052b7c2950f996/logrotate.h#L18)というフラグに対応している。
そしてそのまま[`copyTruncate`](https://github.com/logrotate/logrotate/blob/cb99cda639fb4b65810401878e052b7c2950f996/logrotate.c#L1256)というメソッドと対応している。

#### `copytruncate` ありの場合

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

- [旧ログファイルを開く](https://github.com/logrotate/logrotate/blob/cb99cda639fb4b65810401878e052b7c2950f996/logrotate.c#L1268)
- [新ログファイルを作成](https://github.com/logrotate/logrotate/blob/cb99cda639fb4b65810401878e052b7c2950f996/logrotate.c#L1291)
- [旧ログファイルのfdから新ログファイルのfdに中身をコピー](https://github.com/logrotate/logrotate/blob/cb99cda639fb4b65810401878e052b7c2950f996/logrotate.c#L1302)
- [新ログファイルにfsync](https://github.com/logrotate/logrotate/blob/cb99cda639fb4b65810401878e052b7c2950f996/logrotate.c#L1316)
- [旧ログファイルを空にする](https://github.com/logrotate/logrotate/blob/cb99cda639fb4b65810401878e052b7c2950f996/logrotate.c#L1317)

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

#### `copytruncate` なしの場合

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

- [`rename`する](https://github.com/logrotate/logrotate/blob/cb99cda639fb4b65810401878e052b7c2950f996/logrotate.c#L2181)

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

### `compress`

`compress`を指定するとローテート後のファイルを圧縮できる。
[圧縮には`gzip`が使われる](https://github.com/logrotate/logrotate/blob/cb99cda639fb4b65810401878e052b7c2950f996/configure.ac#L62)。
`gzip`コマンドでは通常、圧縮されたファイルが作られて、元のファイルは削除される。
`gzip`コマンドではファイルをロックしている箇所は無さそうなので、最後のほうの書き込みが欠損する可能性はありそうだ。

#### `compress` ありの場合

- [gzipコマンドを組み立てて実行](https://github.com/logrotate/logrotate/blob/cb99cda639fb4b65810401878e052b7c2950f996/logrotate.c#L935-L940)

#### `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
```

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

```bash
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する。

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

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

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

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

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

- ローテート前

```
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
```

## 結論

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

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

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

```bash
logrotate -dv /etc/logrotate.d/test
```

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