近年、アクセスログを集約して Kibana などで可視化することは普通になってきているが、このログを日常的にどう使えば有用かという情報はあまり出回っていないようである。 Web サーバのアクセスログで何がわかり、何がわからないのか。弊社インフラチームでどのようにログを活用しているか記載する。

アクセスログ

サーバーサイドにおけるアクセスログは、一般的に HTTP リクエスト 1 つにつき 1 行 web サーバが出力するログである。例えば、Apache が標準で吐き出す主なログ項目は以下である。時刻, クライアント IP, リクエスト先頭行, ステータス, ユーザー, レスポンス body サイズ、リファラー, ユーザーエージェントこの情報でもアクセス確認は十分可能だが、詳細な分析を行うのであればログ項目はなるべく多く、ltsv などパースし易い形式で出すのが望ましい。設定例としては https://github.com/bungoume/ume-playbooks/blob/master/webservers/roles/apache/templates/httpd.conf#L53-L76 を参照していただきたい。

ログ分析フロー

闇雲にログを見ても時間を浪費するだけだ。まず分析する目的を決めるべきである。

日常的なメトリクスとして使えるのは以下のような点だろう。

• 全体のアクセス量
  • エラー,レスポンス遅延状況
  • 不審なリクエスト
• CPU 負荷, 通信データ量

アクセスログは時系列データなので、グラフは基本的に X 軸に時刻、Y 軸に件数を表示させる。

CPU 負荷や通信データ量は通常 Zabbix や Prometheus などでモニタリングするが、アクセスログでも時間あたりの「応答時間の合計値」「body サイズ合計値」を縦軸として出力することで、おおよその値が確認できる。アクセスログは path のフィルタ等で詳細な分析が行えるため、単純なリソースメトリクスより有用なケースが多い。

そのほか、

• アプリケーション変更後の影響推測
• 負荷状況や通信データ量の分析
  • キャッシュ効率の改善

などを必要に応じて行う。

SSL の設定を変更した場合、何人のユーザに影響があるのか、古いエンドポイントを削除しても問題ないか、といった情報が即座に取れることはサービスの改善ライフサイクルを早くすることに多いに役に立つ。

いずれのケースにおいても、まずはデータ全体の確認を行い、気になる点があればフィルタを使ってより詳細に調べる流れが良い。

確認順序

原因や影響範囲を具体的に調べる順序としてはまず、値がそれほど分散しない項目 host, method, path, status,server_ip(edge_name) を確認するのがオススメである。

それらで影響範囲が絞れない場合は、次に taken_time,client_ip(x_forwarded_for), user_agent,referer,location res_bytes, upstream_path,upstream_host,load_barancer_ip などを見ていく。

ログ項目

より詳細に見るため、アプリケーションから request_id,user_id,client_id,error_code などを出しておくと便利である。レスポンスヘッダに上手く含めればアクセスログに含められる。

その他、キャッシュ効率向上のため res_cache_control,cache_status,etag,edge_name 通信データ量削減分析として accept_encoding(クライアントが gzip 対応していないと gzip で返さなくて当然) res_content_encoding(gzip されてもデータ量が多いケースはある) res_content_type(画像等には gzip 効果が薄いため) res_body_bytes(res_bytes. サイズにヘッダを含むか区別が必要)

HTTP 関連として h2_server_push ssl_protocol ssl_cipher http_protocol_version などを出力している。

注意すべき点

アクセスログを見る上で、注意すべき点を挙げておこう。

x_forwarded_for の扱い

間にプロキシを複数挟む場合、本来の client_ip は x_forwarded_for や x_client, forwarded ヘッダに記載される。これらの値は追記型で、最初の値はユーザによって任意に書き換え可能なため、適切なプロキシ段数を指定するか、ローカルネットのサブネットを記載して除外して最後に出てくる値を信頼するといった処理が必要である。

時刻の記録はどのタイミングか

apache はリクエストの来た時刻をログとして記録するが、nginx はレスポンス完了時刻を記録する。処理時間が長くなったとき、この記録タイミングの違いにより分析に支障が出る。

記録がレスポンス完了時刻の場合、処理に詰まったのか単にリクエストがなかったのか区別が難しい。リクエスト時間であれば、処理時間だけを見ることでいつから問題が起きているか判断しやすいため、計時にログ時刻から処理時間を引くなどしてリクエスト時刻で統一するのがよいだろう。

逆に apache はログ時刻が一様増加ではないので、パース処理によっては注意が必要だ。

クライアント切断時のログ

サーバー側での処理が終わる前にクライアントが接続を切った場合、ログはサーバによって異なる。

私が確認した範囲では、 nginx の場合は切断時にログが出力され、status:499 で taken_time には切断までの時刻が表示されるが apache はクライアントが切断しても status は 200 で taken_time は処理完了時間が記載される。

AWS ALB は切断時 status460 で taken_time が-1 になるため、処理が遅くて切断されたのか通信状況が悪くて切れたのか判断がつかない。

処理時間はどこからどの時間を指すか

taken_time(request_time)として出力される時間には、リクエスト開始からダウンロード終了までの時間全てが含まれるわけではない。サーバによって計測範囲は異なる。

request_start
->request_end
->server_processing
->response_start
->(response_send_end)
->response_end

詳細は調べられていないが、計測開始は request_end が多く終了時刻として最終パケットに対して ACK を返したタイミングではなく、response バッファにデータを転送し終えたタイミングが記録されるケースや response_start のケースがある様子である。低速なクライアントにより影響を受けたり、逆にダウンロード時間を計測できなかったりするので taken_time はあまり信用しすぎないほうが良いかもしれない。

特に CDN を利用している場合は、具体的な計測範囲が不明確であるし、こちら側で制御できない。このような理由から、ダウンロード時間を計測する場合はサーバーログではなく、RUM の章にある Performance Timing API や Server Timing API によるデータを集計したほうが望ましい。