logrotateがプロセスにHUP送る理由を調べてみた

2016/07/04追記: 当時はこれで試行錯誤していましたが、本当はlogrotateのソースコードを読んで理解すべきだと思います。あとカーネルね。若者が試行錯誤していたのだと、温かい目で見て頂ければと思います。

詳解Linuxカーネル第3版 Linux　2．6対応 [ ダニエル・P．ボベット ]

posted with カエレバ

楽天市場で探す

Amazonで探す

- - - -

ちょっと気になる症状があって、どう追うのがよいのか分からなかったんでけど、呟いたら色々ご意見もらったので、その調査ログ。
メモに残してから随分時間かかってしまった…

まだ整理しきれていない部分があるので、あとで続き書くかも。多分。
ご意見・ご指摘あったら是非宜しくお願いします。

発端

発端は、logrorateが走るタイミングでrsyslogにHUPが送られるんだけど、どういう挙動になるのか、なぜそのHUPが必要なのかを追いたくなった背景がある。

決まった時間に走るんだけど、どうもその時間帯の挙動が気になったので、追ってみようと思った次第。システムコールレベルはごめんな(ry
ソースとしては以下の部分

$ vi /etc/logrotate.d/syslog

/var/log/kernellog /var/log/messages /var/log/secure /var/log/maillog /var/log/spooler /var/log/boot.log /var/log/cron {
    sharedscripts
    postrotate
        /bin/kill -HUP `cat /var/run/rsyslogd.pid 2> /dev/null` 2> /dev/null || true
    endscript
}

ローテートの対象に様々なログファイルがあって、rsyslogに対してHUPが送られてる。
んで、なぜHUPを送るのだろうと思い、こう呟いた。

logrotateで、syslogに対してHUPを送る絶対的な必要性はあるのだろうか。
— Kenichi MASUDA (@masudaK) 2011, 9月 5

ログファイル開きなおしてくれるのならいらないんじゃないかな。 RT @masudaK: logrotateで、syslogに対してHUPを送る絶対的な必要性はあるのだろうか。
— hasegaw (@hasegaw) 2011, 9月 5

hup送る理由はたぶんそこ。そもなくば気づかずにローテートされた前のログファイル(I-node)が開かれたままになっちゃう RT @masudaK: 設定ファイルじゃなくてログファイルだと…！！！ RT @hasegaw: ログファイル開きなおしてくれるのならいらないんじゃないか
— hasegaw (@hasegaw) 2011, 9月 5

@masudaK 書き出してる最中のログを mv して、lsof | grep delete してみるといいかもです。
— 石川@驚きの白々しさ (@ishikawa84g) 2011, 9月 5

ということで、まず単純にlsof。情報多いので、特定のログだけに絞る。

# lsof | fgrep /var/log/secure
rsyslogd  20648     root    5w      REG        8,3          0   36372686 /var/log/secure

# /usr/sbin/logrotate -f /etc/logrotate.conf

# lsof | fgrep /var/log/secure
rsyslogd  20648     root    3w      REG        8,3          0   36372701 /var/log/secure

HUPを送った場合は、対象ファイルのinode「36372686」が「36372701」に変わっている。

まぁ、HUPをそのまま送ってもいいんだけど、再現したかったので、ローテート実行させた。要は、rotateが走ると、ローテート先ファイルのinodeが変わるんだと。

てっきり、HUPって設定ファイル読み直すぐらいにしか考えていなかったので、ログファイルのほうは全然無視していました。どうもそうではないらしいということで、ログファイルのほうもめちゃ関係あるんだと勉強できた次第でございます。

2016/07/04追記: 当時は、ログファイルと設定ファイルのどちらをlogrotateが対象にしているかよく分かっていなかったんですね。言うまでもないですが、対象はログファイルです。

おまけ（ここからが長い）

ちなみに、HUPを送るんじゃなくて、restartするようにしましょう。

$ vi /etc/logrotate.d/syslog

/var/log/kernellog /var/log/messages /var/log/secure /var/log/maillog /var/log/spooler /var/log/boot.log /var/log/cron {
    sharedscripts
    postrotate
        /etc/init.d/rsyslog restart
    endscript
}

まぁ、rsyslogも送り側でキューに溜まる設定にしているし、stop, startではないとは言え、restartするのがいいか悪いかは分からない。とりあえず、昔検証したときはロスはなかったような記憶がある。

このケースで、開いてるファイルの情報を見てみる。

# lsof | fgrep /var/log/secure
rsyslogd  19548     root    5w      REG        8,3          0   36372713 /var/log/secure

# /usr/sbin/logrotate -f /etc/logrotate.conf

# lsof | fgrep /var/log/secure
rsyslogd  20648     root    5w      REG        8,3          0   36372686 /var/log/secure

今度はinodeだけじゃなくて、プロセスIDも変わってる。これは当たり前っちゃ当たり前なので、説明はいらないかも。

deleteされたものたち

プロセスと開いてるファイルのアタッチをより分かりやすくするため、deletedされたものも見てみることにした。

# lsof | grep delete
mysqld     7169    mysql    5u      REG        8,3          0   14745603 /tmp/ibApvcRI (deleted)
mysqld     7169    mysql    6u      REG        8,3          0   14745604 /tmp/ib0VpXB2 (deleted)
mysqld     7169    mysql    7u      REG        8,3          0   14745605 /tmp/ibo4HImm (deleted)
mysqld     7169    mysql    8u      REG        8,3          0   14745606 /tmp/ibbbs87F (deleted)
mysqld     7169    mysql   12u      REG        8,3          0   14745607 /tmp/ibvBHcVZ (deleted)

MySQLが動いてるサーバだけど、どのタイミングでこれらのファイルがdelete扱いになったかは分からない。
ただ、こういうのがまず出てきました。ここはスルー。

んで、ログローテートを走らせてみる。

# /usr/sbin/logrotate -f /etc/logrotate.conf

んで、そのlsofの結果

# lsof | grep delete
mysqld     7169    mysql    5u      REG        8,3          0   14745603 /tmp/ibApvcRI (deleted)
mysqld     7169    mysql    6u      REG        8,3          0   14745604 /tmp/ib0VpXB2 (deleted)
mysqld     7169    mysql    7u      REG        8,3          0   14745605 /tmp/ibo4HImm (deleted)
mysqld     7169    mysql    8u      REG        8,3          0   14745606 /tmp/ibbbs87F (deleted)
mysqld     7169    mysql   12u      REG        8,3          0   14745607 /tmp/ibvBHcVZ (deleted)
rsyslogd  19227     root    3w      REG        8,3       5468   36372676 /var/log/kernellog.1 (deleted)
rsyslogd  19227     root    4w      REG        8,3       5771   36372677 /var/log/messages.1 (deleted)
rsyslogd  19227     root    5w      REG        8,3          0   36372686 /var/log/secure.1 (deleted)
rsyslogd  19227     root    6w      REG        8,3          0   36372687 /var/log/maillog.1 (deleted)
rsyslogd  19227     root    7w      REG        8,3       3099   36372705 /var/log/cron.1 (deleted)
rsyslogd  19227     root    8w      REG        8,3          0   36372696 /var/log/spooler.1 (deleted)
rsyslogd  19227     root    9w      REG        8,3          0   36372697 /var/log/boot.log.1 (deleted)

syslog管理下のものが、「.1」になって圧縮された上で消された結果といえばいいだろうか。

要は上記で説明したようにプロセスはHUPされてもそのまま生き続けるので、deleteとしてプロセスと関連づけられる。

んで、HUPを送るんじゃなくて、restartにしてみる。要領はさっきと同じ。
その結果はこんな感じ。

# lsof | grep delete
mysqld     7169    mysql    5u      REG        8,3          0   14745603 /tmp/ibApvcRI (deleted)
mysqld     7169    mysql    6u      REG        8,3          0   14745604 /tmp/ib0VpXB2 (deleted)
mysqld     7169    mysql    7u      REG        8,3          0   14745605 /tmp/ibo4HImm (deleted)
mysqld     7169    mysql    8u      REG        8,3          0   14745606 /tmp/ibbbs87F (deleted)
mysqld     7169    mysql   12u      REG        8,3          0   14745607 /tmp/ibvBHcVZ (deleted)

当然、デーモンを再起動させたので、デーモンにくっついた上でdeleteされたファイルは見当たらない。Linux系＆ext系の話しとして捉えていいのか分からないけど、稼働中のプロセスと、開いているファイルの関係はしっかり把握しておく必要があるなと痛感した次第。

オープン中にmvしたらどうなるか

アクセスログを書きにいってる状態で、そのファイルをmvしてみる。

$ for i in {1..1000};do curl -G 'http://192.168.1.10/';done;

これで、ログを吐かせる。

この状態で、mvする。

$ mv access_log.20110905 access_log.20110905.orig

ここまではよい。んでlsofで開いてるファイルを見てみる。

# lsof | grep http | fgrep test
httpd     29842     root    7w      REG      253,0     2257    6492569 /home/www/test/log/httpd/error_log
rotatelog 29845     root    3w      REG      253,0   924204    6492702 /home/www/test/log/httpd/access_log.20110905.orig

httpのconfigでは、「/home/user/log/httpd/access_log.20110905」に書きこむよう設定をしていました。そして、その通りの挙動をしていたのに、mvしたら「/home/user/log/httpd/access_log.20110905.orig」というmv先のファイルをアタッチしていることになったのです。

この場合、「# lsof | grep delete」を実行しても、mvしただけなので、deleteには当然出てこない。

要はアタッチしたファイルがmvした先になっているということだ。なので、プロセスを再起動しない限り、ログはmv先のファイルに書かれることになる。今回であれば、「/home/user/log/httpd/access_log.20110905.orig」に書かれ続ける。