fluentdでrailsなどのアプリケーションのログをtailする

fluentdでは、v0.10.45から複数行にまたがるログをparseするための機能 multiline parser が実装されているようです。multiline parserを使えば、railsやその他様々なアプリケーションで複数行にまたがるログを1つのイベントとして扱うことができます。ここでは、in_tailプラグインでformatにmultilineを指定してrailsアプリケーションのログのパースを試してみたいと思います。

tailプラグインでrailsアプリケーションのログをパースして見る

tailプラグインでは、multilineの指定をformatオプションを使って指定します。

format multiline

multiline parser[1]https://github.com/fluent/fluentd/blob/master/lib/fluent/parser.rbでは、formatNとformat_firstlineというオプションを指定することができます。formatNのNは、1〜20の範囲で指定可能となっています。format_firstlineは、複数行のログの開始位置を示す表現を指定することになっています。

公式のドキュメントのRailsアプリケーションのformat例を参照しながら設定を書いて見ると以下のようになりました。長く複雑な正規表現指定となっているので、私のように自信のない方は公式のサンプルを参照しながらカスタマイズした方が良いかもしれません。

<source>
  type tail
  format multiline
  format_firstline /^Started/
  format1 /Started (?<method>[^ ]+) "(?<path>[^"]+)" for (?<host>[^ ]+) at (?<time>[^ ]+ [^ ]+ [^ ]+)\n/
  format2 /Processing by (?<controller>[^\u0023]+)\u0023(?<controller_method>[^ ]+) as (?<format>[^ ]+?)\n/
  format3 /(  Parameters: (?<parameters>[^ ]+)\n)?/
  format4 /  Rendering .+\n/
  format5 /  Rendered (?<template>[^ ]+) within (?<layout>[^ ]+) \([\d\.]+ms\)\n/
  format6 /Completed (?<code>[^ ]+) [^ ]+ in (?<runtime>[\d\.]+)ms \(Views: (?<view_runtime>[\d\.]+)ms \| ActiveRecord: (?<ar_runtime>[\d\.]+)ms\)/
  path /workspace/railsapp/log/development.log
  pos_file /data/tmp/rails.pos
  tag rails.development.log
  read_from_head true
</source>

この設定を送信側のfluentdに加えた上でrailsアプリケーションを起動しアクセスしてみます。この時、development.logに出力されるログは例えば以下のようになります。

Started GET "/hello?hoge=foo" for 127.0.0.1 at 2016-11-04 23:24:10 +0900
Processing by HelloController#index as HTML
  Parameters: {"hoge"=>"foo"}
  Rendering hello/index.erb within layouts/application
  Rendered hello/index.erb within layouts/application (0.3ms)
Completed 200 OK in 13ms (Views: 11.4ms | ActiveRecord: 0.0ms)

送信側で正しくパースされていれば、受信側のfluentdで以下のようなイベントを受信できているのを確認できます。複数行にわたるログを1つのメッセージとして受信できているのがわかります。どうやら上手くいっているようです。

2016-11-04T23:24:10+09:00	rails.development.log	{"method":"GET","path":"/hello?hoge=foo","host":"127.0.0.1","controller":"HelloController","controller_method":"index","format":"HTML","parameters":"{\"hoge\"=>\"foo\"}","template":"hello/index.erb","layout":"layouts/application","code":"200","runtime":"13","view_runtime":"11.4","ar_runtime":"0.0"}

norikraでViewのレンダリングに最も時間のかかったテンプレートを探す

norikra[2]現Treadure Dataの@tagomorisさんが開発されたソフトウェア。http://norikra.github.ioは、ストリームデータをSQLライクな問い合わせ言語で処理することができるソフトウェアです。ストリームデータを一定時間ごとに集計したり、ある閾値を超えるデータをチェックしたりといった処理を馴染みのあるSQLライクに記述することができるので大変便利です。また、スキーマレスでデータを柔軟に扱うことができるといった特徴もあります。

早速、norikraをインストールして試してみます。

rbenv install jruby-9.1.2.0
rbenv shell jruby-9.1.2.0
gem install norikra

続いて起動してみます。

norikra start

無事起動できていれば、Webブラウザでhttp://localhost:26578/にアクセスすると以下のようなWebUIを確認できます。以下の画面では、すでに私がクエリを登録しているのでQueriesにクエリが表示されています。

%e3%82%b9%e3%82%af%e3%83%aa%e3%83%bc%e3%83%b3%e3%82%b7%e3%83%a7%e3%83%83%e3%83%88-2016-11-05-14-28-41

続いてnorikraにクエリを登録します。ここでは、1 minuteごとにViewのレンダリングで15.0 msecを超えるtemplateを抽出し、レンダリングにかかった最大時間と共に取り出すよう設定してみます。

%e3%82%b9%e3%82%af%e3%83%aa%e3%83%bc%e3%83%b3%e3%82%b7%e3%83%a7%e3%83%83%e3%83%88-2016-11-05-14-13-34

fluentdのデータストリームでnorikraとやりとりするように、fluent-plugin-norikra[3]https://github.com/norikra/fluent-plugin-norikraをインストールします。続いて、norikraにイベントを送信し、結果を取り出す設定を追記します。

<match rails.**>
  @type    norikra
  norikra localhost:26571
  target_map_tag    true # tag rails.log -> target rails_log in norikra
</match>

# Gets results from norikra via norikra api
<source>
  @type   norikra
  norikra localhost:26571
  <fetch>
    method   event
    target   Slow rendered view
    tag      string slow_rendered_view.1minute
    interval 60s
  </fetch>
</source>

railsアプリケーションに何回かアクセスしてみると、以下のようなnorikraの実行結果をfluentdで確認することができます。

2016-11-05T05:20:39Z	slow_rendered_view.1minute	{"template":"hello/index.erb","max_view_runtime":"20.2"}

参考リンク

脚注   [ + ]

1. https://github.com/fluent/fluentd/blob/master/lib/fluent/parser.rb
2. 現Treadure Dataの@tagomorisさんが開発されたソフトウェア。http://norikra.github.io
3. https://github.com/norikra/fluent-plugin-norikra

byebyehaikikyou

日記やIT系関連のネタ、WordPressに関することなど様々な事柄を書き付けた雑記です。ITエンジニア経験があるのでプログラミングに関することなどが多いです。

シェアする

コメントを残す

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

コメントする

Translate »