ペペロミア & memoir開発ブログ

React Nativeで開発しているペペロミア & memoirの技術系記事を投稿してます

Goでローカル開発時に必要なスタックトレースのみ表示する

概要

以前、sentry-goの記事でスタックトレースについて軽く触れたが、 www.wheatandcat.me

ローカル開発中もエラー時にスタックトレースを表示したいと思い実装したら、 意外と良い感じにスタックトレースを表示させるのに手間取ったので、その辺の諸々をまとめた。

PR

github.com

github.com

実装

実装した時のポイントを記載

①.情報量の多すぎるスタックトレースをフィルタリングする

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のコードを例に実行してみる

repository/item.go

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のスタックトレースがスタックトレースの情報スタックする方式のため)

f:id:wheatandcat:20211021221054p:plain

全てのerrorの箇所を①の ce.CustomError(err) を使用した結果、エラーを返して受け取った先でもerrors.WithStackを実行しているので、以下の箇所のスタックトレースが出力されている

◎スタックトレース①

■ [https://github.com/wheatandcat/memoir-backend/blob/bd2acdfea71da778c07bc0b214578cfdedbc304b/repository/item.go#L169-L171)

   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)
    }

◎スタックトレース②

graph/item.go

   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) // ←
    }

◎スタックトレース③

graph/schema.resolvers.go

   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を使用する

まとめ

  • 上記を全て実装したら、ローカル開発でのデバッグが快適になった