ログに何を出力するべきか

仕事でHTTPで使うAPIを書いているのだけど、問題が起きた時にログの内容から問題を特定できないといった問題があり、ログを見直すことになった。
そもそも、自分は今まで運用時の問題を意識してログを書いたりとかしたことがなかったので、何が必要なのかとか考えてみた。

何か良い感じの規則を決めるだとか、何も考えなくてもよい感じに解決してくれるような、そんな感じの答えを求めてる。

書きたいこと

ログに出すべき情報
ログはあまり出さないほうがよいか

一例

たとえば、あるユーザが商品を購入しようとしたとき、システムエラーになったとする。
システム側の都合でエラー画面を出されたら、ユーザはいい気持ではないだろうから、早急に直す必要がある。

システム側はシステムエラーが起きていることはわかった。
しかし、この原因を特定したいとき、どういう情報が必要だろう。

ログに出すべき情報

当然、問題が起きた時にその問題を特定するために必要な情報。
でもこれは意識して設計の段階で組み込むべき内容ではないかな、と思っている。

(ちなみに今の仕事で使っている設計書はシステムとして実現するための内容を日本語で書き起こしたようなもので、障害時のことはあんまり考えられていない。運用フェーズになる前にようやく考え始めるような感じ。)

この時どういう情報を集めればよいかを考えた。

ユーザの導線(どの画面・APIアクセスしたときか)
システムエラーと判断した箇所
発生時間
ユーザの状態

システムエラーと判断した箇所だけでも良いのだけど、共通化などで複数のAPIの処理から呼ばれる場合は、ユーザの導線わからないと絞り込めなくなる場合がある。

ユーザの状態はなるべく知りたい。システムエラーと判断した箇所は、どの状態をみて判断したのか。
この「どの状態」というのがログに出しておきたい情報だと考えている。

極論を言えば・・・

大した経験は語れないけども、自分がログの調査依頼されたときは、このあたりさえわかれば・・・と思ってる。

問題が起きた個所
受け付けた情報(リクエスト、プログラム引数)
変数(オブジェクトが持つメンバ/フィールド、できればローカル変数も)
関数(メソッド)の引数
外部連携の要求と結果(DBのクエリログや外部通信のリクエスト/レスポンス)

これらを全部ログに出しておけば、問題はほぼ特定できると思っている。
(外部連携については外部と協力して調査できるなら不要。社内APIならここは意識しなくてもよいかも)

それで特定できない場合、マルチスレッドの問題とかになってくるのかなーと思っている。(同時刻に他のスレッドでどんな処理が走ってたかとか)

現実

極論で挙げた内容は、何も考えずにこれらの情報をログへ垂れ流しにすることは大抵可能なのだけど、実際は本当に必要な情報を絞って出してやることになると思う。

個人情報などログでも出してはダメな情報もあるし、そもそも全部の内容をログに出したら今度は本当にシステムに影響を与えた情報を探すのが大変。(あるに越したことはないのだけど・・・でも1リクエストで100kiBも出力されると辛い。)
また、DBにも情報があるのだからキーになる情報だけ出せばよいって話もある。DB見る手間増やしてログの量を減らす意義はあるのかどうなのか。

こんな感じで単純な話ではないと思っていて、実装者や設計者のセンスに任せるとダメ。何を出すべきかちゃんと考えて決める必要がある。
必要な情報が抜けていると調査が進まなくなることもある。かといって何が必要で何が必要ではないかとかをいちいち考えると辛い。

でも実際、こんなところに工数を割くことは聞いたことがない。みんないい感じにログが出て問題が起きてもうまく解決できることを期待してる。

ログはあまり出さないほうがよいか

ログは全部が全部出す必要はない。そうでなければログレベルはいらない子だから。
開発やデバッグではトレースログが取れれば十分だし、運用時はそのあたりもボトルネックになるから無駄なログは出さないようにしてる。

また、ログは残り続けるデータだし、調査のために開発者や監視・運用の人などに目につくものである。
ログが肥大化すると人力で調査するときに慣れが必要になるし、大量のログを相手にするのは普通は骨が折れる。(心も折れる。)

個人的には「正常時はあまり出さず、異常時は大量に出す」感じがよいのかなーと思っている。

でも問題が起きた時に必要な情報を出そうとしたが、変数が参照できなくて表示できなかったりする。必要だと勘違いしているだけか、実装の問題なのかわからないけど、ままある。

なので異常かどうかわからないけど、とりあえずどっかにため込んでおいて、異常ってわかった時にため込んだ内容をログに書くことができればーって思ってイメージを書いた。

イメージ

package net.ryozi.logcontainer;

import org.junit.Test;

public class LogContainerTest {
	@Test
	public void test() {
		try {
			String message = "message";
			LogContainer.add("transaction variable", message);

			System.out.println("--- 1 ---");
			System.out.println(LogContainer.toMessage());

			{
				LogContainer.pushStack();
				LogContainer.add("nest", "string1", 2);

				if(message.equals("message")){
					LogContainer.add(() -> "variable message value is 'message'");
				}

				System.out.println("--- 2 ---");
				System.out.println(LogContainer.toMessage());

				LogContainer.popStack();
			}

			System.out.println("--- 3 ---");
			System.out.println(LogContainer.toMessage());
		} catch (Exception e) {
			System.err.println(LogContainer.toMessage());
			throw e;
		} finally {
			LogContainer.clear();
		}
	}
}

みたいなコードを書いて、

--- 1 ---
transaction variable=[message] [net.ryozi.logcontainer.LogContainerTest.test(LogContainerTest.java:10)]

--- 2 ---
transaction variable=[message] [net.ryozi.logcontainer.LogContainerTest.test(LogContainerTest.java:10)]
nest=[string1, 2] [net.ryozi.logcontainer.LogContainerTest.test(LogContainerTest.java:17)]
variable message value is 'message' [net.ryozi.logcontainer.LogContainerTest.test(LogContainerTest.java:20)]

--- 3 ---
transaction variable=[message] [net.ryozi.logcontainer.LogContainerTest.test(LogContainerTest.java:10)]

みたいな動きができれば、必要な時に必要なものだけログ出せるのかなーとか思ったり。
実際は例外時とか、エラーログ出力時に、必要だったらLogContainer.toLogMessage()を呼び出す。

良い点
- ログレベル気にしなくてよい
- とりあえず必要そうならぶち込んで必要ならあとで取り出す感じでカジュアルに使える(といいな)
欠点
- 処理する内容が大きくなってくると多分、使いにくいものになる。
- メモリと実行速度に影響があるかもしらん
- ループ中でやってしまうと無尽蔵に作られてしまうので結局使いどころを意識しないといけない

最初、ループ中で呼び出したらただ値を突っ込んでおくだけだとダメということに気づき、
pushStack/popStackで必要なスコープを制限したりすればよいかなーとも思ったが、
基本pushしたらpopを呼び出すことを守らないといけないので面倒なだけな感じ。

書いて気付いたけど、結構面倒だしあまり現実的じゃない感じがした。

まとめ

もうめんどいから必要だと思ったらその時点で都度出したい。ログの量が気になる？圧縮しましょう。ログ見るのがつらい？慣れましょう。
パスワードとかの大事な情報だけはきっちり決めて、誤ってでも出さないように注意する。

うーん。