Heroku アプリのログを fluentd で ElasticSearch に突っ込んで Kibana で監視する方法

目的

Kibana で Heroku アプリのログを可視化したい。ただし、レスポンスタイムとかは New Relic でも見れるので、ここではアプリが出力したらログを可視化する方法を紹介する。

また、今回、アプリからの出力を可能な限りに簡単にするために、アプリからは Heroku の STDOUT に出力するだけで、ログを Kibana サーバに送信できるようにしてみた。

具体的にはこう。（Ruby の場合）出力の形式は、Treasure Data addon の方法を真似ている。

puts "@[tag.name] #{{'uid'=>123}.to_json}"

これで、tag.name が fluentd の tag 名に、それに続く JSON 文字列が送信するデータとして処理される。

環境

Amazon EC2 上に Kibana サーバを構築
OS は Ubuntu 13.10
td-agent と ElasticSearch は導入済み

タイトルで fluentd と書いたが、正確には td-agent を使っているので、fluentd を使っている人は適宜読み替えること。

ログデータの流れ

処理の概要は以下の通り。

Heroku -> (syslog drains)
 -> rsyslog -> (syslog file)
 -> Fluentd(in_tail, rewrite, parser, elasticsearch)
 -> ElasticSearch
 -> Kibana

Heroku の syslog drains を利用して、Kibana サーバに syslog を送信
Kibana サーバに rsyslog サーバを立てて、Heroku からの syslog を受信して、ファイルに出力
Fluentd の in_tail 機能を利用して、ログを読み込み、rewrite, parser プラグインを利用して、ログの変形とフィルタリング
elasticsearch プラグインを利用して ElasticSearch にログを投入
Kibana で見る

Heroku の設定

Heroku の syslog drains 機能を利用して、syslog を指定したサーバに送信する設定をする。 Kibana サーバで 5140 ポートで rsyslog サーバを起動する場合。

$ heroku drains:add syslog://[kibana-server]:5140 -a [heroku-app-name]
Successfully added syslog://[kibana-server]:5140

追加が完了したら、heroku drains コマンドで、drain ID を取得する。この d. で始まる drain ID は後で使うので、記録しておく。

$ heroku drains -a [heroku-app-name]
syslog://[kibana-server]:5140 (d.XXXX)
#                             ~~~~~~~~ ここが drain ID

参考：https://devcenter.heroku.com/articles/logging#syslog-drains

注意点としては、Kibana サーバを EC2 に立てている場合は、Elastic IP を設定した上で、Public DNS をサーバ名として指定する必要があること。これは Heroku 側で AWS の Private Address として Look up できないといけない Heroku のセキュリティ上の仕様のため。

参考: https://devcenter.heroku.com/articles/logging#security-access この制限は今はない。

rsyslog の設定

TCP サーバの起動

Heroku は UDP ではなく TCP で syslog を送信してくるので、rsyslog で TCP サーバを起動する。 /etc/rsyslog.conf を開いて、以下を追記（または、今ある要素をコメントアウト解除）

$ModLoad imtcp
$InputTCPServerRun 5140 # ポート番号は heroku drains で設定したポートを指定。

ファイル作成権限の変更

デフォルトだと、syslog は root:adm に 0640 で作成されるので、fluentd から読み出すことができない。なので、ファイルの作成権限の変更を行います。同じく、/etc/rsyslog.conf の最後に以下を追記する。

$FileCreateMode 0644
$DirCreateMode 0755

参考: http://y-ken.hatenablog.com/entry/fluentd-syslog-permission

ログファイルの振り分け

デフォルトだと、/var/log/syslog に heroku のログが出力されていまうのだが、これだと fluentd で in_tail しにくいので、これを別ファイルに振り分ける。ここでは /var/log/heroku に出力するようにしてみる。

/etc/rsyslog.d/40-heroku.conf という名前のファイルを作成し、以下の内容を記述。

if $hostname startswith '[heroku drain ID]' then /var/log/heroku
& ~

1行目が振り分け設定。2行目が1行目で一致したログを後続の syslog に出力しないようにする設定。もし、複数の Heroku の syslog を受ける場合は、上記の2行をdrain IDを変えながら、繰り返して記述する。

RuleSet を使って、TCP で受け付けるデータのフィルタリングとかすると良いかも。（ここは調整中） http://www.rsyslog.com/doc/multi_ruleset.html

ログローテーションの設定

振り分け設定したログに対して、/etc/logrotate.d/rsyslog にログローテーションの設定をする。以下は daily で 7日間でローテーションする設定する例。

/var/log/heroku
{
        rotate 7
        daily
        missingok
        notifempty
        delaycompress
        compress
        postrotate
                reload rsyslog >/dev/null 2>&1 || true
        endscript
}

rsyslog を再起動

全ての設定を保存したら、rsyslog を再起動。

$ sudo service rsyslog restart

AWS security group の設定

AWS の security group の設定で、EC2 インスタンスに紐付いた security group の TCP 5140 ポートを開放する設定をする。Management Console からでも良いし、aws cli で以下のようにしても良い。

$ aws ec2 authorize-security-group-ingress --group-name MySecurityGroup --protocol tcp --port 5140 --cidr 0.0.0.0/32

AWSじゃない人は、Firewallの設定で同様に 5140 ポートを開放する。

正しく設定できれば、この時点で /var/log/heroku に heroku の syslog が出力されているはず。tailして確認してみる。

$ tail -f /var/log/heroku
Feb  2 03:41:32 [drain ID] app[web.`] Started GET "/XXX" for XXX.XXX.XXX.XXX at 2014-02-02 03:41:32 +0000

こんな感じのログが見えれば、設定は完了。

fluentd の設定

必要な gem のインストール

td-agentの場合は、fluent-gem を使うように注意する。

$ fluent-gem install fluent-plugin-rewrite
$ fluent-gem install fluent-plugin-parser
$ fluent-gem install fluent-plugin-elasticsearch

td-agent.conf の設定

処理の概要は、以下の通り。

in_tail で heroku の syslog を解析
fluent-plugin-rewrite でアプリログと Heroku のログを振り分け
fluent-plugin-parser でJSON データの解析
fluent-plugin-elasticesearch で ElasticSearch に出力

実際の /etc/td-agent/td-agent.conf の設定はこう。

<source>
  type tail
  path /var/log/heroku
  pos_file /var/log/td-agent/posfile_heroku.pos
  format /^(?<time>[^ ]*\s+[^ ]*\s+[^ ]*) (?<host>[^ ]*) (?<ident>[a-zA-Z0-9_\/\.\-]*)(?:\[(?<pid>[a-zA-Z0-9\.]+)\])? *(?<message>.*)$/
  time_format %b %d %H:%M:%S
  tag heroku.syslog
</source>

# アプリログとHerokuが出力するログを振り分け
<match heroku.syslog>
  type rewrite
  <rule>
    key message
    pattern ^@\[([a-zA-Z0-9_\.]+)\]\s+.*$
    append_to_tag true
    fallback others
  </rule>
  <rule>
    key message
    pattern ^@\[[a-zA-Z0-9_\.]+\]\s+(.*)$
    replace \1
  </rule>
</match>

# アプリログ以外は読み捨て
<match heroku.syslog.others>
  type null
</match>

# アプリログの処理
# ここでは @[app.XXX] JSON と出力していることを想定
# JSON データは message プロパティに文字列として格納されている
<match heroku.syslog.app.**>
  type parser
  remove_prefix heroku.syslog
  key_name message
  format json
  reserve_data true
</match>

# ElasticSearch に出力
<match app.**>
  type elasticsearch
  type_name app
  include_tag_key true
  tag_key @log_name
  host localhost
  port 9200
  logstash_format true
  flush_interval 3s
</match>

再起動

設定を保存したら、fluentd (td-agent) を再起動。

$ sudo service td-agent restart

しばらくすると、Kibana でデータが見えるようになる。楽しい！

hakobera's blog

技術メモ。たまに雑談