chrono_logger gem の紹介しつつ Rails アプリのロギングを振り返る

皆さん最近はどうやって Rails アプリのログローテーションをしているでしょうか？
外部ツールを使うなら `logrotate` や `cronolog`、ruby だけで対応するなら標準ライブラリの Logger(以下 `::Logger` と表記)でしょうか。

私は最近自分のプロジェクトでの運用に適した、[`chrono_logger`](https://github.com/ma2gedev/chrono_logger) という gem を作りました。
この記事では Rails のログローテーションを、これまでどうやって行ってきたのか、それらの何を解決するために `chrono_logger` を作ったのか記載します。

## 前提

ログローテーションは日単位で行っていて、ローテーションしたログファイルを圧縮してバックアップしています。


## ::Logger + logrotate

1年半前くらいまでは、 `::Logger` と `logrotate` を使っていました。
2年半以上前ですが、当時 web 検索してみてもほとんどは `logrotate` で、これ以外のケースはあまり見当たなかったように思います。
大抵のケースではこれでも良さそうですが、自分のプロジェクトではマッチしない点がありました。
それは `logrotate` を `copytruncate` するときのログ喪失です。
`logrotate` の `copytruncate` オプションは rails の再起動が不要な代わりに、copy して seek するまでの間のログが失われてしまいます。
この点がログが消えて欲しくない要件と合わずに、`logrotate` の `copytruncate` は使わないようになりました。

追記: twitter で @yteraoka さんからコメントもらいましたが、その他のデメリットとして disk io もあるそうです。巨大なログデータだったりするとってことですね。

<blockquote class="twitter-tweet" data-cards="hidden" lang="ja"><p>copytruncate 極悪な理由にもう一つ disk io がある / “chrono_logger gem の紹介しつつ Rails アプリのロギングを振り返る - Qiita” <a href="http://t.co/50mnwdleUD">http://t.co/50mnwdleUD</a></p>&mdash; yteraoka (@yteraoka) <a href="https://twitter.com/yteraoka/status/570760541699854337">2015, 2月 26</a></blockquote>
<script async src="//platform.twitter.com/widgets.js" charset="utf-8"></script>

また毎日0時に再起動するのは避けたかったため、再起動の方法は検討しませんでした。
そこで次に使われることになったのが `cronolog` でした。


## ruby stdlib Logger + cronolog

1年半前くらいから今も使っています。
前述の `logrotate` を使うことができなくなり、代わりとして `cronolog` を採用しました。
`::Logger` に pipe として起動した `cronolog` を渡すだけです。簡単ですね。

```ruby
# cronolog installed in /usr/sbin/

# in config/environments/{development,production}.rb
config.logger = Logger.new(IO.popen("/usr/sbin/cronolog #{config.paths['log'].first}.%Y%m%d", "w"))
```

`cronolog` の特徴としては、ログローテーションというよりは単に現在時間を元にしたファイルパスに対して書き込みをするだけなところです。
例えば 2015/2/12 のログ書き込みは、`logfile.150212` というファイル名のログファイルに書き込まれます。

この動作のメリットとしては、該当日にログ書き込みがあれば、必ず日付の含まれたファイル名がついたログファイルが存在することです。
例えば、`::Logger` は日付が変わった後に書き込みが行われないと、ファイルローテーションがされません。

```ruby
# 2015/02/01
logger = Logger.new('logfile', 'daily')
# => logfile is generated
logger.info 'today'

# 2015/02/02
logger.info 'next day'
# => logfile.20150201 is generated
```

これは例えば日付が変わったタイミングでファイルをバックアップしたいなどの要求と相性が悪いです。
その点 `cronolog` はファイルがあることが保証されているので、こういった要件にマッチします。

```ruby
# 2015/02/01
logger = Logger.new(IO.popen("/usr/sbin/cronolog logfile.%Y%m%d", "w"))
logger.info 'today'
# => logfile.20150201 is generated

# 2015/02/02
logger.info 'next day'
# => logfile.20150202 is generated
```

要件にマッチした `cronolog` ですが、以下のデメリットもありました。
- 別途 `cronolog` をインストールする必要がある
- pipe buf を超える書き込み時にログが混ざる(頻度は極稀です)
- 公式サイトのドメイン切れている。。。

## chrono_logger

これまでの要件をまとめると、以下の通りです。

- ログ喪失したくない
- 時間ベースのファイルパスへ書き込む
- 別途ミドルウェアの準備が不要

これらの要件を満たすため作ったのが `chrono_logger` になります。
Rails プロジェクトでの使い方は以下のようにすればよいです。`::Logger` と IF は一緒なので、今現在 `::Logger` を使っているのであれば、設定だけ行えば後は特にすることはありません。
とても簡単です。

```ruby
# in Gemfile

gem 'chrono_logger'


# in config/environments/{development,production}.rb

config.logger = ChronoLogger.new("#{config.paths['log'].first}.%Y%m%d")
```

またデメリットの克服以外にも、[こちらの記事](https://coderwall.com/p/vjjszq/chronologger-logging-is-1-5x-faster-than-ruby-s-stdlib-logger)で記載したような lock free の実装を行うことによるちょっとした高速化なども入れています(lock free について詳しくは記事を参照)。
メリットもないと変更の提案も通らないというのもあるので... :smile: 
現在まだ使い始めたばかりですが、今のところ大きな問題は起こっていないです。
もし `chrono_logger` 気になる方は[こちら](https://github.com/ma2gedev/chrono_logger)をチェックしてみてください。

## 追記: ヒアリングした結果

Asakusa.rb でヒアリングしたところ以下のような感じでした。`logrotate` 使っている方が多かったです。

- そもそも人がいない時間帯に rotation しているし、そこまでシビアに気にしていない
- copytruncate ではなく再起動 or log file の reopen している(Unicorn の USR1)
- 本当に重要なものは fluentd で他に流している


## まとめ

ということで簡単に自分の Rails プロジェクトでのログ運用について紹介してみました。
皆さんのプロジェクトではどのようにしていますか？
もし良かったら皆さんのログ運用についても教えていただけると嬉しいです。


## resources

- logrotation
  - [Ruby on Rails production log rotation](http://stackoverflow.com/questions/4883891/ruby-on-rails-production-log-rotation)
- logrotate
  - [logrotateでログのローテーションをする](http://d.hatena.ne.jp/willnet/20081001/1222836601)
  - 最後の方に copytruncate 周りの話がある [log rotation まわりの話](http://blog.1q77.com/2013/02/log-rotation-%E3%81%BE%E3%82%8F%E3%82%8A%E3%81%AE%E8%A9%B1/)
- cronolog
  - 公式はドメイン切れなので載せません
  - [Log rotation in Ruby on Rails applications](http://blogs.helion-prime.com/2009/11/19/log-rotation-in-ruby-on-rails-applications.html)
- chrono_logger 
  - [ChronoLogger logging is 1.5x faster than ruby's stdlib Logger](https://coderwall.com/p/vjjszq/chronologger-logging-is-1-5x-faster-than-ruby-s-stdlib-logger)
  - [github](https://github.com/ma2gedev/chrono_logger)
  - [rubygems.org](https://rubygems.org/gems/chrono_logger)