📝

slogをラップした時に意図したソースコード位置を表示する

2023/11/07に公開

tech

はじめに

ログ出力機能をラップすると本来表示したいログ出力を呼び出したソースコード位置ではなくラップ部分の位置が表示されてしまいトラブル調査の妨げになってしまうことがあるかと思います。

最近Goに標準として入ったslogでこれを回避する方法をテストしたので備忘として残します。

検証

サンプルコード

プロジェクトのトップにloggerディレクトリを作りそこでinterfaceを定義します。またstdlogディレクトリ作りそこでslogをラップしたオリジナルのロガー実装を用意します。

Info, Errorのインターフェースを持ち、いつでも実装を差し替えられるようになってるロガーです。こうすることでログ出力先を切り替えたり何も出力しないようにしたりと振る舞いを簡単に変更できます（ ~~めんどくさい~~ 本題から逸れるので排他制御は割愛）。
まぁよくあるなんてことはないロガーですね。

以下、コードは抜粋なので予め↑のリンクから全体像を見ておいた方が理解が早いと思います。

意図しない位置で出してみる

コード位置を出したいのでハンドラーのオプションに AddSource: true をセットして実行してみましょう。

func New() *StdLogger {
	opts := &slog.HandlerOptions{
		AddSource: true,
	}
	sl := slog.New(slog.NewTextHandler(os.Stdout, opts))
	el := slog.New(slog.NewTextHandler(os.Stderr, opts))

	return &StdLogger{
		stdLogger: sl,
		errLogger: el,
	}
}

main.go

func main() {
	l := stdlog.New()
	logger.SetLogger(l)
	run()
}

func run() {
	logger.Info("info log")
	logger.Error("error log")
}

以下のようにロガーの実装箇所がソースコード位置として表示されてしまいました。
本来であれば main.go 側の呼び出し位置が表示されて欲しいでしょう。また多くの場合フルパスではなくファイル名だけで十分のはずです。

time=2023-11-06T23:31:52.311+09:00 level=INFO source=/Users/***/go/***/slog-wrap-row-num/stdlog/stdlog.go:39 msg="info log"
time=2023-11-06T23:31:52.311+09:00 level=ERROR source=/Users/***/go/***/slog-wrap-row-num/stdlog/stdlog.go:43 msg="error log"

良い感じにする

slogのハンドラーオプションにはログの属性単位で出力差し替える機能があるので、それを利用して以下のように修正します。

	opts := &slog.HandlerOptions{
		AddSource: true,
		ReplaceAttr: func(_ []string, att slog.Attr) slog.Attr {
			if att.Key == slog.SourceKey {
				const skip = 8
				_, file, line, ok := runtime.Caller(skip)
				if !ok {
					return att
				}
				v := fmt.Sprintf("%s:%d", filepath.Base(file), line)
				att.Value = slog.StringValue(v)
			}
			return att
		},
	}
	sl := slog.New(slog.NewTextHandler(os.Stdout, opts))
	el := slog.New(slog.NewTextHandler(os.Stderr, opts))

良い感じになりました

time=2023-11-06T23:39:21.199+09:00 level=INFO source=main.go:15 msg="info log"
time=2023-11-06T23:39:21.199+09:00 level=ERROR source=main.go:16 msg="error log"

何をやっているか？

ベースとしては slog.SourceKey (ソースコード場所の表示であることを示すアトリビュート) が利用されたらコールスタックを取得した上で適切な数スタックを遡り、そこを基準とすることで意図した呼び出し元を表示します。

私の環境では8で良い具合でしたが実際はコード構成によると思うので適宜調整して下さい。

if att.Key == slog.SourceKey {
	const skip = 8
	_, file, line, ok := runtime.Caller(skip)

更に取得したフルパスは filepath.Base() で余計な部分をカットしファイル名のみにし行数と繋げ表示内容とします。加工を上手くやることでプロジェクトルートから表示する等といったことも可能でしょう。

	v := fmt.Sprintf("%s:%d", filepath.Base(file), line)
	att.Value = slog.StringValue(v)

おわりに

コールスタックを呼ぶという力技？なのでパフォーマンスは微妙かもしれません。
もっとスマートな方法があれば是非教えて下さい。