ログがないということも情報だ

一言でいうと

ログがなくても、調査が終わるわけではありません。ほかの痕跡で時間を絞り、次の事故にはログが残るようにするところまでが仕事です。

なぜ必要なのか

「昨日の午後に何件か失敗したそうです」という報告を受けて、ログを探します。ところが、保存期間が24時間ですでに消えていたり、ログレベルがWARNで必要な情報が出力されていなかったり、そもそもその区間にログ文がなかったりします。

このとき、「ログがなくて確認不能」で終わらせると、同じことが繰り返されます。

ログではない痕跡

痕跡	何がわかるか	確認方法
ファイルのmtime	いつ何が変わったか	`find /etc -mmin -1440 -type f`
DBのタイムスタンプ	データが作られた・変わった時刻	`created_at`、`updated_at`の分布
プロセスの開始時刻	いつ再起動されたか	`ps -eo pid,lstart,cmd`
システムの起動時刻	サーバーがいつ立ち上がったか	`uptime -s`
ファイルサイズの変化	いつ急増したか	バックアップスナップショットの間の比較
パッケージのインストール時刻	何がいつ入ったか	`/var/log/dpkg.log`、`rpm -qa --last`
シェル履歴	人が何をしたか	`~/.bash_history`(時刻を設定している場合)
証明書の有効期間	期限切れによる障害の時刻	`openssl x509 -noout -dates`

データそのものがログです。失敗した注文のcreated_atの分布を分単位で集計すれば、ログがなくても、事故が始まった分(minute)を特定できます。

SELECT date_trunc('minute', created_at) AS m, count(*)
FROM orders WHERE status='FAILED' AND created_at >= now() - interval '2 days'
GROUP BY 1 ORDER BY 1;

この結果で値が跳ねる地点が、事故の時刻です。そして、その時刻をデプロイ記録、設定変更、起動時刻と突き合わせると、候補が1つか2つに絞られます。

ないという事実も証拠

ログが空いている区間は、それ自体が情報です。

普段は毎分200行なのに、14:03–14:07が0行なら、プロセスが止まっていたか、ディスクが満杯で書き込めなかったのです。
エラーログだけがなく、アクセスログは正常なら、リクエストがそもそもアプリまで来なかったのです。前段(LB・プロキシ)で切れたことになります。
1台のサーバーだけログがないなら、そのサーバーが、ローテーションに失敗したか、ディスクが満杯の状態です。

「出力されなかった」を「わからない」に翻訳せず、「何が出力されなかったのか」を問えば、範囲が絞られます。

次のために残す

調査の末に原因を見つけたなら、最後の作業は、同じことがまた起きても、今回より早く気づけるようにすることです。

ログ文を追加する: 失敗する経路に、何がなぜ失敗したかを。事後調査で必要だった値(リクエストID、対象、所要時間)も一緒に。
保存期間を調整する: 24時間は、大半の調査には足りません。せめてエラーログだけでも長く。
相関ID: リクエストごとにIDを付けて、システムをまたいで追跡できるように。これがないと、複数のサービスのログを時刻だけで合わせることになります。
指標を1つ: 今回問題だったものを、カウンターやゲージで。次回はグラフで見えます。

この4つを報告書の「再発防止」の項目に書けば、それは形式的な文ではなく、実際に次の調査を数時間短縮します。

事後計装: 今すぐ必要な場合

問題がいま進行中なのにログがないなら、再現している間に観測を付けます。

定期的なスナップショット: while true; do date; ss -s; ps aux --sort=-%cpu | head -5; sleep 10; done >> /tmp/watch.log
応答時間のサンプリング: curl -wを繰り返し実行して、ファイルに残します。
DBのアクティブセッションのスナップショット: 待機イベントごとの集計を、定期的に。

荒削りですが、何もないよりは圧倒的に優れています。そして、このファイルが、次の会議で唯一の根拠になります。

他人のシステムで初めて観測を付けるとき

FDEとして入った現場には、たいていログがないか、あっても見られません。権限もなく、デプロイも勝手にはできない状態で、最小の変更で最大限を見る順序があります。

1つ目は、すでにあるものを探すことです。新しく付ける前に、そのシステムがすでに残しているものを数えます。Webサーバーのアクセスログ、データベースのスロークエリログ、ロードバランサーの統計、クラウドのフローログ。たいてい有効になっているのに、誰も見ていません。

2つ目は、外から測ることです。コードを直せなくても、外から叩くことはできます。数分間隔で主要なパスを呼び出して、レスポンス時間とステータスコードを残せば、障害がいつ始まったかは、それだけでわかります。原因がわからなくても、時刻がわかることが、調査の半分です。

3つ目は、境界に付けることです。アプリケーションを直せなくても、その前段のプロキシやサイドカーは変更できることが多いです。リクエスト単位で時間とステータスを残すようにすれば、コードを1行も直さずに、リクエストごとの観測が得られます。

4つ目は、そこで初めてコードを直すことです。ここまで来れば、どこを計装すべきかをすでに知っています。最初からコードに手を付けると、見当違いの場所を計装することになり、その変更を元に戻すコストまで払います。

残すものと残さないものを、最初に決めます。他人のシステムであるほど、個人情報が何かを知らないままログを有効にしがちです。リクエスト本文をまるごと残す設定は、有効にする前に、何が入っているかを先に確認します。

報告するときは、数字と一緒に、その数字の出所を書きます。「遅いです」ではなく、「このパスのp95が4.2秒で、ロードバランサー基準の過去7日間の中央値は0.4秒です」と書けば、その場で次の行動が決まります。出所がなければ、その数字から争い直すことになります。

現場での姿

保存期間が7日なのに、報告が10日後に来る場合は、データのタイムスタンプで時刻を特定します。
ログにリクエストIDがなく、サービス間をつなげない場合は、時刻で無理に合わせて、誤判断します。
「再現しなければ見られません」という場合は、事後計装を付けておけば、次回は捕まえられます。

続くラボですること

事故の区間のエラーログが消えた現場を受け取ります。データのcreated_at、アクセスログの空き区間、設定ファイルの更新時刻だけで、事故の時刻を分単位まで絞り、候補を1つにします。

最後に、事後計装ツールを自分で作ります。採点ツールがそれを実際に実行して、時刻と観測値が定期的に残るかを確認します。