まーぽんって誰がつけたの?

iOS→Scala→インフラなおじさん技術メモ

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_STDOUTstdout_redirectを使おう

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

pumaのstdout_redirectproduction.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

pumaを使って標準出力をファイルに書き出すstdout_redirectの設定

pumaの場合stdout_redirectオプションを使うとworkerの標準出力を指定したファイルに向けます。

まとめ

なんとなく誰かがいい感じに設定してくれていたlogrotate。 きっとうまくいってると思って見過ごしてたけど奥が深いなと感じました。