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

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

tailプラグインでrailsアプリケーションのログをパースして見る
norikraでViewのレンダリングに最も時間のかかったテンプレートを探す
参考リンク

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

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

format multiline

1	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>

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)

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で以下のようなイベントを受信できているのを確認できます。複数行にわたるログを１つのメッセージとして受信できているのがわかります。どうやら上手くいっているようです。

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"}

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

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

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

rbenv install jruby-9.1.2.0

rbenv shell jruby-9.1.2.0

gem install norikra

続いて起動してみます。

norikra start

1	norikra start

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

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

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>

@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

@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	2016-11-05T05:20:39Z slow_rendered_view.1minute {"template":"hello/index.erb","max_view_runtime":"20.2"}

参考リンク

fluentd tail Input plugin
- http://docs.fluentd.org/articles/in_tail
fluentd parser
- https://github.com/fluent/fluentd/blob/master/lib/fluent/parser.rb
fluent-plugin-norikra
- https://github.com/norikra/fluent-plugin-norikra
http://hase.hateblo.jp/entry/2014/12/16/142250

脚注[+]

脚注
↑1	https://github.com/fluent/fluentd/blob/master/lib/fluent/parser.rb
↑2	http://norikra.github.io
↑3	https://github.com/norikra/fluent-plugin-norikra