散らばったログを因果に束ねる

目標

形式の異なる3つのログを重ねて、散らばった事実を1つの因果にまとめられるようになります。

なぜ重要なのか

エラーログから見るのは自然ですが、物語の途中から読むことです。典型的な劣化は、変更 → 一部リクエストの遅延(警告) → リソースの占有 → タイムアウト(エラー) → アラートの順に進み、エラーログだけを見ると、最後の2つの段階しか見えません。そのため、投げるべき質問は「いつエラーが始まったか」ではなく、「いつ正常でなくなったか」であり、警告レベルの初出時刻が、その答えです。

このラボで確認するもう1つは、平均の無力さです。全体の平均レイテンシはどのリクエストも代表しませんが、「1000msを超えるリクエストが何件か」はすぐに問題を表に出します。指標を1つだけ選ぶなら、平均ではなく、しきい値超過の件数を選んでください。

3つのログ

/opt/data/app.jsonl: 1行が1つのJSONです。ts、level、service、request_id、path、status、latency_ms、msg
/opt/data/db-slow.log: ts=<epoch> duration_ms=<n> table=<name> query="..."
/opt/data/deploy.log: デプロイとロールバックの履歴です。

ステップ

/root/correlateディレクトリを作成してください。
app.jsonlで、levelがerrorの行の数を、/root/correlate/error_count.txtに書いてください。
エラーメッセージが指しているテーブル名を、/root/correlate/table.txtに書いてください。
全体のlatency_msの平均を、整数に切り捨てて/root/correlate/avg_latency.txtに書いてください。
latency_msが1000を超えるリクエストの数を、/root/correlate/slow_count.txtに書いてください。
levelがwarnの最も早い行の時刻を、HH:MMで/root/correlate/first_warn.txtに書いてください。
deploy.logで、事故の直前にデプロイされたpaymentサービスのバージョンを、/root/correlate/version.txtに書いてください。
/root/correlate/link.mdに、因果を整理してください。デプロイバージョン、遅くなったテーブル、最初の警告の時刻、エラーの時刻が、すべて入っている必要があります。

参考

grep '"level": "error"' /opt/data/app.jsonl | wc -l
python3のワンライナーでパースするほうが楽かもしれません: python3 -c "import json,sys; ..."
jqがあればjq -r 'select(.level=="warn") | .ts' /opt/data/app.jsonl | sort | head -1
よくあるミス1: ステップ4で四捨五入してしまうことです。切り捨てです。
よくあるミス2: ステップ6でerrorの最初の時刻を書いてしまうことです。warnのほうが前にあり、その間隔がこのラボの要点です。

作業ディレクトリを作る

/root/correlateディレクトリを作成してください。

/root/correlateの下に、結果を集めます。

エラーログの数を数える

app.jsonlで、levelがerrorの行の数を、/root/correlate/error_count.txtに書いてください。

app.jsonlは、1行が1つのJSONです。levelフィールドがerrorの行を数えてください。

原因のテーブルを突き止める

エラーメッセージが指しているテーブル名を、/root/correlate/table.txtに書いてください。

エラーメッセージ自体に答えが入っています。msgフィールドを、1行だけきちんと読んでみてください。

平均レイテンシを求める

全体のlatency_msの平均を、整数に切り捨てて/root/correlate/avg_latency.txtに書いてください。

全体のlatency_msの平均を、整数に切り捨てます。この値が、後のステップと対比されます。

遅いリクエストの数を数える

latency_msが1000を超えるリクエストの数を、/root/correlate/slow_count.txtに書いてください。

latency_msが1000を超えるリクエストの件数です。平均1つでは見えなかったものが、表に出ます。

最初の警告の時刻を見つける

levelがwarnの最も早い行の時刻を、HH:MMで/root/correlate/first_warn.txtに書いてください。

levelがwarnの行のうち、最も早いtsのHH:MMです。エラーより前にあります。

直前のデプロイバージョンを見つける

deploy.logで、事故の直前にデプロイされたpaymentサービスのバージョンを、/root/correlate/version.txtに書いてください。

deploy.logで、事故の時刻の直前にデプロイされたpaymentサービスのバージョンです。

因果を整理する

/root/correlate/link.mdに、因果を整理してください。デプロイバージョン、遅くなったテーブル、最初の警告の時刻、エラーの時刻が、すべて入っている必要があります。

デプロイバージョン、遅くなったテーブル、最初の警告の時刻、エラーの時刻を、1つのドキュメントにまとめてください。