コピペで使えるELBのアクセスログ解析による事象分析 (ShellScript, Athena)
アクセスログ解析
ELBのアクセスログの事象分析について、ShellScriptとAthenaを用いた実行例についてまとめます。
ShellScript
NLB
No.1 : 最も多いリクエスト元のクライアントIPアドレスのリクエスト数
$ gunzip -dc * | awk '{print $6}' | awk -F ":" '{print $1}' | sort | uniq -c | sort -r| head -n 10
No.2 : 時間毎のリクエスト数
$ gunzip -dc * | awk '{print substr($3,0,13)}' | sort | uniq -c | awk '{print $2, $1}'
No.3 : 分単位でのリクエスト数
$ gunzip -dc * | awk '{print substr($3,0,16)}' | sort | uniq -c | awk '{print $2, $1}'
No.4 : TLSでクライアントが最も使った暗号スイートのランキング
$ gunzip -dc * | awk '{print $15}' | sort | uniq -c | sort -nr | head -5
No.5 : TLSでクライアントが最も使ったTLSバージョンのランキング
$ gunzip -dc * | awk '{print $16}' | sort | uniq -c | sort -nr | head -5
No.6 : TLSでクライアントが最も使ったプロトコルと暗号スイートのランキング
$ gunzip -dc * | awk '{print $15 " " $16}' | sort | uniq -c | sort -nr | head
No.7 : received_bytesとsent_bytesの大きさ別の分布
- received_bytes
$ gunzip -dc * | awk '{ count[int($10/1000)]++;} END{for(size in count){print size" * KB ",count[size]}}' | sort -n
- sent_bytes
$ gunzip -dc * | awk '{ count[int($11/1000)]++;} END{for(size in count){print size" * KB ",count[size]}}' | sort -n
No.8 : リクエスト・レスポンス合計のサイズの平均
$ gunzip -dc * | awk '{ sum += $11; sum += $10; n++ } END { if (n > 0) print sum / n; }'
No.9 : ログ毎のファイルの行数
$ gunzip -dc * | wc -l
No.10 : クライアント別リクエスト数
$ gunzip -dc * | awk '{print $6}' | awk -F ":" '{print $1}' | sort | uniq -c | sort -r
No.11 : NLB IPアドレス別リクエスト数
$ gunzip -dc * | awk '{print $7}' | awk -F ":" '{print $1}' | sort | uniq -c | sort -r
No.12 : connection_timeが5秒以上のレコード一覧
$ gunzip -dc * | awk '$8 >= 5000'
No.13 : tls_handshake_timeが1秒以上のレコード一覧
$ gunzip -dc * | awk '$9 >= 1000'
ALB
No.1 : レスポンスが正常に受け取れていないELBのレスポンスコード毎のカウント
$ gunzip -dc * | awk '$10 == "-"'| awk '{print $9}' | sort | uniq -c
No.2 : ELBのレスポンスコード毎の数集計
$ gunzip -dc * | awk '{print $9}' | sort | uniq -c
No.3 : ELBのレスポンスコードとバックエンドのレスポンスコードの組み合わせ毎の数集計
$ gunzip -dc * | awk '{print $9, $10}' | sort | uniq -c
No.4 : ELBのレスポンスコードとバックエンドのレスポンスコードの組み合わせ毎の数集計(ファイル別)
$ ls ./ | xargs -n 1 sh -c 'echo "######### $0"; gunzip -dc $0 | awk "{print \$9, \$10}" | sort | uniq -c'
No.5 : ELBのレスポンスコードとバックエンドのレスポンスコードの組み合わせ毎の数集計(分単位)
$ gunzip -dc * | awk '{print substr($2,0,16), $9, $10}' | sort | uniq -c | awk '{print $2,$3,$4,$1}'
No.6 : ELB 504のレコード一覧
$ gunzip -dc * | awk '$9 == 504'
No.7 : ELBが504時のクライアント順
$ gunzip -dc * | awk '$9 == 504' | awk '{print $4}' | sed 's/:.*//' | sort | uniq -c
No.8 : 504がどのHTTPリクエストで多く出力されているか
$ gunzip -dc * | awk '$9 == 504' | awk '{print $13, $14, $15}' | sort | uniq -c | sort -r | head -n 5
No.9 : バックエンドから正常に応答が受け取れていない時
$ gunzip -dc * | awk '{if (! int($10) < 0) {print $0}}' | egrep '2018-01-2[45]'
No.10 : request_processing_time の3つの統計値(最小値、最大値、平均)と -1 の値を取った回数
$ gunzip -dc * | awk '{ print $5,$9,$10,$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.11 : target_processing_time の3つの統計値(最小値、最大値、平均)と -1 の値を取った回数
$ gunzip -dc * | awk '{ print $5,$9,$10,$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.12 : response_processing_time の3つの統計値(最小値、最大値、平均)と -1 の値を取った回数
$ gunzip -dc * | awk '{ print $5,$9,$10,$8 }' | 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 : 最も多いリクエスト元のクライアントIPアドレスのリクエスト数
$ gunzip -dc * | awk '{print $4}' | awk -F ":" '{print $1}' | sort | uniq -c | sort -r| head -n 10
No.14 : 時間毎のリクエスト数
$ gunzip -dc * | awk '{print substr($2,0,13)}' | sort | uniq -c | awk '{print $2, $1}'
No.15 : 分単位でのリクエスト数
$ gunzip -dc * | awk '{print substr($2,0,16)}' | sort | uniq -c | awk '{print $2, $1}'
No.16 : ユーザーエージェント毎のランキング
$ gunzip -dc * | awk '{split($0, array, "\""); agent=array[4]; print agent}' | sort | uniq -c | sort -nr | head
No.17 : TLSでクライアントが最も使った暗号スイートのランキング
$ gunzip -dc * | awk '{split($0, array, "\""); agent=array[5]; print agent}' | awk '{print $1}' | sort | uniq -c | sort -nr | head -5
No.18 : TLSでクライアントが最も使ったTLSバージョンのランキング
$ gunzip -dc * | awk '{split($0, array, "\""); agent=array[5]; print agent}' | awk '{print $2}' | sort | uniq -c | sort -nr | head
No.19 : TLSでクライアントが最も使ったプロトコルと暗号スイートのランキング
$ gunzip -dc * | 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
$ gunzip -dc * | awk '{ count[int($11/1000)]++;} END{for(size in count){print size" * KB ",count[size]}}' | sort -n
- sent_bytes
$ gunzip -dc * | awk '{ count[int($12/1000)]++;} END{for(size in count){print size" * KB ",count[size]}}' | sort -n
No.21 : リクエスト・レスポンス合計のサイズの平均
$ gunzip -dc * | awk '{ sum += $12; sum += $11; n++ } END { if (n > 0) print sum / n; }'
No.22: ログ毎のファイルの行数
$ gunzip -dc * | wc -l
No.23 : クライアント別リクエスト数
$ gunzip -dc * | awk '{print $4}' | awk -F ":" '{print $1}' | sort | uniq -c | sort -r
No.24 : バックエンド別リクエスト数
$ gunzip -dc * | awk '{print $5}' | awk -F ":" '{print $1}' | sort | uniq -c | sort -r
No.25 : バックエンド(IP:Port)毎のリクエスト数(分単位)
$ gunzip -dc * | awk '{print substr($2,0,16), $5}' | sort | uniq -c | awk '{print $2,$3, $1}'
No.26 : リクエストされるURLランキング
$ gunzip -dc * | awk '{print $14}' | sort | uniq -c | sort -r | head -n 10
No.27 : target_processing_timeが5秒以上のレコード一覧
$ gunzip -dc * | awk '$7 >= 5'
No.28 : backend_processing_timeが5秒以上のレコード一覧(リクエスト別集計)
$ gunzip -dc * | awk '$7 >= 1' | awk '{print $12, $13, $14, $15}' | sort | uniq -c | sort -r
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 : ELB 504のレコード一覧
$ awk '$8 == 504' *
No.7 : ELBが504時のクライアント順
$ awk '$8 == 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 : 最も多いリクエスト元のクライアント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
$ awk '{ count[int($10/1000)]++;} END{for(size in count){print size" * KB ",count[size]}}' * | sort -n
- sent_bytes
$ 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
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 アクセスログ
Access Logs for Your Network Load Balancer - Elastic Load Balancing
Application Load Balancer のアクセスログ - Elastic Load Balancing Classic Load Balancer のアクセスログ - Elastic Load Balancing https://docs.aws.amazon.com/ja_jp/elasticloadbalancing/latest/classic/access-log-collection.html#access-log-entry-syntaxAthena
Querying Classic Load Balancer Logs - Amazon Athena
Querying Application Load Balancer Logs - Amazon Athena https://docs.aws.amazon.com/athena/latest/ug/application-load-balancer-logs.htmlAmazon AthenaでELBのログを調査するときに使ったSQL
Amazon AthenaでELBログをSQLで解析する #reinvent Amazon Athenaではじめるログ分析入門 https://qiita.com/miyasakura_/items/174dc73f706e8951dbdd