冗長なエラーログを削減し、スタックトレースを手に入れる / Reducing Verbose Error Logs and Obtaining Stack Traces

Slide 1

Slide 1 text

冗長なエラーログを削減し、スタックトレースを手に入れる @upamune / LayerX Inc. Go のエラーハンドリング最新事情Lunch LT - 2024/04/23

Slide 2

Slide 2 text

Slide 3

Slide 3 text

Slide 4

Slide 4 text

Slide 5

Slide 5 text

Slide 6

Slide 6 text

Slide 7

Slide 7 text

© 2024 LayerX Inc. 7 / 32 スタックトレースが欲しい!! … ですよね? エラーが発生したら，ログから簡単にどこから発生したエラーなのかを追いたいスタックトレースが無いと，同じエラーを返している部分があったら，どっちが返したエラーなのか特定が難しい ex. ErrInternal が doSomething1 と doSomething2 のどちらから返ってきたのか特定が難しい func handler() error { if err := doSomething1(); err != nil { return ErrInternal } if err := doSomething2(); err != nil { return ErrInternal } return nil }

Slide 8

Slide 8 text

© 2024 LayerX Inc. 8 / 32 改善前に利用していた方法 rs/zerolog をログライブラリとして利用 Caller オプションを利用することでログが出力される時に file:line も出力されるようにエラーハンドリングしているところで，エラーログを出力するように ⚠️ エラーはWrap せずに，ただ return するだけのコードベースだった func handler() error { if err := doSomething1(); err != nil { logger.Error().Caller().Err(err).Send() // {"level":"error","error":"err1","caller":"handler.go:10"} return ErrInternal } if err := doSomething2(); err != nil { logger.Error().Caller().Err(err).Send() // {"level":"error","error":"err2","caller":"handler.go:15"} return ErrInternal } return nil }

Slide 9

Slide 9 text

Slide 10

Slide 10 text

Slide 11

Slide 11 text

© 2024 LayerX Inc. 11 / 32 改善前：こういうコードがあると 💭 https://play.golang.com/p/3DsLq8TnI_w func Parent() error { if err := Child(); err != nil { log.Error().Err(err).Send() return err } return nil } func Child() error { if err := Grandchild(); err != nil { log.Error().Err(err).Send() return err } return nil } func Grandchild() error { // ... if err := fuga(); err != nil { // ここでエラー発生!! 💣💥 log.Error().Err(err).Send() return err } // ... return nil }

Slide 12

Slide 12 text

© 2024 LayerX Inc. 12 / 32 caller フィールドだけが異なるログがエラーハンドリングしている分だけ出る { "level": "error", "error": " エラー発生!!", "caller": "/tmp/sandbox1821519416/prog.go:40" } { "level": "error", "error": " エラー発生!!", "caller": "/tmp/sandbox1821519416/prog.go:28" } { "level": "error", "error": " エラー発生!!", "caller": "/tmp/sandbox1821519416/prog.go:20" } { "level": "error", "error": " エラー発生!!", "caller": "/tmp/sandbox1821519416/prog.go:14" }

Slide 13

Slide 13 text

© 2024 LayerX Inc. 13 / 32 rs/zerolog の caller で代用した時の問題点 🕵️ 複数のエラーログを見ないとスタックトレースを見ることができないのでエラーの原因を追いづらい 🤑 冗長なエラーログにより、エラーログの件数が増加しログ全体の検索コストと金銭的コストが増加する 1 件のエラーにつき caller フィールドしか違いがないログが4 件出たりする 🤔 エラーログの件数を元にアラートを設定している場合、アラートのしきい値を決めるのが難しい

Slide 14

Slide 14 text

Slide 15

Slide 15 text

Slide 16

Slide 16 text

© 2024 LayerX Inc. 16 / 32 🗺️ 冗長なエラーログを削減し、スタックトレースを手に入れるまでの道程 1. エラーをWrap してスタックトレースを取るためのエラーハンドリングライブラリの選定 2. Wrap されたエラーのスタックトレースを1 箇所でログ出力できるように設定 3. Wrap されたエラーに対応できてない部分を見つけて( errors.Is,As ) 修正 4. エラーをWrap するように修正 5. 冗長なエラーログを削除 6. 今後Wrap されていないエラーが増えないように/ 冗長なエラーログを記述されないように対策

Slide 17

Slide 17 text

© 2024 LayerX Inc. 17 / 32 エラーハンドリングライブラリの選定バクラクではmorikuni/failure を採用 lxerror というパッケージを作って failure を薄くラップして使っている func Wrap(err error, wrappers ...failure.Wrapper) error { return failure.Custom(failure.Custom(err, failure.WithFormatter(), WithCallstack(1)), wrappers...) } Why morikuni/failure ? エラーそのものに情報をもたせるのではなく，関数内で情報を付与してラップしていくスタイルそのため拡張性と汎用性が高くて、様々なエラーユースケースに対応できる🫰 ex. エラーコードを埋め込んだり、多言語メッセージを埋め込んだり、スタックトレースを付与したり… 👇 詳細は次の morikuni さんの発表で!!

Slide 18

Slide 18 text

© 2024 LayerX Inc. 18 / 32 Wrap されたエラーのスタックトレースを1 箇所でログ出力できるように設定 morikuni/failure でWrap してスタックトレースを保持しているエラーログで出力できるように rs/zerolog では Stack() を呼ぶとエラーからスタックトレース取り出してログに付与できる Stack() を付けたエラーログをミドルウェアの1 箇所で出力するようにどうやってエラーからスタックトレースを取り出すかは zerolog.ErrorStackMarshaler によって決まるので実装してあげる func ZerologErrorMarshalStack(err error) interface{} { // ... stack, ok := lxerror.CallStackOf(err) if !ok { return nil } out := &bytes.Buffer{} for i, f := range stack.Frames() { p := f.Path() // ... fmt.Fprintf(out, "%s:%d [%s.%s]\n", p, f.Line(), f.Pkg(), f.Func()) } return out.String() }

Slide 19

Slide 19 text

Slide 20

Slide 20 text

Slide 21

Slide 21 text

Slide 22

Slide 22 text

© 2024 LayerX Inc. 20 / 32 Wrap されたエラーに対応できてない部分を見つけて修正 errors.{Is,As} を利用するようにして，Wrap されてても正しく動作するように修正する // エラーから情報を取り出す: エラーがWrap されていない時 if perr, ok := err.(*fs.PathError); ok { fmt.Println(perr.Path) }

Slide 23

Slide 23 text

© 2024 LayerX Inc. 20 / 32 Wrap されたエラーに対応できてない部分を見つけて修正 errors.{Is,As} を利用するようにして，Wrap されてても正しく動作するように修正する // エラーから情報を取り出す: エラーがWrap されている時 var perr *fs.PathError if errors.As(err, &perr) { fmt.Println(perr.Path) }

Slide 24

Slide 24 text

© 2024 LayerX Inc. 21 / 32 Wrap されたエラーに対応できてない部分を見つける… 大変 🙄 polyfloyd/go-errorlint にお世話になりました🙏 errors.Is を使ってない部分の検出 // bad err == ErrFoo // bad switch err { case ErrFoo: } // good errors.Is(err, ErrFoo) errors.As を使ってない部分の検出 // bad myErr, ok := err.(*MyError) // bad switch err.(type) { case *MyError: } // good var me MyError ok := errors.As(err, &me)

Slide 25

Slide 25 text

Slide 26

Slide 26 text

© 2024 LayerX Inc. 23 / 32 エラーをWrap するように修正かなりマッチョな方法でIDE の置換でゴリゴリやっていった 💪 tomarrell/wrapcheck で漏れている部分を検知しつつ… ex. return nil, err => return nil, lxerror.Wrap(err) return "", err => return "", lxerror.Wrap(err) return nil, nil, err => return nil, nil, lxerror.Wrap(err) 意外と綺麗に置換できたが… もっと良い方法があったかも? 🤔

Slide 27

Slide 27 text

Slide 28

Slide 28 text

Slide 29

Slide 29 text

© 2024 LayerX Inc. 26 / 32 これからのエラーのWrap 漏れ，必要ないエラーログの検知 🕵️ エラーのWrap 漏れ検知 tomarrell/wrapcheck をgolangci-lint で利用必要なくなったエラーログの検知 semgrep でルールを書いてCI で検知 rules: - id: meaningless-error-log patterns: - pattern-either: - pattern: $X.Error().Err($ERR).Send() message: " 冗長なエラーログを出力しないでください" languages: [ go ] severity: ERROR 👇 以下のような，フィールドが設定されていたりメッセージが設定されているログには引っかからない logger.Error().Err(err).Str("key", "value").Msg("blah blah blah")

Slide 30

Slide 30 text

© 2024 LayerX Inc. 27 / 32 改善後：こういうコードがあると 💭 https://play.golang.com/p/9mHbLWVEwpt func main() { if err := Parent(); err != nil { log.Error().Stack().Err(err).Send() } } func Parent() error { if err := Child(); err != nil { return lxerror.Wrap(err) } return nil } func Child() error { if err := Grandchild(); err != nil { return lxerror.Wrap(err) } return nil } func Grandchild() error { // ... if err := fuga(); err != nil { // ここでエラー発生!! 💣💥 return lxerror.Wrap(err) } // ... }

Slide 31

Slide 31 text

© 2024 LayerX Inc. 28 / 32 ログが一箇所に集約されてスタックトレースが出るように 🎉 4 回出力されていたエラーログが1 箇所に ⚠️ 見やすいようにフォーマットを調整しています { "level":"error", "stack":" - /tmp/sandbox1035050178/main.go:73 [main.fuga] - /tmp/sandbox1035050178/main.go:59 [main.Grandchild] - /tmp/sandbox1035050178/main.go:49 [main.Child] - /tmp/sandbox1035050178/main.go:42 [main.Parent] - /tmp/sandbox1035050178/main.go:36 [main.main] - /usr/local/go-faketime/src/runtime/proc.go:271 [runtime.main] - /usr/local/go-faketime/src/runtime/asm_amd64.s:1695 [runtime.goexit] ", "error":" エラー発生!!", "caller":"/tmp/sandbox1035050178/main.go:37" }

Slide 32

Slide 32 text

© 2024 LayerX Inc. 29 / 32 まとめ 🎯 rs/zerolog をエラー箇所で呼んで caller によって呼び出し元を特定していたが，いくつかの問題点があったエラーにスタックトレースを保持して一箇所でエラーログを出力する方針に変更 rs/zerolog がエラーからスタックトレースをエラーから正しく抽出できるように実装 polyfloyd/go-errorlint を利用してエラーがWrap されても問題ないように対応エラーを morikuni/failure でWrap するようにしてスタックトレースを保持エラーがWrap されていなかったり，不要になったログが出力されないように tomarrell/wrapcheck ， semgrep で検知冗長で見づらかったエラーログが一箇所に集約され，スタックトレースも出るようにリクエストログと一緒に出すようにしたので，リクエストのペイロードとスタックトレースを一緒に見ることもできるようになって Happy 🥰