Rails3.2からログの行が他プロセスのものと混ざるようになった件について

rails

Rails 3.2.0 から、マルチプロセス環境下（Unicornなど）では、 Rails.logger によるロギングが、以下のように複数のリクエスト同士で「混ざる」ようになってしまいました。

Started GET "/search?q=blip" for 0.0.0.0 at 2012-03-12 02:20:18 -0700
Processing by SiteController#search as /
Parameters: {"q"=>"blip"}

Started GET "/search?q=2bxen" for 0.0.0.0 at 2012-03-12 02:20:20 -0700
Processing by SiteController#search as /
Parameters: {"q"=>"2bxen"}
Rendered site/foo.html.erb (0.0ms)
Rendered site/foo.html.erb within layouts/foo (1279.3ms)
Rendered site/foo.html.erb (0.0ms)
Rendered site/foo.html.erb (0.6ms)
Rendered site/foo.html.erb (0.0ms)
Completed 200 OK in 2600ms (Views: 726.5ms | ActiveRecord: 556.8ms)
Rendered site/foo.html.erb (0.0ms)
Rendered site/foo.erb within layouts/foo (366.4ms)
Rendered site/foo.html.erb (0.0ms)
Rendered site/foo.html.erb (0.5ms)
Rendered site/foo.html.erb (0.0ms)
Completed 200 OK in 550ms (Views: 326.6ms | ActiveRecord: 43.3ms)

これではログを見ても意味が分かりませんし、由々しき事態です。

なぜこんなことになっているのか

これは、 BufferedLogger の仕様変更が関連しています。
Rails 3.2 のリリースノートによると、以下のような変更がありました。

  • ActiveSupport::BufferedLogger#auto_flushing が非推奨になった
  • ActiveSupport::BufferedLogger#flush が非推奨になった

これまで、 production 環境ではリクエストの処理が終わったときに Rails.logger は flush （ファイルに書き出す）されていました。そのバッファリングの機能を担っていたのがこの BufferedLogger です。その働きのおかげで、複数のリクエストが同時に来ても、ログが混ざらずに済んでいました。

しかしRails 3.2 のこの変更では、BufferedLogger でのバッファリングは行わないようになり、ログ出力のバッファリングはファイルシステムに任せるという方針に変わりました。
BufferedLogger のコードはまだ一応存在していますが、バッファリング関連のメソッドはすべて削除されています。また、Rails 4.0.0 では BufferedLogger は deprecated になることがアナウンスされています。

困っている人たち vs tenderlove

やはり困ってる人たちがいて、以下の issue には、上記の変更を加えた tenderlove 氏とのやりとりが残されています。
https://github.com/rails/rails/issues/5388

tenderlove氏のコメントを意訳すると、以下のとおりです。

マルチプロセスでログが混ざる可能性はどのバージョンのRailsにもあるよ。（Railsでの）バッファリングはその可能性を減らすことはできるけど、そこにはまだ問題がある。
POSIXでは、書き込みがアトミックに行われることが保証されるのは、出力サイズがPIPE_BUF以下のときだけなんだ。
一つ一つのログを PIPE_BUF 以下にすれば大丈夫だけど、OS依存だしね。 :(

なお、 この PIPE_BUF は Linux では 4KB に設定されています。

ベストじゃない対策

ログのバッファリングをファイルシステムが担うようになったことで、これまでと同じ挙動をさせることができなくなりました。

file.sync = false にする

initializer で以下のようにすることで、Linuxではファイルシステムが4KBまでバッファリングしてくれるようになります。

Rails.logger.instance_variable_get(:@logger).instance_variable_get(:@log_dest).sync = false

一応、このようにすれば、リクエストの処理中にはファイルシステムが出力をバッファリングし、リクエスト終了時に Rails::Rack::Logger が IO#flush を呼んでくれます。
しかしこの対策をやっても、ファイルシステムのバッファは、溜まったら勝手にflushされてしまうので、完璧にアトミックにすることはできません。
とはいえ、一番ましな対策かもしれません。

すべての行にPIDを書くようにするとか

イメージはこんな感じ。

[1234]
[1234] Started GET "/search?q=blip" for 0.0.0.0 at 2012-03-12 02:20:18 -0700
[1234] Processing by SiteController#search as /
[1234] Parameters: {"q"=>"blip"}
[5678]
[5678] Started GET "/search?q=2bxen" for 0.0.0.0 at 2012-03-12 02:20:20 -0700
[5678] Processing by SiteController#search as /
[5678] Parameters: {"q"=>"2bxen"}
[1234]   Rendered site/foo.html.erb (0.0ms)
[1234]   Rendered site/foo.html.erb within layouts/foo (1279.3ms)
[1234]   Rendered site/foo.html.erb (0.0ms)
[1234]   Rendered site/foo.html.erb (0.6ms)
[1234]   Rendered site/foo.html.erb (0.0ms)
[1234] Completed 200 OK in 2600ms (Views: 726.5ms | ActiveRecord: 556.8ms)
[5678]   Rendered site/foo.html.erb (0.0ms)
[5678]   Rendered site/foo.erb within layouts/foo (366.4ms)
[5678]   Rendered site/foo.html.erb (0.0ms)
[5678]   Rendered site/foo.html.erb (0.5ms)
[5678]   Rendered site/foo.html.erb (0.0ms)
[5678] Completed 200 OK in 550ms (Views: 326.6ms | ActiveRecord: 43.3ms)

TaggedLoggingの機能を使うか、Formatterを修正すれば簡単にできそうだけど、なんかすごい抵抗あるこれ…。

もしくはあの頃の BufferedLogger を復活させるとか…

意外と影響範囲がでかいので、古い BufferedLogger を持ってくるだけではだめで、 ActiveSupport::TaggedLogging 、 ActiveSupport::LogSubscriber 、 Rails::Rack::Logger あたりの flush まわりもモンキーパッチしないとだめそう。
この周辺の古いコードをもってきて gem にするというのはアリだと思う。

みんなは困ってないの？

ははーん、さてはみなさんレーィルズ 3.2 以降を使っていない……？

結論

ActiveSupport::BufferedLogger は衰退しました。