LTSVフォーマットなログを fluentd + GrowthForecast で料理

ここ数年のデータ解析の重要性の高まりから、ログに関するソリューションが方々で活発に探求されている昨今でございます。ウェブサーバーの単純なアクセスログをそのまま保存するではなく追加情報を添加してみたり、あるいはアプリケーションから直接ログを吐いてそれらをデータウェアに投げ込んで･･･というのも当然のように行うようになりましたね。

しかしあまり自由度のない access_log の combined フォーマット。さてどうしたもんか･･･ここで id:stanaka の登場です。

Labeled Tab Separated Valueというのは、はてなで使っているログフォーマットのことで、広く使われているTSV(Tab Separated Value)フォーマットにラベルを付けて扱い易くしたものです。はてなでは、もう3年以上、このフォーマットでログを残していて、one-linerからfluentd、Apache Hiveまで幅広く便利に使えています。

ほうほう。確かに Apache access_log の combined フォーマットは、そのようなログの変形や拡張にはあんまり向いてない。各フィールドにキーを付けたフォーマット ─ LTSV とすることで、拡張性を付与する。一見単に名前を付与しただけの単純なものようですが

自己記述的なのでフィールド追加に対して開かれていて、かつ行指向なのでワンライナーで集計しやすい。 Unix 哲学の大事な点が形になっていると思う。素晴らしい。 / “Labeled Tab Separated Valueノススメ …” htn.to/hpw58Q
— Takuto Wadaさん (@t_wada) 2013年2月5日

「なかなか筋の良いフォーマットではないか！」と御大も言ってます。データの順番を気にしなくて良くなる、新しいフィールドの追加が容易･･･あたりが日々変化するデータ解析の要求に対して柔軟で、良さそうです。

LTSV の良さ、の例

例えば fluentd で ~~combined フォーマット~~combined フォーマット + アルファなアクセスログを解析しようとすると

<source>
  type   tail
  time_format %d/%b/%Y:%H:%M:%S %z
  path /var/log/nginx/access.log
  format /^(?<host>[^ ]*) [^ ]* (?<user>[^ ]*) \[(?<time>[^\]]*)\] "(?<method>\S+)(?: +(?<path>[^ ]*) +\
\S*)?" (?<status>[^ ]*) (?<size>[^ ]*)(?: "(?<referer>[^\"]*)" "(?<agent>[^\"]*)" (?<response_time>[^ ]*)\
 (?<upstream_response_time>[^ ]*))?$/
  tag nginx.access
  pos_file /var/log/td-agent/nginx.access.log.pos
</source>

こんな感じの嫌な正規表現を config ファイルにべったりと書く必要がある。これが、LTSV フォーマットなアクセスログに変えて id:stanaka さん開発の fluent-plugin-tail-labeled-tsv を使うと

<source>
  type tail_labeled_tsv
  path /var/log/nginx/access.log
  tag nginx.access
  pos_file /tmp/fluent.log.pos
</source>

と書ける。name_keys はアクセスログにある LTSV のキーがそのまま使われるので、DRY でもある。おお･･･

fluentd 以外にも、ちょっとアクセスログを軽く集計しようと思って perl で正規表現で分離するようなスクリプトとか誰もが書いたことあると思います。それも LTSV なら tab で split して key-value にしてしまえば良いだけになる。新しいキーをログ側に追加しても、パーサーのロジックは変わらない。素晴らしい。

JSON のように構造化まではされていないけれど、行指向だし特殊なパーサーも必要としない･･･ということで Simple enough ではないでしょうか。

LTSVログ ⇒ fluentd ⇒ GrowthForecast

そんなわけで、LTSV な nginx のログを fluentd (td-agent) で吸い上げて、GrowthForecast でグラフ化するなど。せっかくの Vagrant + chef-solo 期なので、そのような環境を Berkshelf 一発で立ち上げてみました。以下そのクックブック。

https://github.com/naoya/vagrant-ltsvbox_sample

Vagrant - naoyaのはてなダイアリーでも触れた Berkshelf を使って vagrant up 時に

nginx
td-agent
perlbrew (vagrant ユーザー)
GrowthForecast
supervisor

等をインストールして、nginx のログを LTSV に設定し、td-agent がそれを読み取り supervisord で起動している GrowthForecast にデータを投げ込む環境をワンストップでビルドします。

nginx のログフォーマットが

http {
    …
    log_format  ltsv  'time:$time_local\t'
                      'host:$remote_addr\t'
                      'request:$request\t'
                      'status:$status\t'
                      'size:$body_bytes_sent\t'
                      'referer:$http_referer\t'
                      'ua:$http_user_agent\t'
                      'reqtime:$request_time\t'
                      'upsttime:$upstream_response_time';

    access_log  /var/log/nginx/access.log  ltsv;

こんな感じで書けて良かったです。繰り返しになりますが、ここの順番を変更したり新しいキーと値を追加などしても他システムにクリティカルな影響を与えない、robust なフォーマットです。

td-agent のコンフィグは

<source>
  type tail_labeled_tsv
  path /var/log/nginx/access.log
  tag nginx.access
  pos_file /tmp/fluent.log.pos
</source>

<match nginx.access>
  type copy
  <store>
    type file
    path /var/log/td-agent/nginx.access
  </store>
  <store>
    type growthforecast
    gfapi_url http://localhost:5125/api/
    service   nginx
    section   response
    name_keys reqtime,upsttime
  </store>
  <store>
    type datacounter
    unit minute
    tag nginx.access.status_count
    count_key status
    pattern1 3xx ^3\d\d$
    pattern2 4xx ^4\d\d$
    pattern3 5xx ^5\d\d$
    pattern4 200 ^200$ 
  </store>
</match>

<match nginx.access.status_count>
  type growthforecast
  gfapi_url http://localhost:5125/api/
  service   nginx
  section   status_codes
  name_keys nginx.access_5xx_count,nginx.access_4xx_count,nginx.access_3xx_count,nginx.access_200_count
</match>

という感じですね。プラグインに growthforecast と datacounter を使ってます。fluent-plugin-tail-labeled-tsv は /etc/td-data/plugin に放り込んでアクティベート。

いざ、VM を立ち上げてみましょう。

% vagrant box add base http://developer.nrel.gov/downloads/vagrant-boxes/CentOS-6.3-x86_64-v20130101.box
% git clone git@github.com:naoya/vagrant-ltsvbox_sample.git
% cd vagrant-ltsvbox_sample
% vagrant up

で VM が立ち上がって chef-solo が実行されて、お目当ての環境が自動で完成するはず。あとは 80 番ポートにアクセスしてアクセスログを吐かせたのち、GrowthForecast が待機しているポート 5125 にアクセスすると

という感じで、きちんと HTTP ステータスがグラフに出力されている。LTSV フォーマットがきちんとワークしてます。いいですね。地味なようで触ってみるとその有用性を実感します。既存の自分のサービスも、LTSV に変えてみようかなと思った次第です。

アクセスログとか、不便なフォーマットだけどそんなもんだよね、とあまり疑おうともしなかったものがちょっとした変更でこう扱いやすくなるとは目から鱗です。

追記

@naoya_ito ちなみに… 全く本筋では無いですがcombined formatならfluentdに組み込みパーサーが有り、正規表現を書かなくても'type apache'でパースできます。
— Kazuki Ohtaさん (@kzk_mover) 2013年2月6日

とのことなので少し本文修正しました。いつも combined + アルファなフォーマットで使っていたから気づかなかった･･･