概要
以前、sentry-goの記事でスタックトレースについて軽く触れたが、 www.wheatandcat.me
ローカル開発中もエラー時にスタックトレースを表示したいと思い実装したら、 意外と良い感じにスタックトレースを表示させるのに手間取ったので、その辺の諸々をまとめた。
PR
実装
実装した時のポイントを記載
①.情報量の多すぎるスタックトレースをフィルタリングする
PR: https://github.com/wheatandcat/memoir-backend/pull/80
スタックトレース自体はpkg/errorsの WithStackを使用すれば出力可能
cause := errors.New("whoops") err := errors.WithStack(cause) fmt.Printf("%+v", err) // Example Output: // whoops // github.com/pkg/errors_test.ExampleWithStack_printf // /home/fabstu/go/src/github.com/pkg/errors/example_test.go:55 // testing.runExample // /usr/lib/go/src/testing/example.go:114 // testing.RunExamples // /usr/lib/go/src/testing/example.go:38 // testing.(*M).Run // /usr/lib/go/src/testing/testing.go:744 // main.main // github.com/pkg/errors/_test/_testmain.go:106 // runtime.main // /usr/lib/go/src/runtime/proc.go:183 // runtime.goexit // /usr/lib/go/src/runtime/asm_amd64.s:2086 // github.com/pkg/errors_test.ExampleWithStack_printf // /home/fabstu/go/src/github.com/pkg/errors/example_test.go:56 // testing.runExample // /usr/lib/go/src/testing/example.go:114 // testing.RunExamples // /usr/lib/go/src/testing/example.go:38 // testing.(*M).Run // /usr/lib/go/src/testing/testing.go:744 // main.main // github.com/pkg/errors/_test/_testmain.go:106 // runtime.main // /usr/lib/go/src/runtime/proc.go:183 // runtime.goexit // /usr/lib/go/src/runtime/asm_amd64.s:2086
一旦、確認でmemoir-backendのコードを例に実行してみる
func (re *ItemRepository) GetItemUserMultipleInPeriod(ctx context.Context, f *firestore.Client, userID []string, startDate time.Time, endDate time.Time, first int, cursor ItemsInPeriodCursor) ([]*model.Item, error) { var items []*model.Item query := f.CollectionGroup("items").Where("UserID", "in", userID).Where("Date", ">=", startDate).Where("Date", "<=", endDate).OrderBy("Date", firestore.Asc).OrderBy("CreatedAt", firestore.Asc) if cursor.ID != "" { ds, err := getItemCollection(f, cursor.UserID).Doc(cursor.ID).Get(ctx) if err != nil { return nil, err } query = query.StartAfter(ds) } matchItem := query.Limit(first).Documents(ctx) docs, err := matchItem.GetAll() if err != nil { // ↓に追加 err2 := errors.WithStack(cause) fmt.Printf("%+v", err2) return nil, err2 } for _, doc := range docs { var item *model.Item doc.DataTo(&item) items = append(items, item) } return items, nil }
スタックトレースを追加した箇所でエラーになるリクエストをすると以下のスタックトレースが表示される
running... github.com/wheatandcat/memoir-backend/repository.(*ItemRepository).GetItemUserMultipleInPeriod /Users/iinoyouhei/go/src/github.com/wheatandcat/memoir-backend/repository/item.go:171 github.com/wheatandcat/memoir-backend/graph.(*Graph).GetItemsInPeriod /Users/iinoyouhei/go/src/github.com/wheatandcat/memoir-backend/graph/item.go:142 github.com/wheatandcat/memoir-backend/graph.(*queryResolver).ItemsInPeriod /Users/iinoyouhei/go/src/github.com/wheatandcat/memoir-backend/graph/schema.resolvers.go:263 github.com/wheatandcat/memoir-backend/graph/generated.(*executionContext)._Query_itemsInPeriod.func2 /Users/iinoyouhei/go/src/github.com/wheatandcat/memoir-backend/graph/generated/generated.go:3412 github.com/99designs/gqlgen/graphql/executor.processExtensions.func3 /Users/iinoyouhei/go/1.15.5/pkg/mod/github.com/99designs/gqlgen@v0.13.0/graphql/executor/extensions.go:62 github.com/wheatandcat/memoir-backend/graph/generated.(*executionContext)._Query_itemsInPeriod /Users/iinoyouhei/go/src/github.com/wheatandcat/memoir-backend/graph/generated/generated.go:3410 github.com/wheatandcat/memoir-backend/graph/generated.(*executionContext)._Query.func6 /Users/iinoyouhei/go/src/github.com/wheatandcat/memoir-backend/graph/generated/generated.go:6535 github.com/99designs/gqlgen/graphql.(*FieldSet).Dispatch /Users/iinoyouhei/go/1.15.5/pkg/mod/github.com/99designs/gqlgen@v0.13.0/graphql/fieldset.go:34 github.com/wheatandcat/memoir-backend/graph/generated.(*executionContext)._Query /Users/iinoyouhei/go/src/github.com/wheatandcat/memoir-backend/graph/generated/generated.go:6605 github.com/wheatandcat/memoir-backend/graph/generated.(*executableSchema).Exec.func1 /Users/iinoyouhei/go/src/github.com/wheatandcat/memoir-backend/graph/generated/generated.go:898 github.com/99designs/gqlgen/graphql/executor.(*Executor).DispatchOperation.func1.1.1 /Users/iinoyouhei/go/1.15.5/pkg/mod/github.com/99designs/gqlgen@v0.13.0/graphql/executor/executor.go:105 github.com/99designs/gqlgen/graphql/executor.processExtensions.func2 /Users/iinoyouhei/go/1.15.5/pkg/mod/github.com/99designs/gqlgen@v0.13.0/graphql/executor/extensions.go:59 github.com/99designs/gqlgen/graphql/executor.(*Executor).DispatchOperation.func1.1 /Users/iinoyouhei/go/1.15.5/pkg/mod/github.com/99designs/gqlgen@v0.13.0/graphql/executor/executor.go:104 github.com/99designs/gqlgen/graphql/handler/transport.POST.Do /Users/iinoyouhei/go/1.15.5/pkg/mod/github.com/99designs/gqlgen@v0.13.0/graphql/handler/transport/http_post.go:53 github.com/99designs/gqlgen/graphql/handler.(*Server).ServeHTTP /Users/iinoyouhei/go/1.15.5/pkg/mod/github.com/99designs/gqlgen@v0.13.0/graphql/handler/server.go:115 github.com/go-chi/chi.(*Mux).routeHTTP /Users/iinoyouhei/go/1.15.5/pkg/mod/github.com/go-chi/chi@v3.3.2+incompatible/mux.go:424 net/http.HandlerFunc.ServeHTTP /Users/iinoyouhei/.anyenv/envs/goenv/versions/1.15.5/src/net/http/server.go:2042 github.com/wheatandcat/memoir-backend/auth.FirebaseLoginMiddleware.func1.1 /Users/iinoyouhei/go/src/github.com/wheatandcat/memoir-backend/auth/auth.go:76 net/http.HandlerFunc.ServeHTTP /Users/iinoyouhei/.anyenv/envs/goenv/versions/1.15.5/src/net/http/server.go:2042 github.com/wheatandcat/memoir-backend/auth.NotLoginMiddleware.func1.1 /Users/iinoyouhei/go/src/github.com/wheatandcat/memoir-backend/auth/auth.go:30 net/http.HandlerFunc.ServeHTTP /Users/iinoyouhei/.anyenv/envs/goenv/versions/1.15.5/src/net/http/server.go:2042 github.com/go-chi/chi.(*Mux).ServeHTTP /Users/iinoyouhei/go/1.15.5/pkg/mod/github.com/go-chi/chi@v3.3.2+incompatible/mux.go:81 net/http.serverHandler.ServeHTTP /Users/iinoyouhei/.anyenv/envs/goenv/versions/1.15.5/src/net/http/server.go:2843 net/http.(*conn).serve /Users/iinoyouhei/.anyenv/envs/goenv/versions/1.15.5/src/net/http/server.go:1925 runtime.goexit /Users/iinoyouhei/.anyenv/envs/goenv/versions/1.15.5/src/runtime/asm_amd64.s:1374
上記の通り大量のスタックトレースが出力される
このままでは視認性が悪いので、上記から必要な情報のみが表示されるようにフィルタリングを実装
まず、エラーを置き換える事を考慮して、以下の通りエラーをWrapする処理を作成
■ usecase/custom_error/error.go
package custom_error import ( "fmt" "os" "runtime" "strings" "github.com/pkg/errors" ) func GetCustomStackTrace(err error) errors.StackTrace { var fs errors.StackTrace st, ok := err.(interface{ StackTrace() errors.StackTrace }) if !ok { return fs } frames := st.StackTrace() for _, frame := range frames { pc := uintptr(frame) fun := runtime.FuncForPC(pc) f, _ := fun.FileLine(pc) // 不要なStackトレースが多すぎるのでフィルタリング if strings.Contains(f, "memoir-backend") || strings.Contains(f, "pkg/error") { if !strings.Contains(f, "usecase/custom_error") { fs = append(fs, frame) } } } if os.Getenv("APP_ENV") == "local" { // エラー出力 fmt.Printf("■ error: %+v\n", err.Error()) fmt.Printf("■ stack trace: %+v\n", fs) } return fs } func CustomError(err error) error { e := errors.WithStack(err) GetCustomStackTrace(e) return e } func CustomErrorWrap(err error, message string) error { e := errors.Wrap(err, message) GetCustomStackTrace(e) return e }
上記のエラーをWrapした関数を追加
import ( ce "github.com/wheatandcat/memoir-backend/usecase/custom_error" ) 略） if err != nil { return nil, ce.CustomError(err) }
以下でスタックトレースの内容のフィルタリングを実装
var fs errors.StackTrace st, ok := err.(interface{ StackTrace() errors.StackTrace }) if !ok { return fs } frames := st.StackTrace() for _, frame := range frames { pc := uintptr(frame) fun := runtime.FuncForPC(pc) f, _ := fun.FileLine(pc) // 不要なStackトレースが多すぎるのでフィルタリング if strings.Contains(f, "memoir-backend") || strings.Contains(f, "pkg/error") { if !strings.Contains(f, "usecase/custom_error") { fs = append(fs, frame) } } }
自身のプロジェクト内のスタックトレース以外は、ほぼ役に立たないので除外
フィルタリング処理は以下の通り
- 自身のリポジトリ名 or pkg/errorを含む ファイルパスのみ抽出
- errors.WithStackを使用しているのでpkg/errorも抽出対象にしている
- 実行箇所のファイルパスは除外
- usecase/custom_errorを除外しないと必ず先頭に生成箇所のスタックトレースの情報がつくので除外
上記フィルタリングをして出力すると、以下の通り
running... ■ stack trace: github.com/wheatandcat/memoir-backend/repository.(*ItemRepository).GetItemUserMultipleInPeriod /Users/iinoyouhei/go/src/github.com/wheatandcat/memoir-backend/repository/item.go:171 github.com/wheatandcat/memoir-backend/graph.(*Graph).GetItemsInPeriod /Users/iinoyouhei/go/src/github.com/wheatandcat/memoir-backend/graph/item.go:142 github.com/wheatandcat/memoir-backend/graph.(*queryResolver).ItemsInPeriod /Users/iinoyouhei/go/src/github.com/wheatandcat/memoir-backend/graph/schema.resolvers.go:263 github.com/wheatandcat/memoir-backend/graph/generated.(*executionContext)._Query_itemsInPeriod.func2 /Users/iinoyouhei/go/src/github.com/wheatandcat/memoir-backend/graph/generated/generated.go:3412 github.com/wheatandcat/memoir-backend/graph/generated.(*executionContext)._Query_itemsInPeriod /Users/iinoyouhei/go/src/github.com/wheatandcat/memoir-backend/graph/generated/generated.go:3410 github.com/wheatandcat/memoir-backend/graph/generated.(*executionContext)._Query.func6 /Users/iinoyouhei/go/src/github.com/wheatandcat/memoir-backend/graph/generated/generated.go:6535 github.com/wheatandcat/memoir-backend/graph/generated.(*executionContext)._Query /Users/iinoyouhei/go/src/github.com/wheatandcat/memoir-backend/graph/generated/generated.go:6605 github.com/wheatandcat/memoir-backend/graph/generated.(*executableSchema).Exec.func1 /Users/iinoyouhei/go/src/github.com/wheatandcat/memoir-backend/graph/generated/generated.go:898 github.com/wheatandcat/memoir-backend/auth.FirebaseLoginMiddleware.func1.1 /Users/iinoyouhei/go/src/github.com/wheatandcat/memoir-backend/auth/auth.go:76 github.com/wheatandcat/memoir-backend/auth.NotLoginMiddleware.func1.1 /Users/iinoyouhei/go/src/github.com/wheatandcat/memoir-backend/auth/auth.go:30
上記を内、実際に必要なスタックトレースは先頭から3番目くらいまでなので、さらにフィルタリングを追加
■ usecase/custom_error/error.go
if os.Getenv("APP_ENV") == "local" { // エラー出力 fmt.Printf("■ error: %+v\n", err.Error()) if len(fs) > 3 { // 3番目以降のトレース情報は除外 fs = fs[:3] } fmt.Printf("■ stack trace: %+v\n", fs) }
これで出力すると、以下の通り、丁度良い感じのスタックトレースが表示された
running... ■ stack trace: github.com/wheatandcat/memoir-backend/repository.(*ItemRepository).GetItemUserMultipleInPeriod /Users/iinoyouhei/go/src/github.com/wheatandcat/memoir-backend/repository/item.go:171 github.com/wheatandcat/memoir-backend/graph.(*Graph).GetItemsInPeriod /Users/iinoyouhei/go/src/github.com/wheatandcat/memoir-backend/graph/item.go:142 github.com/wheatandcat/memoir-backend/graph.(*queryResolver).ItemsInPeriod /Users/iinoyouhei/go/src/github.com/wheatandcat/memoir-backend/graph/schema.resolvers.go:263
②.errors.WithStackする毎にスタックトレースが表示されるのを解消
PR: https://github.com/wheatandcat/memoir-backend/pull/81
チーム開発で、スタックトレースを付けるべき箇所、付けなくても良い箇所を判断するのは難しいので、統一でスタックトレースを付けるようにしたい。
しかし、単純に全てのerrorにerrors.WithStackをつけるとスタックトレース時の出力が以下のようになる。
running... ----------------------- ■ error: rpc error: code = InvalidArgument desc = 'IN' requires an non-empty ArrayValue. ■ stack trace: github.com/wheatandcat/memoir-backend/repository.(*ItemRepository).GetItemUserMultipleInPeriod /Users/iinoyouhei/go/src/github.com/wheatandcat/memoir-backend/repository/item.go:170 github.com/wheatandcat/memoir-backend/graph.(*Graph).GetItemsInPeriod /Users/iinoyouhei/go/src/github.com/wheatandcat/memoir-backend/graph/item.go:143 github.com/wheatandcat/memoir-backend/graph.(*queryResolver).ItemsInPeriod /Users/iinoyouhei/go/src/github.com/wheatandcat/memoir-backend/graph/schema.resolvers.go:264 ---------------------------------------------- ■ error: rpc error: code = InvalidArgument desc = 'IN' requires an non-empty ArrayValue. ■ stack trace: github.com/wheatandcat/memoir-backend/graph.(*Graph).GetItemsInPeriod /Users/iinoyouhei/go/src/github.com/wheatandcat/memoir-backend/graph/item.go:145 github.com/wheatandcat/memoir-backend/graph.(*queryResolver).ItemsInPeriod /Users/iinoyouhei/go/src/github.com/wheatandcat/memoir-backend/graph/schema.resolvers.go:264 github.com/wheatandcat/memoir-backend/graph/generated.(*executionContext)._Query_itemsInPeriod.func2 /Users/iinoyouhei/go/src/github.com/wheatandcat/memoir-backend/graph/generated/generated.go:3412 ---------------------------------------------- ■ error: rpc error: code = InvalidArgument desc = 'IN' requires an non-empty ArrayValue. ■ stack trace: github.com/wheatandcat/memoir-backend/graph.(*queryResolver).ItemsInPeriod /Users/iinoyouhei/go/src/github.com/wheatandcat/memoir-backend/graph/schema.resolvers.go:266 github.com/wheatandcat/memoir-backend/graph/generated.(*executionContext)._Query_itemsInPeriod.func2 /Users/iinoyouhei/go/src/github.com/wheatandcat/memoir-backend/graph/generated/generated.go:3412 github.com/wheatandcat/memoir-backend/graph/generated.(*executionContext)._Query_itemsInPeriod /Users/iinoyouhei/go/src/github.com/wheatandcat/memoir-backend/graph/generated/generated.go:3410 -----------------------
ちなみにSentryのスタックトレースも、以下の通り複数件のスタックトレースが出力される（pkg/errorのスタックトレースがスタックトレースの情報スタックする方式のため）
全てのerrorの箇所を①の ce.CustomError(err) を使用した結果、エラーを返して受け取った先でもerrors.WithStackを実行しているので、以下の箇所のスタックトレースが出力されている
◎スタックトレース①
matchItem := query.Limit(first).Documents(ctx)
docs, err := matchItem.GetAll()
if err != nil {
return nil, ce.CustomError(err) // ←
}
for _, doc := range docs {
var item *model.Item
doc.DataTo(&item)
items = append(items, item)
}
◎スタックトレース②
items, err := g.App.ItemRepository.GetItemUserMultipleInPeriod(ctx, g.FirestoreClient, userID, input.StartDate, input.EndDate, input.First, cursor)
if err != nil {
return nil, ce.CustomError(err) // ←
}
◎スタックトレース③
result, err := g.GetItemsInPeriod(ctx, input)
if err != nil {
return nil, ce.CustomError(err) // ←
}
このままでは見づらいので、最初のerrorのみerrors.WithStackを実行 & スタックトレースを出力するように修正
■ usecase/custom_error/error.go
func CustomError(err error) error { // 既にスタックトレースの設定がある場合は、そのままエラーを返す _, ok := err.(interface{ StackTrace() errors.StackTrace }) if ok { return err } e := errors.WithStack(err) GetCustomStackTrace(e) return e }
上記の修正で、既にスタックトレースが設定している場合は、errors.WithStackを実行するのをやめて、errorをそのまま返すようにした。
これで、全てのエラーをce.CustomErrorに変更した状態でエラーが発生してもスタックトレースは最初1つのみ出力されるようになった。
running... ----------------------- ■ error: rpc error: code = InvalidArgument desc = 'IN' requires an non-empty ArrayValue. ■ stack trace: github.com/wheatandcat/memoir-backend/repository.(*ItemRepository).GetItemUserMultipleInPeriod /Users/iinoyouhei/go/src/github.com/wheatandcat/memoir-backend/repository/item.go:170 github.com/wheatandcat/memoir-backend/graph.(*Graph).GetItemsInPeriod /Users/iinoyouhei/go/src/github.com/wheatandcat/memoir-backend/graph/item.go:143 github.com/wheatandcat/memoir-backend/graph.(*queryResolver).ItemsInPeriod /Users/iinoyouhei/go/src/github.com/wheatandcat/memoir-backend/graph/schema.resolvers.go:264 -----------------------
③. errors.WithStackを使用した場合は、エラーの判定時にerrors.Causeを使用する
■ errors.Cause errors package - github.com/pkg/errors - pkg.go.dev
errors.Causeはerrors.WithStackでWrapされる前の状態のerrorを返す関数になっている こちらを使用しないと以下のようなコードの場合に正しくエラーハンドリングが行えない
// ↓エラーコードがNotFoundの場合 _, err := client.Collection("cities").Doc(c.id).Doc("SF").Get(ctx) fmt.Println("status:" status.Code(err)) // status: NotFound 正しく判定できている err1 := errors.WithStack(err) fmt.Println("status:" status.Code(err1)) // status: Unknown 正しく判定できていない fmt.Println("status:" status.Code(errors.Cause(err1))) // status: NotFound 正しく判定できている
なので、エラー判定時は必ずerrors.Causeを使用する
まとめ
- 上記を全て実装したら、ローカル開発でのデバッグが快適になった
