rails + lighttpd + fastcgi + logrotate が上手く機能しない

Rails server 運用

今動かしているアプリケーションで起っている問題です。アプリケーションのログが肥大化するのを防ぐ為に、logrotate でログのローテーションを設定しています。
しかし、ローテーションしたあとはログが書き込まれないという問題が起こってしましました。

環境

logrodate の設定

  • /etc/logrotate.d/myapp
/home/admin/apps/myapp/log/*.log {
    create
    rotate 4
    missingok
    compress
    notifempty
    monthly
    postrotate
      if [ -f /var/run/lighttpd.pid ]; then \
        /etc/init.d/lighttpd reload > /dev/null; \
      fi; \
    endscript
}

再現方法

  • アプリケーションを起動
$ sudo /etc/init.d/lighttpd start
  • 適当にブラウザで操作してproduction.log にログを書き込ませてみる
$ tail -f ~/apps/myapp/log/production.log
.......


色々書き込まれているのが分かる

  • ローテションを走らせてみる
$ sudo /usr/sbin/logrorate -f /etc/logrotate.d/myapp
  • ログの中身を一度確認
$ cat ~/apps/myapp/log/production.log


ローテーションがかかってログファイルの中身が空になっている。

  • 適当にブラウザで操作してproduction.log にログを書き込ませてみる
$ tail -f ~/apps/myapp/log/production.log


ブラウザで操作してもログに書き込まれない・・・・∃ﾖﾖｮｮ｡+ﾟ(ﾉД`)ﾟ+｡ｮｮﾖﾖ∃

  • しかたがないので再起動
$ ps ax | grep fcgi | grep -v grep | awk '{print $1}' | xargs sudo kill -KILL; sudo /etc/init.d/lighttpd restart


こうすると正常に書き込まれるようになる。

原因

この問題の原因は、reload(つまり HUP)のシグナルがfcgi のプロセスに送られても、fcgi プロセスは新しく生成されたproduction.log を開いてくれないからです。

$ ps ax | grep fcgi
1785  ?        S      0:00 /usr/local/sbin/lighttpd -f /etc/lighttpd/lighttpd.conf
31786 ?        S      0:00 /usr/bin/ruby /home/admin/apps/myapp/public/dispatch.fcgi
....

$ sudo /usr/sbin/logrorate -f /etc/logrotate.d/myapp
$ sudo ls -al /proc/31786/fd
Password:
total 0
dr-x------ 2 root root  0 Oct 24 00:09 .
dr-xr-xr-x 5 root root  0 Oct 23 23:55 ..
lrwx------ 1 root root 64 Oct 24 00:09 0 -> socket:[248452]
l-wx------ 1 root root 64 Oct 24 00:09 1 -> /dev/null
lrwx------ 1 root root 64 Oct 24 00:09 2 -> /dev/pts/1
l-wx------ 1 root root 64 Oct 24 00:09 3 -> /home/admin/apps/myapp/log/production.log.1 (deleted)
l-wx------ 1 root root 64 Oct 24 00:09 4 -> /home/admin/apps/myapp/log/fastcgi.crash.log.1 (deleted)


ものの見事にローテーションによって削除されたファイルのファイルディスクリプタを開いたままになっています。

考えられる解決策

  • 1. 毎回ローテーションした跡で手動で再起動する
  • 2. logrorate の設定ファイルを書き換え、ローテーション後に以下を実行するようにする
# /home/admin/apps/myapp/script/process/reaper -a restart


どっちもいまいちです・・・。手動は面倒だし忘れる可能性があり、逆時自動でアプリケーションが再起動して思わぬ問題が発生しないとも限りません。でも、現状は手動で対応しています・・・。
以下のような感じのシェルスクリプトとか回せばいいのだろうか。

#!/bin/sh

gzip -c /home/admin/myapp/log/production.log > production.log.1.gz
cat /dev/null > /home/admin/myapp/log/production.log


今度Rails 系のイベントに参加した時に、ログの管理方法に関して質問してみようかな。

追記

解決しました！copytruncate 使えばおkでした。

  • /etc/logrotate.d/myapp
/home/admin/apps/myapp/log/*.log {
    copytruncate
    create
    rotate 4
    missingok
    compress
    notifempty
    monthly
    postrotate
      if [ -f /var/run/lighttpd.pid ]; then \
        /etc/init.d/lighttpd reload > /dev/null; \
      fi; \
    endscript
}
  • テスト
$ sudo /usr/sbin/logrotate -d -f /etc/logrotate.d/ad_counter

rotating log /home/admin/apps/myapp/log/production.log, log->rotateCount is 4
renaming /home/admin/apps/myapp/log/production.log.4.gz to /home/admin/apps/myapp/log/production.log.5.gz (rotatecount 4, logstart 1, i 4), 
renaming /home/admin/apps/myapp/log/production.log.3.gz to /home/admin/apps/myapp/log/production.log.4.gz (rotatecount 4, logstart 1, i 3), 
renaming /home/admin/apps/myapp/log/production.log.2.gz to /home/admin/apps/myapp/log/production.log.3.gz (rotatecount 4, logstart 1, i 2), 
renaming /home/admin/apps/myapp/log/production.log.1.gz to /home/admin/apps/myapp/log/production.log.2.gz (rotatecount 4, logstart 1, i 1), 
renaming /home/admin/apps/myapp/log/production.log.0.gz to /home/admin/apps/myapp/log/production.log.1.gz (rotatecount 4, logstart 1, i 0), 
copying /home/admin/apps/myapp/log/production.log to /home/admin/apps/myapp/log/production.log.1
truncating /home/admin/apps/myapp/log/production.log
running postrotate script
running script with arg /home/admin/apps/myapp/log/*.log : "
      if [ -f /var/run/lighttpd.pid ]; then \
        /etc/init.d/lighttpd reload > /dev/null; \
      fi; \
"
compressing log with: /bin/gzip
removing old log /home/admin/apps/myapp/log/production.log.5.gz


create でやった場合との差はこんな感じで、圧縮とか他の部分の順序は変化しない模様。

$ diff create.txt truncate.txt
7,8c7,8
< renaming /home/admin/apps/myapp/log/production.log to /home/admin/apps/myapp/log/production.log.1
< creating new log mode = 0664 uid = 500 gid = 500
---
> copying /home/admin/apps/myapp/log/production.log to /home/admin/apps/myapp/log/production.log.1
> truncating /home/admin/apps/myapp/log/production.log


copytruncate してcompress を書くと、copy されたログを圧縮してくれるんですね。かしこい( ´艸｀)
まぁ、copy なので一瞬ログファイルの2倍のサイズ分ディスクを使ってしまうのが難点でしょうか。
そこも考慮して、現在設定ファイルはこんな感じにしてあります。共通の設定は外に出して、ファイル毎の設定は差分のみを書いています。

  • /etc/logrodate.d/myapp
rotate 4
missingok
compress
notifempty
monthly
postrotate
if [ -f /var/run/lighttpd.pid ]; then \
  /etc/init.d/lighttpd reload > /dev/null; \
fi; \
endscript

/home/admin/apps/myapp/log/lighttpd*.log
/home/admin/apps/myapp/log/fastcgi.crash.log {
    create
}

/home/admin/apps/myapp/log/production.log {
    copytruncate
}

追々記

上の設定には問題がありました。この場合、「rotate 4」〜「endscript」の部分はグローバルな設定になってしまい、全てのローテーションのルールを書き換えてしまいます。
よって、以下のようにしました。

/home/admin/apps/myapp/log/lighttpd*.log
/home/admin/apps/myapp/log/fastcgi.crash.log {
    create
    rotate 4
    missingok
    compress
    notifempty
    monthly
    postrotate
    if [ -f /var/run/lighttpd.pid ]; then \
      /etc/init.d/lighttpd reload > /dev/null; \
    fi; \
    endscript
}

/home/admin/apps/myapp/log/production.log {
    copytruncate
    rotate 4
    missingok
    compress
    notifempty
    monthly
    postrotate
    if [ -f /var/run/lighttpd.pid ]; then \
      /etc/init.d/lighttpd reload > /dev/null; \
    fi; \
    endscript
}