アプリケーションログをFluentdを用いてTreasureDataに入れてみる


## 背景
独自フォーマットのログをローカルに残しつつ、`TreasureData`に入れてみたいなと思い調べてみた。

サービスの利用方法や`fluentd(td-agent)`のインストール方法は以下に記載済み。

* [TreasureData使ってみた](http://qiita.com/akito1986/items/4c83ff492ed4b390ad50 "TreasureData使ってみた")
* [nginx + fluentd + TreasureData](http://qiita.com/akito1986/items/a3d77f731f8fb4067c8c "nginx + fluentd + TreasureData")


以下環境情報。

* ubuntu: 12.04
* td-agent: 0.10.50

## ログのフォーマット

以下`TreasureData`に入れたいログ。

```log:log
2014-09-01 15:06:53 test-watch INFO -- bash Check TEST API: Start
2014-09-01 15:06:54 test-watch INFO -- bash Check TEST GET STATUS PAGE: #num:0 Start
2014-09-01 15:06:54 test-watch INFO -- bash Check TEST GET STATUS PAGE: Normal End
2014-09-01 15:06:54 test-watch INFO -- bash Check TEST Web Console login: #num:0 Start
2014-09-01 15:06:54 test-watch INFO -- ruby Start
2014-09-01 15:06:54 test-watch INFO -- ruby HTTP Get Request Start test-server:80
2014-09-01 15:06:54 test-watch INFO -- ruby HTTP Get Request End test-server:80
2014-09-01 15:06:54 test-watch INFO -- ruby HTTP Get Response 200 OK
2014-09-01 15:06:54 test-watch INFO -- ruby HTTP POST Request Start test-server:80
2014-09-01 15:06:54 test-watch INFO -- ruby HTTP POST Request End test-server:80
2014-09-01 15:06:54 test-watch INFO -- ruby HTTP POST Response 302 Found
2014-09-01 15:06:54 test-watch INFO -- ruby Normal End
2014-09-01 15:06:54 test-watch INFO -- bash Check TEST Web Console login: Normal End
2014-09-01 15:06:54 test-watch INFO -- bash Check API Login: #num:0 Start
2014-09-01 15:06:54 test-watch INFO -- bash Check API Login: Normal End
2014-09-01 15:06:54 test-watch INFO -- bash Check DB Create: #num:0 Start
2014-09-01 15:06:55 test-watch INFO -- bash Check DB Create: Normal End
2014-09-01 15:06:55 test-watch INFO -- bash Check Table Create: #num:0 Start
2014-09-01 15:06:57 test-watch INFO -- bash Check Table Create: Normal End
2014-09-01 15:06:57 test-watch INFO -- bash Check Data Import: #num:0 Start
2014-09-01 15:08:28 test-watch INFO -- bash Check Data Import: Normal End
2014-09-01 15:08:28 test-watch INFO -- bash Check Exec Query: #num:0 Start
2014-09-01 15:08:35 test-watch INFO -- bash Check Exec Query: Normal End
2014-09-01 15:08:35 test-watch INFO -- bash Check Table Delete: #num:0 Start
2014-09-01 15:08:36 test-watch INFO -- bash Check Table Delete: Normal End
2014-09-01 15:08:36 test-watch INFO -- bash Check Database Delete: #num:0 Start
2014-09-01 15:08:36 test-watch INFO -- bash Check Database Delete: Normal End
2014-09-01 15:08:36 test-watch INFO -- bash Check TEST API: Normal End
```

フォーマットは以下。

```log:format
日付 ログ名 ログレベル 機能 メッセージ 
```

`機能`については今は使っていないのでsubete「--」にしている。

## Fluentdの設定
[TreasureData公式ドキュメント](http://docs.treasuredata.com/articles/td-agent-tail-custom "Tailing Custom-Formatted Log")を見ると、JSON形式に一度変換してから`fluentd`に渡しているよう。

`fluentd`関連の他のサイトを見ると`fluentd`の設定だけでインポートできそうだったので、`td-agent.conf`を以下のように設定。

```file:/etc/td-agent/td-agent.conf
<match td.*.*>
  type tdlog
  apikey ${MY_API_KEY}
  endpoint ${END_POINT}
  auto_create_table
  buffer_type file
  buffer_path /var/log/td-agent/buffer/td
  flush_interval 10s
  use_ssl true
</match>

<source>
  type tail
  path /opt/td-log-test/app/log/test-watch.log
  pos_file /var/log/td-agent/test-watch.pos
  tag td.test.test-watch
  format /^(?<time>\d{4}-\d{2}-\d{2} \d{2}:\d{2}:\d{2}) (?<system>[^ ]*) (?<log_level>[^ ]*) (?<function>[^ ]*) (?<check_kind>[^ ]*) (?<message>.*)$/
  time_format %Y-%m-%d %H:%M:%S
</source>
```

`tag`にログを保存する`TreasureData`の`DB.Table`を指定する。`path`にアプリケーションのログを指定して、`format`にログの正規表現を書く。
`time_format`を指定することで、`TreasureData`での時間の表示の方法を指定する。

## TreasureDataの設定
ログを保存するDBを以下のコマンドで作成しておく。

```cmd:td_db_create
$ td db:create test
```

## 動かしてみる
以下のコマンドで`fluentd`を再起動する。

```cmd:restart_fluentd
$ sudo service td-agent restart
```

アプリケーション実行。
今の場合以下のコマンドで実行。

```cmd:start_app
$ /opt/td-log-test/app/script/check_test.sh
$
```

## 確認
スクリプト終了後、データが入っているかどうか確認してみる。

```
$ td db:show test
+------------+------+-------+-------------------------------------------------------------------------------------+
| Table      | Type | Count | Schema                                                                              |
+------------+------+-------+-------------------------------------------------------------------------------------+
| test_watch | log  | 28    | message:string, check_kind:string, system:string, log_level:string, function:string |
+------------+------+-------+-------------------------------------------------------------------------------------+
1 row in set
$ 
$ td query -w -t hive -d test "SELECT * FROM test_watch"
....
+--------------------------------------------+------------+------------+-----------+----------+-----------------------------------------------------------------------------------------------------------------------------------------------------------+------------+
| message                                    | check_kind | system     | log_level | function | v                                                                                                                                                         | time       |
+--------------------------------------------+------------+------------+-----------+----------+-----------------------------------------------------------------------------------------------------------------------------------------------------------+------------+
| Check TEST API: Start                      | bash       | test-watch | INFO      | --       | {"function":"--","log_level":"INFO","system":"test-watch","time":"1409553566","check_kind":"bash","message":"Check TEST API: Start"}                      | 1409553566 |
| Check TEST GET STATUS PAGE: #num:0 Start   | bash       | test-watch | INFO      | --       | {"function":"--","log_level":"INFO","system":"test-watch","time":"1409553566","check_kind":"bash","message":"Check TEST GET STATUS PAGE: #num:0 Start"}   | 1409553566 |
| Check TEST GET STATUS PAGE: Normal End     | bash       | test-watch | INFO      | --       | {"function":"--","log_level":"INFO","system":"test-watch","time":"1409553566","check_kind":"bash","message":"Check TEST GET STATUS PAGE: Normal End"}     | 1409553566 |
| Check TEST Web Console login: #num:0 Start | bash       | test-watch | INFO      | --       | {"function":"--","log_level":"INFO","system":"test-watch","time":"1409553566","check_kind":"bash","message":"Check TEST Web Console login: #num:0 Start"} | 1409553566 |
| Start                                      | ruby       | test-watch | INFO      | --       | {"function":"--","log_level":"INFO","system":"test-watch","time":"1409553566","check_kind":"ruby","message":"Start"}                                      | 1409553566 |
| HTTP Get Request Start test-server:80      | ruby       | test-watch | INFO      | --       | {"function":"--","log_level":"INFO","system":"test-watch","time":"1409553566","check_kind":"ruby","message":"HTTP Get Request Start test-server:80"}      | 1409553566 |
| HTTP Get Request End test-server:80        | ruby       | test-watch | INFO      | --       | {"function":"--","log_level":"INFO","system":"test-watch","time":"1409553566","check_kind":"ruby","message":"HTTP Get Request End test-server:80"}        | 1409553566 |
| HTTP Get Response 200 OK                   | ruby       | test-watch | INFO      | --       | {"function":"--","log_level":"INFO","system":"test-watch","time":"1409553566","check_kind":"ruby","message":"HTTP Get Response 200 OK"}                   | 1409553566 |
| HTTP POST Request Start test-server:80     | ruby       | test-watch | INFO      | --       | {"function":"--","log_level":"INFO","system":"test-watch","time":"1409553566","check_kind":"ruby","message":"HTTP POST Request Start test-server:80"}     | 1409553566 |
| HTTP POST Request End test-server:80       | ruby       | test-watch | INFO      | --       | {"function":"--","log_level":"INFO","system":"test-watch","time":"1409553566","check_kind":"ruby","message":"HTTP POST Request End test-server:80"}       | 1409553566 |
| HTTP POST Response 302 Found               | ruby       | test-watch | INFO      | --       | {"function":"--","log_level":"INFO","system":"test-watch","time":"1409553566","check_kind":"ruby","message":"HTTP POST Response 302 Found"}               | 1409553566 |
| Normal End                                 | ruby       | test-watch | INFO      | --       | {"function":"--","log_level":"INFO","system":"test-watch","time":"1409553566","check_kind":"ruby","message":"Normal End"}                                 | 1409553566 |
| Check TEST Web Console login: Normal End   | bash       | test-watch | INFO      | --       | {"function":"--","log_level":"INFO","system":"test-watch","time":"1409553566","check_kind":"bash","message":"Check TEST Web Console login: Normal End"}   | 1409553566 |
| Check API Login: #num:0 Start              | bash       | test-watch | INFO      | --       | {"function":"--","log_level":"INFO","system":"test-watch","time":"1409553566","check_kind":"bash","message":"Check API Login: #num:0 Start"}              | 1409553566 |
| Check API Login: Normal End                | bash       | test-watch | INFO      | --       | {"function":"--","log_level":"INFO","system":"test-watch","time":"1409553567","check_kind":"bash","message":"Check API Login: Normal End"}                | 1409553567 |
| Check DB Create: #num:0 Start              | bash       | test-watch | INFO      | --       | {"function":"--","log_level":"INFO","system":"test-watch","time":"1409553567","check_kind":"bash","message":"Check DB Create: #num:0 Start"}              | 1409553567 |
| Check DB Create: Normal End                | bash       | test-watch | INFO      | --       | {"function":"--","log_level":"INFO","system":"test-watch","time":"1409553568","check_kind":"bash","message":"Check DB Create: Normal End"}                | 1409553568 |
| Check Table Create: #num:0 Start           | bash       | test-watch | INFO      | --       | {"function":"--","log_level":"INFO","system":"test-watch","time":"1409553568","check_kind":"bash","message":"Check Table Create: #num:0 Start"}           | 1409553568 |
| Check Table Create: Normal End             | bash       | test-watch | INFO      | --       | {"function":"--","log_level":"INFO","system":"test-watch","time":"1409553569","check_kind":"bash","message":"Check Table Create: Normal End"}             | 1409553569 |
| Check Data Import: #num:0 Start            | bash       | test-watch | INFO      | --       | {"function":"--","log_level":"INFO","system":"test-watch","time":"1409553569","check_kind":"bash","message":"Check Data Import: #num:0 Start"}            | 1409553569 |
| Check Exec Query: Normal End               | bash       | test-watch | INFO      | --       | {"function":"--","log_level":"INFO","check_kind":"bash","time":"1409553665","system":"test-watch","message":"Check Exec Query: Normal End"}               | 1409553665 |
| Check Table Delete: #num:0 Start           | bash       | test-watch | INFO      | --       | {"function":"--","log_level":"INFO","check_kind":"bash","time":"1409553665","system":"test-watch","message":"Check Table Delete: #num:0 Start"}           | 1409553665 |
| Check Table Delete: Normal End             | bash       | test-watch | INFO      | --       | {"function":"--","log_level":"INFO","check_kind":"bash","time":"1409553666","system":"test-watch","message":"Check Table Delete: Normal End"}             | 1409553666 |
| Check Database Delete: #num:0 Start        | bash       | test-watch | INFO      | --       | {"function":"--","log_level":"INFO","check_kind":"bash","time":"1409553666","system":"test-watch","message":"Check Database Delete: #num:0 Start"}        | 1409553666 |
| Check Database Delete: Normal End          | bash       | test-watch | INFO      | --       | {"function":"--","log_level":"INFO","check_kind":"bash","time":"1409553667","system":"test-watch","message":"Check Database Delete: Normal End"}          | 1409553667 |
| Check TEST API: Normal End                 | bash       | test-watch | INFO      | --       | {"function":"--","log_level":"INFO","check_kind":"bash","time":"1409553667","system":"test-watch","message":"Check TEST API: Normal End"}                 | 1409553667 |
| Check Data Import: Normal End              | bash       | test-watch | INFO      | --       | {"function":"--","log_level":"INFO","check_kind":"bash","time":"1409553659","system":"test-watch","message":"Check Data Import: Normal End"}              | 1409553659 |
| Check Exec Query: #num:0 Start             | bash       | test-watch | INFO      | --       | {"function":"--","log_level":"INFO","check_kind":"bash","time":"1409553659","system":"test-watch","message":"Check Exec Query: #num:0 Start"}             | 1409553659 |
+--------------------------------------------+------------+------------+-----------+----------+-----------------------------------------------------------------------------------------------------------------------------------------------------------+------------+
$
```
`test_watch table`が作成され、ちゃんとデータが入ってるっぽい。

おしまい。