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

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

私は最近自分のプロジェクトでの運用に適した、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 もあるそうです。巨大なログデータだったりするとってことですね。

copytruncate 極悪な理由にもう一つ disk io がある / “chrono_logger gem の紹介しつつ Rails アプリのロギングを振り返る - Qiita” http://t.co/50mnwdleUD

— yteraoka (@yteraoka) 2015, 2月 26

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

ruby stdlib Logger + cronolog

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

# 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 は日付が変わった後に書き込みが行われないと、ファイルローテーションがされません。

# 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 はファイルがあることが保証されているので、こういった要件にマッチします。

# 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 を使っているのであれば、設定だけ行えば後は特にすることはありません。
とても簡単です。

# in Gemfile

gem 'chrono_logger'


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

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

またデメリットの克服以外にも、こちらの記事で記載したような lock free の実装を行うことによるちょっとした高速化なども入れています(lock free について詳しくは記事を参照)。
メリットもないと変更の提案も通らないというのもあるので...
現在まだ使い始めたばかりですが、今のところ大きな問題は起こっていないです。
もし chrono_logger 気になる方はこちらをチェックしてみてください。

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

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

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

まとめ

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

resources

• logrotation
  • Ruby on Rails production log rotation
• logrotate
  • logrotateでログのローテーションをする
  • 最後の方に copytruncate 周りの話がある log rotation まわりの話
• cronolog
  • 公式はドメイン切れなので載せません
  • Log rotation in Ruby on Rails applications
• chrono_logger
  • ChronoLogger logging is 1.5x faster than ruby's stdlib Logger
  • github
  • rubygems.org