td-agentでRails 5のproduction.logを取得する

Tweet

• English
• 日本語

概要

みなさんこんにちはcandleです。
今回はrails 5のproduction ログをtd-agentで取得してみたいと思います。
rails5からログのフォーマットが変更され、多少問題がでてきたので、そこもうまく汲み取って、解説していきます。

関連記事

rails4の方は以下の記事を参考にしてください。

td-agentでRails 4のproduction.logを取得する

前提

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箇所違うところがあります。

１つは、リクエストIDが追加されたことです。

railsのログは１アクセスでもステータス、どのページ、パラメータは何かなど、複数行のログが出力されます。
リクエストIDは非常に便利で、その１アクセス中は同じリクエストIDが表示されるので、どこからどこまでが同一のアクセスか分かるようになりました。

もう１つは、あまりtd-agentからすると嬉しくないことですが、FATALエラーメッセージの改行が別のログとして出力される様になりました。

実際は１つのエラーにもかかわらず、エラーメッセージの改行ごとに、別のエラーとしてログに記述されます。

例えば、td-agentとslackを連携させ、FATALエラーを通知する様にした場合、実際は１つのエラーにもかかわらず、改行ごとに通知が届いてしまいます。

Rails4まではFATALは１つでメッセージは改行で表示されていました。

この記事では、エラーログを表示する関数をオーバーライドして、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の情報も表示されます。
この情報はログファイルのサイズを圧迫するだけ無駄なので、ログに残さないようにします。

以下が該当する部分のログになります。

この変更はあくまで、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 エラーのメッセージは１文にまとまっています。
なので、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エラーメッセージの形式上変更せざるをえませんでした。もしも、今後よりより取得の仕方が出てきたら随時対応していきたいと思います。