Linux のログ調査 Tips

uzuki

こんにちは、uzukiです。
Elasticsearch とかとても便利ですよね。
ただファイルにログを書き出すだけのケースも多く、そこから目的の情報を取得するのに時間がかかる時もあります。
そんな時に、私が普段行っているログ調査について、お話したいと思います。

対象読者

  • bash を利用していること
  • cat / grep / sed / awk 等のコマンドがある程度扱えること

ログ調査で気を付けるポイント

  • 稼働サーバに負荷をかけない
    • CPU やメモリに負荷がかかりそうな場合、scp や rsync でログファイルを手元に持ってくるのをオススメします
  • なんでもかんでもワンライナーでやらない
    • ログが大量にある場合など実行に時間がかかる時は、細かく中間ファイルを生成することにより、手戻り時も途中から再開できるので安心です
  • ファイル出力には気を付ける
    • 意図せず無限ループコマンドになっており、かつファイル追記だった場合、とても悲惨なことになります
  • 試しながらコマンド実行する場合、head を適度に入れ込む
    • 数百万行のログを対象に少しずつ grep で絞り込む、ってことをしている時等に必須です

ログ調査に必要なコマンドとは?

私は下記コマンドをよく利用しています。

  • cat 系(cat / zcat / bzcat)
  • grep 系(grep / zgrep / bzgrep)
  • sed
  • awk
  • sort
  • uniq
  • head
  • wc
  • xargs

たまに下記コマンドを使います。

  • echo
  • while / read
  • bash
  • find
  • env
  • for
  • if(test)

私は開発者なので OS や bash の知識はそこまでありませんが、この辺りのコマンドだけでログ調査はなんとかなってます。

基本的な出力

Plain Text

bzcat は CPU 負荷が高いので head を使いながら確認すると良いです。 cat 系(cat / zcat / bzcat 等)コマンドの後にパイプで grep に渡すか、最初から grep 系(grep / zgrep / bzgrep 等)を使うかはお好みで 。

ログローテーションで日付をログファイル名に付加している場合、

Plain Text

で、前日のログファイルを参照できます。
ポイントは、シェル変数を汚染しないよう env コマンドを使用するところと、変数化しておくことにより任意の日時指定を容易(コマンド先頭になるため)にしているところです。

特定フィールドの抜き出し

Plain Text

フィールドから抜き出す場合、順序が固定なログであれば cut コマンドで出すのが楽かと思います。

ltsv の場合、awk でフィールド名から抜き出す方法もあります。
sed で不要文字列を空白文字列に置換する方法もありますが、冗長になるので省きます。

特定の日時の件数を確認

下記ログが出力されている web サーバのアクセスログファイルを対象にします。

Plain Text

下記コマンドでは、web サーバのアクセスログから、秒間何リクエスト来ていたのか、等を調べる時に使用します。

Plain Text

応用として、時間辺り何リクエスト来ていたか、を調べるには下記の通りとなります。

Plain Text

時までを cut で抜き出し、その件数を調べています。

途中で落ちたプロセスの特定

アプリケーションのログで、下記のようなログを出力していると仮定します。

Plain Text

ログを出力せずに落ちたっぽい、という時に、どのあたりで落ちたのか調べるのは下記の通りです。

Plain Text

ユニークである id 値を配列のキーとして指定することにより、「End process.」で終わっていない id 値を持つ行を取得します。
pid を用いる場合、重複する可能性があるので注意が必要です。ログに pid 程度しか識別できる情報がない場合、time 値の一部をキーに含ませることにより、ある程度識別することは可能です。
しかしながら完全な識別はできませんので、なんらかのユニークな値をログに書き出すと良いでしょう。

特定の id 値を持つデータが適切に処理されたかの確認

昨今マイクロサービス化していく流れとなっていますが、各サービス間で適切にデータを受け渡せているかの確認方法となります。
例えば A サービスから B サービスへの非同期引き渡しを行うサービスがあり、下記ログを出力していると仮定します。

Plain Text

A サービスへの負荷集中により A サービスが落ちたしまった場合、A サービスが受け取っていたデータを B サービスにすべて引き渡せていたか?の確認方法です。

Plain Text

中間ファイルを2つ出力していますが、量が少なければワンライナーでも問題ありません。
1つ目のコマンドでは、影響があったであろう時間帯のログから id 値のみを出力し、2つ目のコマンドで1つ目のコマンドの結果を1行ずつ grep しています。
それらの結果を3つ目のコマンドで差分を出し、差分のあった(=b_service.log に出力がない)行を出しています。

1行に複数データが含まれている場合のデータ数カウント

1行に複数データが含まれてしまっているログの内、どのくらいデータがあるのかをカウントする方法です。
下記ログを出力していると仮定します。

Plain Text

data 値内の events 配列の件数をカウントする方法です。

Plain Text

時間毎の data 値内の events 配列の合計値を求めるには、下記方法にて可能です。

Plain Text

awk を使ってうまいこと時間ごとの events 配列の合計値を出すことができます。

まとめ

各コマンドの説明は色んなサイトで紹介されていますが、それらを組み合わせて目的の出力を得る方法がまとまっているサイトがなかったので記事にしてみました。
慣れてくればパッと各コマンドの組み合わせを思いつくことができるようになりますので、私も精進していきたいと思います。

また、冒頭で「稼働サーバに負荷をかけない 」ポイントとして手元に持ってくると書きましたが、稼働サーバの属するネットワークへの配慮(ログの圧縮や転送時の速度制限の実施等)や、個人情報を含むログファイルの場合は転送時のSSL化 / 調査完了時に削除を忘れない、ってことも大切ですね。

uzuki

Posted by uzuki