アルパカログ

Webエンジニア兼マネージャーがプログラミングやマネジメント、読んだ本のまとめを中心に書いてます。

logrotate ローテーションされたログファイルを再オープンする(Ruby)

f:id:otoyo0122:20200919144807p:plain:w300

サーバーの様々なログを、日付などでローテーションしてくれるlogrotateはよく使われます。

しかし、ログファイルを開きっぱなしにするサーバーアプリケーションなどでは、logrotateがログファイルをローテーションしても、ずっと元のログファイルに書き込み続けてしまうということがあります。

このことを知らないと、logrotateによってログが消えてしまったように錯覚してしまいます。

このエントリでは、logrotateによってログファイルがローテーションされたとき、アプリケーションに通知してログファイルを再オープンする方法を、Rubyのコードを例に説明します。

logrotateの挙動

logrotateの挙動は、現在のファイルをリネームし元のファイルと同名のファイルを作成するというものです。

例えばsample.logというログファイルをローテーションすると、sample.logsample.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ので観察してみます。

$ pry

loggerを使ってログを書き込みます。

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つあります。

ひとつはObjectSpaceFileオブジェクトを全て再オープンする方法で、この方法はUnicornで採用されています。

もうひとつの方法はLoggerを継承するなどしてlogdevアクセサを追加し、logdev.devに格納されているFileオブジェクトを無理やり再オープンする方法です。

以下のopen_or_reopenはファイルの存在チェックをして、存在しない場合はopenし、存在する場合はreopenするものと思ってください。

方法1. ObjectSpaceを使う方法

ObjectSpace.each_object(File) { |f| f.open_or_reopen if is_log?(f) }

すべてのFileオブジェクトを取得するので、ログファイルであることを確認する必要があります。

方法2. logdevアクセサを使う方法

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-20160305sample.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のコードを例に説明しました。

参考になった方は、ぜひ「はてブ」やSNSでシェアしていただけると嬉しいです。

参考サイト