安全なログローテーション

ログローテーションの落とし穴

Rails でのデフォルトのロガーは、Ruby 標準添付の Logger クラスを少し変えたものである。ログのサイズが大きくなったとき、サイズやら日付やらを基準にログのアーカイブ化を行う(ログローテーション)することが多い。一番簡単な方法は

Developmentモードのログを日毎にローテートする

みたいなやり方だ。しかし、複数の Ruby インスタンスがひとつのログファイルを共有すると、うまく動かないのだ。典型的なのは Mongrel Cluster で複数の Rails インスタンスを運用している状況だ。ログローテーションが起こった直後から、"Status: 500 Internal Server Error" というエラーメッセージを吐いて Rails アプリが動かなくなってしまう。

これは、Logger がローテーション時に、

  1. 現行のログファイルをアーカイブログファイルにリネームし、((例) development.log => development.log.20071007)
  2. 現行のログファイル名と同名のファイル名を新たに作成する ((例) development.log を新規作成)

という手順を実行しているからである。複数の Ruby インスタンスのひとつ(プロセスAと呼ぼう)が何らかの基準に基づいて、ログローテーションを行った後でも、他の Ruby インスタンス(プロセスBと呼ぼう)は、古いログファイル(上の例ではリネームされた development.log.20071007) を現行のログファイルと認識している。プロセスAがログローテーションを行ったにもかかわらず、プロセスB は自分へのログ書き込み指令の際に、さらにもういちどログローテーションを行おうとする。しかし、すでにリネームされたアーカイブ用のログファイルが存在するのでエラーとなるのだ。

パッチ

上の問題を解決するために下のようなパッチを書いてみた。Rails では、とりあえず config/environment.rb の末尾に配置すればよい。(Rails は必須ではなく、Ruby 単体からもこのパッチは利用できる)

# 複数の Ruby インスタンスがひとつのログファイルを共有している状況で、
# 安全にログローテーションを実現する。
require 'fileutils'

class Logger::LogDevice

  def shift_log_age_with_safe_log_rotation
    (@shift_age-3).downto(0) do |i|
      if FileTest.exist?("#{@filename}.#{i}")
        File.rename("#{@filename}.#{i}", "#{@filename}.#{i+1}")
      end
    end
    FileUtils.cp("#{@filename}", "#{@filename}.0")
    File.truncate @filename, 0
    add_log_header(@dev)
    return true
  end

  def shift_log_period_with_safe_log_rotation(now)
    postfix = previous_period_end(now).strftime("%Y%m%d") # YYYYMMDD
    age_file = "#{@filename}.#{postfix}"
    if FileTest.exist?(age_file)
      raise RuntimeError.new("'#{ age_file }' already exists.")
    end
    FileUtils.cp("#{@filename}", age_file)
    File.truncate @filename, 0
    add_log_header(@dev)
    return true
  end

  alias_method :shift_log_age_without_safe_log_rotation, :shift_log_age
  alias_method :shift_log_age, :shift_log_age_with_safe_log_rotation

  alias_method :shift_log_period_without_safe_log_rotation, :shift_log_period
  alias_method :shift_log_period, :shift_log_period_with_safe_log_rotation
end

要するに

  1. 現行のログファイルをアーカイブログファイルにコピーし、(≒ cp development.log development.log.20071007)
  2. 現行のログファイルのファイルサイズを0にする。 (≒ cat < /dev/null > development.log)

としているだけである。現行のログファイルの実体が変更されないため、複数 Ruby インスタンスに共有されても誤動作しないはずである。

追記

コメント欄を見ていただければわかるように、なんだかこの Logger は普通の write でさえきちんと排他制御していないのではないかという気がしてきた。すると「安全なログローテーション」というタイトルに偽りあり、という気もしてきたが・・・。このエントリの趣旨としては、とりあえずログローテーションがきっかけで Rails がハングアップしてしまうことはなくなるよ、という程度のことでしかないことをご了承ねがいたい。

ほんと、write は大丈夫なのかな??

追記2

実は mongrel cluster でサーバを走らせながら、rake タスクを cron に登録して早朝にバッチ処理をするというアプリケーションを走らせているのだが、この構成で上のコードを使ったところ、なぜかうまくいかない・・・(涙目) おそらくは、初期化の順序の問題だとおもうのだが・・・。あまりにも微妙すぎるので、私は上の解決策を使うのをあきらめた・・・。とほほ。