アクセスログ解析

ELBのアクセスログの事象分析について、ShellScriptとAthenaを用いた実行例についてまとめます。

ShellScript

CLB

No.1 : レスポンスが正常に受け取れていないELBのレスポンスコード毎のカウント

$ awk '$10 == "-"' * | awk '{print $9}' | sort | uniq -c

No.2 : ELBのレスポンスコード毎の数集計

$ awk '{print $8}' *.log | sort | uniq -c

No.3 : ELBのレスポンスコードとバックエンドのレスポンスコードの組み合わせ毎の数集計

$ awk '{print $8, $9}' *.log | sort | uniq -c

No.4 : ELBのレスポンスコードとバックエンドのレスポンスコードの組み合わせ毎の数集計(ファイル別)

$ ls *.log | 
xargs -n 1 sh -c 'echo "####### $0"; awk "{print \$8, \$9}" $0 | sort | uniq -c'

No.5 : ELBのレスポンスコードとバックエンドのレスポンスコードの組み合わせ毎の数集計(分単位)

$ awk '{print substr($1,0,16), $8, $9}' *.log | sort | uniq -c | awk '{print $2,$3,$4,$1}'

No.6 : 504のレコード一覧

$ awk '$8 == 504' *

No.7 : 504がどのELBノードから多く出力されているか

$ grep ' 504 ' *.log | awk '{print $3}' | sed 's/:.*//' | sort | uniq -c

No.8 : 504がどのHTTPリクエストで多く出力されているか

$ awk '$8 == 504' *.log | awk '{print $12, $13, $14}' | sort | uniq -c | sort -r | head -n 5 

No.9 : バックエンドから正常に応答が受け取れていない時

$ awk '{if (! int($5) < 0) {print $0}}' * | egrep '2018-01-2[45]'

No.10 : request_processing_time の3つの統計値(最小値、最大値、平均)と -1 の値を取った回数

$ awk '{ print $4,$8,$9,$5 }' * | sort | sed -e 's/ /!!/' -e 's/ /!!/' | awk '{if(count[$1]==0) min[$1]=100; count[$1]+=1; if(max[$1]<$2&&$2!=-1) max[$1]=$2; if(min[$1]>$2&&$2!=-1) min[$1]=$2; if($2!=-1)sum[$1]+=$2; else minus[$1]+=1;} END{for(k in count)print k,", count:",count[k],", max:",max[k],", min:",min[k],", avg:",sum[k]/count[k],", -1:",minus[k];}' | sort -k4nr

No.11 : backend_processing_time の3つの統計値(最小値、最大値、平均)と -1 の値を取った回数

$ awk '{ print $4,$8,$9,$6 }' * | sort | sed -e 's/ /!!/' -e 's/ /!!/' | awk '{if(count[$1]==0) min[$1]=100; count[$1]+=1; if(max[$1]<$2&&$2!=-1) max[$1]=$2; if(min[$1]>$2&&$2!=-1) min[$1]=$2; if($2!=-1)sum[$1]+=$2; else minus[$1]+=1;} END{for(k in count)print k,", count:",count[k],", max:",max[k],", min:",min[k],", avg:",sum[k]/count[k],", -1:",minus[k];}' | sort -k4nr

No.12 : response_processing_time の3つの統計値(最小値、最大値、平均)と -1 の値を取った回数

$ awk '{ print $4,$8,$9,$7 }' * | sort | sed -e 's/ /!!/' -e 's/ /!!/' | awk '{if(count[$1]==0) min[$1]=100; count[$1]+=1; if(max[$1]<$2&&$2!=-1) max[$1]=$2; if(min[$1]>$2&&$2!=-1) min[$1]=$2; if($2!=-1)sum[$1]+=$2; else minus[$1]+=1;} END{for(k in count)print k,", count:",count[k],", max:",max[k],", min:",min[k],", avg:",sum[k]/count[k],", -1:",minus[k];}' | sort -k4nr

No.13 : 最も多いリクエスト元のELBノードIPアドレスのリクエスト数

$ awk '{print $3}' * | awk -F ":" '{print $1}' | sort | uniq -c | sort -r| head -n 10 

No.14 : 時間毎のリクエスト数

$ awk '{print substr($1,0,13)}' *.log | sort | uniq -c | awk '{print $2, $1}'

No.15 : 分単位でのリクエスト数

$ awk '{print substr($1,0,16)}' *.log | sort | uniq -c | awk '{print $2, $1}'

No.16 : ユーザーエージェント毎のランキング

$ awk '{split($0, array, "\""); agent=array[4]; print agent}' * | sort | uniq -c | sort -nr | head

No.17 : TLSでクライアントが最も使った暗号スイートのランキング

$ awk '{split($0, array, "\""); agent=array[5]; print agent}' * | awk '{print $1}' | sort | uniq -c | sort -nr | head -5

No.18 : TLSでクライアントが最も使ったTLSバージョンのランキング

$ awk '{split($0, array, "\""); agent=array[5]; print agent}' * | awk '{print $2}' | sort | uniq -c | sort -nr | head

No.19 : TLSでクライアントが最も使ったプロトコルと暗号スイートのランキング

$ awk '{split($0, array, "\""); proto=array[1]; agent=array[5]; print proto agent}' * | awk '{print $1 " " $13}' | sort | uniq -c | sort -nr | head

No.20 : received_bytesとsent_bytesの大きさ別の分布

  • received_bytes
$ grep "" * | awk '{ count[int($10/1000)]++;} END{for(size in count){print size" * KB ",count[size]}}'  | sort -n
  • sent_bytes
$ grep "" * | awk '{ count[int($11/1000)]++;} END{for(size in count){print size" * KB ",count[size]}}'  | sort -n

No.21 : リクエスト・レスポンス合計のサイズの平均

$ awk '{ sum += $11; sum += $10; n++ } END { if (n > 0) print sum / n; }' *.log

No.22: ログ毎のファイルの行数

$ wc -l *.log

No.23 : クライアント別リクエスト数

$ awk '{print $3}' *.log | awk -F ":" '{print $1}' | sort | uniq -c | sort -r

No.24 : バックエンド別リクエスト数

$ awk '{print $4}' *.log | awk -F ":" '{print $1}' | sort | uniq -c | sort -r

No.25 : バックエンド(IP:Port)毎のリクエスト数(分単位)

$ awk '{print substr($1,0,16), $4}' *.log | sort | uniq -c | awk '{print $2,$3, $1}'

No.26 : リクエストされるURLランキング

$ awk '{print $13}' *.log | sort | uniq -c | sort -r | head -n 10

No.27 : backend_processing_timeが5秒以上のレコード一覧

$ awk '$6 >= 5' *.log 

No.28 : backend_processing_timeが5秒以上のレコード一覧(リクエスト別集計)

$ awk '$6 >= 5' *.log | awk '{print $12, $13, $14}' | sort | uniq -c | sort -r

ALB

No.1 : レスポンスが正常に受け取れていないELBのレスポンスコード毎のカウント

$ awk '$10 == "-"' *.log | awk '{print $9}' | sort | uniq -c

No.2 : ELBのレスポンスコード毎の数集計

$ awk '{print $9}' *.log | sort | uniq -c

No.3 : 504のレコード一覧

$ awk '$9 == 504' *

No.4 : 504がどのELBノードから多く出力されているか

$ grep ' 504 ' *.log | awk '{print $4}' | sed 's/:.*//' | sort | uniq -c

No.5 : バックエンドから正常に応答が受け取れていない時

$ awk '{if (! int($10) < 0) {print $0}}' * | egrep '2018-01-2[45]'

No.6 : request_processing_time の3つの統計値(最小値、最大値、平均)と -1 の値を取った回数

$ awk '{ print $5,$9,$10,$6 }' *.log | sort | sed -e 's/ /!!/' -e 's/ /!!/' | awk '{if(count[$1]==0) min[$1]=100; count[$1]+=1; if(max[$1]<$2&&$2!=-1) max[$1]=$2; if(min[$1]>$2&&$2!=-1) min[$1]=$2; if($2!=-1)sum[$1]+=$2; else minus[$1]+=1;} END{for(k in count)print k,", count:",count[k],", max:",max[k],", min:",min[k],", avg:",sum[k]/count[k],", -1:",minus[k];}' | sort -k4nr

No.7 : target_processing_time の3つの統計値(最小値、最大値、平均)と -1 の値を取った回数

$ awk '{ print $5,$9,$10,$7 }' *.log | sort | sed -e 's/ /!!/' -e 's/ /!!/' | awk '{if(count[$1]==0) min[$1]=100; count[$1]+=1; if(max[$1]<$2&&$2!=-1) max[$1]=$2; if(min[$1]>$2&&$2!=-1) min[$1]=$2; if($2!=-1)sum[$1]+=$2; else minus[$1]+=1;} END{for(k in count)print k,", count:",count[k],", max:",max[k],", min:",min[k],", avg:",sum[k]/count[k],", -1:",minus[k];}' | sort -k4nr

No.8 : response_processing_time の3つの統計値(最小値、最大値、平均)と -1 の値を取った回数

$ awk '{ print $5,$9,$10,$8 }' *.log | sort | sed -e 's/ /!!/' -e 's/ /!!/' | awk '{if(count[$1]==0) min[$1]=100; count[$1]+=1; if(max[$1]<$2&&$2!=-1) max[$1]=$2; if(min[$1]>$2&&$2!=-1) min[$1]=$2; if($2!=-1)sum[$1]+=$2; else minus[$1]+=1;} END{for(k in count)print k,", count:",count[k],", max:",max[k],", min:",min[k],", avg:",sum[k]/count[k],", -1:",minus[k];}' | sort -k4nr

Athena

以下、全て CLB を前提とします。
また、以下のような、デフォルトで生成されている sampledb データベースの elb_logs テーブルを使用します。

CREATE EXTERNAL TABLE `elb_logs`(
  `request_timestamp` string COMMENT '', 
  `elb_name` string COMMENT '', 
  `request_ip` string COMMENT '', 
  `request_port` int COMMENT '', 
  `backend_ip` string COMMENT '', 
  `backend_port` int COMMENT '', 
  `request_processing_time` double COMMENT '', 
  `backend_processing_time` double COMMENT '', 
  `client_response_time` double COMMENT '', 
  `elb_response_code` string COMMENT '', 
  `backend_response_code` string COMMENT '', 
  `received_bytes` bigint COMMENT '', 
  `sent_bytes` bigint COMMENT '', 
  `request_verb` string COMMENT '', 
  `url` string COMMENT '', 
  `protocol` string COMMENT '', 
  `user_agent` string COMMENT '', 
  `ssl_cipher` string COMMENT '', 
  `ssl_protocol` string COMMENT '')
ROW FORMAT SERDE 
  'org.apache.hadoop.hive.serde2.RegexSerDe' 
WITH SERDEPROPERTIES ( 
  '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.-]*)$') 
STORED AS INPUTFORMAT 
  'org.apache.hadoop.mapred.TextInputFormat' 
OUTPUTFORMAT 
  'org.apache.hadoop.hive.ql.io.HiveIgnoreKeyTextOutputFormat'
LOCATION
  's3://athena-examples-us-west-2/elb/plaintext'
TBLPROPERTIES (
  'transient_lastDdlTime'='1480278335');

HTTPステータスコードが200のレコード一覧

SELECT * 
FROM elb_logs
WHERE elb_response_code <> '200'
ORDER BY request_timestamp;

ELB毎のリクエスト数

SELECT elb_name,
         count(*) AS request_count
FROM elb_logs
GROUP BY elb_name
ORDER BY request_count DESC;

ELB毎のリクエスト数(期間指定)

SELECT elb_name,
         count(*) AS request_count
FROM elb_logs
WHERE request_timestamp >= '2014-01-01T00:00:00Z'
        AND request_timestamp < '2016-01-01T00:00:00Z'
GROUP BY elb_name
ORDER BY request_count DESC;

ELB毎のリクエスト数(期間+ELB 指定)

SELECT elb_name,
         count(*) AS request_count
FROM elb_logs
WHERE elb_name LIKE 'elb_demo_008'
        AND request_timestamp >= '2014-01-01T00:00:00Z'
        AND request_timestamp < '2016-01-01T00:00:00Z'
GROUP BY elb_name
ORDER BY request_count DESC;

ELB毎の5XXエラーのリクエスト数

SELECT elb_name,
         backend_response_code,
         count(*) AS request_count
FROM elb_logs
WHERE backend_response_code >= '500'
GROUP BY backend_response_code, elb_name
ORDER BY backend_response_code, elb_name;

ELB毎の5XXエラーのリクエスト数(ELB指定)

SELECT elb_name,
         backend_response_code,
         count(*) AS request_count
FROM elb_logs
WHERE elb_name LIKE 'elb_demo_008'
        AND backend_response_code >= '500'
GROUP BY backend_response_code, elb_name
ORDER BY backend_response_code, elb_name;

ELB毎の5XXエラーのリクエスト数(期間+ELB 指定)

SELECT elb_name,
         backend_response_code,
         count(*) AS request_count
FROM elb_logs
WHERE elb_name LIKE 'elb_demo_008'
        AND backend_response_code >= '500'
        AND request_timestamp >= '2014-01-01T00:00:00Z'
        AND request_timestamp < '2016-01-01T00:00:00Z'
GROUP BY backend_response_code, elb_name
ORDER BY backend_response_code, elb_name;

ELB毎の5XXエラーのリクエスト数(期間+ELB+URL 指定)

SELECT count(*) AS request_count,
         elb_name,
         url,
         elb_response_code,
         backend_response_code
FROM elb_logs
WHERE elb_name LIKE 'elb_demo_008'
        AND backend_response_code >= '500'
        AND url LIKE 'http://www.example.com/jobs/%'
        AND request_timestamp >= '2014-01-01T00:00:00Z'
        AND request_timestamp < '2016-01-01T00:00:00Z'
GROUP BY elb_name,url,elb_response_code,backend_response_code
ORDER BY request_count DESC limit 10;

ELB毎の5XXエラーのリクエスト数(期間+ELB+URL+UserAgent 指定)

SELECT count(*) AS request_count,
         elb_name,
         url,
         elb_response_code,
         backend_response_code,
         user_agent
FROM elb_logs
WHERE elb_name LIKE 'elb_demo_008'
        AND backend_response_code >= '500'
        AND url LIKE 'http://www.example.com/jobs/%'
        AND user_agent LIKE '%Mozilla/5.0%'
        AND request_timestamp >= '2014-01-01T00:00:00Z'
        AND request_timestamp < '2016-01-01T00:00:00Z'
GROUP BY elb_name,url,elb_response_code,backend_response_code,user_agent
ORDER BY request_count DESC limit 10;

送信元IPのリクエスト数ランキング

SELECT request_ip,
         url,
         count(*) AS request_count
FROM elb_logs
WHERE elb_name LIKE 'elb_demo_008'
        AND request_timestamp >= '2014-01-01T00:00:00Z'
        AND request_timestamp < '2016-01-01T00:00:00Z'
GROUP BY request_ip,url
ORDER BY request_count DESC limit 5;

日付ごとのリクエスト数

SELECT date(from_iso8601_timestamp(request_timestamp)),
         count(*)
FROM elb_logs
WHERE url LIKE '%/jobs/%'
        AND date(from_iso8601_timestamp(request_timestamp)) >= date('2014-12-01')
GROUP BY  1
ORDER BY  1;

直近1年の500エラー発生のリクエスト数

SELECT elb_response_code,
         count(*)
FROM elb_logs
WHERE from_iso8601_timestamp(request_timestamp) >= date_add('day', -365 * 1, now())
        AND elb_response_code >= '500'
GROUP BY  1
ORDER BY  1;

レスポンスに1.0s以上時間がかかっているリクエスト

SELECT url,
         count(*) AS count,
         backend_processing_time
FROM elb_logs
WHERE backend_processing_time >= 1.0
GROUP BY  url, backend_processing_time
ORDER BY backend_processing_time DESC;

任意のエントリ取得(期間+リクエスト元IP 指定)

SELECT *
FROM elb_logs
WHERE request_ip = '245.85.197.169'
        AND request_timestamp >= '2014-01-01T00:00:00Z'
        AND request_timestamp <= '2016-01-01T00:00:00Z';

あるページからの遷移先ページ傾向

SELECT d.*
FROM 
    (SELECT b.request_ip,
         min(b.request_timestamp) AS request_timestamp
    FROM 
        (SELECT *
        FROM elb_logs
        WHERE url LIKE '%/jobs/%') a
        JOIN elb_logs b
            ON a.request_timestamp < b.request_timestamp
        GROUP BY  1 ) c
    JOIN elb_logs d
    ON c.request_ip = d.request_ip
        AND c.request_timestamp = d.request_timestamp
ORDER BY  d.request_timestamp;

参考

ELB アクセスログ

Classic Load Balancer のアクセスログ – Elastic Load Balancing
https://docs.aws.amazon.com/ja_jp/elasticloadbalancing/latest/classic/access-log-collection.html#access-log-entry-syntax
Application Load Balancer のアクセスログ – Elastic Load Balancing
https://docs.aws.amazon.com/ja_jp/elasticloadbalancing/latest/application/load-balancer-access-logs.html#access-log-entry-syntax

Athena

Querying Classic Load Balancer Logs – Amazon Athena
https://docs.aws.amazon.com/ja_jp/athena/latest/ug/elasticloadbalancer-classic-logs.html
Querying Application Load Balancer Logs – Amazon Athena
https://docs.aws.amazon.com/athena/latest/ug/application-load-balancer-logs.html

Amazon AthenaでELBのログを調査するときに使ったSQL
https://dev.classmethod.jp/cloud/amazon-athena-sql-for-elb/
Amazon AthenaでELBログをSQLで解析する #reinvent
https://dev.classmethod.jp/cloud/aws/amazon-athena-sql-elb-log-reinvent/
Amazon Athenaではじめるログ分析入門
https://qiita.com/miyasakura_/items/174dc73f706e8951dbdd

コメントを残す

メールアドレスが公開されることはありません。 * が付いている欄は必須項目です