logrotate のことを昨日書いた。
hiro99ma blog: [linux]思ったより logrotate が難しい
https://blog.hirokuma.work/2022/04/linux-logrotate.html
VirtualBox 環境では確認しづらかったので、AWS に立てている Ubuntu で設定して、眠たかったので明日のお楽しみ、だったのだが、今朝見てみるとまだ動いていなかった。
かなり長くなったので結論を書くと、
- systemd の service で動かす logrotate は /tmp や /var/tmp に mount する PrivateTmp が trueになっている
- /tmp にログファイルを置いていたのだが、PrivateTmp=true によって /tmp に mount されたことでファイルが見えなくなっていた
である。
/var/lib/logrotate/status を見ると、2022年4月17日の0時(UTC)に更新されているものがあった(これを書いているのは2022年4月17日 11時(JST))ので、少なくとも 1回は動作していることがわかる。
うーん、ありそうなのはこんなところか。
- systemctrl の timer が hourly で動いていない
- logrotate の設定が hourly で動いていない
- logrotate は実行したけれどもローテートしなくて良いと判断された
まず、自分で追加した logrotate の設定をなかったことにするため、 /var/lib/logrotate/status の中から自分のアプリの行を削除した。
これで前回動作したという記憶がなくなったはずだ。
この状態で logrotate を実行してみよう。
$ cat /var/lib/logrotate/status | grep aaaa
$ sudo logrotate /etc/logrotate.d/aaaa
$ cat /var/lib/logrotate/status | grep aaaa
"/tmp/aaaa/aaaa.log" 2022-4-17-2:0:0
うむ、status ファイルに記録が残った。
日本時間11時・・・UTC 2時なので「2:0:0」でよかろう。
なお logrotate の設定ファイルはこんな感じだ。
/tmp/aaaa/aaaa.log {
missingok
hourly
rotate 12
copytruncate
compress
}
aaaa.log はアプリがオープンしたまま書き込むので copytruncate でコピーしてオリジナルは ftruncate してサイズだけ切り詰めてもらう・・・という動作をしてほしい。
あと 1時間待って、systemctl の timer が自発的にやってくれるのを待とう。
放置している間に情報を探しておこう。
How To Manage Logfiles with Logrotate on Ubuntu 20.04 | DigitalOcean
https://www.digitalocean.com/community/tutorials/how-to-manage-logfiles-with-logrotate-on-ubuntu-20-04#step-3-setting-up-an-example-config
んん？
システムの logrotate は1日1回しか動かないから hourly は動かない・・・？
このサイトの人は、自分のアプリ用に logrotate の設定を用意して、ユーザレベルの cron に logrotate を実行するよう書き加えている。
まあ、私が hourly にしているのもさっさと結果を確認したいからであって、時間ごとにログをローテートさせたいわけではないので、本当に daily 以上の間隔じゃないと動作しなかったとしても別に問題ではない。
ただこのアプリは最終的には systemctl で起動させようと思っているので、logrotate も systemctl の方でやってほしい。
さて、あれから1時間が経過した。
/var/lib/logrotate/status に変化はなかった・・・。
systemctl list-timers の方は LAST の時間が更新されていたので、タイマーは動いたのだと思う。
journalctl -u logrotate でも Succeeded になってるしね。
となると、やはりシステムでは logrotate が daily 以上の間隔という話が真実味を帯びてくる。
もしかすると /etc/logrotate.conf の設定がそうなっているのかと思ったのだが、そこは weekly だったので関係ないだろう。
では、/lib/systemd/system/logrotate.service を /etc/systemd/system/ にコピーして、logrotate を -v で実行させよう。
そうすれば journalctl でももう少しログが出てくれるんじゃなかろうか。
さらに1時間待った。
logrotate -v のおかげで journalctl で詳細が出てきた。
Apr 17 04:00:12 logrotate: rotating pattern: /tmp/aaaa/aaaa.log hourly (12 rotations)
Apr 17 04:00:12 logrotate: empty log files are rotated, old logs are removed
Apr 17 04:00:12 logrotate: switching euid to 0 and egid to 4
Apr 17 04:00:12 logrotate: considering log /tmp/aaaa/aaaa.log
Apr 17 04:00:12 logrotate: log /tmp/aaaa/aaaa.log does not exist -- skipping
does not exist ???
ls すると見えるんですけど ???
sudo logrotate -d で実行してもエラーになりませんし !!!
... すまん、動揺してしまった。
「empty log files are rotated」の方を気にしないといけない気がする。
前の方で logrotate の動作確認をしたので、そのときに truncate されてファイルサイズがゼロになったままだったのだ。
だからきっと「(ファイル自体はあるかもしれんが)ローテートすべきファイルがない」という意味の「does not exist」なのではなかろうか。
ファイルサイズがゼロにならないようにしてもう1時間待ってみよう。
なお、設定ファイルの方は root:root がよいそうだ。
これは私の方もそうしていた。
logrotateの設定ファイル、オーナーが重要 - Qiita
https://qiita.com/abetomo/items/59ee7d55e5458a33988c
ログを格納しているディレクトリのパーミッションが影響することもあるそうだ。
私のはこのエラーログではない。
logrotate ～ ログがローテートされないときに～ | GMOインターネットグループ 次世代システム研究室
https://recruit.gmo.jp/engineer/jisedai/blog/logrotate/
エラーログはそうではなかったのだが、ディレクトリが ubuntu:ubuntu だ！
そういえばアプリは AWS の EC2 に立てた Ubuntu そのままのユーザで動かしているのでそうなっている。
does not exist がサイズが原因だったとして、その次はアカウントの方でエラーになるんじゃなかろうか。
conf ファイルを変更しておきたいところだが、あと 10分くらいで timer の時間になるので待っておこう。
「empty log files are rotated」はここ。
LOG_FLAG_IFEMPTY がセットされているということは conf に "ifempty" を書いているということかと思ったのだが、私は書いてない。 "notifempty" もあるので、デフォルトは "ifempty" ということか？ なら空ファイルでもローテーションするということではないのか？？
https://github.com/logrotate/logrotate/blob/4c52ff5a1ddd0c34096824d786e6a68e20c18136/logrotate.c#L2350
そうならば、ログファイルのサイズを増やした次タイミングでも失敗するに違いない。
1時間経った。
「does not exist」は変わらず。。。
ログファイルはサイズそのままだし、ローテートもされていない。
「does not exist」はここ。
https://github.com/logrotate/logrotate/blob/4c52ff5a1ddd0c34096824d786e6a68e20c18136/logrotate.c#L1394
missingok だから return 0 になっているだけだ。
それよりも lstat() が ENOENT になっているせいだということがわかる。
まあ、ENOENT は「ファイルやディレクトリがありません」だろう。
しかし %s しているファイル名と lstat() しているファイルは同じものだから実物の有無以外で ENOENT になっているはずだ。
ログの「switching euid to 0 and egid to 4」は、ユーザID を 0、グループID を 4にするということだろう。
https://github.com/logrotate/logrotate/blob/4c52ff5a1ddd0c34096824d786e6a68e20c18136/logrotate.c#L145-L146
conf で su を設定するとそれを使うということだろう。
未設定の場合は
id コマンドで調べると、0 は root、 4 は sync だった。
ならば、ログのファイルやディレクトリが ubuntu:ubuntu なので、logrotate が root:sync に切り替えるとアクセスできないので ENOENT になった、だろうか。
そういうわけで、 conf に「su ubuntu ubuntu」を追加して次のタイミングを待とう。
1時間経過。
はい、変わらず。
su を指定したのに「switching euid to 0 and egid to 4」ってのも変な話よね。
どこかもっと違うところで間違えている気もする。
が、せめて単独でコマンドを実行したときと同じ現象であれば調べる気力が湧くのだけど、試せるのが1時間に1回となると非常に効率が悪い。
まずはコマンドラインなどで同じことができるようにしよう。
先ほど /etc/systemd/system にコピーした logrotate.service をリネームして自分の名前にする(aaaa.service とか)。
ExecStart で logrotate の設定ファイルを /etc/logrotate.d/ においた自分の設定ファイルにする。
そして、
sudo systemctl start aaaa
これで、
journalctl -u aaaa
を見てみると、ほら、does not exist に！
これで検証できる。
さて、does not exist にはなったのだが、。
rotating pattern: /tmp/aaaa/aaaa.log hourly (12 rotations)
empty log files are rotated, old logs are removed
switching euid to 1000 and egid to 1000
considering log /tmp/aaaa/aaaa.log
log /tmp/aaaa/aaaa.log does not exist -- skipping
switching euid to 0 and egid to 0
そう、su を書いたのだからこうなってほしかったのだよ、さっきも。
それはそれで納得できないし、ここでは切り替えたにもかかわらず does not exist だし。
直接 logrotate コマンドを実行すると成功するので、そのログの違いから探っていこう。
rotating pattern: /tmp/aaaa/aaaa.log hourly (12 rotations)
empty log files are rotated, old logs are removed
switching euid to 1000 and egid to 1000
considering log /tmp/aaaa/aaaa.log
Now: 2022-04-17 06:43
Last rotated at 2022-04-17 02:00
log needs rotating
色を付けたメッセージは skipping の少しあとにある。
やっぱり lstat() をなんとかしないといかんという結論になる。
ちなみにまだ status ファイルに記述がない場合はこういうログになる。
considering log /tmp/aaaa/aaaa.log
Creating new state
そして /var/lib/logrotate/status ファイルに追加されて、実際のログファイルには変更無し。
続けて実行しても、何もならなかった(1時間経っていないからか)。
そもそも、コマンドラインで実行すると成功して systemctl だと失敗するというなら、service に原因を求めるのが筋だろう。
GitHub のサンプルはこうだった。
https://github.com/logrotate/logrotate/blob/master/examples/logrotate.service
そして Ubuntu の方は下の方がこうなっていた。
PrivateDevices=true
PrivateTmp=true
ProtectControlGroups=true
ProtectKernelModules=true
ProtectSystem=full
RestrictRealtime=true
自分で書くときには指定したことがないオプションだ。
そしてこれらをコメントアウトして systemctl start すると実行するではないか！ ローテートされるじゃないか！
もうちょっと前に気付いてもよかったんじゃないかと思わなくもないが、まあよかろう。
私は未来を愛しているのだ。
では、これらのオプションが何かを調べる。
hardening options らしい。
https://www.freedesktop.org/software/systemd/man/systemd.exec.html
PrivateTmp
If true, sets up a new file system namespace for the executed processes and mounts private /tmp/ and /var/tmp/ directories inside it that are not shared by processes outside of the namespace. This is useful to secure access to temporary files of the process, but makes sharing between processes via /tmp/ or /var/tmp/ impossible. If true, all temporary files created by a service in these directories will be removed after the service is stopped. Defaults to false.
ああ、そういうことね・・・。
/tmp に mount してから実行するので /tmp 以下に置いていたファイルは not exist になるということか。
/tmp にログをおいたのは、出来心だった。
ちょうどログを出力する実装をしているときに見たサイトが /tmp の下に置いていたのでまねしただけ。
それがこんな悲劇を生もうとは・・・。
いや、私も /var/log とかに格好良く(?)ログファイルを置きたいのだけど、権限が通常ユーザだと足りないので /tmp はちょうど良かったのだ。
仮にログファイルを置くなら、まだユーザディレクトリの中の方がましだったようだ。