joppot

コピペで絶対動く。説明を妥協しない

サーバ

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

投稿日:2017年4月3日 更新日:

Pocket


概要

みなさんこんにちは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がインストールされている事が前提になります。

SPONSORED LINK


railsのログフォーマットを変更する

railsのproductionログのフォーマットはデフォルトで下のような感じになっていると思います。

Rails 5のログフォーマットはRails 4と2箇所違うところがあります。

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

[5865421e-16ac-4ced-8a64-8153a981e583]

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

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

F, [2017-04-02T15:30:34.412677 #59749] FATAL — : [ac9e209a-bec…]
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エラーは以下の様に、一行に収まります。

F, [2017-04-02T16:34:38.573875 #60108] FATAL — : [e9287f69-3a2d-47a0-a556-c5789141239d] NoMethodError (undefined method `each’ for nil:NilClass): app/controllers/pages_controller.rb:6:in `about’

エラーログの設定はこれでいいでしょう

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.314646 #5689] INFO — : Rendered users/shared/_links.html.haml (0.5ms)
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のところはこうなっています。

2017-04-02 08:42:04.485309539 +0000 rails.production: {“log_initial”:”F”,”date”:”2017-04-02T08:42:00.564377″,”process_id”:”#11178″,”log_level”:”FATAL”,”request_id”:”44099c89-5e55-49b9-9d1f-0f18308133d6″,”message”:”NoMethodError (undefined method `each’ for nil:NilClass): app/controllers/pages_controller.rb:6:in `about'”}


まとめ

どうでしょうか、うまく取得できたでしょうか。理想的には、railのログフォーマットはできるだけいじらないことがベストだと思います。ただ、FATALエラーメッセージの形式上変更せざるをえませんでした。もしも、今後よりより取得の仕方が出てきたら随時対応していきたいと思います。

スポンサードリンク

「為になったなぁ」と思ったら、シェアお願いします。

-サーバ
-, ,

執筆者:


comment

メールアドレスが公開されることはありません。 * が付いている欄は必須項目です

関連記事

MAMPでphpのshell_execを使用してunixコマンドを実行できない場合の対処(imagemagick,convert)

概要 みなさんこんにちはcandleです。今回はちょっと問題が起きてshell_execがうまくいかないときのトラブルシューティングをまとめます。 私はMAMPをバージョンアップする前は、phpのsh …

pythonのfabricでファイルを分割しfabfileに読み込む方法

概要 皆さんこんにちはcandleです。今回はfabricで分割したpythonファイルを読み込んでみましょう。 fabricはfabfile.pyというファイルに実行したいコマンドを書くのですが、 …

apache2.4でvirtualhost毎に環境変数を定義しphpで使用する方法

English 日本語 概要 みなさんこんにちはcandleです。 今回はapache2.4でバーチャルホスト毎に環境変数を定義して、それをphp側で受け取る方法を紹介します。 例えば、wordpre …

railsのaws-sdk gemを使ってs3のファイルを削除する

by martinak15 概要 みなさんこんにちはcandleです。今回はs3にアップロードされている画像ファイルをrailsのaws-sdk gemを使用して削除してみたいと思います。 記事中で開 …

ruby on railsのbundleのGemfileでインストールしたgemを削除する

概要 みなんさんこんにちはcandleです。今回は間違って入れてしまったり、不必要になったgemの削除のやり方を紹介します。 前提 ruby on railsの環境が整っている gemの概念を理解して …

プロフィール


ベンチャー企業のCTOをやってます。大学時代にプログラミングを始め、javaから入門し、C++へて、PHPへと進み、会社ではRailsを使用。自動化が大好きなプログラマー

スポンサードリンク

アーカイブ