goのエラーをスタックトレースも含めて構造化ログで残したい

こんにちは、エムスリーエンジニアリンググループの福林 (@fukubaya) です。

golangでずっと課題に思っていたエラーの処理について試行錯誤してみました。

イオンモールセンソックシティは、カンボジアにある商業施設。本文には関係ありません。

エラー処理のベストプラクティスは？
ぼくがかんがえるエラー処理の要件
検討したパッケージ
構造化ログ
パッケージの検討
go-errors/errors がよさそう?
pkg/errors や cockroachdb/errors は使えないのか
ラップして使う
- errors.WithStack(err) と呼びたい
- slogで使う
errors.Join() に対応したい
まとめ
We are hiring!

エラー処理のベストプラクティスは？

golangで開発をある程度経験すると、エラーの処理について悩むことがあると思います。調べてみると、年代によって様々な提案がなされてきましたが、現在でも多くの開発者がベストと考える唯一の方法はなさそうです。

それぞれの開発者でエラー処理に望むものが異なるため、標準パッケージに何を入れるべきかがなかなか決まらないのかもしれません。

ぼくがかんがえるエラー処理の要件

そのため、今のところは、自分のプロダクトで必要となるエラー処理の要件を整理して、それに合った方法を選択するしかないと思います。

僕たちのチームが望む要件は以下の通りです。

スタックトレースが欲しい
- 最終的に得られたエラーだけを見ても、どこで発生したものか分からないことが多く、エラーの原因調査が困難。スタックトレースなしで特定できるようにするためには、エラーの発生箇所が一意に特定できるエラーメッセージを設定しておく必要がある。
log/slog などの構造化ログで使える
- AWS CloudWatch Logs などで、JSON形式のログを出力しておくと便利なので、スタックトレースを含めて構造化したログを出力したい。
誰が書いても同じようなエラー処理になる
- 後で書くとおり、エラーの発生箇所ごとに書き方を変えないといけないのは面倒だし、間違えが起きやすいし、チームで開発する上ではレビューもしんどい。
他のパッケージができた時でも移行しやすくしておきたい
- 今後、標準パッケージに追加された場合、もしくは別の有望なパッケージに移行する場合、あまりコードを変更しないで済むようにしておきたい。

検討したパッケージ

要件を元に検討したパッケージは以下です。

github.com/pkg/errors
- スタックトレースを扱うパッケージといえばまずこれが挙げられる。
- ただし、2021年12月にPublic Archiveになって、これ以上の新規開発はなさそう。
gihub.com/cockroachdb/errors
- pkg/errors の置き換えとして提案されている。
- スタックトレース以外にも機能が豊富。現在も開発は続いている。内部で pkg/errors を使っているのが気になる。
github.com/goark/errs
- スタックトレース以外の扱いもある。
- WithContext() で任意のコンテキストを埋め込める。
github.com/go-errors/errors
- スタックトレースの扱いがメインとしている。他の機能はあまりない？

構造化ログ

log/slog は、構造化ログを扱える標準パッケージです。これまでも、https://github.com/uber-go/zap や https://github.com/rs/zerolog などサードパーティーのパッケージがありましたが、標準パッケージで構造化ログが扱えるようになったので、これからはこれを使います。 log/slog でエラーも含めて構造化して出力することを考えます。

package main

import (
    "log/slog"
    "os"
)

func main() {
    j := slog.New(slog.NewJSONHandler(os.Stdout, nil))
    t := slog.New(slog.NewTextHandler(os.Stdout, nil))

    log(j, 1, "json logger")
    log(t, 2, "text logger")
}

func log(logger *slog.Logger, num int, str string) {
    logger.Info("log",
        "num", num,
        "str", str,
    )
}

出力

# JSON
{"time":"2024-07-09T21:41:21.813076+09:00","level":"INFO","msg":"log","num":1,"str":"json logger"}

# text
time=2024-07-09T21:41:21.813+09:00 level=INFO msg=log num=2 str="text logger"

パッケージの検討

それぞれのパッケージを使った共通のコードでエラーとスタックトレースを構造化ログで出力して比較します。

以下のコードで、err1st() を呼んだらエラーになったとして、それをログに出力するとします。 outerErr() は外部のライブラリなどで発生したエラーを想定しています。スタックトレースとしては、err3rd() がエラーの発生元として、トレースできればよいです。そのままインポートするとパッケージ名が errors か errs になって分かりづらいので、それぞれ別の名前でインポートしています。

package main

import (
    "encoding/json"
    "fmt"
    "log/slog"
    "os"
    "runtime"

    ckr_errors "github.com/cockroachdb/errors"
    "github.com/cockroachdb/errors/errbase"
    go_errors "github.com/go-errors/errors"
    goark_errs "github.com/goark/errs"
    pkg_errors "github.com/pkg/errors"
)

func err3rd(withStack func(error) error) error { return withStack(outerErr()) }
func err2nd(withStack func(error) error) error { return withStack(err3rd(withStack)) }
func err1st(withStack func(error) error) error { return withStack(err2nd(withStack)) }
func outerErr() error                          { return fmt.Errorf("org error") }

func main() {
    // slog
    logger := slog.New(slog.NewJSONHandler(os.Stdout, nil))

    err := err1st(ckr_errors.WithStack)
    logger.Error("error package",
        "err", err,
    )
}

pkg/errors

github.com/pkg/errors は、"%+v" で出力する場合と、 StackTrace() で出力した場合を試します。JSONの出力はjqで整形して手動で整理しています。

コード

   // github.com/pkg/errors
    perr := err1st(pkg_errors.WithStack)
    logger.Error("pkg errors",
        "%+v", fmt.Sprintf("%+v", perr),
        "StackTrace", perr.(interface{ StackTrace() pkg_errors.StackTrace }).StackTrace(),
    )

出力

{
  "time": "2024-07-10T12:22:37.493071+09:00",
  "level": "ERROR",
  "msg": "pkg errors",
  "%+v": "org error\nmain.err3rd\n\t./main.go:17\nmain.err2nd\n\t./main.go:18\nmain.err1st\n\t./main.go:19\nmain.main\n\t./main.go:47\nruntime.main\n\truntime/proc.go:271\nruntime.goexit\n\truntime/asm_amd64.s:1695\nmain.err2nd\n\t./main.go:18\nmain.err1st\n\t./main.go:19\nmain.main\n\t./main.go:47\nruntime.main\n\truntime/proc.go:271\nruntime.goexit\n\truntime/asm_amd64.s:1695\nmain.err1st\n\t./main.go:19\nmain.main\n\t./main.go:47\nruntime.main\n\truntime/proc.go:271\nruntime.goexit\n\truntime/asm_amd64.s:1695",
  "StackTrace": [
    "main.err1st ./main.go:19",
    "main.main ./main.go:47",
    "runtime.main runtime/proc.go:271",
    "runtime.goexit runtime/asm_amd64.s:1695"
  ]
}

"%+v" はスタックトレースが出力されますが、テキストで出力されることを前提としているので、構造化はされていません。また、このテキストを展開すると分かりますが、 WithStack() を呼ぶたびに、それまでのスタックトレースが全部追加されるので、同じスタックトレースが重複して出力されます。

# 元のエラーのエラーメッセージ
org error

# 3rd->2nd->1st->main.main までのスタックトレース
main.err3rd
    ./main.go:17
main.err2nd
    ./main.go:21
main.err1st
    ./main.go:25
main.main
    ./main.go:65
runtime.main
    runtime/proc.go:271
runtime.goexit
    runtime/asm_amd64.s:1695

# 2nd->1st->main.main までのスタックトレース
main.err2nd
    ./main.go:21
main.err1st
    ./main.go:25
main.main
    ./main.go:65
runtime.main
    runtime/proc.go:271
runtime.goexit
    runtime/asm_amd64.s:1695

# 1st->main.main までのスタックトレース
main.err1st
    ./main.go:25
main.main
    ./main.go:65
runtime.main
    runtime/proc.go:271
runtime.goexit
    runtime/asm_amd64.s:1695

StackTrace() はスタックトレースを取得できますが、err1st() より前のスタックトレースは取得できません。 pkg/errors の WithStack() は、呼ばれた箇所をスタートとしてスタックトレースが記録されるため、この例のように重ねて呼ぶと、最後に呼ばれた箇所より前のスタックトレースは取得できません。

したがって、StackTrace() を使う場合は WithStack() を発生元 (err3rd()) だけで呼び、それより上層では呼ばないようにする必要があります。しかし、このルールを守るのが難しく、発生元なのに WithStack() を忘れると発生元までのスタックトレースが取れないし、途中経路で WithStack() を呼んでしまうと、それまでのスタックトレースが消失し、やはり発生元までのスタックトレースが取れません。特に、コードレビューにおいて、つけるべき箇所かそうでない箇所か(自コードから発生したエラーか、外部ライブラリが発生させたエラーか)を判断するのが難しいです。

一方、 "%+v" は、どこで呼んでもスタックトレースが取れるので、とりあえずerrorを返すときは WithStack() で包めばいいのですが、層が深くなると、上記のような重複が重なってスタックトレースが読みにくくなりますし、深さの2乗のオーダーでスタックトレースが増えていくので、効率が悪いです。

cockroachdb/errors

github.com/cockroachdb/errors は、"%+v" で出力する場合と、 GetReportableStackTrace() を出力する場合と、 GetAllSaveDetails() を出力する場合を試します。

コード

   // github.com/cockroachdb/errors
    cerr := err1st(ckr_errors.WithStack)
    logger.Error("cockroachdb errors",
        "%+v", fmt.Sprintf("%+v", cerr),
        "GetReportableStackTrace", ckr_errors.GetReportableStackTrace(cerr),
        "GetAllSaveDetails", ckr_errors.GetAllSafeDetails(cerr),
    )

出力

{
  "time": "2024-07-10T12:22:37.493637+09:00",
  "level": "ERROR",
  "msg": "cockroachdb errors",
  "%+v": "org error\n(1) attached stack trace\n  -- stack trace:\n  | main.err1st\n  | \t./main.go:19\n  | main.main\n  | \t./main.go:54\n  | runtime.main\n  | \truntime/proc.go:271\nWraps: (2) attached stack trace\n  -- stack trace:\n  | main.err2nd\n  | \t./main.go:18\n  | [...repeated from below...]\nWraps: (3) attached stack trace\n  -- stack trace:\n  | main.err3rd\n  | \t./main.go:17\n  | main.err2nd\n  | \t./main.go:18\n  | main.err1st\n  | \t./main.go:19\n  | main.main\n  | \t./main.go:54\n  | runtime.main\n  | \truntime/proc.go:271\n  | runtime.goexit\n  | \truntime/asm_amd64.s:1695\nWraps: (4) org error\nError types: (1) *withstack.withStack (2) *withstack.withStack (3) *withstack.withStack (4) *errors.errorString",
  "GetReportableStackTrace": {
    "frames": [
      {"function": "goexit", "module": "runtime", "filename": "runtime/asm_amd64.s", "abs_path": "runtime/asm_amd64.s", "lineno": 1695,"in_app": true},
      {"function": "main", "module": "runtime", "filename": "runtime/proc.go", "abs_path": "runtime/proc.go", "lineno": 271, "in_app": true},
      {"function": "main", "module": "main", "filename": "./main.go", "abs_path": "./main.go", "lineno": 54, "in_app": true},
      {"function": "err1st", "module": "main", "filename": "./main.go", "abs_path": "./main.go", "lineno": 19, "in_app": true}
    ]
  },
  "GetAllSaveDetails": [
    {
      "OriginalTypeName": "github.com/cockroachdb/errors/withstack/*withstack.withStack",
      "ErrorTypeMark": {"family_name": "github.com/cockroachdb/errors/withstack/*withstack.withStack"},
      "SafeDetails": ["\nmain.err1st\n\t./main.go:19\nmain.main\n\t./main.go:54\nruntime.main\n\truntime/proc.go:271\nruntime.goexit\n\truntime/asm_amd64.s:1695"]
    },
    {
      "OriginalTypeName": "github.com/cockroachdb/errors/withstack/*withstack.withStack",
      "ErrorTypeMark": {"family_name": "github.com/cockroachdb/errors/withstack/*withstack.withStack"},
      "SafeDetails": ["\nmain.err2nd\n\t./main.go:18\nmain.err1st\n\t./main.go:19\nmain.main\n\t./main.go:54\nruntime.main\n\truntime/proc.go:271\nruntime.goexit\n\truntime/asm_amd64.s:1695"]
    },
    {
      "OriginalTypeName": "github.com/cockroachdb/errors/withstack/*withstack.withStack",
      "ErrorTypeMark": {"family_name": "github.com/cockroachdb/errors/withstack/*withstack.withStack"},
      "SafeDetails": ["\nmain.err3rd\n\t./main.go:17\nmain.err2nd\n\t./main.go:18\nmain.err1st\n\t./main.go:19\nmain.main\n\t./main.go:54\nruntime.main\n\truntime/proc.go:271\nruntime.goexit\n\truntime/asm_amd64.s:1695"]
    },
    {
      "OriginalTypeName": "errors/*errors.errorString",
      "ErrorTypeMark": {"family_name": "errors/*errors.errorString"},
      "SafeDetails": null
    }
  ]
}

"%+v" で出力すると、pkg/errors と同じようにテキストでスタックトレースを取得できます。 pkg/errors と同じように、WithStack() を呼ぶたびにスタックトレースが追加されます。

org error
(1) attached stack trace
  -- stack trace:
  | main.err1st
  |     ./main.go:25
  | main.main
  |     ~./main.go:57
  | runtime.main
  |     runtime/proc.go:271
Wraps: (2) attached stack trace
  -- stack trace:
  | main.err2nd
  |     ./main.go:21
  | [...repeated from below...]
Wraps: (3) attached stack trace
  -- stack trace:
  | main.err3rd
  |     ./main.go:17
  | main.err2nd
  |     ./main.go:21
  | main.err1st
  |     ./main.go:25
  | main.main
  |     ./main.go:57
  | runtime.main
  |     runtime/proc.go:271
  | runtime.goexit
  |     runtime/asm_amd64.s:1695
Wraps: (4) org error
Error types: (1) *withstack.withStack (2) *withstack.withStack (3) *withstack.withStack (4) *errors.errorString

GetReportableStackTrace() は、 sentry で送信することを想定した形式だそうで、 pkg/errors の StackTrace() と同じように、複数回重ねると、それまでのスタックトレースが取れなくなります。

GetAllSafeDetails() は、%+v をある程度構造化したものと言えそうです。"SafeDetails" にスタックトレースが入りますが、テキスト形式です。

cockroachdb/errors もpkg/errors と同じく、WithStack() を発生元だけで呼ぶか、全部呼ぶ場合はテキスト形式でしか重複したスタックトレースしか取得できず、同じ課題が残ります。

goark/errs

github.com/goark/errs は、"%+v" で出力する場合と、 JSON形式で出力したものを any に unmasrshal したものを出力する場合を試します。

コード

   // github.com/goark/errs
    gerr := err1st(func(e error) error {
        _, file, line, _ := runtime.Caller(1)
        return goark_errs.Wrap(e,
            goark_errs.WithContext("file", file),
            goark_errs.WithContext("line", line),
        )
    })
    logger.Error("goark errors",
        "%+v", fmt.Sprintf("%+v", gerr),
        "json", func() any {
            jsonstr := goark_errs.EncodeJSON(gerr)
            var a any
            _ = json.Unmarshal([]byte(jsonstr), &a)
            return a
        }(),
    )

出力

{
  "time": "2024-07-10T12:22:37.493994+09:00",
  "level": "ERROR",
  "msg": "goark errors",
  "%+v": "{\"Type\":\"*errs.Error\",\"Err\":{\"Type\":\"*errs.Error\",\"Err\":{\"Type\":\"*errs.Error\",\"Err\":{\"Type\":\"*errors.errorString\",\"Msg\":\"org error\"},\"Context\":{\"file\":\"./main.go\",\"function\":\"main.main.func1\",\"line\":17}},\"Context\":{\"file\":\"./main.go\",\"function\":\"main.main.func1\",\"line\":18}},\"Context\":{\"file\":\"./main.go\",\"function\":\"main.main.func1\",\"line\":19}}",
  "json": {
    "Context": {"file": "./main.go", "function": "main.main.func1", "line": 19},
    "Err": {
      "Context": {"file": "./main.go", "function": "main.main.func1", "line": 18},
      "Err": {
        "Context": {"file": "./main.go", "function": "main.main.func1", "line": 17},
        "Err": {
          "Msg": "org error",
          "Type": "*errors.errorString"
        },
        "Type": "*errs.Error"
      },
      "Type": "*errs.Error"
    },
    "Type": "*errs.Error"
  }
}

"%+v" と EncodeJSON() は、同じものなので、JSONだけ見ると、 Wrap() を重ねて呼んでも消えることはないですが、呼んだ箇所のファイル名や行番号を runtime で取得して context に入れてあげないといけません。また、Wrap() した関数名は、この実装では取得できません。エラーの発生元は追うことはできます。

go-errors/errors

github.com/go-errors/errors は、"%+v" で出力する場合と、StackFrames() で出力した場合を試します。

コード

   // github.com/go-errors/errors
    goerr := err1st(func(e error) error { return go_errors.Wrap(e, 0) })
    logger.Error("go-errors errors",
        "%+v", fmt.Sprintf("%+v", goerr),
        "StackFrames", goerr.(*go_errors.Error).StackFrames(),
    )

出力

{
  "time": "2024-07-10T12:22:37.494067+09:00",
  "level": "ERROR",
  "msg": "go-errors errors",
  "%+v": "org error",
  "StackFrames": [
    {"File": "./main.go", "LineNumber": 80, "Name": "main.func3", "Package": "main","ProgramCounter": 95084424},
    {"File": "./main.go", "LineNumber": 17, "Name": "err3rd", "Package": "main", "ProgramCounter": 95079702},
    {"File": "./main.go", "LineNumber": 18, "Name": "err2nd", "Package": "main", "ProgramCounter": 95079768},
    {"File": "./main.go", "LineNumber": 19, "Name": "err1st", "Package": "main", "ProgramCounter": 95079832},
    {"File": "./main.go", "LineNumber": 80, "Name": "main", "Package": "main", "ProgramCounter": 95082277},
    {"File": "runtime/internal/atomic/types.go", "LineNumber": 194, "Name": "(*Uint32).Load", "Package": "runtime/internal/atomic", "ProgramCounter": 92876605},
    {"File": "runtime/asm_amd64.s", "LineNumber": 1695, "Name": "goexit", "Package": "runtime", "ProgramCounter": 93081313}
  ]
}

"%+v" は、元のエラーのメッセージだけを取得できます。

StackFrames() は、スタックトレースを取得できますし、何回 Wrap() を呼んでも途中で消えることはありませんし、重複したスタックトレースもありません。ファイル名も行番号も関数名も取得できています。

go-errors/errors がよさそう?

ここまでの結果をまとめると、go-errors/errors が一番使いやすそうです。

github.com/pkg/errors
gihub.com/cockroachdb/errors
- 構造化したスタックトレースを取得するには、発生元だけで WithStack() を呼ぶ、それより上層では呼んではいけない。
- WithStack() を毎回呼んでも、"%+v" で出力すればスタックトレースは残ってはいるが、重複しているし、テキスト形式なので構造化のためにはさらに加工が必要。
github.com/goark/errs
- 何回 Wrap() を呼んでもスタックトレースは消えないが、ファイル名や行番号、関数名を自分で取得して context に入れないといけない。
github.com/go-errors/errors
- 何回 Wrap() を呼んでもスタックトレースは消えないし、ファイル名や行番号、関数名も構造化してスタックトレースに含めてくれる。

pkg/errors や cockroachdb/errors は使えないのか

pkg/errors や cockroachdb/errors も、呼び方に気をつければ、構造化したスタックトレースは取得できます。すでに WithStack() で包まれている err は包まず、それ以上は包まないようにすれば、いけるかもしれません。

渡されたerrが、それぞれのパッケージのprivateな構造体 (withStack) であるかどうかを判定して、それに応じて WithStack() を呼ぶかどうかを判定する関数を新たに WithStack() と呼べば、何回包んでも、実際には1回だけ包まれるようにできるはずです。

func PkgWithStack(err error) error {
    if err == nil {
        return pkg_errors.WithStack(err)
    }

    // pkg/errors の withStack かどうか
    _, ok := err.(interface{ StackTrace() pkg_errors.StackTrace })
    if ok {
        return err
    }

    return pkg_errors.WithStack(err)
}

func CkrWithStack(err error) error {
    if err == nil {
        return ckr_errors.WithStack(err)
    }

    // cockroachdb/errors の withStack かどうか
    _, ok := err.(interface{ SafeFormatError(errbase.Printer) error })
    if ok {
        return err
    }

    return ckr_errors.WithStack(err)
}

コード

   // PkgWithStack
    p2err := err1st(PkgWithStack)
    logger.Error("PkgWithStack",
        "%+v", fmt.Sprintf("%+v", p2err),
        "StackTrace", p2err.(interface{ StackTrace() pkg_errors.StackTrace }).StackTrace(),
    )

    // CkrWithStack
    c2err := err1st(CkrWithStack)
    logger.Error("CkrWithStack",
        "%+v", fmt.Sprintf("%+v", c2err),
        "GetReportableStackTrace", ckr_errors.GetReportableStackTrace(c2err),
        "GetAllSafeDetails", ckr_errors.GetAllSafeDetails(c2err),
    )

出力

{
  "time": "2024-07-10T12:22:37.494165+09:00",
  "level": "ERROR",
  "msg": "PkgWithStack",
  "%+v": "org error\nmain.PkgWithStack\n\t./main.go:26\nmain.err3rd\n\t./main.go:17\nmain.err2nd\n\t./main.go:18\nmain.err1st\n\t./main.go:19\nmain.main\n\t./main.go:87\nruntime.main\n\truntime/proc.go:271\nruntime.goexit\n\truntime/asm_amd64.s:1695",
  "StackTrace": [
    "main.PkgWithStack ./main.go:26",
    "main.err3rd ./main.go:17",
    "main.err2nd ./main.go:18",
    "main.err1st ./main.go:19",
    "main.main ./main.go:87",
    "runtime.main runtime/proc.go:271",
    "runtime.goexit runtime/asm_amd64.s:1695"
  ]
}
{
  "time": "2024-07-10T12:22:37.494297+09:00",
  "level": "ERROR",
  "msg": "CkrWithStack",
  "%+v": "org error\n(1) attached stack trace\n  -- stack trace:\n  | main.CkrWithStack\n  | \t./main.go:36\n  | main.err3rd\n  | \t./main.go:17\n  | main.err2nd\n  | \t./main.go:18\n  | main.err1st\n  | \t./main.go:19\n  | main.main\n  | \t./main.go:94\n  | runtime.main\n  | \truntime/proc.go:271\n  | runtime.goexit\n  | \truntime/asm_amd64.s:1695\nWraps: (2) org error\nError types: (1) *withstack.withStack (2) *errors.errorString",
  "GetReportableStackTrace": {
    "frames": [
      {"function": "goexit", "module": "runtime", "filename": "runtime/asm_amd64.s", "abs_path": "runtime/asm_amd64.s", "lineno": 1695, "in_app": true},
      {"function": "main", "module": "runtime", "filename": "runtime/proc.go", "abs_path": "runtime/proc.go", "lineno": 271, "in_app": true},
      {"function": "main", "module": "main", "filename": "./main.go", "abs_path": "./main.go", "lineno": 94, "in_app": true},
      {"function": "err1st", "module": "main", "filename": "./main.go", "abs_path": "./main.go", "lineno": 19, "in_app": true},
      {"function": "err2nd", "module": "main", "filename": "./main.go", "abs_path": "./main.go", "lineno": 18, "in_app": true},
      {"function": "err3rd", "module": "main", "filename": "./main.go", "abs_path": "./main.go", "lineno": 17, "in_app": true},
      {"function": "CkrWithStack", "module": "main", "filename": "./main.go", "abs_path": "./main.go", "lineno": 36, "in_app": true}
    ]
  },
  "GetAllSafeDetails": [
    {
      "OriginalTypeName": "github.com/cockroachdb/errors/withstack/*withstack.withStack",
      "ErrorTypeMark": {"family_name": "github.com/cockroachdb/errors/withstack/*withstack.withStack"},
      "SafeDetails": ["\nmain.CkrWithStack\n\t./main.go:36\nmain.err3rd\n\t./main.go:17\nmain.err2nd\n\t./main.go:18\nmain.err1st\n\t./main.go:19\nmain.main\n\t./main.go:94\nruntime.main\n\truntime/proc.go:271\nruntime.goexit\n\truntime/asm_amd64.s:1695"]
    },
    {
      "OriginalTypeName": "errors/*errors.errorString",
      "ErrorTypeMark": {"family_name": "errors/*errors.errorString"},
      "SafeDetails": null
    }
  ]
}

どちらの場合も、過不足なく構造化したスタックトレースを取得できました。ただし、それぞれのパッケージ由来の構造体かどうかを判定しているので、別のパッケージでラップしてしまうと、再度 WithStack() が呼ばれてしまい、スタックトレースが消失してしまうので注意が必要です。

ラップして使う

errors.WithStack(err) と呼びたい

将来的に標準パッケージに追加された場合に、移行しやすいように、ラップして使うことを考えます。 pkg/errors が広く使われてきたので、標準パッケージに pkg/errors 互換のパッケージが追加されると仮定した場合、 errors.WithStack(err) と呼ぶことが多いはずです。

    if err := someFunc(); err != nil {
        return errors.WithStack(err)
    }

なので、どのパッケージを使っても errors.WithStack(err) と呼ぶことができるように、ラップして使うことを考えます。 errors.Wrap(err) でもいいかもしれません。

errors パッケージを作成し、そこに WithStack() を定義します。

package errors

import (
    "runtime"

    ckr_errors "github.com/cockroachdb/errors"
    "github.com/cockroachdb/errors/errbase"
    go_errors "github.com/go-errors/errors"
    goark_errs "github.com/goark/errs"
    pkg_errors "github.com/pkg/errors"
)

// pkg/errors を使う場合
func WithStack(err error) error {
    if err == nil {
        return pkg_errors.WithStack(err)
    }

    // pkg/errors の withStack かどうか
    _, ok := err.(interface{ StackTrace() pkg_errors.StackTrace })
    if ok {
        return err
    }

    return pkg_errors.WithStack(err)
}

// cockroachdb/errors を使う場合
func WithStack(err error) error {
    if err == nil {
        return ckr_errors.WithStack(err)
    }

    // cockroachdb/errors の withStack かどうか
    _, ok := err.(interface{ SafeFormatError(errbase.Printer) error })
    if ok {
        return err
    }

    return ckr_errors.WithStack(err)
}

// goark/errs を使う場合
func WithStack(err error) error {
    _, file, line, _ := runtime.Caller(1)
    return goark_errs.Wrap(err,
        goark_errs.WithContext("file", file),
        goark_errs.WithContext("line", line),
    )
}

// go-errors/errors を使う場合
func WithStack(err error) error {
    return go_errors.Wrap(err, 0)
}

slogで使う

さらに、slogでスタックトレースを出力する部分も同じ記述で出力できるようにラップしておきます。

       logger.Error("an error has occured",
            slog.String("error", err.Error()),
            errors.LogStackTrace(err),
        )

どのパッケージを使っても errors.LogStackTrace(err) と呼ぶことができるように定義します。

// pkg/errors を使う場合
func LogStackTrace(err error) slog.Attr {
    if err == nil {
        return slog.Any("stacktrace", []any{})
    }
    // pkg/errors の withStack かどうか
    perr, ok := err.(interface{ StackTrace() pkg_errors.StackTrace })
    if !ok {
        return slog.String("details", fmt.Sprintf("%+v", err))
    }
    return slog.Any("stacktrace", perr.StackTrace())
}

// cockroachdb/errors を使う場合
func LogStackTrace(err error) slog.Attr {
    if err == nil {
        return slog.Any("stacktrace", []any{})
    }

    // cockroachdb/errors の withStack かどうか
    _, ok := err.(interface{ SafeFormatError(errbase.Printer) error })
    if !ok {
        return slog.String("details", fmt.Sprintf("%+v", err))

    }
    return slog.Any("stacktrace", ckr_errors.GetReportableStackTrace(err).Frames)
}

// goark/errs を使う場合
func LogStackTrace(err error) slog.Attr {
    if err == nil {
        return slog.Any("stacktrace", []any{})
    }

    // goark/errs の Error かどうか
    _, ok := err.(*goark_errs.Error)
    if !ok {
        return slog.String("details", fmt.Sprintf("%+v", err))
    }
    var stacktrace any
    _ = json.Unmarshal([]byte(goark_errs.EncodeJSON(err)), &stacktrace)
    return slog.Any("stacktrace", stacktrace)
}

// go-errors/errors を使う場合
func LogStackTrace(err error) slog.Attr {
    if err == nil {
        return slog.Any("stacktrace", []any{})
    }

    // go-errors/errors の Error かどうか
    goerror, ok := err.(*go_errors.Error)
    if !ok {
        return slog.String("details", fmt.Sprintf("%+v", err))
    }
    return slog.Any("stacktrace", goerror.StackFrames())
}

これでどのパッケージを使っていても呼び方は同じなので、切り替えが容易になります。

package main

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

    "sample/errors"
)

func f3() error { return errors.WithStack(fmt.Errorf("f3 error")) }
func f2() error { return errors.WithStack(f3()) }
func f1() error { return errors.WithStack(f2()) }

func main() {
    // slog
    logger := slog.New(slog.NewJSONHandler(os.Stdout, nil))

    if err := f1(); err != nil {
        logger.Error("an error has occured",
            slog.String("error", err.Error()),
            errors.LogStackTrace(err),
        )
    }
}

同じコードで、それぞれのパッケージに合わせてスタックトレースを取得できます。

pkg/errors

{
  "time": "2024-07-10T12:47:27.23559+09:00",
  "level": "ERROR",
  "msg": "an error has occured",
  "error": "f3 error",
  "stacktrace": [
    "sample/errors.WithStack sample/errors/errors.go:23",
    "main.f3 ./x.go:11",
    "main.f2 ./x.go:12",
    "main.f1 ./x.go:13",
    "main.main ./x.go:19",
    "runtime.main runtime/proc.go:271",
    "runtime.goexit runtime/asm_amd64.s:1695"
  ]
}

cockroachdb/errors

{
  "time": "2024-07-10T12:48:25.339823+09:00",
  "level": "ERROR",
  "msg": "an error has occured",
  "error": "f3 error",
  "stacktrace": [
    {"function": "goexit", "module": "runtime", "filename": "runtime/asm_amd64.s", "abs_path": "runtime/asm_amd64.s", "lineno": 1695, "in_app": true},
    {"function": "main", "module": "runtime", "filename": "runtime/proc.go", "abs_path": "runtime/proc.go", n"lineno": 271, "in_app": true},
    {"function": "main", "module": "main", "filename": "./x.go", "abs_path": "./x.go", "lineno": 19, "in_app": true},
    {"function": "f1", "module": "main", "filename": "./x.go", "abs_path": "./x.go", "lineno": 13, "in_app": true},
    {"function": "f2", "module": "main", "filename": "./x.go", "abs_path": "./x.go", "lineno": 12, "in_app": true},
    {"function": "f3", "module": "main", "filename": "./x.go", "abs_path": "./x.go", "lineno": 11, "in_app": true},
    {"function": "WithStack", "module": "sample/errors", "filename": "sample/errors/errors.go", "abs_path": "sample/errors/errors.go", "lineno": 33, "in_app": true}
  ]
}

goark/errs

{
  "time": "2024-07-10T12:49:25.936361+09:00",
  "level": "ERROR",
  "msg": "an error has occured",
  "error": "f3 error",
  "stacktrace": {
    "Context": {"file": "./x.go", "function": "sample/errors.WithStack", "line": 13},
    "Err": {
      "Context": {"file": "./x.go", "function": "sample/errors.WithStack", "line": 12},
      "Err": {
        "Context": {"file": "./x.go", "function": "sample/errors.WithStack", "line": 11},
        "Err": {
          "Msg": "f3 error",
          "Type": "*errors.errorString"
        },
        "Type": "*errs.Error"
      },
      "Type": "*errs.Error"
    },
    "Type": "*errs.Error"
  }
}

go-errors/errors

{
  "time": "2024-07-10T12:49:54.608353+09:00",
  "level": "ERROR",
  "msg": "an error has occured",
  "error": "f3 error",
  "stacktrace": [
    {"File": "sample/errors/errors.go", "LineNumber": 45, "Name": "f3", "Package": "main", "ProgramCounter": 167806966},
    {"File": "./x.go", "LineNumber": 11, "Name": "f3", "Package": "main", "ProgramCounter": 167806927},
    {"File": "sample/errors/errors.go", "LineNumber": 45, "Name": "WithStack", "Package": "sample/errors", "ProgramCounter": 167807027},
    {"File": "sample/errors/errors.go", "LineNumber": 45, "Name": "WithStack", "Package": "sample/errors", "ProgramCounter": 167807091},
    {"File": "./x.go", "LineNumber": 19, "Name": "main", "Package": "main", "ProgramCounter": 167807525},
    {"File": "runtime/internal/atomic/types.go", "LineNumber": 194, "Name": "(*Uint32).Load", "Package": "runtime/internal/atomic", "ProgramCounter": 165682717},
    {"File": "runtime/asm_amd64.s", "LineNumber": 1695, "Name": "goexit", "Package": "runtime", "ProgramCounter": 165887425}
  ]
}

errors.Join() に対応したい

go 1.20 で errors.Join() が追加されました。

pkg.go.dev

これが間に入ると、エラーの構造体が変わってしまうので、スタックトレースが追えなくなります。また、追えたとしても、複数のエラーを1つのエラーにまとめるため、スタックトレースが分岐して、木構造のようになってしまいます。 cockroachdb/errors は、Join() にも対応しているので %+v 出力では表示できます。 pkg/errors や go-errors/errors は、Join() に対応していないので、取得できません。

speakerdeck.com

なんとかこれを取得できないか考えてみます。cockroachdb/errors を例に実装してみます。

まずはJoinに対応したスタックトレースを格納する構造体を定義します。JoinedStackTrace によって木構造を表現します。

// stackTrace スタックトレース
type stackTrace struct {
    // error エラーメッセージ
    Error string

    // Frames スタックトレース
    Frames []any
}

// joinedStackTrace Joinを適用されたスタックトレース
type joinedStackTrace struct {
    // StackTrace Joinの後続スタックトレース
    StackTrace stackTrace

    // Join Joinのそれぞれのエラーのスタックトレース
    Join []joinedStackTrace
}

次に、errors.Join() に対応した extractStackTraces() を定義します。

// joinedError Joinを適用されたエラー
type joinedError interface{ Unwrap() []error }

// extractStackTraces スタックトレースを抽出する
func extractStackTraces(err error) *joinedStackTrace {
    if err == nil {
        return nil
    }

    // joinedError を含むかどうか
    var joinedErr joinedError
    subStackTraces := make([]joinedStackTrace, 0)
    if ckr_errors.As(err, &joinedErr) {
        errs := joinedErr.Unwrap()
        subStackTraces = make([]joinedStackTrace, 0, len(errs))
        for _, e := range errs {
            // Join は nil を含まないが念のため
            if e != nil {
                v := extractStackTraces(e)
                if v != nil {
                    subStackTraces = append(subStackTraces, *v)
                }
            }
        }
    }

    // cockroachdb/errors の withStack かどうか
    _, ok := err.(interface{ SafeFormatError(errbase.Printer) error })
    if !ok {
        return &joinedStackTrace{
            StackTrace: stackTrace{Error: err.Error(), Frames: []any{fmt.Sprintf("%+v", err)}},
            Join:       subStackTraces,
        }
    }

    frames := make([]any, 0, len(ckr_errors.GetReportableStackTrace(err).Frames))
    for _, f := range ckr_errors.GetReportableStackTrace(err).Frames {
        frames = append(frames, f)
    }
    return &joinedStackTrace{
        StackTrace: stackTrace{Error: err.Error(), Frames: frames},
        Join:       subStackTraces,
    }
}

Join() が適用されたエラーは Unwarp() で []error を返すので、このメソッドの有無でJoinされたエラーかどうかを判定します。 errors.As(err, &joinedErr) で err に Join() されたエラーが含まれるかどうかを判定し、存在していれば、Unwrap() して取得された個々のエラーに対して再帰的に extractStackTraces() を適用して、それぞれのスタックトレースを取得します。

子のスタックトレースを取得した後は、親のスタックトレースを取得して、それらを結合して JoinedStackTrace として返します。

以下のコードで試してみます。

package main

import (
    std_errors "errors"
    "fmt"
    "log/slog"
    "os"

    "sample/errors"
)

func j4_1() error { return errors.WithStack(fmt.Errorf("j4_1 error")) }
func j4_2() error { return errors.WithStack(fmt.Errorf("j4_2 error")) }
func j3_1() error { return errors.WithStack(fmt.Errorf("j3_1 error")) }
func j3_2() error {
    return errors.WithStack(std_errors.Join(
        errors.WithStack(j4_1()),
        errors.WithStack(j4_2()),
    ))
}
func j2() error {
    return errors.WithStack(std_errors.Join(
        errors.WithStack(j3_1()),
        errors.WithStack(j3_2()),
    ))
}
func j1() error { return errors.WithStack(j2()) }

func main() {
    // slog
    logger := slog.New(slog.NewJSONHandler(os.Stdout, nil))

    if err := j1(); err != nil {
        logger.Error("an error has occured",
            slog.String("error", err.Error()),
            errors.LogStackTrace(err),
        )
    }
}

構造としては、以下のようにエラーが渡されています。

errors.LogStackTrace() は取得したスタックトレースをそのまま返すことにします。

func LogStackTrace(err error) slog.Attr {
    st := extractStackTraces(err)
    if st == nil {
        return slog.Any("stacktraces", stackTrace{})
    }
    return slog.Any("stacktraces", extractStackTraces(err))
}

以下のようなログが得られました(長いので一部項目を消してます)。

{
  "time":"2024-07-11T12:52:51.548806+09:00",
  "level":"ERROR",
  "msg":"an error has occured",
  "error":"j3_1 error\nj4_1 error\nj4_2 error",
  "stacktraces":{
    "StackTrace":{
      "Error":"j3_1 error\nj4_1 error\nj4_2 error",
      "Frames":[
        {"function":"goexit","lineno":1695},
        {"function":"main","abs_path":"runtime/proc.go","lineno":271},
        {"function":"main","abs_path":"./join.go","lineno":33},
        {"function":"j1","abs_path":"./join.go","lineno":27},
        {"function":"j2","abs_path":"./join.go","lineno":22},
        {"function":"WithStack","abs_path":"sample/errors/errors.go","lineno":27}
      ]},
      "Join":[
        {"StackTrace":
          {"Error":"j3_1 error",
            "Frames":[
              {"function":"goexit","abs_path":"runtime/asm_amd64.s","lineno":1695},
              {"function":"main","abs_path":"runtime/proc.go","lineno":271},
              {"function":"main","abs_path":"./join.go","lineno":33},
              {"function":"j1","abs_path":"./join.go","lineno":27},
              {"function":"j2","abs_path":"./join.go","lineno":23},
              {"function":"j3_1","abs_path":"./join.go","lineno":14},
              {"function":"WithStack","abs_path":"sample/errors/errors.go","lineno":27}]},
          "Join":[]},
        {"StackTrace":
          {"Error":"j4_1 error\nj4_2 error",
            "Frames":[
              {"function":"goexit","abs_path":"runtime/asm_amd64.s","lineno":1695},
              {"function":"main","abs_path":"runtime/proc.go","lineno":271},
              {"function":"main","abs_path":"./join.go","lineno":33},
              {"function":"j1","abs_path":"./join.go","lineno":27},
              {"function":"j2","abs_path":"./join.go","lineno":24},
              {"function":"j3_2","abs_path":"./join.go","lineno":16},
              {"function":"WithStack","abs_path":"sample/errors/errors.go","lineno":27}]},
          "Join":[
            {"StackTrace":
              {"Error":"j4_1 error",
                "Frames":[
                  {"function":"goexit","abs_path":"runtime/asm_amd64.s","lineno":1695},
                  {"function":"main","abs_path":"runtime/proc.go","lineno":271},
                  {"function":"main","abs_path":"./join.go","lineno":33},
                  {"function":"j1","abs_path":"./join.go","lineno":27},
                  {"function":"j2","abs_path":"./join.go","lineno":24},
                  {"function":"j3_2","abs_path":"./join.go","lineno":17},
                  {"function":"j4_1","abs_path":"./join.go","lineno":12},
                  {"function":"WithStack","abs_path":"sample/errors/errors.go","lineno":27}]},
              "Join":[]},
            {"StackTrace":
              {"Error":"j4_2 error",
                "Frames":[
                  {"function":"goexit","lineno":1695},
                  {"function":"main","abs_path":"runtime/proc.go","lineno":271},
                  {"function":"main","abs_path":"./join.go","lineno":33},
                  {"function":"j1","abs_path":"./join.go","lineno":27},
                  {"function":"j2","abs_path":"./join.go","lineno":24},
                  {"function":"j3_2","abs_path":"./join.go","lineno":18},
                  {"function":"j4_2","abs_path":"./join.go","lineno":13},
                  {"function":"WithStack","abs_path":"sample/errors/errors.go","lineno":27}]},
                "Join":[]}]}]}}

分岐も含めて木構造でスタックトレースを取得できていますが、よく見ると末端のスタックトレース("Join":[]のスタックトレース) だけを取得できればいいので、これを平坦化します。

// flatten
func (j *joinedStackTrace) flatten() []stackTrace {
    // Joinを含まない
    if j.Join == nil || len(j.Join) == 0 {
        return []stackTrace{j.StackTrace}
    }

    // Joinを含むものは展開する
    flatten := []stackTrace{}
    for _, s := range j.Join {
        flatten = append(flatten, s.flatten()...)
    }
    return flatten
}

func LogStackTrace(err error) slog.Attr {
    st := extractStackTraces(err)
    if st == nil {
        return slog.Any("stacktraces", []stackTrace{})
    }
    return slog.Any("stacktraces", extractStackTraces(err).flatten())
}

末端の j3_1, j4_1, j4_2 からのスタックトレースだけを取得できるようになりました。

{
  "time":"2024-07-11T13:07:52.455414+09:00",
  "level":"ERROR",
  "msg":"an error has occured",
  "error":"j3_1 error\nj4_1 error\nj4_2 error",
  "stacktraces":[
    {"Error":"j3_1 error",
     "Frames":[
       {"function":"goexit","abs_path":"runtime/asm_amd64.s","lineno":1695},
       {"function":"main","abs_path":"runtime/proc.go","lineno":271},
       {"function":"main","abs_path":"./join.go","lineno":33},
       {"function":"j1","abs_path":"./join.go","lineno":27},
       {"function":"j2","abs_path":"./join.go","lineno":23},
       {"function":"j3_1","abs_path":"./join.go","lineno":14},
       {"function":"WithStack","abs_path":"sample/errors/errors.go","lineno":27}]},
    {"Error":"j4_1 error",
     "Frames":[
       {"function":"goexit","abs_path":"runtime/asm_amd64.s","lineno":1695},
       {"function":"main","abs_path":"runtime/proc.go","lineno":271},
       {"function":"main","abs_path":"./join.go","lineno":33},
       {"function":"j1","abs_path":"./join.go","lineno":27},
       {"function":"j2","abs_path":"./join.go","lineno":24},
       {"function":"j3_2","abs_path":"./join.go","lineno":17},
       {"function":"j4_1","abs_path":"./join.go","lineno":12},
       {"function":"WithStack","abs_path":"sample/errors/errors.go","lineno":27}]},
    {"Error":"j4_2 error",
     "Frames":[
       {"function":"goexit","abs_path":"runtime/asm_amd64.s","lineno":1695},
       {"function":"main","abs_path":"runtime/proc.go","lineno":271},
       {"function":"main","abs_path":"./join.go","lineno":33},
       {"function":"j1","abs_path":"./join.go","lineno":27},
       {"function":"j2","abs_path":"./join.go","lineno":24},
       {"function":"j3_2","abs_path":"./join.go","lineno":18},
       {"function":"j4_2","abs_path":"./join.go","lineno":13},
       {"function":"WithStack","abs_path":"sample/errors/errors.go","lineno":27}]}
  ]
}

まとめ

goのエラー処理において、スタックトレースを取得して、log/slog で構造化ログとして出力する方法を検討しました。
現状では標準パッケージではスタックトレースを取得できないので、サードパーティのパッケージを使う必要があります。
どのサードパーティのパッケージを使っても、同じ呼び方でスタックトレースを取得し、 log/slog で出力できるようにラップして使う方法を考えました。
go 1.20 で追加された errors.Join() に対応したスタックトレースを取得する方法も考えました。

We are hiring!

m3の多様なサービスを一緒に開発してくれる仲間を募集中です。お気軽にお問い合わせください。

jobs.m3.com

エムスリーテックブログ

エムスリー(m3)のエンジニア・開発メンバーによる技術ブログです