Rails5とpumaを使ったときのlogrotateでハマった話 - まーぽんって誰がつけたの？

現象

f:id:masato47744:20171110000311p:plain

普通Railsのアクセスログってproduction.logに出力されますが、出力されないことがあったという怪談の話です。

対応を1行でまとめると、Puma使うときはRails5からはRAILS_LOG_TO_STDOUTを設定しようということです。

👇 ここからは怪談の詳細です

原因1: logrotateの後処理の実行タイミングが悪かった

開発環境で確認してみたところ、logがログローテートされたあとファイル名の後ろにyyyy-mm-ddが付与されますが、そのファイルに対して引きつづきログが出力されつづけていたのです🙀

で、既存のログローテートでこんな設定が書いてありました。

lastaction
    puma_pid=/path/to/puma.pid
    test -s $puma_pid && /usr/bin/kill -HUP -U root "$(cat $puma_pid)" > /dev/null 2>&1 || :
endscript

ざっくり言うと、lastactionなのでgzに圧縮されたタイミングで、pumaのプロセスにSIGHUPシグナルを送るという処理が行われてます。

logrotateスクリプトの調査これを参考にするとlastactionはgzに圧縮されたタイミングなので、こういうことになっていたんでしょう。

今回はpostrotateが適切と考えたので変更しました。

-    lastaction
+    sharedscripts
+    postrotate

原因2: pumaとシグナルの関係

さっきのlastactionでHUPのシグナルを送っています。このシグナルはpumaにとってどんなことを意味するんでしょうか。 signals.md | puma/pumaを見ると、

HUP reopen log files defined in stdout_redirect configuration parameter

stdout_redirect設定したファイルに対してログファイルをreopenしますと書いてあります。

なんかよくわからないけどログをreopenしてくれるんだろう☺️ めでたしめでたしと思って手動でkillコマンドでHUPを送るもreopenされない・・・

よくよく調べてみると、pumaのstdout_redirectの設定はcapistrano-pumaのデフォルトを使ってるんですが、対象はpuma_access.logでした。なので、HUPを送ってもrailsのlogではなくpuma_access.logをreopenするだけなのです😢

logrotate後にRailsのlogの場所が分からなくなったpuma君がRailsのログを書き込めなくなってたということでした。

Rails5 + pumaの組み合わせでは`RAILS_LOG_TO_STDOUT`と`stdout_redirect`を使おう

RAILS_LOG_TO_STDOUTなしの場合、workerプロセスのloggerがそれぞれproduction.logをつかみます。 pumaにworkerのloggerの出力先を書き換える機能がないのでUSR2 or USR1シグナルでworkerをまるごと再起動しないと、古いログファイルを掴んだままになります。

pumaのstdout_redirectでproduction.logを指定しているとき、workerの標準出力の向き先がproduction.logになります。 RAILS_LOG_TO_STDOUTを設定しておくと、loggerは標準出力にログを出力するので、標準出力の向き先のproduction.logにログが出力されます。 HUPシグナルを送ると、この標準出力の向き先だけが書き換わります。workerをまるごと再起動する必要はありません。

実際の設定方法

PumaとRails5で特に何も設定しないと、Railsのloggerは直接log/production.logを開くようになってます。以下の設定をすることで変更することができます。

RailsでRAILS_LOG_TO_STDOUTの設定

環境変数RAILS_LOG_TO_STDOUTを指定するとログをSTDOUTに吐くようになります。

  if ENV["RAILS_LOG_TO_STDOUT"].present?
    logger           = ActiveSupport::Logger.new(STDOUT)
    logger.formatter = config.log_formatter
    config.logger = ActiveSupport::TaggedLogging.new(logger)
  end