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

スライド内にリンクが複数あるため以下のSPA版で見ることを推奨します :)

https://upamune.github.io/go-lunch-lt-2024-04

元ネタのブログ: https://tech.layerx.co.jp/entry/2023/11/29/132325
layerx.go #0: https://layerx.connpass.com/event/317228/

Transcript

1. 冗長なエラーログを削減し、 スタックトレースを手に入れる @upamune / LayerX Inc. Go のエラーハンドリング 最新事情Lunch LT - 2024/04/23
2. © 2024 LayerX Inc. 2 / 32 自己紹介 @upamune ( うぱみゅん) 株式会社LayerX バクラク事業部 ex. 株式会社メルペイ バクラク申請・経費精算 テックリード 最近は同僚のPdM と趣味で始めたポッドキ ャストでキラキラシールを作ったんですが盛 大に失敗しました 🎙️ マヂカル.fm https://magical.fm/
3. © 2024 LayerX Inc. 3 / 32
4. © 2024 LayerX Inc. 4 / 32 話すこと 🏗️ バクラクでのGo 言語のAPI サーバーのエラーハンドリングの改善事例をご紹介 🗒️ 今回の話は 👇 のブログ記事がベース Go 言語のAPI サーバーの冗長なエラーログを40% 削減した話 🔗 link.serizawa.me/err40
5. © 2024 LayerX Inc. 5 / 32 突然ですが…
6. © 2024 LayerX Inc. 6 / 32 スタックトレースが 欲しい!!
7. © 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 }
8. © 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 }
9. © 2024 LayerX Inc. 9 / 32 どこから発生したエラーなのかは分かるようになった 😉
10. © 2024 LayerX Inc. 10 / 32 だがしかし… 🤨
11. © 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 }
12. © 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" }
13. © 2024 LayerX Inc. 13 / 32 rs/zerolog の caller で代用した時の問題点 🕵️ 複数のエラーログを見ないとスタックトレースを見ることができないのでエラーの原因を追いづらい 🤑 冗長なエラーログにより、エラーログの件数が増加しログ全体の検索コストと金銭的コストが増加する 1 件のエラーにつき caller フィールドしか違いがないログが4 件出たりする 🤔 エラーログの件数を元にアラートを設定している場合、アラートのしきい値を決めるのが難しい
14. © 2024 LayerX Inc. 14 / 32 📑ここまでの課題整理 エラー調査のためにスタックトレースが欲しい エラーログを複数出力することによって，どこから呼ばれているかは分かったが以下の点で課題アリ エラー調査の煩雑さ ログのコスト ログのアラートの閾値調整の難しさ
15. © 2024 LayerX Inc. 15 / 32 冗長なエラーログを削減し、 スタックトレースを手に入れるぞ!!
16. © 2024 LayerX Inc. 16 / 32 🗺️ 冗長なエラーログを削減し、 スタックトレースを手に入れるまでの道程 1. エラーをWrap してスタックトレースを取るためのエラーハンドリングライブラリの選定 2. Wrap されたエラーのスタックトレースを1 箇所でログ出力できるように設定 3. Wrap されたエラーに対応できてない部分を見つけて( errors.Is,As ) 修正 4. エラーをWrap するように修正 5. 冗長なエラーログを削除 6. 今後Wrap されていないエラーが増えないように/ 冗長なエラーログを記述されないように対策
17. © 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 さんの発表で!!
18. © 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() }
19. © 2024 LayerX Inc. 19 / 32 Wrap されているエラーはスタックトレースが出るようになった 🎉 🎉 🎉
20. © 2024 LayerX Inc. 20 / 32 Wrap されたエラーに対応できてない部分を見つけて修正 errors.{Is,As} を利用するようにして，Wrap されてても正しく動作するように修正する // エラーの比較: エラーがWrap されていない時 if err == ErrNotFound { return nil }
21. © 2024 LayerX Inc. 20 / 32 Wrap されたエラーに対応できてない部分を見つけて修正 errors.{Is,As} を利用するようにして，Wrap されてても正しく動作するように修正する // エラーの比較: エラーがWrap されている時 if errors.Is(err, ErrNotFound) { return nil }
22. © 2024 LayerX Inc. 20 / 32 Wrap されたエラーに対応できてない部分を見つけて修正 errors.{Is,As} を利用するようにして，Wrap されてても正しく動作するように修正する // エラーから情報を取り出す: エラーがWrap されていない時 if perr, ok := err.(*fs.PathError); ok { fmt.Println(perr.Path) }
23. © 2024 LayerX Inc. 20 / 32 Wrap されたエラーに対応できてない部分を見つけて修正 errors.{Is,As} を利用するようにして，Wrap されてても正しく動作するように修正する // エラーから情報を取り出す: エラーがWrap されている時 var perr *fs.PathError if errors.As(err, &perr) { fmt.Println(perr.Path) }
24. © 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)
25. © 2024 LayerX Inc. 22 / 32 エラーをWrap するように修正
26. © 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) 意外と綺麗に置換できたが… もっと良い方法があったかも? 🤔
27. © 2024 LayerX Inc. 24 / 32 冗長なエラーログを削除 🗑️
28. © 2024 LayerX Inc. 25 / 32 冗長なエラーログを削除 🗑️ これもIDE の一括置換で対応 logger.Error().Caller().Err(err).Send() を一括で削除 有用なログはメッセージを付けていたり，他のフィールドが付与されているので，完全に一致するコードだ けを削除対応
29. © 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")
30. © 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) } // ... }
31. © 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" }
32. © 2024 LayerX Inc. 29 / 32 まとめ 🎯 rs/zerolog をエラー箇所で呼んで caller によって呼び出し元を特定していたが，いくつかの問題点が あった エラーにスタックトレースを保持して一箇所でエラーログを出力する方針に変更 rs/zerolog がエラーからスタックトレースをエラーから正しく抽出できるように実装 polyfloyd/go-errorlint を利用してエラーがWrap されても問題ないように対応 エラーを morikuni/failure でWrap するようにしてスタックトレースを保持 エラーがWrap されていなかったり，不要になったログが出力されないように tomarrell/wrapcheck ， semgrep で検知 冗長で見づらかったエラーログが一箇所に集約され，スタックトレースも出るように リクエストログと一緒に出すようにしたので，リクエストのペイロードとスタックトレースを一緒に見 ることもできるようになって Happy 🥰
33. © 2024 LayerX Inc. 30 / 32 おわり 🔚 ご清聴ありがとうございました
34. © 2024 LayerX Inc. 31 / 32 お知らせ
35. © 2024 LayerX Inc. 32 / 32 layerx.go やります!!! 昨日決まったんですが，layerx.go をやります!! 👇 以下のリンクから参加登録ができるので，ぜひ来てください ( 発表してくださる方もお待ちしておりま す) https://layerx.connpass.com/event/317228