RAKUS Developers Blog | ラクス エンジニアブログ

株式会社ラクスのITエンジニアによる技術ブログです。

【新米エンジニア向け】ログ調査に便利なLinuxコマンド

はじめに

はじめまして。開発エンジニアのwest-cです。
ラクスに新卒で入社し、今年で3年目になります。

ラクスでもエンジニアブログをはじめることになりました。
記念すべき1エントリ目を書くことになり光栄です。

本題

そんな1エントリ目のテーマですが、現在、私自身が新卒メンバーの育成を担当していることもあり、今年入社した新米エンジニアを対象にお話をしたいと思います。

大学や会社の研修でプログラムは学ぶかと思いますが、ログの見方・調査方法についてしっかり学んだことのある方は少ないのではないでしょうか。

個人で作成したプログラムであればエラーが発生したとき程度しか見ないログですが、お客様に提供するアプリケーションとなると話はちょっと変わってきます。
ログは、ユーザがとった行動の証跡(証拠)となることから、利用状況の把握から問題が発生した場合の原因特定まで非常に重要な役割を担います。

ログの形式はソフトウェアによって異なるためそれぞれの公式ドキュメントに譲るとして、ここではログ調査にあたり知っておくと便利なLinuxコマンドを紹介したいと思います。
なお、今回は Apache のアクセスログを例として説明を行います。

リアルタイムでログを監視したい

$ tail -f access_log

ファイルの末尾が更新されると自動的に追加分が表示されます。
例えば、検証環境にて画面遷移をした瞬間のログを確認したい場合などに重宝します。
長いスタックトレースを確認する場合は、予めEnterキーでいくつか改行を入れておくとログの切れ目が分かりやすくなり便利です。

ログをスクロールして表示したい

$ less access_log

行数の長いファイルの場合、catでファイルの中身を見ようとすると画面に収まり切らず、目的のログに辿り着くのにひと苦労します。
そのようなときにlessを利用すると、スクロールしながら閲覧することができます。
lessコマンド内で利用できる操作のうち、個人的によく使うものは以下になります。

キーバインド 説明
b 1画面分上にスクロール
スペース 1画面分下にスクロール
g ファイル先頭に移動
G ファイル末尾に移動
/文字列 ファイル内を文字列で検索
n 次にヒットした検索文字列の行に移動
N 前にヒットした検索文字列の行に移動
F リアルタイムで監視(tail -fと同様)
q lessコマンドを終了する

表示する行を絞り込みたい

以降は、以下のようなアクセスログを前提として説明を行います。
(GET or POST の前の数値はリクエスト処理にかかった時間(単位:秒)、末尾の数値はレスポンスサイズと解釈してください)

$ cat access_log
192.168.10.11 - - [10/Oct/2000:13:55:36 -0700] 1 "GET /index.php HTTP/1.0" 200 2326
192.168.10.11 - - [10/Oct/2000:13:55:36 -0700] 0 "GET /top.jpg HTTP/1.0" 200 310
192.168.20.8 - - [10/Oct/2000:13:56:01 -0700] 10 "POST /login.php HTTP/1.0" 200 1793
192.168.30.50 - - [10/Oct/2000:13:57:11 -0700] 5 "GET /mypage.php HTTP/1.0" 200 831
192.168.30.50 - - [10/Oct/2000:13:57:11 -0700] 0 "GET /room.png HTTP/1.0" 200 4530

特定の文字列が含まれる行のみを抽出したい場合はgrepの出番です。

$ grep "login" access_log
192.168.20.8 - - [10/Oct/2000:13:56:01 -0700] 10 "POST /login.php HTTP/1.0" 200 1793

ファイルから「login」という文字列が含まれる行のみが抽出されました。

逆に「login」という文字列を含まない行を表示する場合は、-vオプションを付けましょう。

$ grep -v "login" access_log
192.168.10.11 - - [10/Oct/2000:13:55:36 -0700] 1 "GET /index.php HTTP/1.0" 200 2326
192.168.10.11 - - [10/Oct/2000:13:55:36 -0700] 0 "GET /top.jpg HTTP/1.0" 200 310
192.168.30.50 - - [10/Oct/2000:13:57:11 -0700] 5 "GET /mypage.php HTTP/1.0" 200 831
192.168.30.50 - - [10/Oct/2000:13:57:11 -0700] 0 "GET /room.png HTTP/1.0" 200 4530

grep -Eまたはegrepを利用すると、検索文字列に正規表現を利用することができます。

上記を組み合わせると、画像ファイル(*.jpg, *.gif, *.png)を除外したログを表示したい場合に、以下のように記述することができます。

$ egrep -v "\.(jpg|gif|png)" access_log
192.168.10.11 - - [10/Oct/2000:13:55:36 -0700] 1 "GET /index.php HTTP/1.0" 200 2326
192.168.20.8 - - [10/Oct/2000:13:56:01 -0700] 10 "POST /login.php HTTP/1.0" 200 1793
192.168.30.50 - - [10/Oct/2000:13:57:11 -0700] 5 "GET /mypage.php HTTP/1.0" 200 831

表示する列を絞り込みたい

例えば以下の3つの情報がログ調査に必要であるとします。

  • アクセス日時
  • リクエストURL
  • リクエストにかかった時間

この3つ以外の情報は今回は必要の無いノイズ情報ですので、awkで表示する列を絞り込みましょう。

awkで列を絞り込む場合、デフォルトでは空白(スペース)またはタブ単位で区切られます。
今回の例だと、4列目(アクセス日時)・6列目(リクエストURL)・8列目(リクエストにかかった時間)だけを表示したいことになります。

$ awk '{print $4,$6,$8}' access_log
[10/Oct/2000:13:55:36 1 /index.php
[10/Oct/2000:13:55:36 0 /top.jpg
[10/Oct/2000:13:56:01 10 /login.php
[10/Oct/2000:13:57:11 5 /mypage.php
[10/Oct/2000:13:57:11 0 /room.png

必要な情報のみが表示され、見通しが良くなりました。

$の後の数字には、区切り文字で行を分割した際の順番が入ります(1始まり)。
区切り文字を変更したい場合は、-F '区切り文字'とオプションを付与すれば良いです。

ちなみにcutコマンドでも同様のことは実現できますが、次に紹介する話との関連で、ログの確認時にはawkを利用することをおすすめします。

条件に合致するログのみを抽出したい

ひとつ前の例に追加して「リクエストに3秒以上かかったログのみを抽出したい」場合を考えてみましょう。
awkプログラミング言語なので、条件分岐を記述することもできます。

$ awk '$6>=3{print $4,$6,$8}' access_log
[10/Oct/2000:13:56:01 10 /login.php
[10/Oct/2000:13:57:11 5 /mypage.php

このように「○番目の項目が□□だった場合」と記述することができるため、単純な文字列一致の条件の場合でもgrepよりも細かく絞り込みを行うことができます。

まとめ

私自身、入社したての頃にログファイルをviで開いて怒られたりログファイルを根こそぎExcelに貼り付けてちまちま絞り込みを行ったりと苦い経験があったため、今回このテーマを選ぶことにしました。

今回取り上げた内容は基本的なものであり、さらに高度なログ集計を行おうとすると、sortuniqsedなども必要になるかと思います。
まずはこの記事を足がかりに、その他のコマンドも習得してステップアップしてもらえると嬉しいです!


◆TECH PLAY
techplay.jp

◆connpass
rakus.connpass.com

Copyright © RAKUS Co., Ltd. All rights reserved.