[IMPORTANT]
この記事で紹介した事象に対応したAthenaテーブル定義が、すでに公式ドキュメントで公開されています。
正式な対応方法については公式ドキュメントをの情報をご参照ください。
先日、Athenaを使ってALBのアクセスログを集計していたところ、ある日のログを境にクエリ結果が表示されなくなってしまいました。
調査の結果、S3に出力されているALBアクセスログの末尾に、テーブル定義に存在しないフィールドが追加されていることが原因で、
ログのパースがうまくいかず、クエリ結果が表示されなくなっていることがわかりました。
追加されたフィールドの値は、TID_から始まる文字列で、数日前から一部のログに追加されはじめていました。
フィールドの追加されていないログレコードは、既存のテーブルへのクエリで集計ができていたため、
すべてのログに未定義のフィールドが追加された状態になるまで気が付きませんでした。
ALBアクセスログエントリのフォーマットに追加があったのかと思い、公式ドキュメントを確認したり、AWSブログ、AWS Health Dashboardの通知を確認しましたが、情報は見つかりませんでした。
追加されたフィールドの詳細についてはAWSサポートに問い合わせが必要ですが、それはそれとして、ログの集計の業務を行わなければなりません。
追加フィールドのカラムを追加した、新しいテーブルを作成して対応する場合、新しいテーブルでは、追加フィールドのない古いログを集計できなくなってしまいます。
また、公式ドキュメントには、以下のような記述がありました。
新しいフィールドが導入されると、ログエントリの最後に追加されます。予期していなかったログエントリの最後のフィールドは無視する必要があります。
今後もログエントリの最後に予期せぬフィールドが追加されることを前提に、フィールド追加前後のログも同じテーブルでクエリできるようにテーブル定義を考えました。
Athenaのテーブル定義
テーブル定義は、公式ドキュメントで紹介されている、パーティション射影を使用したテーブル定義を基にします。
CREATE EXTERNAL TABLE IF NOT EXISTS alb_access_logs ( type string, time string, elb string, client_ip string, client_port int, target_ip string, target_port int, request_processing_time double, target_processing_time double, response_processing_time double, elb_status_code int, target_status_code string, received_bytes bigint, sent_bytes bigint, request_verb string, request_url string, request_proto string, user_agent string, ssl_cipher string, ssl_protocol string, target_group_arn string, trace_id string, domain_name string, chosen_cert_arn string, matched_rule_priority string, request_creation_time string, actions_executed string, redirect_url string, lambda_error_reason string, target_port_list string, target_status_code_list string, classification string, classification_reason string, tid string, unexpected string ) PARTITIONED BY ( day 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]*) ([-.0-9]*) (|[-0-9]*) (-|[-0-9]*) ([-0-9]*) ([-0-9]*) \"([^ ]*) (.*) (- |[^ ]*)\" \"([^\"]*)\" ([A-Z0-9-_]+) ([A-Za-z0-9.-]*) ([^ ]*) \"([^\"]*)\" \"([^\"]*)\" \"([^\"]*)\" ([-.0-9]*) ([^ ]*) \"([^\"]*)\" \"([^\"]*)\" \"([^ ]*)\" \"([^\s]+?)\" \"([^\s]+)\" \"([^ ]*)\" \"([^ ]*)\" ?([^ ]*) ?(.*)') LOCATION 's3://DOC-EXAMPLE-BUCKET/AWSLogs/<ACCOUNT-NUMBER>/elasticloadbalancing/<REGION>/' TBLPROPERTIES ( "projection.enabled" = "true", "projection.day.type" = "date", "projection.day.range" = "2022/01/01,NOW", "projection.day.format" = "yyyy/MM/dd", "projection.day.interval" = "1", "projection.day.interval.unit" = "DAYS", "storage.location.template" = "s3://DOC-EXAMPLE-BUCKET/AWSLogs/<ACCOUNT-NUMBER>/elasticloadbalancing/<REGION>/${day}" )
修正ポイント
tidとunexpectedカラムを追加classification string, - classification_reason string + classification_reason string, + tid string, + unexpected string )ログパースの正規表現を修正
'input.regex' = - '([^ ]*) ([^ ]*) ・・・省略・・・\"([^ ]*)\" \"([^ ]*)\"') + '([^ ]*) ([^ ]*) ・・・省略・・・\"([^ ]*)\" \"([^ ]*)\" ?([^ ]*) ?(.*)') LOCATION 's3://DOC-EXAMPLE-BUCKET/AWSLogs/<ACCOUNT-NUMBER>/elasticloadbalancing/<REGION>/'
執筆時点では、公式ドキュメントに記載されている最後のフィールドはclassification_reasonとなっており、それに対応する正規表現が、input.regexの\"([^ ]*)\"の部分です。
tidが存在しない古いログレコードのために、スペース区切りのフィールドが、0回または1回出現する正規表現にしています。
末尾に予期せぬフィールドが追加されている場合は、すべてunexpectedカラムのフィールドとなります。
検証のため、ダミーのALBアクセスログをクエリした結果がこちらです。
tid追加されていないレコードが検索できているtidが追加されたレコードが検索できているtidの後ろに複数の追加レコードが存在していてもunexpectedとして扱えている
まとめ
事前の告知なしにログのフォーマットが変更になったことには驚きました。しかし、ドキュメントを調査していくうちに、ALBアクセスログを利用するのであれば、予期せぬフィールドが追加されることを前提に利用しなければならないと知ることができました。
今回紹介したテーブル定義を使って、予期せぬフィールド追加の影響を軽減することにお役立ていただければと思います。
記事執筆後に公式ドキュメントが更新されました
ALBアクセスログに追加されたTID_から始まるフィールドはtraceability_idというカラム名で、公式ドキュメントのテーブル定義例が更新されました。
クラスメソッドさんの記事でtraceability_idについて解説されていますので、ご参照ください。
dev.classmethod.jp
