Linuxコマンドでログを解析し、障害の原因を突き止めよう(総合演習)

調査は「どこにログがあるか」を探すところから始まります。lsで今いる場所の中身を見て、logsというディレクトリを見つけてcdで入ります。

lsの表示で末尾に/が付いているものがディレクトリです。ファイルとディレクトリを見分ける手がかりになります。

移動したらpwdで今いる場所を確かめる癖をつけてください。ディレクトリを間違えたまま作業して、見当違いのファイルを調べていた——というのは実際によくあります。

ls -lにするとサイズや権限まで見えます。ログ調査ではファイルサイズが手がかりになることがあり、異常に大きいログは何かが大量に出力されている印です。

本番のサーバーでは、ログはたいてい/var/log/の下にあります。cd /var/logから始めるのが定石です。

いきなりcatで全部表示したくなりますが、本番のログは数万行あります。画面が流れるだけで何も分かりません。

まずwc app.logでどのくらいの量なのかを確かめます。左から行数・単語数・バイト数です。10行ならそのまま読めますが、10万行なら読み方を変える必要がある——その判断のための一手です。

次にheadとtailで前後だけを覗きます。-n 3で3行だけです。

ログ調査ではtailのほうを先に見ます。ログは下に行くほど新しいので、「今起きている問題」は末尾にあるからです。実務ではtail -fで流れ続けるログを眺めながら操作を再現する、という使い方をよくします。

今回のログは「時刻,レベル,メッセージ」のカンマ区切りだと分かりました。形式が分かれば、あとは機械的に絞り込めます。

ここからが本番です。grep ERROR app.logでERRORを含む行だけが残ります。

grepはログ調査で最もよく使うコマンドです。何万行あっても、必要な行だけが一瞬で出てきます。「ログを読む」というのは、実際にはほとんど「grepで絞る」作業です。

結果は4行。10行中4行がエラーという、かなり良くない状態です。

ここで大文字小文字が区別されることに注意してください。grep error app.logでは1行も出ません。実務ではgrep -iで区別せずに探すことが多く、ログの書式が揃っていないときに効きます。

数を数えたいときは本来grep ERROR app.log | wc -lとパイプでつなぎます。この疑似ターミナルはパイプに対応していないので、ここでは出てきた行を目で数えてください。本物のサーバーではこの書き方が基本になります。

WARNも見ておくと、エラーの前後で何が起きていたかが見えてきます。

エラーが4件あることは分かりました。次に知りたいのは「何が原因なのか」「同じ原因が繰り返されているのか」です。

cut -d , -f 3 app.logで3列目(メッセージ)だけを取り出します。-dが区切り文字、-fが何列目かです。時刻やレベルが消えて、メッセージだけが並びます。

次にsortを通すと同じ文字列が隣り合って並びます。するとdatabase connection timeoutが3回並んでいるのが目で見て分かります。

これが「集計」の第一歩です。本来はsort | uniq -cとつないで件数を出しますが、この疑似ターミナルはパイプとuniq -cの件数表示に対応していないため、ここでは並べるところまでにしています。本物のサーバーではcut -d , -f 3 app.log | sort | uniq -c | sort -rnが定番の一行です。

この演習ではcut -d , -f 3と空白を空けて書いてください。cut -d, -f3と詰めて書くと、この疑似エンジンではエラーを出さずに1列目を返してしまいます(本物のLinuxでは詰めて書いても正しく動きます)。

怪しいのはdatabase connection timeoutです。これだけを狙って引きます。

grep timeout app.log——3件出ました。時刻を見ると10:02:17、10:02:25、15:58:02。10時台に2件が8秒差で連続し、午後にもう1件です。

時刻の固まりは大きな手がかりです。8秒差で2回というのは、1回失敗して再試行し、それも失敗したという形です。実際、WARNにretrying connectionが出ていたのと符合します。

もうひとつのログも見てみましょう。grep 500 access.logでサーバーエラーを返したアクセスが引けます。時刻が10:02:17・12:44:52・15:58:02——app.logのERRORと時刻がぴったり一致します。

2つのログを時刻で突き合わせるのは、障害調査の基本です。「アプリ側のエラー」と「利用者から見たエラー」が同じ時刻で繋がると、原因と影響が一本の線になります。

コマンドはここまでです。最後は分かったことを人に伝えられる形にします。調べただけで終わっては仕事になりません。

今回のログから言えるのは、次の3点です。

1. エラーは10行中4件。うち3件が同じ原因(database connection timeout)で、残り1件が決済APIの500エラー。

2. 発生時刻は10:02台に2件(8秒差)と15:58に1件。8秒差の連続は、再試行して再び失敗した形。WARNのretrying connectionと符合する。

3. 利用者にも影響が出ている。access.logの500エラーが同じ時刻に記録されており、/api/orders——注文の処理——が失敗している。

ここまで書ければ、「データベースへの接続がときどきタイムアウトしていて、注文が通らなくなっている」という報告になります。あとは接続数の上限や、ネットワークの状態を疑う番です。

ログ調査のコツは、いきなり原因を探さないこと。「量をつかむ → 絞る → 並べる → 突き合わせる」の順に手を動かせば、たいていの障害は形が見えてきます。

下の疑似ターミナルで、STEP1から自分の手で通してみてください。

下は本物の疑似ターミナルです。まっさらな状態から始まるので、STEP1のコマンドから順に打って、マージまで辿り着いてください。読んで分かった気になるのと、自分で打てるのとは別物です。

詰まったら上のステップに戻って構いません。resetと打てば最初からやり直せます。