Rails6系でログが正しく出てこなくなったときの対応

TL;DR

puma 5.2.0と5.2.1で、Rubyの標準出力がバッファリングされるようになってしまうというバグが埋め込まれた。
根本的に回避するためにはpumaのバージョンを変えるのが良い。
(他にも$stdout.syncを書き換える等でも解決できるが、バージョンを変えてしまうのが一番手っ取り早い)

Puma 5.2 log not flushed · Issue #2545 · puma/puma · GitHub

はじめに

最近作ったRailsアプリで、ログが出てこなくなって困りました。
少し調べてみると、ログが一定量以上溜まってから出るようになっていることがわかりました。

挙動から入出力ストリームのバッファリングらへんであることまではわかりましたが、原因と解決策を見つけるのが大変だったので、備忘を兼ねて書き留めておきます。

事象

Puma starting in single mode...
(中略)
Use Ctrl-C to stop

のようなログが出た後、Railsから(一見)ログが出なくなる。
何度もリロードを繰り返す等で、一定行数以上のログが貯まると全て出力される。

発生条件

pumaのバージョンが5.2.0か5.2.1で、かつpryのgemを使っていない場合。 また、OSにも依存しているかもしれず、自分の場合はRailsをDocker上で動かしていて、dockerのttyをtrueにしていなかった。

(他にも別のgemとの兼ね合いで、発生したりしなかったりすると考えられる)

原因

Puma 5.2 log not flushed · Issue #2545 · puma/puma · GitHub

pumaのバグで、従来$stdout.sync == trueであったものが、$stdout.sync == falseになってしまった。
デフォルトではrubyは標準出力をバッファリングする設定で、その設定が残っているため、出力がバッファリングされる。

OSでの入出力ストリームの設定にもよるが、ログが1行ずつ出ない場合がある。

解決策

pumaのバージョンを変えてしまうのが良い。

本質的な解決ではないが、pryをインストールしたり、コードの最初に$stdout.sync = true等を書き加える等でも解決できる。

おわりに

グローバル変数周りのバグで、原因特定がとても大変でした。
特に、pumaのバージョンが同じでも、pryと共存している場合は再現しないので、当初はpumaのバージョンを疑うことができませんでした。

グローバル変数は相当慎重に使わないと、原因の特定しにくいバグになることを実感しました。(この例では、グローバル変数を使わざるを得ないときなのでしょうが……)

グローバル変数には、気をつけよう！