notebook

都内でWEB系エンジニアやってます。

railsアプリのログ(複数行)を整理する

なんでもかんでもRailsのLoggerに投げているといろんなログが一つのファイルにまとまってしまって調査、分析が時間がかかったりストレスになっていたので内容によって出力するファイルを分類するようにした時のメモ

集約したログをいったんファイルに保存しそれをtialプラグインでさらに分割していくといった流れにしました

forwardで受け取ったデータをmultilineでパースできるかちょっと調べただけではわからなかったので一手間入れる形になりました

ちなみにパースするログはこんな感じ

ip-10-0-9-112: W, [2017-01-30T13:22:08.270613 #24414]  WARN -- : 403 Forbidden (OpenURI::HTTPError)
ip-10-0-9-112: /usr/share/ruby/2.2/open-uri.rb:358:in `open_http'
ip-10-0-9-112: /usr/share/ruby/2.2/open-uri.rb:736:in `buffer_open'
ip-10-0-9-112: /usr/share/ruby/2.2/open-uri.rb:211:in `block in open

Railsloggerのログ出力

ホスト名,logレベルのprefix,時刻,ログレベル,ログといった順番でログが吐かれているのでそれに応じた正規表現を適用させてあげます

例外エラーなどでの複数行に渡るログだったり、アプリケーションからのログが複数行になったりといったことがあったのでinputはmultilineを使用します

余談ですが、multiline対応に関しては最初embulkでやろうと思ったのですが、なかなかうまく行かず時間だけかかっていました。

fluentdで試してみたところサクッとできてしまったので最初からfluentdを使っておけばよかったです…

公式にも使用例が載っていますが、'format_firstline'で最初の行に当てはまる正規表現を記述します

その後format1,2,3…といった形で必要な分だけformatを記述します

@type tail
format multiline
format_firstline /^ip-\d+-\d+-\d+-\d+: \w, /
format1 /^ip-\d+-\d+-\d+-\d+: (?<prefix>\w), \[(?<timestamp>.*?).\d+ \#\d+\]\s+(?<loglevel>\w+) -- :(?<message>.*)/

今回の場合だと、全ての行でホスト名が出力されているのでホスト名以降で最初の行か判断できるようにログレベルのprefixまでマッチさせました

message以外はある程度分類を分けれる状態のラベルになりました

{"prefix":"W","timestamp":"2017-01-30T11:16:50","loglevel":"WARN","message":" 403 Forbidden (OpenURI::HTTPError)\nip-10-0-9-112: /usr/share/ruby/2.2/open-uri.rb:358:in `open_http'\nip-10-0-9-112: /usr/share/ruby/2.2/open-uri.rb:736:in `buffer_open'\n.....}

ログレベルごとにタグを設定

loglevelラベルの内容を元にタグを分割します

rewrite_tag_filterを使用して正規表現でマッチさせて分類します

type rewrite_tag_filter
rewriterule1 loglevel ^DEBUG$ rails.debug
rewriterule2 loglevel ^INFO$  rails.info
rewriterule3 loglevel ^WARN$  rails.warn
rewriterule4 loglevel ^ERROR$ rails.error
rewriterule5 loglevel ^FATAL$ rails.fatal

Rails側でログレベルをしっかり管理していればここだけでもよさそうです

出力内容ごとにタグを設定

次はさらに踏み込んでmessageの内容ごとにタグを分類します

特定のログだけ別タグにすることが出来るようになります

forestプラグインを使っているのは${tag}プレースホルダを使いたかったため

deprecateが出てたけど今回はこのまま行きます…今度直す…

  @type forest
  subtype rewrite_tag_filter
  <template>
    rewriterule1 message ^\sRule condition is checked:.*$ formatted.${tag}.rule_checked
    rewriterule2 message ^\s\[StatsV1SchedulerJob\] .*$   formatted.${tag}.no_credentials
    rewriterule3 message .* formatted.${tag}.misc
  </template>

タグ名によってファイル名を決定

最後にタグごとにファイルを分割して保存するように設定します

ここでもforestが使われていますがこれもtag_partsのプレースホルダを使うために設定を入れました

<match formatted.**>
  @type forest
  subtype file
  <template>
    path /data/fluentd/parsed/${tag_parts[1]}.${tag_parts[2]}.${tag_parts[3]}.log
  </template>
</match>

実際のファイル

最終的に出来上がった設定が下記になります

<source>
  @type tail
  format multiline
  format_firstline /^ip-\d+-\d+-\d+-\d+: \w, /
  format1 /^ip-\d+-\d+-\d+-\d+: (?<prefix>\w), \[(?<timestamp>.*?).\d+ \#\d+\]\s+(?<loglevel>\w+) -- :(?<message>.*)/
  path /data/fluentd/rails.log
  pos_file /etc/td-agent/raw.pos
  tag raw
</source>

<match raw>
  @type copy
  <store>
    @type file
    path /data/fluentd/parsed/raw2.log
  </store>
  <store>
    @type rewrite_tag_filter
    rewriterule1 loglevel ^DEBUG$ rails.debug
    rewriterule2 loglevel ^INFO$  rails.info
    rewriterule3 loglevel ^WARN$  rails.warn
    rewriterule4 loglevel ^ERROR$ rails.error
    rewriterule5 loglevel ^FATAL$ rails.fatal
  </store>
</match>
<match rails.*>
  @type forest
  subtype rewrite_tag_filter
  <template>
    rewriterule1 message ^\sDEBUG1.*$       formatted.${tag}.debug1
    rewriterule2 message ^\s\[DEBUG2\] .*$  formatted.${tag}.debug2
    rewriterule3 message .*                 formatted.${tag}.misc
  </template>
</match>
<match formatted.**>
  @type forest
  subtype file
  <template>
    path /data/fluentd/parsed/${tag_parts[1]}.${tag_parts[2]}.${tag_parts[3]}.log
  </template>
</match>
  • 実行結果
|-- parsed
|   |-- rails.error.misc.log.20170130.b5474df3d0a934ed4
|   |-- rails.fatal.misc.log.20170130.b5474df54cf1938c3
|   |-- rails.warn.misc.log.20170130.b5474df41e46e4eda

パスやタグ名は掲載用に変えましたがとりあえずログの内容ごとにファイルを分類することが出来ました

特定のログしかないので調査などがはかどりそう?ですね