- English
- 日本語
概要
みなさんこんにちはcandleです。
今回はrails 5のproduction ログをtd-agentで取得してみたいと思います。
rails5からログのフォーマットが変更され、多少問題がでてきたので、そこもうまく汲み取って、解説していきます。
関連記事
rails4の方は以下の記事を参考にしてください。
前提
ruby on railsをproductionモードで動かせる
webrickでもnginxでもpumaでもapacheでも良いですが、productionモードで動かせる状態を作っておいてください。
td-agentかfluentdがインストールされている
ruby on railsを動かすマシーンにtd-agentかfluentdがインストールされている事が前提になります。
railsのログフォーマットを変更する
railsのproductionログのフォーマットはデフォルトで下のような感じになっていると思います。
Rails 5のログフォーマットはRails 4と2箇所違うところがあります。
1つは、リクエストIDが追加されたことです。
railsのログは1アクセスでもステータス、どのページ、パラメータは何かなど、複数行のログが出力されます。
リクエストIDは非常に便利で、その1アクセス中は同じリクエストIDが表示されるので、どこからどこまでが同一のアクセスか分かるようになりました。
もう1つは、あまりtd-agentからすると嬉しくないことですが、FATALエラーメッセージの改行が別のログとして出力される様になりました。
F, [2017-04-02T15:30:34.412796 #59749] FATAL — : [ac9e209a-bec…] NoMethodError (undefined method `each’ for nil:NilClass):
F, [2017-04-02T15:30:34.412847 #59749] FATAL — : [ac9e209a-bec…]
F, [2017-04-02T15:30:34.412897 #59749] FATAL — : [ac9e209a-bec…] app/controllers/pages_controller.rb:6:in `about’
実際は1つのエラーにもかかわらず、エラーメッセージの改行ごとに、別のエラーとしてログに記述されます。
例えば、td-agentとslackを連携させ、FATALエラーを通知する様にした場合、実際は1つのエラーにもかかわらず、改行ごとに通知が届いてしまいます。
Rails4まではFATALは1つでメッセージは改行で表示されていました。
この記事では、エラーログを表示する関数をオーバーライドして、Rails4の様なログの出力に変更します。
もちろん、FATALのエラーメッセージが別々のログとして保存されても良いという方は次の章を飛ばしても問題ありません。
FATALエラーのログフォーマットを変更する
幸いなことに、FATALのメッセージの部分の変更はそこまで難しくありません。
log_error関数をRails4の書き方に変更します。
ついでに改行文字も削除しておくと、fluentd側の処理が楽になるのでそうしてあります。
railsプロジェクトのconfig/environment.rbを開いて、以下を記述します。
module ActionDispatch class DebugExceptions def log_error(request, wrapper) logger = logger(request) return unless logger exception = wrapper.exception trace = wrapper.application_trace trace = wrapper.framework_trace if trace.empty? ActiveSupport::Deprecation.silence do message = "#{exception.class} (#{exception.message}):" message << exception.annoted_source_code.to_s if exception.respond_to?(:annoted_source_code) message << " " << trace.join("\n ") logger.fatal("#{message}") end end end end
一度サーバを再起動して、FATALエラーログがどの様に変わったか確認しましょう。
FATALエラーは以下の様に、一行に収まります。
エラーログの設定はこれでいいでしょう
Viewのログは表示しない
下のコードはデフォルトのログフォーマットから何も変更して無い状態のコードです。
class Logger::Formatter def call(severity, time, progname, msg) format = "%s, [%s #%d] %5s -- %s: %s\n" format % [severity[0], "#{time.strftime('%Y-%m-%dT%H:%M:%S')}.#{'%06d' % time.usec.to_s}", $$, severity, progname, msg2str(msg)] end end
railsのプロダクションログにはviewの情報も表示されます。
この情報はログファイルのサイズを圧迫するだけ無駄なので、ログに残さないようにします。
以下が該当する部分のログになります。
I, [2017-03-24T06:19:15.315840 #5689] INFO — : Rendered users/registrations/new.html.haml within layouts/application (6.6ms)
I, [2017-03-24T06:19:15.318778 #5689] INFO — : Rendered layouts/_header.html.haml (0.6ms)
I, [2017-03-24T06:19:15.320581 #5689] INFO — : Rendered layouts/_footer.html.haml (0.8ms)
この変更はあくまで、viewの情報を表示しないコードなので、変更しなくても問題ありません。
config/environment.rbを開きます。
先ほどのフォーマットを以下の様に変更します。
erbを使っている人は”.haml”の部分を”.erb”に変更してください。
class Logger::Formatter def call(severity, time, progname, msg) if !msg.include?('.haml') format = "%s, [%s #%d] %5s -- %s: %s\n" format % [severity[0], "#{time.strftime('%Y-%m-%dT%H:%M:%S')}.#{'%06d' % time.usec.to_s}", $$, severity, progname, msg2str(msg)] end end end
if文を見ればわかる様に、.hamlが含まれているログを表示しない様にしています。
これでrailsの設定は以上です。
td-agentでrailsログを取得する準備
それでは、td-agent側に移動します。
私はCentOS6.5の中でtd-agentを動かしています。
railsはunicorn + nginxで動かしたいと思います。
それらのサーバー構築はあらかじめお願いします。
td-agentの設定
Rails4の時はFatalエラーが複数行で表示されるため、「format multiline」を使いましたが、
先ほど、error_log関数をオーバーライドし他のでFATAL エラーのメッセージは1文にまとまっています。
なので、td-agentの設定はシンプルになります。
<source> @type tail path /usr/share/nginx/alice5/log/production.log tag rails.production pos_file /var/log/td-agent/rails.production.pos format /^(?<log_initial>.*), \[(?<date>\d{1,4}-\d{1,2}-\d{1,2}T\d{1,2}:\d{1,2}:\d{1,2}.\d{1,6}) (?<process_id>[^ ]*)\] *(?<log_level>[^ ]*) -- : \[(?<request_id>[^ ]*)\] (?<message>[^\']*[^\]]*)/ </source> <match rails.production> @type stdout </match>
pathでrailsプロジェクトのlogフォルダにあるproduction.logを参照します。
参照先のパスは各自のものにしてください。
tag rails.production
で取得したログにタグをつけます。
pos_file /var/log/td-agent/rails.production.pos
一時ファイルの置き場を指定します。
formatはrails5のproduction.logのフォーマットに合わせています。
rails4と違うところはrequest_idが加わっています。
<match rails.production>
で上のログを受け取り、標準出力します。
以上がfluentdがrails logを取得する為の設定です。
ログの取得を確認する
td-agentを再起動します。
sudo serice td-agent restart
本番環境のrailsアプリケーションを起動します。
td-agentの確認は
/var/log/td-agent/td-agent.logに出力されます。
sudo tail -f /var/log/td-agent/td-agent.log
FATALのところはこうなっています。
まとめ
どうでしょうか、うまく取得できたでしょうか。理想的には、railのログフォーマットはできるだけいじらないことがベストだと思います。ただ、FATALエラーメッセージの形式上変更せざるをえませんでした。もしも、今後よりより取得の仕方が出てきたら随時対応していきたいと思います。