CloudWatch Logs InsightsでALBのELB 5XX発生時のアクセスログを分析してみた

ALBのアクセスログを Lambdaを利用して CloudWatchLogsに転送し、CloudWatch Logs Insights で分析してみました。

suzuki.ryo

2019.09.10

この記事は公開されてから1年以上経過しています。情報が古い可能性がありますので、ご注意ください。

AWSチームのすずきです。

ALBのELB 5XX発生時の解析のため、アクセスログをパース、CloudWatch Logsに転送するLambda関数を用意。 Amazon CloudWatch Logs Insights で可視化する機会がありましたので、紹介させていただきます。

Lambda

パーサー

Python 3.7 のランタイム、「re」正規表現モジュールを利用しました。

import re

RE_TEXT = r"""
  ^(?P<type>[^ ]*)\u0020
  (?P<time>[^ ]*)\u0020
  (?P<elb>[^ ]*)\u0020
  (?P<client_ip>[^ ]*):(?P<client_port>[0-9]*)\u0020
  (?P<target_ip>[^ ]*)[:-](?P<target_port>[0-9]*)\u0020
  (?P<request_processing_time>[-.0-9]*)\u0020
  (?P<target_processing_time>[-.0-9]*)\u0020
  (?P<response_processing_time>[-.0-9]*)\u0020
  (?P<elb_status_code>|[-0-9]*)\u0020
  (?P<target_status_code>-|[-0-9]*)\u0020
  (?P<received_bytes>[-0-9]*)\u0020
  (?P<sent_bytes>[-0-9]*)\u0020
  \"(?P<request_method>[^ ]*)\u0020
  (?P<request_url>[^ ]*)\u0020
  (?P<request_http_version>- |[^ ]*)\"\u0020
  \"(?P<user_agent>[^\"]*)\"\u0020
  (?P<ssl_cipher>[A-Z0-9-]+)\u0020
  (?P<ssl_protocol>[A-Za-z0-9.-]*)\u0020
  (?P<target_group_arn>[^ ]*)\u0020
  \"(?P<trace_id>[^\"]*)\"\u0020
  \"(?P<domain_name>[^\"]*)\"\u0020
  \"(?P<chosen_cert_arn>[^\"]*)\"\u0020
  (?P<matched_rule_priority>[-.0-9]*)\u0020
  (?P<request_creation_time>[^ ]*)\u0020
  \"(?P<actions_executed>[^\"]*)\"\u0020
  \"(?P<redirect_url>[^\"]*)\"\u0020
  \"(?P<error_reason>[^\"]*)\"
  (?P<new_field>.*)
  """
RE_FORMAT = re.compile(RE_TEXT, flags=re.VERBOSE)

正規表現とカラム名は Amazon Athena のユーザガイドに準拠しました。

Application Load Balancer ログのクエリ

ALBの機能追加にあわせてアクセスログの仕様も更新されています。追加された項目が従来のログの末尾以外に追加された場合、正規表現の修正が必要になる点はご留意下さい。

AZ、ELBノードIP

S3のログファイル名より ELBノードのIPを取得、アベイアビリティゾーンを求めました。

https://dev.classmethod.jp/cloud/aws/add-az-alb-accesslog/

  elb_listener_ip = s3key.split('_')[-2]
  d = {}
  if len(elb_listener_ip) > 4:
    d["elb_listener_ip"] = elb_listener_ip
    r = ec2.describe_network_interfaces(
      Filters=[{'Name':'association.public-ip','Values':[elb_listener_ip]}]
    )
    if ("NetworkInterfaces" in r):
      d["elb_availabilityzone"] = r["NetworkInterfaces"][0]["AvailabilityZone"]
      d["elb_private_ip"] = r["NetworkInterfaces"][0]["PrivateIpAddress"]

テスト

Application Load Balancer のアクセスログに記載されたログサンプルのパースを試みました。

  import json
  log_h2 = 'h2 2018-07-02T22:23:00.186641Z app/my-loadbalancer/50dc6c495c0c9188 10.0.1.252:48160 10.0.0.66:9000 0.000 0.002 0.000 200 200 5 257 "GET https://10.0.2.105:773/ HTTP/2.0" "curl/7.46.0" ECDHE-RSA-AES128-GCM-SHA256 TLSv1.2 arn:aws:elasticloadbalancing:us-east-2:123456789012:targetgroup/my-targets/73e2d6bc24d8a067 "Root=1-58337327-72bd00b0343d75b906739c42" "-" "-" 1 2018-07-02T22:22:48.364000Z "redirect" "https://example.com:80/" "-"'
  a = RE_FORMAT.match(log_h2).groupdict()
  a.update(d)
  print(json.dump(a))

出力結果

{
  "type": "h2",
  "time": "2018-07-02T22:23:00.186641Z",
  "elb": "app/my-loadbalancer/50dc6c495c0c9188",
  "client_ip": "10.0.1.252",
  "client_port": "48160",
  "target_ip": "10.0.0.66",
  "target_port": "9000",
  "request_processing_time": "0.000",
  "target_processing_time": "0.002",
  "response_processing_time": "0.000",
  "elb_status_code": "200",
  "target_status_code": "200",
  "received_bytes": "5",
  "sent_bytes": "257",
  "request_method": "GET",
  "request_url": "https://10.0.2.105:773/",
  "request_http_version": "HTTP/2.0",
  "user_agent": "curl/7.46.0",
  "ssl_cipher": "ECDHE-RSA-AES128-GCM-SHA256",
  "ssl_protocol": "TLSv1.2",
  "target_group_arn": "arn:aws:elasticloadbalancing:us-east-2:123456789012:targetgroup/my-targets/73e2d6bc24d8a067",
  "trace_id": "Root=1-58337327-72bd00b0343d75b906739c42",
  "domain_name": "-",
  "chosen_cert_arn": "-",
  "matched_rule_priority": "1",
  "request_creation_time": "2018-07-02T22:22:48.364000Z",
  "actions_executed": "redirect",
  "redirect_url": "https://example.com:80/",
  "error_reason": "-",
  "new_field": "",
  "elb_availabilityzone": "us-east-2a"
  "elb_private_ip": "172.xx.xx.xx"
}

ELB 5XX抽出

ターゲットのEC2応答(target_status_code)が「500」台応答を戻さず、ELB(ALB)応答(elb_status_code)が「500」台、ELB 5XX に該当するログレコードのみを抽出します。

if a["elb_status_code"][0:1] == '5':
    if not a["target_status_code"][0:1] == '5':
        print(json.dumps(a))

正常系のログを除外する事で、CloudWatch Logsのデータ取り込み課金(0.76USD/GB @東京)、Insightsのクエリ課金(スキャンしたデータ 1 GB あたり 0.0076USD)を抑制します。

Loggerは、Lambda標準のものを利用しました。任意のロググループ、ログストリームを出力先とする場合、CloudWatch Logs の制限にご注意ください。

CloudWatch Logs の制限

CloudWatchLogs