読者です 読者をやめる 読者になる 読者になる

アルパカログ

まじめなことを書きます。

logrotate されたログファイルを reopen する

あるデーモンプロセスのログが消えていることに気付きました。
厳密には、 restart した日はログがあるのに、日付が変わってからのログが空っぽなのです。
ログが消えるのは開発者にとって悪夢です。折しも障害発生なんてことがあれば…恐ろしくて想像したくないですね。
今日はデーモンプログラムのログを logrotate によりローテーションさせたときに発生する問題とその解決策についてお話ししたいと思います。

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 のようなファイルが見つかるでしょう。

logrotate されると logger はどこに書き込むか

話を戻して、デーモンプロセス内の logger が sample.log を開いている状態で logrotate するとどうなるのでしょうか?

Ruby の pry を使って観察してみましょう。

$ gem install pry
$ 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

元のファイルに書き込まれていました。

$ 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?

ログファイルを open してからリネームされたので当然と言えば当然ですね。

どうやってログファイルを reopen するか

File だと File#reopen でファイルを開き直すことができますが、 Logger の場合はどうすれば良いのでしょうか?

方法は2つあります。
1つは ObjectSpaceFile オブジェクトを片っ端から reopen する方法で、 Unicorn で採用されています (*1)。 もう1つは Logger を継承するなどして logdev アクセサを追加し、 logdev.dev に格納されている File オブジェクトに対し reopen する方法で、私が考えました (どうでもいい)。
open_or_reopen はファイルの存在チェックをして存在しない場合は open, 存在する場合は reopen と読み替えてください。

ObjectSpace を使う方法

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

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

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 (*2) が使えます。

デーモンに logrotate を通知するには

ログファイルを reopen する方法はわかりましたが、デーモンとして実行中のプロセスに logrotate されたことを通知するにはどうすれば良いのでしょうか?

logrotate には lastaction/endscript というディレクティブがあり、すべてのログファイルがローテーションされた後に実行されるコマンドを記述することができます。
つまり lastaction/endscript ディレクティブでデーモンプロセスに対してシグナルを送り、デーモン側ではシグナルを受け取ったらログファイルを reopen すれば良いというわけです。

SIGUSR1 を trap してログファイルを reopen する下記のようなプログラム 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
}

これで準備完了です。
daemon_sample.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 はどうしているのでしょうか?
実は Unicorn も Nginx も SIGUSR1 が送られるとログファイルを reopen するように作られているのです。

おわりに

この問題に直面したとき、logrotate の挙動や open しているファイルがリネームされるとどうなるかということを知らなかったので、「数日前のログは出ているが、出ているはずの今日のログがない」という現象の原因についてまったく見当もつきませんでした。
周囲のアドバイスがなければ原因究明できなかったでしょう。
助けてくださった方々に感謝し、なんとか解決まで持っていくことができたため記録しておきます。

参考文献

お詫びと訂正

  • 「どうやってログファイルを reopen するか」の項で、存在しないファイルを reopen した場合にエラーとなるため修正しました。