Y-Ken Studio

新しもの好きのデータエンジニアが四方山話をお届けします。

ApacheログをLTSV形式にする際の２つの落とし穴と対処法＋Apache＆FluentdのLTSV設定サンプル

CentOS Apache fluentd

ApacheのアクセスログをLTSV形式にしたいと思った方に是非お伝えしたい、
私がハマった落とし穴とその対処方法、その後にApacheとFluentdの設定サンプルを紹介します。

以下に1つでも該当するものがあれば、LTSVの導入メリットは高いでしょう。

  • テクニカルな正規表現のメンテナンスに疲れた
  • awk等のテキスト整形ツールで加工や集計を容易に行いたい
  • ログ収集ツールFluentdを使ってリアルタイム集計などを行いたい

落とし穴 その１「request_first_line」

一般的なApacheの設定ファイルhttpd.confでは、デフォルトで以下の設定が行われています。

LogFormat "%h %l %u %t \"%r\" %>s %b \"%{Referer}i\" \"%{User-Agent}i\"" combined

このLogFormatStringをそのままLTSV形式にすると、以下の形式になります。

LogFormat "host:%h\tident:%l\tuser:%u\ttime:%t\trequest_first_line:%r\tstatus:%>s\tsize:%b\treferer:%{Referer}i\tagent:%{User-Agent}i" combined

読みづらいので、タブを改行に置換したものはこちら。

host:%h
ident:%l
user:%u
time:%t
request_first_line:%r
status:%>s
size:%b
referer:%{Referer}i
agent:%{User-Agent}i

これのどこに落とし穴があるかというと、request_first_line:%rにあります。
Apache combine形式の\"%r\"をLSTV化したrequest_first_line:%rは、
request_first_line:GET /apache_pb.gif HTTP/1.0 という出力となります。
このキーには、request_first_lineの値にREQUEST_URI以外も含まれているため、
データ加工が困難になるのです。

著名な方のブログでも言及されています。

今からLTSVでhttpdのログを扱い始めるなら、リクエストを
「req:GET / HTTP/1.0」のように単一のフィールドに入れるのは避けるべきだと思います。
HTTP/2.0 になった時に対応できない可能性があるので…
http://d.hatena.ne.jp/kazuhooku/20130208/1360322477

ではどうするか？

公式ドキュメントにそのものズバリな説明がありました。

"GET /apache_pb.gif HTTP/1.0"
クライアントからのリクエストが二重引用符の中に示されています。
リクエストには多くの有用な情報があります。
まず、この場合クライアントが 使ったメソッドは GET です。
次に、クライアントは リソース /apache_pb.gif を要求しました。
そして、 クライアントはプロトコル HTTP/1.0 を使用しました。
リクエストの各部分を独立にログ収集することもできます。
例えば、 フォーマット文字列 "%m %U%q %H" は メソッド、パス、
クエリ文字列、プロトコルをログ収集し、 結局 "%r" とまったく同じ出力になります。 http://httpd.apache.org/docs/2.2/ja/logs.html

素晴らしい。これは使うしか無いですね！

request_first_line:%rを以下の3つに分割する事で、この問題を解決しましょう。

  • method:%m
  • path:%U%q
  • protocol:%H

落とし穴 その２「time」

もう1つ、落とし穴を発見しました。 time:%tだと出力は中括弧で囲われたtime:[27/Apr/2013:20:09:01 +0900]となります。
このままでは2つ問題があります。

  • 中括弧があるので文字列処理が手間となる
  • Fluentdの設定も以下のように手を入れる必要がある
    time_format [%d/%b/%Y:%H:%M:%S %z]という具合に中括弧で囲う

そのため、%tと中身は同一だが中括弧無しで出力される
time:%{%d/%b/%Y:%H:%M:%S %z}tを使いましょう。
Fluentd側のtime_format設定も変更する必要はありません。

ApacheのアクセスログをLTSV形式にする際のオススメ設定

これらの落とし穴を踏まえて次に、httpd.confのLogFormat設定のオススメを紹介します。
今回はcombined形式に含まれている情報に加えて、あると便利なデータも含めた例で紹介します。

  • Hostヘッダー内容
  • 応答を返したサーバのローカルIPアドレス
  • cookieの送受信内容（セッションID含む）
  • マイクロ秒単位での応答速度
LogFormat "domain:%V\thost:%h\tserver:%A\tident:%l\tuser:%u\ttime:%{%d/%b/%Y:%H:%M:%S %z}t\tmethod:%m\tpath:%U%q\tprotocol:%H\tstatus:%>s\tsize:%b\treferer:%{Referer}i\tagent:%{User-Agent}i\tresponse_time:%D\tcookie:%{cookie}i\tset_cookie:%{Set-Cookie}o" combined

内容としては以下の通り。

項目名 Format String 説明
domain %V Hostヘッダーの内容
host %h リクエストしたリモートホスト名
server %A 応答を返したサーバのローカルIPアドレス
ident %l リモートユーザ名
user %u 認証に使用されたリモートユーザー名
time %{%d/%b/%Y:%H:%M:%S %z}t リクエストを受けた時刻
method %m リクエストメソッド
path %U%q REQUEST_URI
protocol %H リクエストプロトコル
status %>s サーバーがリクエストに対して返したステータスコード
size %b HTTPヘッダを除いた転送バイト数
referer %{Referer}i Refererヘッダーの内容
agent %{User-Agent}i User-Agentヘッダーの内容
response_time %D リクエストを処理するのにかかった時間、マイクロ秒単位
cookie %{cookie}i サーバが受信したクッキー
set_cookie %{Set-Cookie}o サーバが送出したクッキー

出力サンプル

$ curl -v localhost/foo/bar?foo=bar -H "Host: foo.bar.jp" -A "Mozilla"

$ sudo tail -1 /var/log/httpd/access_log | perl -pe 's/\t/\n/g'
domain:foo.bar.jp
host:127.0.0.1
server:127.0.0.1
ident:-
user:-
time:27/Apr/2013:20:44:13 +0900
method:GET
path:/foo/bar?foo=bar
protocol:HTTP/1.1
status:404
size:205
referer:-
agent:Mozilla
response_time:795
cookie:-
set_cookie:-

$ sudo tail /var/log/td-agent/td-agent.log | perl -pe 's/","/"\n"/g'
2013-04-27 20:44:13 +0900 td.apache.access: {"domain":"foo.bar.jp"
"host":"127.0.0.1"
"server":"127.0.0.1"
"ident":"-"
"user":"-"
"time":"27/Apr/2013:20:44:13 +0900"
"method":"GET"
"path":"/foo/bar?foo=bar"
"protocol":"HTTP/1.1"
"status":"404"
"size":"205"
"referer":"-"
"agent":"Mozilla"
"response_time":"795"
"cookie":"-"
"set_cookie":"-"}

Fluentd側のLTSV形式ログを読み込む設定

ログ収集ツールfluentd-v0.10.32で、LTSV形式に標準対応しました。
fluentdをyumで入れられるパッケージtd-agentを利用している方向けに、Apache＋LTSVの設定サンプルも紹介します。

<source>
  type tail
  path /var/log/httpd/access_log
  format ltsv
  time_key time
  time_format %d/%b/%Y:%H:%M:%S %z
  tag td.apache.access
  pos_file /var/log/td-agent/apache_access.pos
</source>

まとめ

以上、LTSV形式を採用する時の2つのTipsでした。
* %rは扱いにくいので利用を避け、%m %U%q %Hの3つに分割しましょう。
* %tは中括弧で囲われるため、time:%{%d/%b/%Y:%H:%M:%S %z}tを使いましょう。

それでは良いLTSVライフをお過ごし下さい！！

更新履歴

  • 2013/04/29 落とし穴「time」を追加し、LogFormatの表記を修正
  • 2013/04/30 fluentd側の設定にtime_keyを応急処置的に追加
    time_formatのみを指定してもfluentdにログが読み込まれた時刻となる問題について、修正版をpullreqしております。それまではtime_keyも指定しましょう。https://github.com/fluent/fluentd/pull/124
  • 2013/05/06 先日のpullreqが取り込まれました。次期リリースfluentd-0.10.33へ含まれる予定です