Ruby
Rails
Sinatra

Rubyでのログローテーション

tl;dr

RubyのLoggerクラスのログローテーションの実装を調べた勉強メモです。

仕様

RubyのLoggerクラスはログローテーションの機能が入っています。
Rubyist Magazine - 標準添付ライブラリ紹介 【第 2 回】 Logger が参考になります。

例えば

Logger.new('foo.log', 'daily') 

と呼び出せば、日毎にローテーションします。

実装の概説

疑問

ログローテーションの実装で気になるのは

  • ログをローテーションするトリガー
  • ローテーションの書き込みロック

の二点です。

Loggerの実装

  • 毎書き込み毎にローテーションするかのチェック
  • ローテーション中に他のスレッドから書き込みされないように、Synchronizationで保護
  • 他プロセスからの書き込みはOSのファイルロックで保護

処理の流れ

実際の順序は多少入れ替わっています。

  1. ログの書き込みAPIはSynchronizationを使って、マルチスレッドの衝突を回避している
  2. 書き込む直前に、ローテーション対象か判定する
  3. ローテーションが必要な場合は
    1. ファイルのロックを取得する(Windowsの場合は違う。何もしていない?)
    2. ファイルをリネームする
    3. 新しいログファイルを作る
  4. ログを書き込む

実装の詳細

ソースコードを見ながら参照

Synchronization

https://github.com/ruby/ruby/blob/f2aa7f409aa2130888ceed21d128523e4392084a/lib/logger.rb#L686

def write(message)
  begin
    synchronize do
      if @shift_age and @dev.respond_to?(:stat)
        begin
          check_shift_log
        rescue
          warn("log shifting failed. #{$!}")
        end
      end
      begin
        @dev.write(message)
      rescue
        warn("log writing failed. #{$!}")
      end
    end
  rescue Exception => ignored
    warn("log writing failed. #{ignored}")
  end
end

writeの先頭でsynchronizeして、次にcheck_shift_logします。

ローテーションする?

https://github.com/ruby/ruby/blob/f2aa7f409aa2130888ceed21d128523e4392084a/lib/logger.rb#L773

def check_shift_log
  if @shift_age.is_a?(Integer)
    # Note: always returns false if '0'.
    if @filename && (@shift_age > 0) && (@dev.stat.size > @shift_size)
      lock_shift_log { shift_log_age }
    end
  else
    now = Time.now
    if now >= @next_rotate_time
      @next_rotate_time = next_rotate_time(now, @shift_age)
      lock_shift_log { shift_log_period(previous_period_end(now, @shift_age)) }
    end
  end
end

@shift_ageが数値であれば、サイズでチェック、そうでなければ日付でチェックします。

ローテーション

ファイルロック

https://github.com/ruby/ruby/blob/f2aa7f409aa2130888ceed21d128523e4392084a/lib/logger.rb#L788

if /mswin|mingw/ =~ RUBY_PLATFORM
  def lock_shift_log
    yield
  end
else
  def lock_shift_log
    retry_limit = 8
    retry_sleep = 0.1
    begin
      File.open(@filename, File::WRONLY | File::APPEND) do |lock|
        lock.flock(File::LOCK_EX) # inter-process locking. will be unlocked at closing file
        if File.identical?(@filename, lock) and File.identical?(lock, @dev)
          yield # log shifting
        else
          # log shifted by another process (i-node before locking and i-node after locking are different)
          @dev.close rescue nil
          @dev = open_logfile(@filename)
          @dev.sync = true
        end
      end
    rescue Errno::ENOENT
      # @filename file would not exist right after #rename and before #create_logfile
      if retry_limit <= 0
        warn("log rotation inter-process lock failed. #{$!}")
      else
        sleep retry_sleep
        retry_limit -= 1
        retry_sleep *= 2
        retry
      end
    end
  rescue
    warn("log rotation inter-process lock failed. #{$!}")
  end
end

mswin|mingw、つまりWindowsでは何もしません。
そうでなければlock.flock(File::LOCK_EX)で排他ロックします。
他プロセスからの読み書きを禁止します。

ファイルリネーム

https://github.com/ruby/ruby/blob/f2aa7f409aa2130888ceed21d128523e4392084a/lib/logger.rb#L824

def shift_log_age
  (@shift_age-3).downto(0) do |i|
    if FileTest.exist?("#{@filename}.#{i}")
      File.rename("#{@filename}.#{i}", "#{@filename}.#{i+1}")
    end
  end
  @dev.close rescue nil
  File.rename("#{@filename}", "#{@filename}.0")
  @dev = create_logfile(@filename)
  return true
end

@shift_ageの数だけログを残すために、***.n ファイルの n をひとつずつ増やして行きます。
その後、現在のログファイルのファイル名の末尾に、.0を追加します。

新しいログファイルを作る

https://github.com/ruby/ruby/blob/f2aa7f409aa2130888ceed21d128523e4392084a/lib/logger.rb#L752

def create_logfile(filename)
  begin
    logdev = File.open(filename, (File::WRONLY | File::APPEND | File::CREAT | File::EXCL))
    logdev.flock(File::LOCK_EX)
    logdev.sync = true
    add_log_header(logdev)
    logdev.flock(File::LOCK_UN)
  rescue Errno::EEXIST
    # file is created by another process
    logdev = open_logfile(filename)
    logdev.sync = true
  end
  logdev
end

File.openでログファイルを作って、ヘッダーを書き込んで、作ったファイルオブジェクトを返します。

ログを書き込む

writeメソッドに戻って、@dev.write(message)します。

Loggerの使われ方

多くのWebアプリケーションフレームワークはLoggerインスタンスを受け取ります。Ruby共通のログローテーションの仕組みが使えます。

Ruby on Rails

Ruby on Railsで使われているActiveSupport::Loggerは、RubyのLoggerクラスを継承しています。

Rack

RackのRack::CommonLogger

logger can be any class, including the standard library Logger, and is expected to have either write or << method

とあり、writeメソッドか<<メソッドを持っているクラスはなんでも指定できます。Loggerクラス(writeメソッドを持っている)か、IOクラス(<<を持っている)を想定していそうです。

実際の実装はこんな感じです。

if logger.respond_to?(:write)
  logger.write(msg)
else
  logger << msg
end