サーバーの様々なログを、日付などでローテーションしてくれるlogrotateはよく使われます。
しかし、ログファイルを開きっぱなしにするサーバーアプリケーションなどでは、logrotateがログファイルをローテーションしても、ずっと元のログファイルに書き込み続けてしまうということがあります。
このことを知らないと、logrotateによってログが消えてしまったように錯覚してしまいます。
このエントリでは、logrotateによってログファイルがローテーションされたとき、アプリケーションに通知してログファイルを再オープンする方法を、Rubyのコードを例に説明します。
logrotateの挙動は、現在のファイルをリネームし元のファイルと同名のファイルを作成するというものです。
例えばsample.logというログファイルをローテーションすると、sample.logはsample.log-20160305にリネームされ（dateext指定時）、新たに sample.logが作成されます。
logrotateの設定は/etc/logrotate.confもしくは/etc/logrotate.d/以下に記述します。
試しに下記の内容で/etc/logrotate.d/sampleを作成してみましょう（vagrant 部分はご自身の環境に置き換えてください）。
/home/vagrant/sample.log {
missingok
daily
dateext
create 0755 vagrant vagrant
rotate 5
}対象となるログファイルも作成しておきましょう。
$ touch /home/vagrant/sample.log-
dオプションで設定ファイルをデバッグすることができます。
$ sudo logrotate -d /etc/logrotate.d/sample
reading config file /etc/logrotate.d/sample
reading config info for /home/vagrant/sample.log
Handling 1 logs
rotating pattern: /home/vagrant/sample.log after 1 days (5 rotations)
empty log files are rotated, old logs are removed
considering log /home/vagrant/sample.log
log does not need rotating-
fオプションで即時にローテーションさせることができます。
$ sudo logrotate -f /etc/logrotate.d/sample ローテーションすると、sample.log-20160305のようなファイルが作成されているはずです。
アプリケーションのロガーがsample.logを開いている状態で、sample.logがローテーションされるとどうなるでしょうか？
Rubyので観察してみます。
$ pryloggerを使ってログを書き込みます。
logger = Logger.new "sample.log"
logger.info "It's great log!" ログはsample.logに書き込まれています。
$ cat sample.log
I, [2016-03-05T18:57:25.920004 #18403] INFO -- : It's great log!次にlogrotateでログファイルをローテーションします。
$ sudo logrotate -f /etc/logrotate.d/sample再度書き込んでみます。
logger.info "Where is rotated log?"空っぽです。
$ cat sample.log 最初に開いたファイル（ローテーションされてsample.log-20160305になった）に書き込まれています。
$ cat sample.log-20160305
I, [2016-03-05T18:57:25.920004 #18403] INFO -- : It's great log!
I, [2016-03-05T18:58:16.273417 #18403] INFO -- : Where is rotated log?ファイルをオープンしてからファイルがリネームされたので、当然と言えば当然です。
単純にファイルを再オープンしたいだけなら、RubyのFileクラスでは、File#reopenでファイルを開き直すことができます。
Loggerが保持しているログファイルを再オープンするにはどうすれば良いのでしょうか？
方法は2つあります。
ひとつはObjectSpaceのFileオブジェクトを全て再オープンする方法で、この方法はUnicornで採用されています。
もうひとつの方法はLoggerを継承するなどしてlogdevアクセサを追加し、logdev.devに格納されているFileオブジェクトを無理やり再オープンする方法です。
以下のopen_or_reopenはファイルの存在チェックをして、存在しない場合はopenし、存在する場合はreopenするものと思ってください。
ObjectSpace.each_object(File) { |f| f.open_or_reopen if is_log?(f) } すべてのFileオブジェクトを取得するので、ログファイルであることを確認する必要があります。
class MyLogger < Logger
attr_reader :logdev
end
logger = MyLogger.new "sample.log"
logger.logdev.dev.open_or_reopen Ruby 2.3.0 以上の場合はLogDevice#reopenが使えます。
ログファイルを再オープンする方法はわかりましたが、アプリケーションにlogrotateによるローテーションを通知しなければならないという課題がまだ残っています。
実はlogrotateにはlastaction/endscriptというディレクティブがあり、すべてのログファイルがローテーションされた後に実行されるコマンドを記述することができます。
つまり、lastaction/endscriptディレクティブでアプリケーションプロセスに対してシグナルを送り、アプリケーション側ではシグナルを受け取ったらログファイルを再オープンすれば良いというわけです。
下記はSIGUSR1をtrapしてログファイルを再オープンするサンプルプログラムsample_daemon.rbです。
これをアプリケーションに見立てて動作を見ていきましょう。このプログラムは5秒毎に現在時刻をログファイルに書き出します。
require 'logger'
File.open("sample_daemon.pid", "w") { |f| f.write "#{Process.pid}" }
class MyApp
def self.logger
@@logger ||= Class.new(Logger) { attr_reader :logdev }.new "sample.log"
end
end
trap("USR1") do
logger = MyApp.logger
logger.logdev.dev.reopen logger.logdev.filename
end
loop do
MyApp.logger.info "#{Time.now}"
sleep 5
end 次に、/etc/logrotate.d/sampleに下記のようにlastaction/endscriptディレクティブを追加します。
/home/vagrant/sample.log {
missingok
daily
dateext
create 0755 vagrant vagrant
rotate 5
lastaction
pid=$(cat /home/vagrant/sample_daemon.pid)
test -d /proc/${pid} && kill -USR1 $pid
endscript
} これで準備完了です。sample_daemon.rbを実行しlogrotateを実行します。
# アプリケーションの実行
$ ruby sample_daemon.rb
# (別タブで)logrotateでローテーションを実行
$ sudo logrotate -f /etc/logrotate.d/sample sample.log-20160305とsample.log を見てみましょう。
ローテーション後はsample.logにログが書き出されているのがわかります。
$ cat sample.log-20160305
I, [2016-03-05T22:01:17.052339 #18596] INFO -- : 2016-03-05 22:01:17 +0900
I, [2016-03-05T22:01:22.054765 #18596] INFO -- : 2016-03-05 22:01:22 +0900
I, [2016-03-05T22:01:27.055418 #18596] INFO -- : 2016-03-05 22:01:27 +0900
$ cat sample.log
I, [2016-03-05T22:01:32.057495 #18596] INFO -- : 2016-03-05 22:01:32 +0900
I, [2016-03-05T22:01:37.058164 #18596] INFO -- : 2016-03-05 22:01:37 +0900
I, [2016-03-05T22:01:42.058839 #18596] INFO -- : 2016-03-05 22:01:42 +0900 ちなみに、UnicornやNginxも、SIGUSR1が送られるとログファイルを再オープンするように作られているようです。
以上です。
このエントリでは、logrotateによってログファイルがローテーションされたとき、アプリケーションに通知してログファイルを再オープンする方法を、Rubyのコードを例に説明しました。
コメントを送る
コメントはブログオーナーのみ閲覧できます