既存のログ調査コマンド修正を想定しつつ、awk超入門してみる

awk Linux

はじめに

プログラミング言語AWK 第2版が少し前に出版され話題になったり、Zennのこちらの記事（プログラミング言語AWKのここがLOVE）を拝見し、触ってみたい気持ちが高まった。

なので今回は簡単な例としてawkを使って、ログ調査コマンド修正を想定しながら超入門していく。

目次

  1. 調査対象のログの確認
  2. awkを試す
    1. 日付とステータスコードを抽出
    2. URL＋ステータスコードを抽出
    3. その他
  3. まとめ

調査対象のログの確認

想定するログは以下の通り。

2024-08-31 23:55:00.629 [INFO ] [http-nio-8080-exec-5] com.example.Template.controller.servletFilter.RequestAndResponseLogFilter.doFilterInternal:29 - > REQUEST GET /api/batch  0:0:0:0:0:0:0:1 curl/8.7.1 Referer: N/A 
2024-08-31 23:55:00.630 [INFO ] [http-nio-8080-exec-5] com.example.Template.controller.servletFilter.RequestAndResponseLogFilter.doFilterInternal:37 - < RESPONSE 200 batch Response Size: 0 Cache Control: null
2024-08-31 23:55:01.210 [INFO ] [http-nio-8080-exec-7] com.example.Template.controller.servletFilter.RequestAndResponseLogFilter.doFilterInternal:29 - > REQUEST GET /api/batch  0:0:0:0:0:0:0:1 curl/8.7.1 Referer: N/A 
2024-08-31 23:55:01.211 [INFO ] [http-nio-8080-exec-7] com.example.Template.controller.servletFilter.RequestAndResponseLogFilter.doFilterInternal:37 - < RESPONSE 200 batch Response Size: 0 Cache Control: null
2024-08-31 23:55:01.729 [INFO ] [http-nio-8080-exec-9] com.example.Template.controller.servletFilter.RequestAndResponseLogFilter.doFilterInternal:29 - > REQUEST GET /api/batch  0:0:0:0:0:0:0:1 curl/8.7.1 Referer: N/A 
2024-08-31 23:55:01.730 [INFO ] [http-nio-8080-exec-9] com.example.Template.controller.servletFilter.RequestAndResponseLogFilter.doFilterInternal:37 - < RESPONSE 200 batch Response Size: 0 Cache Control: null
2024-08-31 23:55:02.433 [INFO ] [http-nio-8080-exec-1] com.example.Template.controller.servletFilter.RequestAndResponseLogFilter.doFilterInternal:29 - > REQUEST GET /api/batch  0:0:0:0:0:0:0:1 curl/8.7.1 Referer: N/A 
2024-08-31 23:55:02.435 [INFO ] [http-nio-8080-exec-1] com.example.Template.controller.servletFilter.RequestAndResponseLogFilter.doFilterInternal:37 - < RESPONSE 200 batch Response Size: 0 Cache Control: null
2024-08-31 23:55:02.940 [INFO ] [http-nio-8080-exec-3] com.example.Template.controller.servletFilter.RequestAndResponseLogFilter.doFilterInternal:29 - > REQUEST GET /api/batch  0:0:0:0:0:0:0:1 curl/8.7.1 Referer: N/A 
2024-08-31 23:55:02.941 [INFO ] [http-nio-8080-exec-3] com.example.Template.controller.servletFilter.RequestAndResponseLogFilter.doFilterInternal:37 - < RESPONSE 200 batch Response Size: 0 Cache Control: null
2024-08-31 23:55:03.792 [INFO ] [http-nio-8080-exec-5] com.example.Template.controller.servletFilter.RequestAndResponseLogFilter.doFilterInternal:29 - > REQUEST GET /api/test  0:0:0:0:0:0:0:1 curl/8.7.1 Referer: N/A 
2024-08-31 23:55:03.794 [INFO ] [http-nio-8080-exec-5] com.example.Template.controller.servletFilter.RequestAndResponseLogFilter.doFilterInternal:37 - < RESPONSE 200 test Response Size: 0 Cache Control: null
2024-08-31 23:55:04.655 [INFO ] [http-nio-8080-exec-7] com.example.Template.controller.servletFilter.RequestAndResponseLogFilter.doFilterInternal:29 - > REQUEST GET /api/test  0:0:0:0:0:0:0:1 curl/8.7.1 Referer: N/A 
2024-08-31 23:55:04.656 [INFO ] [http-nio-8080-exec-7] com.example.Template.controller.servletFilter.RequestAndResponseLogFilter.doFilterInternal:37 - < RESPONSE 200 test Response Size: 0 Cache Control: null

SpringBoot製のサンプルプログラムから出した、リクエスト/レスポンスのログファイルを題材として扱う。

awkを試す

1. 日付とステータスコードのみを抽出

まずは日付のみ抽出。

-> % less access_log | awk '{print $1}'
2024-08-31
2024-08-31
2024-08-31
2024-08-31
2024-08-31
2024-08-31
2024-08-31
2024-08-31
2024-08-31
2024-08-31
2024-08-31
2024-08-31
2024-08-31
2024-08-31

！！！すごい！

次に、ステータスコードの抽出。

-> % less access_log | grep 'RESPONSE' | awk '{print $10}'
200
200
200
200
200
200
200

ステータスコードが200の列を抽出。ログ調査で重宝しそう。

-> % less access_log | awk '$10 == 200 {print $0}'
2024-08-31 23:55:00.630 [INFO ] [http-nio-8080-exec-5] com.example.Template.controller.servletFilter.RequestAndResponseLogFilter.doFilterInternal:37 - < RESPONSE 200 batch Response Size: 0 Cache Control: null
2024-08-31 23:55:01.211 [INFO ] [http-nio-8080-exec-7] com.example.Template.controller.servletFilter.RequestAndResponseLogFilter.doFilterInternal:37 - < RESPONSE 200 batch Response Size: 0 Cache Control: null
2024-08-31 23:55:01.730 [INFO ] [http-nio-8080-exec-9] com.example.Template.controller.servletFilter.RequestAndResponseLogFilter.doFilterInternal:37 - < RESPONSE 200 batch Response Size: 0 Cache Control: null
2024-08-31 23:55:02.435 [INFO ] [http-nio-8080-exec-1] com.example.Template.controller.servletFilter.RequestAndResponseLogFilter.doFilterInternal:37 - < RESPONSE 200 batch Response Size: 0 Cache Control: null
2024-08-31 23:55:02.941 [INFO ] [http-nio-8080-exec-3] com.example.Template.controller.servletFilter.RequestAndResponseLogFilter.doFilterInternal:37 - < RESPONSE 200 batch Response Size: 0 Cache Control: null
2024-08-31 23:55:03.794 [INFO ] [http-nio-8080-exec-5] com.example.Template.controller.servletFilter.RequestAndResponseLogFilter.doFilterInternal:37 - < RESPONSE 200 test Response Size: 0 Cache Control: null
2024-08-31 23:55:04.656 [INFO ] [http-nio-8080-exec-7] com.example.Template.controller.servletFilter.RequestAndResponseLogFilter.doFilterInternal:37 - < RESPONSE 200 test Response Size: 0 Cache Control: null

/api/testへのリクエストに対するステータスコードが200の列を抽出。

-> % less access_log | awk '$10 == 200 {print $0}' | grep 'test'
2024-08-31 23:55:03.794 [INFO ] [http-nio-8080-exec-5] com.example.Template.controller.servletFilter.RequestAndResponseLogFilter.doFilterInternal:37 - < RESPONSE 200 test Response Size: 0 Cache Control: null
2024-08-31 23:55:04.656 [INFO ] [http-nio-8080-exec-7] com.example.Template.controller.servletFilter.RequestAndResponseLogFilter.doFilterInternal:37 - < RESPONSE 200 test Response Size: 0 Cache Control: null

日付とステータスコード（200）のみを抽出。

-> % less access_log | awk '$10 == 200 {print $1, $10}'
2024-08-31 200
2024-08-31 200
2024-08-31 200
2024-08-31 200
2024-08-31 200
2024-08-31 200
2024-08-31 200

-> % less access_log | awk '{print $1, $10}'| grep '200'
2024-08-31 200
2024-08-31 200
2024-08-31 200
2024-08-31 200
2024-08-31 200
2024-08-31 200
2024-08-31 200

2. URL＋ステータスコードを抽出

if文の条件、大事。

-> % less access_log | awk '$10 == 200 {print $10, $11}'
200 batch
200 batch
200 batch
200 batch
200 batch
200 test
200 test

-> % less access_log | awk '{print $10, $11}' | grep '200'
200 batch
200 batch
200 batch
200 batch
200 batch
200 test
200 test

後者の方が何を絞りたいか指定が早く出来そう（後ろの方で指定をしているので）なので、調査の時とかはこっちもあり。

3. その他

基本的に日時とログレベル、ステータスコード、リクエストされたURL。

これ以外だと対象スキーマやIPアドレスなどを抽出したい場面が多いと思うので、それに合わせてawkの$nの部分を整理していけばいいと思う。

あと便利な機能として、順番を入れ替えられそう。

-> % less access_log | awk '{print $11, $10}' | grep '200'
batch 200
batch 200
batch 200
batch 200
batch 200
test 200
test 200

はい、これめちゃ便利ですね。

また整形もできるようで、

-> % less access_log | awk '{print $11, $10, $1}'  
/api/batch GET 2024-08-31
batch 200 2024-08-31
/api/batch GET 2024-08-31
batch 200 2024-08-31
/api/batch GET 2024-08-31
batch 200 2024-08-31
/api/batch GET 2024-08-31
batch 200 2024-08-31
/api/batch GET 2024-08-31
batch 200 2024-08-31
/api/test GET 2024-08-31
test 200 2024-08-31
/api/test GET 2024-08-31
test 200 2024-08-31

↓

-> % less access_log | awk '{printf "%10s %3s %5s\n", $11, $10, $1}' 
/api/batch GET 2024-08-31
     batch 200 2024-08-31
/api/batch GET 2024-08-31
     batch 200 2024-08-31
/api/batch GET 2024-08-31
     batch 200 2024-08-31
/api/batch GET 2024-08-31
     batch 200 2024-08-31
/api/batch GET 2024-08-31
     batch 200 2024-08-31
 /api/test GET 2024-08-31
      test 200 2024-08-31
 /api/test GET 2024-08-31
      test 200 2024-08-31

とても見やすくなります。

まとめ

今までcutやsedを使ってゴニョゴニョしており、似た様なログでも文字数が違ったり一覧系のレスポンスになると綺麗に抽出できず困っていました。 ですので、awkを使って改善できそうです。

また出力の順番を変えたり、これが欲しいと宣言するのはプログラミングっぽいので嬉しいですね。

超入門にしては、とても収穫が多かったです。ではこの辺で。

参考リンク

ありがとうございました。