tweeeetyのぶろぐ的めも

アウトプットが少なかったダメな自分をアウトプット<br>\(^o^)/

td-agent(fluentd)でtagを色々してみたメモ②-out_exec_filterでタグをもっといろいろしてみる

はじめに

td-agent使って最初はいろいろ四苦八苦しましたが、
だいぶ期間も経ってしまって忘れそうなのでタグの扱いについて自分なりにメモっておこーっていう記事です
 
では

  • fluent-plugin-parse
  • fluent-plugin-config-expander
  • fluent-plugin-rewrite
  • fluent-plugin-record-reformer

を使っていろいろやりましたが、もっと好きにやりたいけどplugin作るまでではないんだよなーというときのout_exec_filterについてです。

こちらも参考にしてみてください
td-agent(fluentd)を本番サ―ビスで小さく使ってみたメモ-まとめ - tweeeetyのぶろぐ的めも

ながれ

  1. 前提とか(fluent-plugin-parser)
    • 前提
    • 関連ディレクトリ構成
    • イメージ
  2. out_exec_filter使ってみる
    • シンプルに動かしてみる
    • デバッグ、動かない場合やエラーについて
    • 例)jsonから静的ファイル名だけ抜き出してみる

補足

そんなにテクニカルでも有用でもないカモですがこちらにメモまとめをメモっておきました →td-agent(fluentd)を本番サ―ビスで小さく使ってみたメモ-まとめ

前提とか

前提
  • td-agentインストール済み
  • apacheaccessログをtailする(フォーマットデフォルトではない)
  • 送信側は受信側にそのまんま送る(後述のイメージ参照)
  • 受信側ではまず最初にfluent-plugin-parserでパース処理する
関連ディレクトリ構成

outファイルで出力するログやpos、シンボリックリンクを格納するフォルダの構成はこんな感じにしてます

  • 送信・受信側共通
# tree /var/log/td-agent
/var/log/td-agent
|-- project
|   |-- aclog
|   |-- buffer
|   |-- out
|   |-- pos
|   `-- slink
`-- unmatched
イメージ

いくつかプラグインを使いますが基本的な流れはこれで行います。

送信側はaccessログをそのまんまの形で送信

受信側は来たログをparserでパースしてemit~からのいろいろやる

理由はサービスに導入時にwebサーバに負荷をかけたくなかったので
パース処理は受信側で行いたいという感じです

  • 図だとこんな感じ

f:id:tweeeety:20140521222128p:plain

準備

fluent-plugin-parserだけは最初にインストールしておきます

/usr/lib64/fluent/ruby/bin/gem install fluent-plugin-parser

2. out_exec_filter使ってみる

やってみるながれはこんな感じです

  • シンプルに動かしてみる
  • デバッグ、動かない場合やエラーについて
  • 例)jsonから静的ファイル名だけ抜き出してみる

ってことで早速

シンプルに動かしてみる

まずはシンプルに動かしてみます。

主に受信側ですが、動かしてみる内容としてはこんな感じのイメージ
perlに渡すだけで何もしませんw

td-agentでアクセスログをparseしてjsonにする

out_exec_filterでjsonperlに渡す

perlプログラムでjsonを受け取って何もせずそのまま標準出力

td-agentでperlから出力されたjsonをファイルに出力

そして用意はこれだけ
  • config書く
  • perlプログラム
config書く
  • 送信側
<source>
  type config_expander
  <config>
    type tail
    format none
    time_format %d/%b/%Y:%T %z
    path /var/log/td-agent/project/slink/access.log
    pos_file /var/log/td-agent/project/pos/access.pos
    #rotate_wait 30
    tag raw.project.apache.access.__HOSTNAME__
  </config>
</source>
  • 受信側
    exec_filterにfluentd_exec_filter_simple.plという後述するperlを指定します
<match raw.project.apache.**>
  type parser
  remove_prefix raw
  add_prefix parsed
  format /^(?<host>[^ ]+) [^ ]+ [^ ]+ \[(?<time>[^\]]+)\] "(?<method>[^ ]+) (?<path>[^ ]+) [^ ]+" (?<code>[^ ]+) .+ ".+" "(?<ua>.+)" (?<response_time>[^ ]+)$/
  time_format %d/%b/%Y:%T %z
  key_name message
</match>

<match parsed.**>
  type exec_filter
  command /usr/bin/perl /etc/td-agent/script/fluentd_exec_filter_simple.pl
  in_format json
  out_format msgpack
  tag exec.filtered
</match>

<match  exec.**>
  type file
  path /var/log/td-agent/project/out/exec
</match>
perlプログラム
ソース補足
$| = 1;

printするごとに強制的にフラッシュします($OUTPUT_AUTOFLUSH)

while ( my $json = <STDIN> ) {
  my $decode = eval { decode_json($json); };
  next if ($@);
  print $mp->pack($decode);
}

while文で標準入力を受け取ってjson形式でなければスルー、json形式だったらprintします

結果

結果はこんな感じです。
tailするアクセスログと、いったんperl経由でout_fileプラグインでファイルに出したjsonを載せときます

アクセスログ
172.21.65.97 - - [27/May/2014:14:41:18 +0900] "GET /mypage HTTP/1.1" 200 78958 "-" "Mozilla/5.0 (Windows NT 6.1; WOW64) AppleWebKit/535.11 (KHTML, like Gecko) Chrome/17.0.963.33 Safari/535.11" 297664
172.21.65.97 - - [27/May/2014:14:41:18 +0900] "GET /js/mypage/main.js?4 HTTP/1.1" 200 11760 "http://hogehoge.co.jp/mypage" "Mozilla/5.0 (Windows NT 6.1; WOW64) AppleWebKit/535.11 (KHTML, like Gecko) Chrome/17.0.963.33 Safari/535.11" 346
172.21.65.97 - - [27/May/2014:14:41:18 +0900] "GET /js/libs/jquery.htmlaudio.js HTTP/1.1" 200 2079 "http://hogehoge.co.jp/mypage" "Mozilla/5.0 (Windows NT 6.1; WOW64) AppleWebKit/535.11 (KHTML, like Gecko) Chrome/17.0.963.33 Safari/535.11" 334
/var/log/td-agent/project/out/exec
# pwd
/var/log/td-agent/project/out

# ls 
exec.20140527.b4fa5ac92e18cc51c

# cat exec.20140527.b4fa5ac92e18cc51c
2014-05-27T14:41:20+09:00  exec.filtered  {"code":"200","host":"172.21.65.97","method":"GET","path":"/mypage","response_time":"297664","ua":"Mozilla/5.0 (Windows NT 6.1; WOW64) AppleWebKit/535.11 (KHTML, like Gecko) Chrome/17.0.963.33 Safari/535.11"}
2014-05-27T14:41:20+09:00  exec.filtered  {"code":"200","host":"172.21.65.97","method":"GET","path":"/js/mypage/main.js","response_time":"346","ua":"Mozilla/5.0 (Windows NT 6.1; WOW64) AppleWebKit/535.11 (KHTML, like Gecko) Chrome/17.0.963.33 Safari/535.11"}
2014-05-27T14:41:20+09:00  exec.filtered  {"code":"200","host":"172.21.65.97","method":"GET","path":"/js/libs/jquery.htmlaudio.js","response_time":"334","ua":"Mozilla/5.0 (Windows NT 6.1; WOW64) AppleWebKit/535.11 (KHTML, like Gecko) Chrome/17.0.963.33 Safari/535.11"}

うまく行きました!

デバッグ、動かない場合やエラーについて

exec_filterやってみたけど、
デバッグの仕方やエラーのときわかりにくいという記事をいくつか見かけたので
自分なりにやった感じをメモっておきます

動かない、エラーについて

動かないとかエラーの場合は当たり前ですがこのいずれかだと思います

  • configの間違え
  • perのエラー
  • td-agent再起動忘れ

config間違えの場合はおおよそ/etc/init.d/td-agent startやった直後のログ見ればわかります。perlのエラーの場合が若干わかりにくいですが、後述するデバッグなんかでうまくやりましょう
また、正常に動いていたperlを変更した場合はtd-agentを再起動しないと反映されません。当たり前ですね  

一応、エラーの感じをのっけときます

perlシンタックスエラーにしてみた場合

起動時にこんなエラーが出ます

2014-05-27 15:46:20 +0900 [error]: plugin/out_exec_filter.rb:327:run: exec_filter process unexpectedly exited. command="/usr/bin/perl /etc/td-agent/script/fluentd_exec_filter_simple.pl" ecode=65280
perlを実行時エラーにしてみた場合

アクセスログのparse後にこんな(上記と同じ)エラーが出ます
今回はprint $mp->pack($decode);print $mp->pack();にしてみました

2014-05-27 15:51:58 +0900 [error]: plugin/out_exec_filter.rb:327:run: exec_filter process unexpectedly exited. command="/usr/bin/perl /etc/td-agent/script/fluentd_exec_filter_simple.pl" ecode=65280

デバッグについて

デバッグ方法は何でも良いかと思いますがこんな感じでやれば良いかと。

  1. perl単体で実行
  2. perlをtd-agentから呼ばれる想定でもう一つ用意したperlから実行
  3. perlに標準エラーを書き出すよう追記
1. perl単体で実行
  • 概要

そのまんまですが、結果がわかりやすいようにwhile内のプログラムを変えました

  • プログラム
  • 結果
# perl fluentd_exec_filter_simple.pl
※入力待ちになるので何か打つ
aaa
not a json! at fluentd_exec_filter_simple02.pl line 16, <STDIN> line 1.

※jsonを打つとエラーは出ない
{"name":"hoge"}
2. perlをtd-agentから呼ばれる想定でもう一つ用意したperlから実行
  • 概要

上記の方法でも十分ですが、
アクセスログ並みのjsonを手で打って確認するのはしんどいので
out_exec_filterに指定するperlを他のperlからjson渡す&実行してみます

  • プログラム

fluentd_exec_filter_simple.plはエラーの際に$jsonの内容を表示するように変えました

呼び出し側はこんな感じ。パイプで標準入力として渡すように呼び出します

  • 結果
# ls -al
drwxr-xr-x 3 root     wheel    4096  5月 27 15:19 2014 .
drwxr-xr-x 8 root     wheel    4096  1月 15 20:51 2014 ..
-rwxrwxrwx 1 td-agent td-agent  593  5月 27 15:17 2014 call_fluentd_exec_filter_simple.pl
-rwxrwxrwx 1 td-agent td-agent  283  5月 27 14:19 2014 fluentd_exec_filter_simple.pl

# perl call_fluentd_exec_filter_simple.pl
#### not json sample####
[ERROR]not a json! [IN] mojiretu

#### json sample####
3. perlに標準エラーを書き出すよう追記
  • 概要

1でも2でもデバッグは十分できますが、
実際にtd-agentのconfigに指定してperlにゴリゴリ書いてみた結果、
動かない、意味わかんない、やめたいみたい。。orz...
みたいな感じにならないように標準エラーをファイルに書き出すようにしてみます

  • 下準備(error.log) 下準備としてエラーを書き出すファイルを用意しておきます
# pwd
/etc/td-agent/script

# touch error.log

# chown td-agent:td-agent error.log

# chmod 777 error.log

補足しておくと、
chownするのはtd-agentを起動した際にtd-agentが書き込めるように、
chmodするのはperlコマンドで直接プログラム叩いたときに書き込めるように、
です。
td-agent起動かperlコマンド実行かのどちらかではエラーが出力されないかも
という本文ではないところで躓かないようにやっちゃいましょう。

  • プログラム

out_exec_filterに指定するperlを修正します。こんな感じ(8~11行目)
fluentd_exec_filter_fix.pl

  • 結果

fluentd_exec_filter_fix.plをわざとシンタックスエラーにしてperlコマンドで実行してみる (13行目に$vvvv;とだけ追記)

# perl fluentd_exec_filter_fix.pl
Global symbol "$vvvv" requires explicit package name at fluentd_exec_filter_fix.pl line 13.
Execution of fluentd_exec_filter_fix.pl aborted due to compilation errors.

# cat error.log
Global symbol "$vvvv" requires explicit package name at fluentd_exec_filter_fix.pl line 13.
Execution of fluentd_exec_filter_fix.pl aborted due to compilation errors.

td-agent起動してみる(/etc/init.d/td-agent restart)
td-agent.log

2014-05-27 18:10:04 +0900 [error]: plugin/out_exec_filter.rb:327:run: exec_filter process unexpectedly exited. command="/usr/bin/perl /etc/td-agent/script/fluentd_exec_filter_fix.pl" ecode=65280

error.log

# cat error.log
※↓perlコマンドで出たエラー
Global symbol "$vvvv" requires explicit package name at fluentd_exec_filter_fix.pl line 13.
Execution of fluentd_exec_filter_fix.pl aborted due to compilation errors.

※↓td-agent起動時に出たエラー
Global symbol "$vvvv" requires explicit package name at /etc/td-agent/script/fluentd_exec_filter_fix.pl line 13.
Execution of /etc/td-agent/script/fluentd_exec_filter_fix.pl aborted due to compilation errors.

ってことで、エラーが出るようになりました。
json形式かどうかにかかわらずwhileの直後にwarn "$json";とかしておけば、
中身もerror.logに出るので本当にちゃんと値が来てるのか見たいときも良いですね!

例)jsonから静的ファイル名だけ抜き出してみる

ここからは説明なしでサンプルソースメインです。
 
こんな想定

  • 画像などをCDNにおいてる
  • 画像などはアクセスログに出て欲しくない(CDNアクセスであってほしいので)
  • CDNに向け忘れてアクセスされてる画像など(ファイル名)を知りたい
  • そんなファイル名をテキストファイルに書き出したい!
    (他のプラグインでやればいいじゃんは一旦忘れる方向でww)
config修正
  • 受信側 exec_filterにfluentd_exec_filter_staticfile_list.plを指定
<match raw.project.apache.**>
  type parser
  remove_prefix raw
  add_prefix parsed
  format /^(?<host>[^ ]+) [^ ]+ [^ ]+ \[(?<time>[^\]]+)\] "(?<method>[^ ]+) (?<path>[^ ]+) [^ ]+" (?<code>[^ ]+) .+ ".+" "(?<ua>.+)" (?<response_time>[^ ]+)$/
  time_format %d/%b/%Y:%T %z
  key_name message
</match>

<match parsed.**>
  type exec_filter
  command /usr/bin/perl /etc/td-agent/script/fluentd_exec_filter_staticfile_list.pl
  in_format json
  out_format msgpack
  tag exec.filtered
</match>

<match  exec.**>
  type file
  path /var/log/td-agent/project/out/exec
</match>
perlプログラム
結果

結果はこんな感じです。

アクセスログ
172.21.65.97 - - [27/May/2014:18:45:48 +0900] "GET /mypage HTTP/1.1" 200 79061 "-" "Mozilla/5.0 (Windows NT 6.1; WOW64) AppleWebKit/535.11 (KHTML, like Gecko) Chrome/17.0.963.33 Safari/535.11" 302246
172.21.65.97 - - [27/May/2014:18:45:48 +0900] "GET /js/project.js HTTP/1.1" 200 35020 "http://hogehoge.co.jp/mypage" "Mozilla/5.0 (Windows NT 6.1; WOW64) AppleWebKit/535.11 (KHTML, like Gecko) Chrome/17.0.963.33 Safari/535.11" 1573
172.21.65.97 - - [27/May/2014:18:45:48 +0900] "GET /js/mypage/main.js HTTP/1.1" 200 11760 "http://hogehoge.co.jp/mypage" "Mozilla/5.0 (Windows NT 6.1; WOW64) AppleWebKit/535.11 (KHTML, like Gecko) Chrome/17.0.963.33 Safari/535.11" 339
172.21.65.97 - - [27/May/2014:18:45:48 +0900] "GET /img/project/640/background.png HTTP/1.1" 200 99635 "http://hogehoge.co.jp/mypage" "Mozilla/5.0 (Windows NT 6.1; WOW64) AppleWebKit/535.11 (KHTML, like Gecko) Chrome/17.0.963.33 Safari/535.11" 8231
172.21.65.97 - - [27/May/2014:18:45:48 +0900] "GET /img/project/640/base.png HTTP/1.1" 200 117854 "http://hogehoge.co.jp/mypage" "Mozilla/5.0 (Windows NT 6.1; WOW64) AppleWebKit/535.11 (KHTML, like Gecko) Chrome/17.0.963.33 Safari/535.11" 13856
/var/log/td-agent/project/out/exec
# pwd
/var/log/td-agent/project/out

# ls 
static_file_list.20140527.b4fa5e7fcd972e80b

# cat static_file_list.20140527.b4fa5e7fcd972e80b
2014-05-27T18:45:51+09:00  exec.filtered  {"file_name":"project.js"}
2014-05-27T18:45:51+09:00  exec.filtered  {"file_name":"main.js"}
2014-05-27T18:45:51+09:00  exec.filtered  {"file_name":"background.png"}
2014-05-27T18:45:51+09:00  exec.filtered  {"file_name":"base.png"}

/mypageみたいなページアクセスは無視してファイル名っぽいのでだけfile_nameとして出るようになりました!

まとめ

思った以上に長くなってしまいましたが、
out_exec_filterもいろいろできて面白いですね! \(^o^)/

また、下記のサイトがすごく参考になるかと思います!thx!