RHEL7からRHEL8へインプレースアップグレードした際のlogrotateの挙動変化

shiraiwa

■はじめに

RHEL7系からRHEL8系へインプレースアップグレードした際に、logrotateの不具合が発生しました。
今回はlogrotate不具合のトラブルシューティングについてお話できればと思います。
　

■事象と原因

【事象】
logrotateの処理は正常に実行されるが、rsyslogの再起動が実行されず同じログファイルにログ出力し続ける。
結果、以下のような容量０のファイルだけが作成されてしまう事象が発生。

# ll /var/log/messages*
-rw-r--r--  1 root        root             0 Jan 14 08:13 messages
-rw-r--r--  1 root        root             0 Jan 11 08:12 messages-20240112
-rw-r--r--  1 root        root             0 Jan 12 08:13 messages-20240113
-rw-r--r--  1 root        root             0 Jan 13 08:13 messages-20240114

　
【原因】
/etc/logrotate.d/syslogの設定をRHEL7系からRHEL8系へ、そのまま引継いだことにより予期せぬ動作を引き起こしました。
下記記載したものが引き継いだ設定となります。

# cat /etc/logrotate.d/syslog
/var/log/cron
/var/log/maillog
/var/log/messages
/var/log/secure
/var/log/spooler
{
    rotate 3
    daily
    dateext
    missingok
    sharedscripts
    postrotate
        /bin/kill -HUP `cat /var/run/syslogd.pid 2> /dev/null` 2> /dev/null || true
    endscript
}

　

■そもそもlogrotateとは

ローテーションとは、設定されたログファイルの最大数を超えると、最新のファイルによって最も古いファイルが書き換えられ、ファイルの名前が変更されることを意味します。たとえば、ローテーションの数が 30 の場合は、31 番目のファイル (最も古いファイル) が新しいファイルにより置き換えられます。
ログローテーションは、膨大なログファイルを減らして整理するため、ログの分析に役立ちます。

redhat公式ドキュメントより引用

　
上記logrotateを実行する際に読み込む設定ファイルには、ログローテーション全体の設定ファイルである/etc/logrotate.confと各サービスごとの設定ファイルのlogrotate.d/*があり、ファイル構成としては以下のようになります。

/etc/
├── logrotate.conf(共通設定)
├── logrotate.d
│   ├─ syslog
│   ├─ ...
│   ├─ ...
│   └─ ...
│

logrotate.d/*の設定内容の詳細については、分かりやすくまとめている記事が協栄情報ブログにあるので、気になる方はご確認ください。
　

■トラブルシューティング

実際に原因特定までを段階的に解説していきます。
　

-ステップ１

まず最初の調査としは、そもそもlogrotateが実行されているかどうかのログ確認です。
Google先生にlogrotate ログ確認　方法と聞くと /var/lib/logrotate.statusを見てねと返事をもらえたので確認してみました。
確認すると以下のような前回実行履歴が記載されていることが分かります。

# cat /var/lib/logrotate/logrotate.status
logrotate state -- version 2
"/var/log/spooler" 2023-10-12-10:0:0
"/var/log/maillog" 2023-10-12-10:0:0
"/var/log/secure" 2024-1-10-7:40:23
"/var/log/messages" 2024-1-14-8:13:24
"/var/log/cron" 2024-1-14-8:13:24

上記ログを確認すると2024-1-14-8:13:24に実行されていることが分かったのでlogrotateの実行は問題なしとしました。
※ここでもう少し深堀りしておけば早期解決できました。。
　

-ステップ２

logrotateの実行が問題ないなら、そもそもログ出力できていないのではないかという考えになり、ログ出力が正常にされているかの観点で調査を始めました。
調査してみるとjournalがlog収集し、収集したログを変形、ログファイルに出力するのがrsyslogであることが分かりました。
　

-ステップ３

ステップ２の情報からjournalがログ収集できているかを確認することにしました。
/run/log/journal/配下にjournalログが存在することからjournalの動作としては問題なさそうであると判断しました。
　

-ステップ４

もう一度確認漏れがないかステップ１から再度確認することにしました。
確認箇所としては、■そもそもlogrotateとはで確認した下記設定ファイルを確認しました。
・/etc/logrotate.conf
・logrotate.d/syslog
　
■事象と原因でも記載したsyslogを読み解いていくとpostrotate と endscript の間にコマンドの記載があることが分かりました。

# cat /etc/logrotate.d/syslog
/var/log/cron
/var/log/maillog
/var/log/messages
/var/log/secure
/var/log/spooler
{
    rotate 3
    daily
    dateext
    missingok
    sharedscripts
    postrotate
        /bin/kill -HUP `cat /var/run/syslogd.pid 2> /dev/null` 2> /dev/null || true
    endscript
}

上記コマンドを読み解いていくと、syslogd.pidに記載のPIDを指定して再起動していることが分かります。
syslogd.pidに記載のPIDが何のプロセスIDかを調べるとrsyslogのPIDであることが分かりました。
実際に確認した結果です。

# cat /var/run/syslogd.pid
1142
# systemctl status rsyslog
● rsyslog.service - System Logging Service
   Loaded: loaded (/usr/lib/systemd/system/rsyslog.service; enabled; vendor preset: enabled)
   Active: active (running) since Sun 2024-01-14 06:21:03 UTC; 3h 32min ago
     Docs: man:rsyslogd(8)
           http://www.rsyslog.com/doc/
 Main PID: 1142 (rsyslogd)
   CGroup: /system.slice/rsyslog.service
           └─1142 /usr/sbin/rsyslogd -n

syslogd.pidに記載のPIDとrsyslog.serviceのステータス確認で確認できたPIDの値が一致しています。
　
このことからsyslogの設定上、日時でログローテを実施しした後にrsyslogを再起動していることが分かりました。
　

– -なぜ、rsyslogの再起動を実施しているのか

ログローテ後にrsyslogを再起動することにより、ログファイルに紐づいたrsyslogのPIDを再読み込みさせる。
これにより、再起動後のrsyslogのPIDが新たに作成されたログファイルに紐づき、ログ出力がされるようです。
　

– -もう少し詳しく

下記コマンドで、先程確認したPIDを使用しているファイルディスクリプタを確認できます。
一度オリジナルログファイル(messages-20240110(リネーム前:messages))を削除した後、同じファイル名のログファイル(messages)を作成したとしてもdeletedとなり、削除したログファイル(/var/log/messages-20240110)に紐づいたままとなります。
同じファイル名(messages)のログファイルを作成したとしても、rsyslogは削除された元ファイルに紐付いたままなのでrsyslogを再起動してログファイルの紐付けを変えてあげないとログ出力されないとういことだったみたいです。
※ファイルディスクリプタ（file descriptor）とは、プログラムからファイルを操作する際、操作対象のファイルを識別・同定するために割り当てられる番号。

# ls -l /proc/1223/fd
total 0
lr-x------ 1 root root 64 Jan 14 07:22 0 -> /dev/null
l-wx------ 1 root root 64 Jan 14 07:22 1 -> /dev/null
lr-x------ 1 root root 64 Jan 14 07:22 10 -> /run/log/journal/38193d45b1a74a60a81037519c7026ad/system@940019254177499fa7c97737ab0ee09f-000000000000035c-00060ebb248dd182.journal
lr-x------ 1 root root 64 Jan 14 07:22 11 -> /run/log/journal/38193d45b1a74a60a81037519c7026ad/system@940019254177499fa7c97737ab0ee09f-0000000000000333-00060ea6df3ff816.journal
lr-x------ 1 root root 64 Jan 14 07:22 12 -> /run/log/journal/38193d45b1a74a60a81037519c7026ad/system@940019254177499fa7c97737ab0ee09f-0000000000000324-00060ee31607a1f1.journal
lr-x------ 1 root root 64 Jan 14 07:22 13 -> /run/log/journal/38193d45b1a74a60a81037519c7026ad/system@940019254177499fa7c97737ab0ee09f-00000000000002fe-00060ea6af0543f9.journal
lr-x------ 1 root root 64 Jan 14 07:22 14 -> /run/log/journal/38193d45b1a74a60a81037519c7026ad/system@940019254177499fa7c97737ab0ee09f-00000000000002f5-00060e5633cc17a9.journal
lr-x------ 1 root root 64 Jan 14 07:22 15 -> /run/log/journal/38193d45b1a74a60a81037519c7026ad/system@940019254177499fa7c97737ab0ee09f-00000000000002e4-00060e928a7063d6.journal
lr-x------ 1 root root 64 Jan 14 07:22 16 -> /run/log/journal/38193d45b1a74a60a81037519c7026ad/system@940019254177499fa7c97737ab0ee09f-00000000000002da-00060ee2f6422d4b.journal
l-wx------ 1 root root 64 Jan 14 07:22 17 -> '/var/log/cron-20240112 (deleted)'
lr-x------ 1 root root 64 Jan 14 07:22 18 -> /run/log/journal/38193d45b1a74a60a81037519c7026ad/system@940019254177499fa7c97737ab0ee09f-0000000000000001-00060ee2bf53e165.journal
lr-x------ 1 root root 64 Jan 14 07:22 19 -> /run/log/journal/ec242ade1d5a9d166d4054b9e165de60/system.journal
l-wx------ 1 root root 64 Jan 14 07:22 2 -> /dev/null
lr-x------ 1 root root 64 Jan 14 07:22 3 -> /dev/urandom
lrwx------ 1 root root 64 Jan 14 07:22 4 -> 'socket:[27420]'
l-wx------ 1 root root 64 Jan 14 07:22 5 -> '/var/log/messages-20240110 (deleted)'
lr-x------ 1 root root 64 Jan 14 07:22 6 -> anon_inode:inotify
l-wx------ 1 root root 64 Jan 14 07:22 7 -> '/var/log/secure-20240110 (deleted)'
l-wx------ 1 root root 64 Jan 14 07:22 8 -> /var/log/maillog-20240114
lr-x------ 1 root root 64 Jan 14 07:22 9 -> /run/log/journal/38193d45b1a74a60a81037519c7026ad/system.journal

– -rsyslogが再起動出来ていない原因

RHEL7系からRHEL8系へインプレースアップグレードした際に、/var/run/syslogd.pidが削除され、PIDの確認が出来ずrsyslogが再起動出来なかったことが根本の原因でした。
　

-ステップ５

syslogをRHEL8系のデフォルトの設定値に修正することでRHEL8系へ移行後もrsyslogの再起動を実施することが出来るようになります。
大きな修正内容としては、/var/run/syslogd.pidのPIDを参照して再起動を行っていたところを、直接rsyslog.serviceを再起動するようにした箇所です。
この修正により、rsyslogを再起動させることができ新たに作成されたログファイルにPIDを紐付けることが出来ました。

# cat /etc/logrotate.d/syslog
/var/log/cron
/var/log/maillog
/var/log/messages
/var/log/secure
/var/log/spooler
{
    rotate 3
    daily
    dateext
    missingok
    sharedscripts
    postrotate
        /usr/bin/systemctl -s HUP kill rsyslog.service >/dev/null 2>&1 || true
    endscript
}

■動作確認
手動でlogrotateを実行し、再度ファイルディスクリプタを確認したところ/var/log/messagesの行に出ていたdeletedは消え、ファイルパスも更新されていることが確認できました。

# ls -l /proc/1223/fd
total 0
lr-x------ 1 root root 64 Jan 14 07:22 0 -> /dev/null
l-wx------ 1 root root 64 Jan 14 07:22 1 -> /dev/null
lr-x------ 1 root root 64 Jan 14 07:22 10 -> /run/log/journal/38193d45b1a74a60a81037519c7026ad/system@940019254177499fa7c97737ab0ee09f-000000000000035c-00060ebb248dd182.journal
lr-x------ 1 root root 64 Jan 14 07:22 11 -> /run/log/journal/38193d45b1a74a60a81037519c7026ad/system@940019254177499fa7c97737ab0ee09f-0000000000000333-00060ea6df3ff816.journal
lr-x------ 1 root root 64 Jan 14 07:22 12 -> /run/log/journal/38193d45b1a74a60a81037519c7026ad/system@940019254177499fa7c97737ab0ee09f-0000000000000324-00060ee31607a1f1.journal
lr-x------ 1 root root 64 Jan 14 07:22 13 -> /run/log/journal/38193d45b1a74a60a81037519c7026ad/system@940019254177499fa7c97737ab0ee09f-00000000000002fe-00060ea6af0543f9.journal
lr-x------ 1 root root 64 Jan 14 07:22 14 -> /run/log/journal/38193d45b1a74a60a81037519c7026ad/system@940019254177499fa7c97737ab0ee09f-00000000000002f5-00060e5633cc17a9.journal
lr-x------ 1 root root 64 Jan 14 07:22 15 -> /run/log/journal/38193d45b1a74a60a81037519c7026ad/system@940019254177499fa7c97737ab0ee09f-00000000000002e4-00060e928a7063d6.journal
lr-x------ 1 root root 64 Jan 14 07:22 16 -> /run/log/journal/38193d45b1a74a60a81037519c7026ad/system@940019254177499fa7c97737ab0ee09f-00000000000002da-00060ee2f6422d4b.journal
lr-x------ 1 root root 64 Jan 14 07:22 18 -> /run/log/journal/38193d45b1a74a60a81037519c7026ad/system@940019254177499fa7c97737ab0ee09f-0000000000000001-00060ee2bf53e165.journal
lr-x------ 1 root root 64 Jan 14 07:22 19 -> /run/log/journal/ec242ade1d5a9d166d4054b9e165de60/system.journal
l-wx------ 1 root root 64 Jan 14 07:22 2 -> /dev/null
lr-x------ 1 root root 64 Jan 14 07:22 3 -> /dev/urandom
lrwx------ 1 root root 64 Jan 14 07:22 4 -> 'socket:[27420]'
l-wx------ 1 root root 64 Jan 14 07:22 5 -> /var/log/messages
lr-x------ 1 root root 64 Jan 14 07:22 6 -> anon_inode:inotify
lr-x------ 1 root root 64 Jan 14 07:22 9 -> /run/log/journal/38193d45b1a74a60a81037519c7026ad/system.journal

新たに作成されたログファイルにログ出力されていることも確認できたので事象解消しました。

# ll /var/log/messages*
-rw-r--r-- 1 root root 284 Jan 15 11:27 /var/log/messages
-rw-r--r-- 1 root root   0 Jan 12 08:13 /var/log/messages-20240113
-rw-r--r-- 1 root root   0 Jan 13 08:13 /var/log/messages-20240114
-rw-r--r-- 1 root root   0 Jan 14 08:13 /var/log/messages-20240115

■まとめ

インプレースアップグレードはOS設定を引き継げるところが良いところですが、軽微な変更点で既存の機能が動作しないなんてこともあるので、バージョンアップ前後で設定値の再確認は必須ですね。。

Last modified: 2024-01-14

Author