みなさま。分析基盤の運用は大変ですよね(他人事)
今回アクセスログをtdでS3に保存してdigdag/embulkで定期的にBigQueryにシンクしているのですが、遭遇したことがないエラーに出会ってしまいました….
|
1 2 3 4 5 6 7 |
2019-07-01 xx:xx:xx +0900 [ERROR] (2682@[0:s3_to_bigquery]+run+access_log^sub+transform) io.digdag.standards.operator.gcp.BqJobRunner: BigQuery job failed: prd-xxxx:digdag_s0_p_s3_to_bigquery_w_run_t_120907_a_4540_da1748a0-be91-427d-8e02-33ad2ccda7af 2019-07-01 xx:xx:xx +0900 [ERROR] (2682@[0:s3_to_bigquery]+run+access_log^sub+transform) io.digdag.standards.operator.gcp.BqJobRunner: { "location" : "query", "message" : "Bad int64 value: 11\\357\\277\\275\\357\\277\\275]\\030>", "reason" : "invalidQuery" } 2019-07-01 xx:xx:xx +0900 [ERROR] (2682@[0:s3_to_bigquery]+run+access_log^sub+transform) io.digdag.core.agent.OperatorManager: Task +run+access_log^sub+transform failed. |
これはわからん
前回Athenaでクエリが叩けないという問題がありましたが、
[AWS][Athena] Error running query: HIVE_CURSOR_ERROR: Unexpected end of input stream
|
1 2 |
$ ./check.sh $ |
そもそもログはJSONで吐かれてSyntax errorもないし、欠損もない。
というわけでどのように300万行もあるログから犯人特定したかブログします。
■awkでログ抽出してみた
そもそもs3にあるログは以下のように3つある。
- nginx_access_20190630.log_0.gz
- nginx_access_20190630.log_1.gz
- nginx_access_20190630.log_2.gz
どのログからエラーを出しているのかわからないので、1つずつS3にあげて digdag run をすると nginx_access_20190630.log_1.gz だと判断できました。
そしてエラーをちゃんと見てみると…
Bad int64 value
integer(整数)なのに違う値入ってるわ！と怒られています。
そこでint64で対象のカラムからawkすればいけそう?
- 対象カラム
- reqsize
- status
- size
|
1 2 3 |
$ awk -F '","' '{ print $5 }' nginx_access_20190630.log_1 > nginx_access_20190630.log_1-reqsize $ awk -F '","' '{ print $8 }' nginx_access_20190630.log_1 > nginx_access_20190630.log_1-status $ awk -F '","' '{ print $9 }' nginx_access_20190630.log_1 > nginx_access_20190630.log_1-size |
ここから数字以外をegrepします。
|
1 2 3 |
$ egrep -v "[0-9]|-" nginx_access_20190630.log_1-reqsize $ egrep -v "[0-9]|-" nginx_access_20190630.log_1-size $ egrep -v "[0-9]|-" nginx_access_20190630.log_1-status |
ないじゃん?
他にもuser_idカラムも抽出してみた。
|
1 2 3 4 5 |
$ awk -F '","' '{ print $15 }' nginx_access_20190630.log_1 > nginx_access_20190630.log_1-new $ cut -b 11-20 nginx_access_20190630.log_1-new > nginx_access_20190630.log_1-renew $ grep '\[a-z]' nginx_access_20190630.log_1-renew |
ありません?
■二分探索で見極める
|
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 |
$ split -l 100000 nginx_access_20190630.log_1 nginx_access $ ll total 4399416 -rw-r--r-- 1 xxxxxx staff 1073735631 7 4 16:04 nginx_access_20190630.log_1 -rw-r--r--@ 1 xxxxxx staff 94169761 7 4 10:16 nginx_access_20190630.log_1.gz -rw-r--r-- 1 xxxxxx staff 49764729 7 4 16:05 nginx_accessaa -rw-r--r-- 1 xxxxxx staff 49896015 7 4 16:05 nginx_accessab -rw-r--r-- 1 xxxxxx staff 50106254 7 4 16:05 nginx_accessac -rw-r--r-- 1 xxxxxx staff 50167366 7 4 16:05 nginx_accessad -rw-r--r-- 1 xxxxxx staff 50251815 7 4 16:05 nginx_accessae -rw-r--r-- 1 xxxxxx staff 50282166 7 4 16:05 nginx_accessaf -rw-r--r-- 1 xxxxxx staff 50200245 7 4 16:05 nginx_accessag -rw-r--r-- 1 xxxxxx staff 50610331 7 4 16:05 nginx_accessah -rw-r--r-- 1 xxxxxx staff 50514746 7 4 16:05 nginx_accessai -rw-r--r-- 1 xxxxxx staff 50595600 7 4 16:05 nginx_accessaj -rw-r--r-- 1 xxxxxx staff 50451539 7 4 16:05 nginx_accessak -rw-r--r-- 1 xxxxxx staff 50411960 7 4 16:05 nginx_accessal -rw-r--r-- 1 xxxxxx staff 50939502 7 4 16:05 nginx_accessam -rw-r--r-- 1 xxxxxx staff 50668059 7 4 16:05 nginx_accessan -rw-r--r-- 1 xxxxxx staff 50454048 7 4 16:05 nginx_accessao -rw-r--r-- 1 xxxxxx staff 50810337 7 4 16:05 nginx_accessap -rw-r--r-- 1 xxxxxx staff 50251342 7 4 16:05 nginx_accessaq -rw-r--r-- 1 xxxxxx staff 50374259 7 4 16:05 nginx_accessar -rw-r--r-- 1 xxxxxx staff 50279086 7 4 16:05 nginx_accessas -rw-r--r-- 1 xxxxxx staff 50294283 7 4 16:05 nginx_accessat -rw-r--r-- 1 xxxxxx staff 49798780 7 4 16:05 nginx_accessau -rw-r--r-- 1 xxxxxx staff 16613169 7 4 16:05 nginx_accessav |
とりあえず 100000万行 分割して、 このログらを1個ずつS3に置いて digdag run をするしかない！！(地味な戦い?)
すると
"user_id": "11��]\u0018>",
！！！！?
そうエラーにもある 11\\357\\277\\275\\357\\277\\275]\\030> なんなのよって感じですが、UTF-8(文字コード)で文字列が入っているということですな。
どうやらサーバ再起動時におかしくなったかと思われ。
■まとめ
みなさんもログ系でハマったら split コマンドで二分探索をしよう！！！！！
0件のコメント