Amazon Athena RegexSerDe を利用して CLB ログ / Apache Web のアクセスログを探索する

eyecatch_athena

本日は、Amazon Athena RegexSerDe を利用して CLB / ELB v1 (Classic Load Balancer / Elastic Load Balancing Version 1)のログを探索する方法を紹介します。CLBのファイルフォーマットは Apache Web の アクセスログ と同じ形式なので、ウェブのアクセスログも CLB と同様に Amazon Athena で探索することが可能です。

CLB / ELB v1 とは

CLB は、アクセスログを使用して、ロードバランサーに対して行われたリクエストの詳細情報をキャプチャし、Amazon S3 でログファイルとして保存できます。これらのアクセスログを使用して、トラフィックパターンの分析や、ターゲットの問題のトラブルシューティングを行うことができます。

2016年8月にALB(Application Load Balancer)がリリースされるまで、ELBは、CLB(Classic Load Balancer)を意味していました。現在は、ELB のVersion1 が CLB(Classic Load Balancer)、ELB のVersion2 が ALB(Application Load Balancer)をそれぞれ意味します。

CLB は、ウェブブラウザをはじめとするクライアントのトラフィックを複数のアベイラビリティーゾーンの複数の EC2 インスタンス間で分散し、クライアントにとって単一の通信先として機能します。クライアントからのアクセスログは、CLB に対するリクエストの詳細情報をキャプチャし、それをログファイルとして、指定した Amazon S3 バケットに保存します。なお、CLB のアクセスログを有効にするには、アクセスログの有効化 (Classic Load Balancer) を御覧ください。

以降、このアクセスログファイルに対して、Amazon Athena のテーブル定義とログの探索をご紹介します。

CLBのアクセスログ

各ログエントリには、ロードバランサーに対する 1 件のリクエストの詳細が含まれます。ログエントリのすべてのフィールドはスペースで区切られています。ログファイルの各エントリは次の形式になります。

timestamp elb_name client_addrport backend_addrport request_processing_time backend_processing_time response_processing_time elb_status_code backend_status_code received_bytes sent_bytes "request" "user_agent" ssl_cipher ssl_protoc

様々なアクセスログエントリを確認したいので、CLBのマニュアルアクセスログのエントリの例から引用しました。

2015-05-13T23:38:43.945958Z my-loadbalancer 192.168.131.39:2817 - 0.000073 0.001048 0.000057 200 200 0 29 "GET http://www.example.com:81/ HTTP/1.1" "curl/7.38.0" - -
2015-05-13T23:39:43.945958Z my-loadbalancer 192.168.131.39:2817 10.0.0.1:80 0.000073 0.001048 0.000057 200 200 0 29 "GET http://www.example.com:80/ HTTP/1.1" "curl/7.38.0" - -
2015-05-13T23:39:43.945958Z my-loadbalancer 192.168.131.39:2817 10.0.0.1:80 0.000086 0.001048 0.001337 200 200 0 57 "GET https://www.example.com:443/ HTTP/1.1" "curl/7.38.0" DHE-RSA-AES128-SHA TLSv1.2
2015-05-13T23:39:43.945958Z my-loadbalancer 192.168.131.39:2817 10.0.0.1:80 0.001069 0.000028 0.000041 - - 82 305 "- - - " "-" - -
2015-05-13T23:39:43.945958Z my-loadbalancer 192.168.131.39:2817 10.0.0.1:80 0.001065 0.000015 0.000023 - - 57 502 "- - - " "-" ECDHE-ECDSA-AES128-GCM-SHA256 TLSv1.2

テーブル定義

上記のログファイルのフィールドを、以下の様にテーブルのカラムにマッピングしています。CLB がバックエンドのEC2インスタンスと通信できない場合もクエリできるように、IP と PORT のカラムを別にマッピングしています。

フィールド 説明
request_timestamp ロードバランサーがクライアントからリクエストを受け取った時刻 (ISO 8601 形式)。
elb_name ロードバランサーの名前
client_addrport リクエストを送信したクライアントの IP アドレスとポート。
client_ip リクエストを送信したクライアントの IP アドレス。
client_port リクエストを送信したクライアントのポート。
backend_addrport このリクエストを処理した登録済みインスタンスの IP アドレスとポート。

ロードバランサーが登録されたインスタンスにリクエストを送信できない場合、または応答が送信される前にインスタンスが接続を閉じた場合、この値は - に設定されます。

登録済みインスタンスからアイドルタイムアウトまで応答がない場合にも、この値は - に設定される場合があります。

backend_ip このリクエストを処理した登録済みインスタンスの IP アドレス。

ロードバランサーが登録されたインスタンスにリクエストを送信できない場合、または応答が送信される前にインスタンスが接続を閉じた場合、この値は null に設定されます。

登録済みインスタンスからアイドルタイムアウトまで応答がない場合にも、この値は null に設定される場合があります。

backend_port このリクエストを処理した登録済みインスタンスのポート。

ロードバランサーが登録されたインスタンスにリクエストを送信できない場合、または応答が送信される前にインスタンスが接続を閉じた場合、この値は null に設定されます。

登録済みインスタンスからアイドルタイムアウトまで応答がない場合にも、この値は null に設定される場合があります。

request_processing_time [HTTP リスナー] ロードバランサーがリクエストを受け取った時点から登録済みインスタンスに送信するまでの合計経過時間 (秒単位)。

[TCPリスナー] ロードバランサーがクライアントから TCP/SSL 接続を受け入れた時点から、ロードバランサーがデータの最初のバイトを登録されたインスタンスに送信するまでの合計経過時間 (秒単位)。

ロードバランサーがリクエストを登録済みインスタンスにディスパッチできない場合、この値は -1 に設定されます。この状況が発生するのは、登録済みインスタンスがアイドルタイムアウト前に接続を閉じた場合か、クライアントが誤った形式のリクエストを送信した場合です。さらに、TCP リスナーの場合、クライアントがロードバランサーと接続を確立するが、データを送信しない場合にもこの状況が発生する可能性があります。

登録済みインスタンスからアイドルタイムアウトまで応答がない場合にも、この値は -1 に設定される場合があります。

backend_processing_time (HTTP リスナーの場合) ロードバランサーが登録済みインスタンスにリクエストを送信した時点から、そのインスタンスが応答ヘッダーの送信を開始した時点までの合計経過時間 (秒単位)。

[TCP リスナー] ロードバランサーが、登録済みインスタンスへの接続を正常に確立するまでの合計経過時間 (秒)。

ロードバランサーがリクエストを登録済みインスタンスにディスパッチできない場合、この値は -1 に設定されます。この状況が発生するのは、登録済みインスタンスがアイドルタイムアウト前に接続を閉じた場合か、クライアントが誤った形式のリクエストを送信した場合です。

登録済みインスタンスからアイドルタイムアウトまで応答がない場合にも、この値は -1 に設定される場合があります。

response_processing_time (HTTP リスナーの場合) ロードバランサーが登録済みインスタンスから応答ヘッダーを受け取った時点から、クライアントへの応答の送信を開始した時点までの合計経過時間 (秒単位)。これには、ロードバランサーでの待機時間と、ロードバランサーからバックエンドへの接続の取得時間の両方が含まれます。

(TCP リスナーの場合) ロードバランサーが登録済みインスタンスから最初のバイトを受け取った時点から、クライアントへの応答の送信を開始した時点までの合計経過時間 (秒単位)。

ロードバランサーがリクエストを登録済みインスタンスにディスパッチできない場合、この値は -1 に設定されます。この状況が発生するのは、登録済みインスタンスがアイドルタイムアウト前に接続を閉じた場合か、クライアントが誤った形式のリクエストを送信した場合です。

登録済みインスタンスからアイドルタイムアウトまで応答がない場合にも、この値は -1 に設定される場合があります。

elb_status_code (HTTP リスナーの場合) ロードバランサーからの応答のステータスコード。
backend_status_code (HTTP リスナーの場合) 登録済みインスタンスからの応答のステータスコード。
received_bytes クライアント (リクエスタ) から受け取ったリクエストのサイズ (バイト単位)。

(HTTP リスナーの場合) この値にはリクエストの本文が含まれますがヘッダーは含まれません。

(TCP リスナーの場合) この値にはリクエストの本文とヘッダーが含まれます。

sent_bytes クライアント (リクエスタ) に返される応答のサイズ (バイト単位)。

(HTTP リスナーの場合) この値には応答の本文が含まれますがヘッダーは含まれません。

(TCP リスナーの場合) この値にはリクエストの本文とヘッダーが含まれます。

request クライアントからのリクエスト行は二重引用符で囲まれており、次の形式でログに記録されます。HTTP メソッド + プロトコル://ホストヘッダー:ポート + パス + HTTP バージョン。

(TCP リスナーの場合) URL は、3 個のダッシュをそれぞれスペース 1 個で区切り、末尾がスペースになります ("- - - ")。

user_agent [HTTP/HTTPS リスナー] リクエスト元のクライアントを特定する User-Agent 文字列。この文字列は、1 つ以上の製品 ID (製品[/バージョン]) から構成されます。文字列が 8 KB より長い場合は切り捨てられます。
ssl_cipher [HTTPS/SSL リスナー] SSL 暗号。正常なネゴシエーションの後に受信 SSL/TLS 接続が確立した場合にのみ、この値が記録されます。それ以外の場合、値は - に設定されます。
ssl_protocol [HTTPS/SSL リスナー] SSL プロトコル。正常なネゴシエーションの後に受信 SSL/TLS 接続が確立した場合にのみ、この値が記録されます。それ以外の場合、値は - に設定されます。

では、これらを順にカラムとして定義します。Amazon Athena は、ログが複数のファイルの場合でも、同じフォルダに配置することで同じテーブル内のデータとしてクエリーを実行できます。

CREATE EXTERNAL TABLE IF NOT EXISTS clb_logs (
request_timestamp string,
elb_name string,
client_addrport string,
client_ip string,
client_port int,
backend_addrport string,
backend_ip string,
backend_port int,
request_processing_time decimal(8,6),
backend_processing_time decimal(8,6),
response_processing_time decimal(8,6),
elb_status_code string,
backend_status_code string,
received_bytes int,
sent_bytes int,
request string,
user_agent string,
ssl_cipher string,
ssl_protocol string
)
ROW FORMAT SERDE 'org.apache.hadoop.hive.serde2.RegexSerDe'
WITH SERDEPROPERTIES (
'serialization.format' = '1',
'input.regex' = '([^ ]*) ([^ ]*) (([0-9.]*):([0-9]*)|-) (([0-9.]*):([0-9]*)|-) ([^ ]*) ([^ ]*) ([^ ]*) ([^ ]*) ([^ ]*) ([^ ]*) ([^ ]*) (\\"[^\\"]*\\") (\\"[^\\"]*\\") ([^ ]*) ([^ ]*)$'
)
LOCATION 's3://devio2017-handson/07-clblogs/2015/05/13/'
TBLPROPERTIES ('has_encrypted_data'='false');

上記のDDLをテンプレートとして利用する場合、LOCATION に指定するクエリ対象のロフファイルを保存している S3バケット/フォルダ名を変更するだけで、再利用できます。

全てのレコードの全てのカラムデータが参照できることが確認できます。

20170725-clblogs-all

CLB ログを探索

別のデータにて、CLB ログを探索する例をご紹介します。

CLB毎のリクエスト数

CLBをデプロイすると複数のCLBインスタンスが起動されます。CLBのインスタンス毎に処理しているリクエスト数を参照することができます。

20170725-clblogs-request_per_elb

ELB毎のレスポンスコードの出現数

ウェブアプリケーションを運用していると、ウェブサーバーのレスポンスコードが何かによって、障害原因がサーバーとクライアントのどちらであるかを切り分けしたり、更にその出現頻度を把握することができます。下記の例では、レスポンスコードが500番以上、つまりサーバーのエラーレスポンスをCLB毎に集計しています。

20170725-clblogs-sever_error_per_elb

リクエスト数をIPアドレス毎に表示

単位時間あたりの IP アドレス毎のリクエスト数の Top10 を表示します。特定のIPアドレスからリクエストが集中的に発生している場合はDoS攻撃の可能性があります。サービス継続に支障をきたす場合は、Network ACL で IP アドレスをブロックするなどの対策が可能になります。

20170725-clblogs-request_per_ip

CLB のログを簡単に「速く」「安く」探索するには

ログファイルの検索範囲を限定する

CLBのログは、デフォルトで年月日の階層的なフォルダ構成になっていますので、簡単に期間を限定できます。 例えば、

  • 2017年1月1日の場合: s3://<logbacket and folder>/2017/01/01/
  • 2017年1月の場合: s3://<logbacket and folder>/2017/01/
  • 2017年の場合: s3://<logbacket and folder>/2017/

探索範囲のスコープが明らかな場合は、利用費の削減や応答時間の短縮の観点から探索するログの期間を限定することをおすすめします。

パーティション設定する

CLBのログのフォルダ名や階層は決まっているので、「カラム名なしパーティション」として、パーティションを設定します。上記のテーブル定義に PARTITIONED BY (year int, month int, day int) を追加して、テーブルを再作成した後、ログの検索範囲のパーティションを追加します。恒久的にテーブルを定義して、常ににログを監視したい場合は、パーテイション設定することもご検討ください。パーティションの設定は Scenario 2: Data is not partitioned を御覧ください。

その他

読み込むファイルサイズを小さくするためデータの圧縮がベターですが、CLBのログファイルが既にgzip圧縮済みですのでそのままで構いません。その他、ファイルサイズの最適化やカラムナフォーマットへの変換については、必要に応じて検討してください。

最後に

今回の内容は、Developers.IO 2017 ハンズオンセミナー でご紹介した内容の一部です。Grepのような文字列検索のみならず、カラム間の状態による抽出や集計ができるのは、Amazon Athenaならではの特長です。CLB は "Classic" と言われてもまだまだ現役で使われていることが多いので覚えておいて損はありません。

関連ブログ: Amazon Athena RegexSerDe を利用して ALB ログを探索する