Herokuのアクセスログを自前のFluentdで収集する

$ heroku drains:add syslog://[FQDN or IP]:[PORT] -a access-log-js
Successfully added drain syslog://HOME.dip.jp:PORT

$ heroku drains -a access-log-js
=== Drains
syslog://HOME.dip.jp:PORT (d.fd8d2572-7604-4521-94df-9fe4dae8fabb)
=== Add-on Drains
papertrail:choklad (papertrail-metric-35971)

Fluentd (td-agent) での Syslog 受信設定

上記設定により、TCP Syslogでログが転送されるため、Fluentd (td-agent) で受信設定をする。最低限の受信設定は以下の通り、TCPの受信設定でログを受け取れる。(Fluentd基本設定は割愛)

<source>
  @type tcp
  port 514xx (syslog drain PORT)
  bind 0.0.0.0
  tag designetwork.access_log.heroku
  format none
</source>

受信したログは以下の通り。(一部マスク)

2017-10-10T19:52:42+09:00   designetwork.access_log.heroku  {"message":"317 <158>1 2017-10-10T10:52:42.350627+00:00 d.fd8d2572-7604-4521-94df-9fe4dae8fabb heroku router - - at=info method=GET path=\"/script/access_log.js\" host=access-log-js.herokuapp.com request_id=bacbef15-abdc-40ae-b9e4-32f0ba13414b fwd=\"x.x.x.x\" dyno=web.1 connect=0ms service=2ms status=200 bytes=327 protocol=http"}
2017-10-10T19:52:43+09:00   designetwork.access_log.heroku  {"message":"250 <190>1 2017-10-10T10:52:42.350167+00:00 d.fd8d2572-7604-4521-94df-9fe4dae8fabb app web.1 - - 10.65.79.7 - - [10/Oct/2017:10:52:42 +0000] \"GET /script/access_log.js HTTP/1.1\" 200 84 \"-\" \"Mozilla/4.0 (compatible; MSIE 8.0; Windows NT 5.1; Trident/4.0)"}
2017-10-10T19:58:39+09:00   designetwork.access_log.heroku  {"message":"317 <158>1 2017-10-10T10:58:39.053006+00:00 d.fd8d2572-7604-4521-94df-9fe4dae8fabb heroku router - - at=info method=GET path=\"/script/access_log.js\" host=access-log-js.herokuapp.com request_id=bf3e5470-6036-4fb0-a0e7-046ea646769b fwd=\"x.x.x.x\" dyno=web.1 connect=0ms service=1ms status=200 bytes=327 protocol=http"}
2017-10-10T19:58:40+09:00   designetwork.access_log.heroku  {"message":"393 <190>1 2017-10-10T10:58:39.052405+00:00 d.fd8d2572-7604-4521-94df-9fe4dae8fabb app web.1 - - 10.13.233.121 - - [10/Oct/2017:10:58:39 +0000] \"GET /script/access_log.js HTTP/1.1\" 200 84 \"http://designetwork.hatenablog.com/entry/2016/04/09/Windows-Server-2016-Technical-Preview\" \"Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/61.0.3163.100 Safari/537.36"}
2017-10-10T20:07:32+09:00   designetwork.access_log.heroku  {"message":"316 <158>1 2017-10-10T11:07:32.046948+00:00 d.fd8d2572-7604-4521-94df-9fe4dae8fabb heroku router - - at=info method=GET path=\"/script/access_log.js\" host=access-log-js.herokuapp.com request_id=cedeb331-609d-49e1-915b-7b0bc3b103d2 fwd=\"x.x.x.x\" dyno=web.1 connect=0ms service=1ms status=304 bytes=127 protocol=http"}
2017-10-10T20:07:32+09:00   designetwork.access_log.heroku  {"message":"307 <190>1 2017-10-10T11:07:32.050362+00:00 d.fd8d2572-7604-4521-94df-9fe4dae8fabb app web.1 - - 10.145.25.250 - - [10/Oct/2017:11:07:32 +0000] \"GET /script/access_log.js HTTP/1.1\" 304 - \"http://designetwork.hatenablog.com/entry/2017/01/21/esxi6.5-centos7.3\" \"Mozilla/5.0 (Windows NT 6.1; WOW64; Trident/7.0; rv:11.0) like Gecko"}

(参考)サンプルログ

サンプルログとして、はてなブログの記事中にScriptを埋め込み、Heroku上のJavaScriptを取得するようにしている。(自身でのアクセスログ解析のため)

<script type="text/javascript" src="https://access-log-js.herokuapp.com/script/access_log.js"></script>

Heroku Router を考慮したパース

Herokuは内部でHTTPリクエストルーティングが組み込まれており、すべての通信はHeroku Routerを経由する。そのため、アクセスログはheroku routerとapp web.xという二つ一組で出力される。

アクセス元IPアドレスの取得がやや面倒で、app web.xで見えるIPアドレス10.x.x.xはHeroku RouterのIPアドレスで、実際のアクセス元IPアドレスはheroku routerのfwd=\"x.x.x.x\"部分になる。

上記を踏まえて、Fluentdではmultiline Parser Pluginを使用して二行をまとめてパースする。

事前準備としてpos管理用ディレクトリを作成

$ sudo mkdir -p /var/log/td-agent/pos/designetwork
$ sudo chown td-agent:td-agent /var/log/td-agent/pos
$ sudo chown td-agent:td-agent /var/log/td-agent/pos/designetwork

multiline Parser Pluginはtailインプットのみで使用可能なため、一旦ファイルに保存し、それを再度取り込む構成とする。

<source>
  @type tcp
  port 51411
  bind 0.0.0.0
  tag designetwork.access_log.heroku.raw
  format none
</source>

<match designetwork.access_log.heroku.raw>
  @type file
  path /var/log/td-agent/designetwork/access_log.raw
  append true
</match>

<source>
  @type tail
  path /var/log/td-agent/designetwork/access_log.raw.*
  pos_file /var/log/td-agent/pos/designetwork/access_log.raw.pos
  format multiline
  multiline_flush_interval 5s
  format_firstline /heroku router/
  format1 /.*\"message\":\"\d+ <\d+>\d+ (?<time>\d+-\d+-\d+T\d+:\d+:\d+\.\d+\+\d+:\d+) (?<container_id>[^ ]+) .* fwd=\\\"(?<src_ip>\d+\.\d+\.\d+\.\d+)\\\" .*/
  format2 /.*://(?<access_host>[^/]+)(?<access_path>[^"]+)\\" .*/
  time_key time
  tag designetwork.access_log.heroku
</source>

見直しの余地はあるが、上記の通り二行にまたがる正規表現でマッチングすることにより、以下の通り、src_ip, access_host, access_pathを抽出できた。

2017-10-10T22:12:07+09:00   designetwork.access_log.heroku  {"container_id":"d.fd8d2572-7604-4521-94df-9fe4dae8fabb","src_ip":"103.x.x.x","access_host":"designetwork.hatenablog.com","access_path":"/entry/2016/12/05/home-server-selection"}
2017-10-10T22:15:33+09:00   designetwork.access_log.heroku  {"container_id":"d.fd8d2572-7604-4521-94df-9fe4dae8fabb","src_ip":"117.x.x.x","access_host":"designetwork.hatenablog.com","access_path":"/entry/2016/11/19/sync-request-post-node-js"}
2017-10-10T22:19:43+09:00   designetwork.access_log.heroku  {"container_id":"d.fd8d2572-7604-4521-94df-9fe4dae8fabb","src_ip":"27.x.x.x","access_host":"designetwork.hatenablog.com","access_path":"/entry/2016/04/09/Windows-Server-2016-Technical-Preview"}