独自エラーにスタックトレースをつけて構造化ログ(slog)で出力する

題名の通り、独自エラーにスタックトレース情報をもたせ、
slogで構造化ログとして出力できるようにします

goでスタックトレースを取得するとパフォーマンスへの影響もあるとかないとか
詳しい説明はこちらの記事が大変わかりやすかったです

[Goのerrorがスタックトレースを含まない理由](https://methane.hatenablog.jp/entry/2024/04/02/Go%E3%81%AEerror%E3%81%8C%E3%82%B9%E3%82%BF%E3%83%83%E3%82%AF%E3%83%88%E3%83%AC%E3%83%BC%E3%82%B9%E3%82%92%E5%90%AB%E3%81%BE%E3%81%AA%E3%81%84%E7%90%86%E7%94%B1)

## 実装

### スタックトレースの取得

エラーの生成とともにスタック情報を取得しています

```go
type MyError struct {
	Msg   string
	stack []uintptr
	err   error
}

func NewMyError(msg string) *MyError {
	if !hasStack {
		return &MyError{Msg: msg}
	}
	stack := make([]uintptr, maxDepth)
    // skip 2 frames [NewMyError, runtime.Callers]
	length := runtime.Callers(2, stack)
	return &MyError{Msg: msg, stack: stack[:length]}
}
```

履歴（スタックトレース）を格納する箱を用意して、その箱に履歴（スタックトレース）を積むイメージです
runtime.Callers(2, stack)の第一引数は取得するスタックトレースの開始位置を指定しており、
この場合2なので、自分自身（runtime.Callers）と呼び出し関数（NewMyError）をスキップします

### スタックトレースの出力

エラー発生時に取得したスタックトレースを出力します
slogで出力した際に以下のように出力したいので、スライスで返すようにします

```json
{
	"time": "2024-12-19T08:33:23.232035471Z",
	"level": "ERROR",
	"msg": "occured error",
	"stackTrace": [
		{
			"file": "/workspaces/caller_sample/cmd/main.go",
			"function": "main.f3",
			"line": 40
		},
		{
			"file": "/workspaces/caller_sample/cmd/main.go",
			"function": "main.f2",
			"line": 33
		},
	]
}
```

```go
func (e *MyError) StackTrace() []map[string]interface{} {
	if !hasStack {
		return nil
	}

	if e.err != nil {
		if myErr, ok := e.err.(*MyError); ok {
			return myErr.StackTrace()
		}
	}

	frames := runtime.CallersFrames(e.stack)
	res := make([]map[string]interface{}, 0)
	for {
		frame, more := frames.Next()
		res = append(res, map[string]interface{}{
			"file":     frame.File,
			"line":     frame.Line,
			"function": frame.Function,
		})

		if !more {
			break
		}
	}
	return res
}
```

runtime.CallersFrames(e.stack)でスタックトレースを解析し、フレーム情報（関数名、ファイル名、行番号など）を出力する準備をしています

上記で取得できるフレーム情報をループで回し、各フレーム情報を取得しスライスに格納していきます

エラーがラップされている場合も考慮して、ラップされている場合は再起的に処理を繰り返します

### コード全体

```go
package main

import (
	"fmt"
	"log/slog"
	"os"
	"runtime"
)

const (
	maxDepth = 50
)

var hasStack = true

type MyError struct {
	Msg   string
	stack []uintptr
	err   error
}

func NewMyError(msg string) *MyError {
	if !hasStack {
		return &MyError{Msg: msg}
	}
	stack := make([]uintptr, maxDepth)
	length := runtime.Callers(2, stack)
	return &MyError{Msg: msg, stack: stack[:length]}
}

func (e *MyError) Error() string {
	return e.Msg
}

func (e *MyError) Unwrap() error {
	return e.err
}

func (e *MyError) Wrap(err error) {
	e.err = err
}

func (e *MyError) StackTrace() []map[string]interface{} {
	if !hasStack {
		return nil
	}

	if e.err != nil {
		if myErr, ok := e.err.(*MyError); ok {
			return myErr.StackTrace()
		}
	}

	frames := runtime.CallersFrames(e.stack)
	res := make([]map[string]interface{}, 0)
	for {
		frame, more := frames.Next()
		res = append(res, map[string]interface{}{
			"file":     frame.File,
			"line":     frame.Line,
			"function": frame.Function,
		})

		if !more {
			break
		}
	}
	return res
}

```

## 使ってみる

https://go.dev/play/p/bD1d6_JgYZZ

```go
func main() {
    // slogの出力設定
	logger := slog.New(slog.NewJSONHandler(os.Stdout, nil))

	err := f1()
 
	if myErr, ok := err.(*MyError); ok {
		logger.Error("occured error", slog.Any("stackTrace", myErr.StackTrace()))
	} else {
		fmt.Println("error is not of type *MyError")
	}
}

func f1() error {
	return f2()
}

func f2() error {
	err := f3()
	newErr := NewMyError("this is f2 error")
    // f3で起きたエラーをラップ
	newErr.Wrap(err)
	return newErr
}

func f3() error {
    // エラー発生
	err := NewMyError("this is f3 error")
	return err
}
```

ログ

※JSONは整形しています

```json
{
	"time": "2009-11-10T23:00:00Z",
	"level": "ERROR",
	"msg": "occured error",
	"stackTrace": [
		{
			"file": "/tmp/sandbox1721138770/prog.go",
			"function": "main.f3",
			"line": 40
		},
		{
			"file": "/tmp/sandbox1721138770/prog.go",
			"function": "main.f2",
			"line": 33
		},
		{
			"file": "/tmp/sandbox1721138770/prog.go",
			"function": "main.f1",
			"line": 29
		},
		{
			"file": "/tmp/sandbox1721138770/prog.go",
			"function": "main.main",
			"line": 19
		},
		{
			"file": "/usr/local/go-faketime/src/runtime/proc.go",
			"function": "runtime.main",
			"line": 272
		},
		{
			"file": "/usr/local/go-faketime/src/runtime/asm_amd64.s",
			"function": "runtime.goexit",
			"line": 1700
		}
	]
}
```

## ベンチマーク

パフォーマンスへの影響がどれほどあるのかも確認してみます

テスコード

```go
func BenchmarkWithStackTrace(b *testing.B) {
	hasStack = true
	output, _ := os.Create("output_withstack.log")
	logger := slog.New(slog.NewJSONHandler(output, nil))
	b.ResetTimer()
	for i := 0; i < b.N; i++ {
		logger.Error("occured error", slog.Any("stackTrace", NewMyError("occured error").StackTrace()))
	}

}

func BenchmarkWithoutStackTrace(b *testing.B) {
	hasStack = false
	output, _ := os.Create("output_withoutstack.log")
	logger := slog.New(slog.NewJSONHandler(output, nil))
	b.ResetTimer()
	for i := 0; i < b.N; i++ {
		logger.Error("occured error", slog.Any("stackTrace", NewMyError("occured error")))
	}
}
```

結果

```
BenchmarkWithStackTrace-10                 16770             70639 ns/op            3733 B/op         56 allocs/op
BenchmarkWithoutStackTrace-10              20995             49570 ns/op             112 B/op          2 allocs/op
```

- 実行時間: スタックトレースを含む場合、約1.43倍の時間がかかる
- メモリ使用量: スタックトレースを含む場合、約33.34倍のメモリを使用
- アロケーション数: スタックトレースを含む場合、28倍のアロケーションが発生

##  参考

https://pkg.go.dev/runtime

https://pkg.go.dev/github.com/go-errors/errors@v1.5.1#section-readme