カイワレの大冒険 Third

技術的なことや他愛もないことをたまに書いてます

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

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

        • -

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

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

発端

発端は、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を送るのだろうと思い、こう呟いた。


ということで、まず単純に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」に書かれ続ける。

結論
  • HUPは設定ファイルを読み直すというような単純なものじゃない
  • 注意すべきは設定ファイルではなく、ログファイル
  • プロセスが生きている限りは、開いたままのファイルをmvしたりしても、それはmvした先に書かれる。要はファイル名なんて関係ない
  • ログローテートが走ったときにsyslogとかrsyslogにHUP送るけど、これはプロセスを殺さず、ログファイルのinodeを更新するため。
  • inode更新されるので、ファイルを読みなおしたのと同じ挙動となる

そのうち、open(2)させたのちに無限ループさせたあたりの挙動追ってみると面白いのかもなぁと思ったり、誰か書いてくれると期待したり。


以下のLinux記事もおすすめです!