アップデートすると以前の設定では動かないFluentd

しばらくアップデートしていなかったので、Fluentdをアップデートすべく、td-agent2を導入しました。
簡単な作業かと思いきや、設定ファイルの形式や、プラグインの挙動が変更になっており、正常に動作させるのに苦労しました。その作業ログです。

その中で学んだFluentdで値が取れない場合の対象法も紹介します。

td-agent2へのアップデート

td-agentを削除するとインストールしていたプラグインも削除されるので、インストールしているプラグインを調べます。（1.9.1の部分は環境で違うかもしれません）

# ls -1 /usr/lib64/fluent/ruby/lib/ruby/gems/1.9.1/gems/

出てきたプラグインをメモっといてください。

そしてtd-agent1を削除。

# yum --setopt=tsflags=noscripts remove td-agent
（省略）
Dependencies Resolved

================================================================================
 Package          Arch           Version            Repository             Size
================================================================================
Removing:
 td-agent         x86_64         1.1.21-0           @treasuredata          99 M

Transaction Summary
================================================================================
Remove        1 Package(s)
（省略）

続いて用意されているスクリプトでtd-agent2をインストールします。
すでに1系をインストールした方はご存知だと思いますが完了まで数十分かかります。

# curl -L http://toolbelt.treasuredata.com/sh/install-redhat-td-agent2.sh | sh
（省略）
Dependencies Resolved

================================================================================
 Package          Arch           Version             Repository            Size
================================================================================
Installing:
 td-agent         x86_64         2.2.1-0.el6         treasuredata          53 M

Transaction Summary
================================================================================
Install       1 Package(s)
（省略）

無事にtd-agentの2.2.1-0.el6がインストールできました。

ではインストールされているプラグインを調べます。現時点でのrubyのバージョンは2.1.0のようです。

# ls -l /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/

比較して入ってないプラグインをインストールします。
当方の環境では以下のようにインストールしました。

# td-agent-gem install fluent-plugin-growthforecast \
fluent-plugin-dstat \
fluent-plugin-map \
fluent-plugin-df \
fluent-plugin-datacounter \
fluent-plugin-mysqlslowquery \
fluent-plugin-numeric-counter \
fluent-plugin-amplifier-filter \
fluent-plugin-record-modifier \
fluent-plugin-nata2
（省略）
15 gems installed

では起動してみます。

# /etc/init.d/td-agent start
Warning: Declaring --user in $DAEMON_ARGS has been deprecated. Use $TD_AGENT_USER instead.
Warning: Declaring --user in $DAEMON_ARGS has been deprecated. Use $TD_AGENT_USER instead.
Warning: Declaring --group in $DAEMON_ARGS has been deprecated. Use $TD_AGENT_GROUP instead.
Shutting down td-agent:                                    [  OK  ]
Starting td-agent:                                         [  OK  ]

起動はできましたが、なにやら警告が表示されています。
調べてみると、どうやら起動オプションを設定する「/etc/sysconfig/td-agent」の記述方法が古いとのこと。調べてみます。

# vi /etc/sysconfig/td-agent

DAEMON_ARGS="--user root"
TD_AGENT_ARGS="/usr/sbin/td-agent --user root --group td-agent --log /var/log/td-agent/td-agent.log"

これを警告を元に、以下のように変更します。

TD_AGENT_USER="root"
TD_AGENT_GROUP="td-agent"
TD_AGENT_ARGS="/usr/sbin/td-agent --log /var/log/td-agent/td-agent.log"

そして再起動。

# /etc/init.d/td-agent restart

エラー無く実行できました。念のためログを確認します。

# vi /var/log/td-agent/td-agent.log

エラーもないようです。
これでtd-agentを2にバージョンアップできました。

しかし、これで終了ではありません。
新しいFluentdは設定ファイルの形式が変更になっているのでそれに合わせて変更する必要があります。

Fluentdの設定ファイルをv1に合わせて変更

Fluentdはバージョン0.10.50から設定ファイルがv1という形式に変更になりました。
そのための修正が必要になります。（前のバージョンの形式はv0と言うようです）

その辺の詳しい話は「fluentd – td-agentで–use-v1-config – Qiita」でまとめられているので、ご覧ください。

ざっくり言うと「設定ファイルに環境変数を指定したり、Rubyのコードを使用することができる」というのが変更点です。

「公式の設定ページ」も見ておくと助けになります。

今回インストールしたtd-agent2.2.1はv0と互換性があるということで、「以前の投稿で紹介した設定」で問題なく動作するかと思いきや、全く動作しませんでした。
同じように悩まれる方も多いだろうと思うので、エラーメッセージと合わせて対処した方法を紹介します。

いつまでたってもカウントが開始されないので、おかしいと思いtd-agentのログ確認します。

# vi /var/log/td-agent/td-agent.log

fluent-plugin-growthforecastのエラー

fluent-plugin-growthforecastのページ
以下のエラーが出ています。

2015-11-17 09:17:17 +0900 [warn]: parameter 'max_keepalive_reqs' in <match nginx.access.status_count>

TCP接続の負荷対策のためにkeepaliveとmax_keepalive_reqsを設定したのですが、どうもエラーが出るようです。
プラグインの説明画面にもkeepaliveに関する設定は生きてるのですが、数値や順序を変更してもエラーが出続けます。しかたがないので削除しました。

fluent-plugin-dstatとfluent-plugin-mapのエラー

fluent-plugin-dstatのページ
fluent-plugin-mapのページ

以下のエラーが出ています。

2015-11-17 09:48:08 +0900 [error]: unexpected error error="undefined local variable or method `perf' for #<Fluent::MapOutput:0x007f7442d59b58>"

どうやらtagを追加するべく設定したtag perf.cpuという設定が引っかかってるようです。

mapプラグインのページに解説がありますが、tagの項目は()で囲まないといけないとのこと。
また、v1の設定では文字列は””で囲む必要があるということで以下のように変更しました。（ただ他の設定はそのように囲まなくても文字列として認識しているのでプラグインの仕様なのでしょうか？疑問が残ります）

<store>
    type map
    tag perf.cpu
    time time
    record record["dstat"]["total cpu usage"]
</store>

以下のように変更。

<store>
    type map
    tag ("perf.cpu")
    time time
    record record["dstat"]["total cpu usage"]
</store>

と、これでtagに関してはエラーが無くなったのですが、なぜか値がGrowthForecastに転送できません。
「recordに関しても特殊な記述が必要なのかも」といろいろ試しますが、logにエラーが出力されないため途方に暮れました。

と、そんなときは、どこまで正しく値を取得できているかファイルに書き出して確認するのがお薦めです。
例えば今回のdstatの出力なら以下のようにcopyプラグインを利用してファイルに書き出します。

<match dstat> # 対象とするタグを指定
    type copy
    <store>
        type file # fileプラグイン（ファイルにログを出力する）
        path /var/log/td-agent/dstat.test
    </store>
    <store>
        type map
        tag ("perf.cpu")
        time time
        record record["dstat"]["total cpu usage"]
    </store>
</match>

書きだされた「/var/log/td-agent/dstat.test」を開いて確認してみます。

2015-11-18T16:31:38+09:00	dstat	{"hostname":"example.com","dstat":{"total_cpu_usage":{"usr":"1.022","sys":"0.204","idl":"97.955","wai":"0.613","hiq":"0.0","siq":"0.204"},"dsk/total":{"read":"14745.600","writ":"286720.0"},"net/total":{"recv":"7221.300","send":"76817.0"},"memory_usage":{"used":"1011761152.0","buff":"32649216.0","cach":"767877120.0","free":"154394624.0"},"tcp_sockets":{"lis":"17.0","act":"27.0","syn":"0.0","tim":"190.0","clo":"2.0"},"udp":{"lis":"5.0","act":"0.0"}}}

「total cpu usage」じゃなくて、「total_cpu_usage」になってる！
そう、dstatプラグインによるレコード名がスペースからアンダースコアに変更されたため、値が取得できなかった、という単純なミスだったのです。
こんな単純なミスですが、検証方法がわからず何時間も格闘しました。

同じように「memory_usage」や「tcp_sockets」も変更たところ、無事にGrowthForecastへ出力されるようになりました。

このように思わぬミスが発覚することがあるため、意図した結果にならない場合は、ファイルに出力してみてください。
ミスだけでなく、プラグインが独自で生成する便利なレコードも発見できるかもしれません。

td-agent2にアップデートして変更した設定一覧

と、fileに書き出しては確認。書き出しては確認としていき、完成したのが以下の設定です。

同じような設定で動作しないという方は、v0形式で動作していた「以前の投稿で紹介した設定」と比較してみてください。何かの参考になれば幸いです。

パラメータはコメントで解説しました。詳しく知りたい方はプラグインの解説ページをご覧ください。

基本的にGrowthForecastに転送することを想定しています。

dfでディスク用量を取得してGrowthForecastへ

# dfからディスク容量を取得
<source>
    type df
    option -k              # dfコマンドのオプション
    interval 30            # 実行間隔。そんな頻繁に書き換わらないので30秒
    tag_prefix df          # 接頭辞デフォルトのdfで良い
    target_mounts /        # マウントの指定。普通に/のみなのでこのまま
    replace_slash true     # スラッシュをアンダーバーに置き換えるようだ
    # tag free_disk        # tag (default is nil)
    rm_percent true        # パーセンテージマークを削除する
    hostname false          # ホストネームを追加する
</source>

# GrowthForecastに転送する（ローカル用）
<match df.**> # 上で設定した接頭辞perfをまとめて設定
    type growthforecast
    gfapi_url http://127.0.0.1:5125/api/ # GrowthForecastのURLを指定
    service df # service名を入力（カテゴリ）
    tag_for section # sectionとすると接頭辞（tag）が入る（項目名）
    name_key_pattern .* # パターンを使えるname_keyにあたるもの。この例では全て
</match>

dstatから各種情報を取得しGrowthForecastへ

<source>
    type dstat # dstatプラグインを指定
    tag dstat # ログに付けるタグを指定
    option -cdnm --tcp --udp # dstat実行時のオプションを指定
    delay 10 # 何秒おきにデータを出力するかを指定（結構time waitを消費するので頻度は調整すべし）
</source>
<match dstat> # 対象とするタグを指定
    type copy # out_copyプラグインを指定（複数の出力をする場合に使う）

    # CPU関連の結果だけを取り出す
    # 後にmatchディレクティブでperf.**で一致させるようにtagに接頭辞perfを付ける
    <store> # match dstatの出力を受ける一つ目の受け皿
        type map # mapプラグインを指定
        tag ("perf.cpu") # ログに付けるタグを指定（URLにもなるので/などは使えない）
        time time # ログのイベント日時の指定
        record record["dstat"]["total_cpu_usage"] # 対象となるレコードの指定（dstatプラグインでJSONに変換されたレコード）
    </store>

    # ディスクIO関連の結果だけを取り出す
    <store>
        type map
        tag ("perf.dsk")
        time time
        record record["dstat"]["dsk/total"]
    </store>

    # メモリ関連の結果だけを取り出す
    <store>
        type map
        tag ("perf.mem")
        time time
        record record["dstat"]["memory_usage"]
    </store>

    # TCP関連の結果を抜き出す
    <store>
        type map
        tag ("perf.tcp-sockets")
        time time
        record record["dstat"]["tcp_sockets"]
    </store>

    # 通信量関連の結果を抜き出す
    <store>
        type map
        tag ("perf.network")
        time time
        record record["dstat"]["net/total"]
    </store>

    # UDP関連の結果を抜き出す
    <store>
        type map
        tag ("perf.udp")
        time time
        record record["dstat"]["udp"]
    </store>
</match>

<match perf.**> # 上で設定した接頭辞perfをまとめて設定
    type growthforecast
    gfapi_url http://127.0.0.1:5125/api/
    service dstat
    tag_for section
    remove_prefix perf
    name_key_pattern .* # パターンを使えるname_keyにあたるもの。この例では全て
</match>

Nginxのログからステータスコードやレスポンスタイムを取得しGrowthForecastへ

Nginxのログはデフォルトのmainではなく、ltsv形式で書き出している前提です。

<source>
    type tail # tailプラグインを指定。Fluentdがイベントログをテキストファイルの末尾から読み取れる。
    path /var/log/nginx/access.log # 読み込むログファイルを指定
    pos_file /var/log/td-agent/fluent.log.pos # 指定しないとなぜかwarningが出る
    tag nginx.access # ログにタグを指定
    format ltsv # ltsv形式を読み込む公式プラグイン
    time_key time # nginxで定義したltsvの時間にあたる部分
    time_format %d/%b/%Y:%H:%M:%S %z # ltsvの時間形式を指定
</source>

<match nginx.access> # 上で定義したタグにマッチする
    type copy # マッチしたログを複数の形式で書き出すためのプラグイン
    <store> # copyプラグインの1つ目の出力先
        type file # fileプラグイン（ファイルにログを出力する）
        path /var/log/td-agent/nginx.access
    </store>
    <store>
        type amplifier_filter # amplifier_filterプラグインで小数点の位置を変更
        ratio 1000 # 1000倍にする
        add_prefix amplifier # タグを付ける（前に付くので注意）
        key_pattern .*(reqtime|upsttime)$ # パターンに一致するレコードの値に適用する
    </store>
    <store>
        type datacounter # datacounterプラグインでカウントする
        unit minute # 1分ごとに取得
        tag nginx.access.status_count # タグを付ける
        count_key status # ltsvで設定したレコードを指定
        pattern1 3xx ^3\d\d$
        pattern2 4xx ^4\d\d$
        pattern3 5xx ^5\d\d$
        pattern4 200 ^200$
    </store>
</match>

<match amplifier.nginx.access>
    type growthforecast
    gfapi_url http://127.0.0.1:5125/api/
    service nginx # カテゴリ
    section response # 項目名
    remove_prefix amplifier.nginx.access # 不要タグを削除
    name_keys reqtime,upsttime # ltsvで設定したレコードを指定
</match>

<match nginx.access.status_count>
    type growthforecast
    gfapi_url http://127.0.0.1:5125/api/
    service   nginx # カテゴリ
    section   status_codes # 項目名
    remove_prefix nginx.access.status_count # 不要タグを削除
    name_keys nginx.access_5xx_count,nginx.access_4xx_count,nginx.access_3xx_count,nginx.access_200_count
</match>

MySQLのスロークエリをカウントしてGrowthForecastへ

MySQLのスロークエリは「/var/log/mysql-slow.log」で書き出すことが前提です。
また、デフォルトではmysqlユーザーしか扱えないので、logrotateで読み取り権限も設定するようにしてください。

<source>
     type mysql_slow_query
     path /var/log/mysql-slow.log
     tag mysqld.slow_query
     pos_file /var/log/td-agent/slowquery.log.pos # どこまでログを読んだか保存しとくファイル
</source>

# 小数点を扱えないので繰り上げ処理
<match mysqld.slow_query>
     type amplifier_filter # amplifier_filterプラグインで小数点の位置を変更
     ratio 1000000 # 1000000倍にする
     add_prefix amplifier # タグを付ける
     key_pattern .*(lock_time|query_time|rows_examined|rows_sent)$ # パターンに一致するレコードの値に適用する
</match>

# MySQLのlock_time等の表示と、スロークエリカウント用
<match amplifier.mysqld.slow_query>
    type copy
    <store>
        type file
        path /var/log/td-agent/mysqld.slow_query
    </store>
    <store>
        type numeric_counter # numeric_counterプラグインで範囲を取得する
        unit minute # 1分ごとに取得
        aggregate tag # 集計するタグ デフォルトは現在のtag
        tag responsetime # タグを付ける デフォルトはnumcount
        count_key query_time # カウントするレコードを指定
        pattern1 0-1s 0 1000000 # 1秒以下
        pattern2 1s- 1000000 # 1秒以上
    </store>
    <store>
        type growthforecast
        gfapi_url http://127.0.0.1:5125/api/
        service mysql # カテゴリ
        section slow_query # 項目名（まとめようと思って下のsectionと同じにすると動作しなくなるので注意）
        remove_prefix amplifier.mysqld.slow_query
        name_key_pattern .*(lock_time|query_time|rows_examined|rows_sent)$
    </store>
</match>
 
# カウントしたスロークエリ用
<match responsetime.**>
     type copy
     <store>
          type file
          path /var/log/td-agent/mysqld.slow_query.count
     </store>
     <store>
          type growthforecast
          gfapi_url http://127.0.0.1:5125/api/
          service mysql # カテゴリ
          section slow_query_count # 項目名
          remove_prefix responsetime
          name_key_pattern .*(slow_query_0-1s_count|slow_query_1s-_count)$
     </store>
</match>

以上、さくっとアップデートしようとしたところ、Fluentdの検証方法がわからず、何時間も格闘したというメモでした。