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

# tl;dr

Rubyの[Logger](http://ruby-doc.org/stdlib-2.5.0/libdoc/logger/rdoc/Logger.html)クラスのログローテーションの実装を調べた勉強メモです。

# 仕様

RubyのLoggerクラスはログローテーションの機能が入っています。
[Rubyist Magazine - 標準添付ライブラリ紹介 【第 2 回】 Logger](http://magazine.rubyist.net/?0008-BundledLibraries) が参考になります。

例えば

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

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

# 実装の概説

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

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

の二点です。

## Loggerの実装

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

## 処理の流れ

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

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

# 実装の詳細

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

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

```rb
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

```rb
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

```rb
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

```rb
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

```rb
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](http://api.rubyonrails.org/classes/ActiveSupport/Logger.html)は、RubyのLoggerクラスを継承しています。


## Rack

Rackの[Rack::CommonLogger](http://www.rubydoc.info/gems/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](http://ruby-doc.org/core-2.5.0/IO.html)クラス（`<<`を持っている）を想定していそうです。

実際の[実装](https://github.com/rack/rack/blob/master/lib/rack/common_logger.rb#L59)はこんな感じです。

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