Goでスタックトレースを構造化して取り扱う

はじめましてfreee株式会社でソフトウェアエンジニアをしているbudougumi0617ことしみっちょです。普段はGoによるアカウントアグリゲーション機能（銀行同期基盤）の開発に携わっています。

この記事はfreee Developers Advent Calendar 2018 の23日目の記事です。

12月23日と言えば国民の祝日、Perfumeかしゆかさんの誕生日ですね。おめでとうございます。今回は私が先日参加したPerfume 7th Tour 2018 ｢FUTURE POP｣の感想を書こうと思ったのですが、ツアーが終わるまでネタバレは禁止なのでGoの話をすることにしました。

この記事では私が携わっているプロダクトで行なっているエラーハンドリングの一部とGoでスタックトレースを構造化に扱う方法について紹介します。

なお、文中で利用しているソースコードや出力結果は以下のサンプルリポジトリに用意したコードを利用しています。

github.com

Goのエラーハンドリングについて

Goの標準パッケージから生成されるエラーはそのまま愚直に利用するとエラーメッセージしか持っていない非常なシンプルな情報しか得られません。プロダクトで利用する上ではスタックトレースやSeverityの仕組みがほしいですね。各社・各人が多様なアプローチをとっており、2018年12月のアドベントカレンダーや勉強会だけでもエラーの扱い方について以下のような投稿・発表がなされています（漏れていたらごめんなさい）。

私のGoのプロダクトではpkg/errorsをラップした独自errorsパッケージを利用しています。

github.com

pkg/errorsを利用すると、エラー情報にスタックトレースをエラー情報に含めることが可能です。以下はpkg/errors.New関数から生成したエラーをfmt.Printf("%+v",err)と出力した結果に含まれているスタックトレースの引用です。

github.com/budougumi0617/errors-example/errors.NewByPkg
        /Users/budougumi0617/go/src/github.com/budougumi0617/errors-example/errors/errors.go:14
github.com/budougumi0617/errors-example/root/sub.(*Sub).ReturnErrorByPkg
        /Users/budougumi0617/go/src/github.com/budougumi0617/errors-example/root/sub/sub.go:18
github.com/budougumi0617/errors-example/root.secondFuncWithPkg
        /Users/budougumi0617/go/src/github.com/budougumi0617/errors-example/root/root.go:24
github.com/budougumi0617/errors-example/root.FirstFuncWithPkg
        /Users/budougumi0617/go/src/github.com/budougumi0617/errors-example/root/root.go:19
main.main
        /Users/budougumi0617/go/src/github.com/budougumi0617/errors-example/main.go:14
runtime.main
        /usr/local/opt/go/libexec/src/runtime/proc.go:201
runtime.goexit
        /usr/local/opt/go/libexec/src/runtime/asm_amd64.s:1333

呼び出し元の関数名や呼び出された場所のファイル行数などのスタックフレームを出力しているのがわかります。上記のようにpkg/errorsを使うだけでスタックトレースをエラー情報に含めることができるようになるのですが、私のプロダクトの独自エラー型ではスタックトレースの生成を一部独自に行なっています。

なぜ独自にスタックトレース情報を取り扱うのか？

pkg/errorsで出来る以上ほとんど車輪の再発明なのですが、スタックトレースの取得を独自にすることの利点は、エラートラッキングサービスに加工後のスタックトレース情報を送信できることです。私が担当しているプロダクトでは、BugSnagを利用してエラー情報のトラッキングをしています。BugSnagはSentryなどと同様のエラートラッキングサービスです。

www.bugsnag.com

そして、私が担当しているGoのプロダクトはos/exec.Cmd経由でRubyのスクリプトに一部の処理を移譲しています。Rubyスクリプトのスタックフレームについては当然Goのランタイムからは取得できません。そのため、Rubyスクリプトの実行時に例外が発生したとき、Rubyのスタックトレースのフレーム情報ををGoのスタックトレースに追加してからBugSnagに送信しています*1 。ではどのようにすればGoのスタックトレースを操作することが可能なのでしょうか。

Goでスタックトレース（スタックフレーム）を構造化して操作する

まず、pkg/errorsはどのようにスタックトレースを取得しているのでしょうか。pkg/errorsでerrorを生成するerrors.Newなどは以下のような実装をしています。

https://github.com/pkg/errors/blob/2233dee583dcf88f3c8b22cb7a33f05a499800d8/errors.go#L100-L107

// New returns an error with the supplied message.
// New also records the stack trace at the point it was called.
func New(message string) error {
    return &fundamental{
        msg:   message,
        stack: callers(),
    }
}

このstackフィールドに入っている情報がスタックトレースの情報なのですが、実際に格納するオブジェクトを返しているcallers関数の実装は以下です。

https://github.com/pkg/errors/blob/059132a15dd08d6704c67711dae0cf35ab991756/stack.go#L133-L139

func callers() *stack {
    const depth = 32
    var pcs [depth]uintptr
    n := runtime.Callers(3, pcs[:])
    var st stack = pcs[0:n]
    return &st
}

この中のruntime.Callers関数で取得した[]uintptrがスタックトレースの各フレーム情報になります。pkg/errorsでは独自型のpkg/errors.Frame(type Frame uintptr)に格納して情報を取得しています。
なお、Go1.7以降ではruntimeパッケージ内にスタックトレース情報を模すruntime.Framesと、runtime.Callers関数で取得したuintptrをからFramesを取得するruntime.CallersFrames関数が追加されているのですが、こちらを利用すると加工が少し面倒なため、今回は利用しません。（runtime.CallersFramesの利用方法はruntimeパッケージのExampleをご覧ください。）

本稿では以下のような独自型を定義します。

// Frame はスタックフレームを表現する独自構造体
type Frame struct {
    // File はそのスタックが発生した開始されたファイル
    File string
    // LineNumber はそのスタックが開始されたファイル行数
    LineNumber int
    // Name はそのスタックが開始された関数・メソッド名
    Name string
    // ProgramCounter は元データ
    ProgramCounter uintptr
}

そしてこのFrame構造体にruntime.Func構造体を介して各スタックフレーム情報を格納してきます。*runtime.Funcオブジェクトはruntime.Callersで取得したスタックフレーム情報のuintptrからruntime.FuncForPC関数を使って取得できます。*runtime.Funcオブジェクトを介してスタックフレーム情報を[]Frameに格納し直すコードが以下になります。

func callers() []uintptr {
    const depth = 32
    var pcs [depth]uintptr
    n := runtime.Callers(3, pcs[:])
    return pcs[0 : n-2]
}

// NewFrame はスタックトレースの各スタックフレームをFrameに格納する
func NewFrame(pcs []uintptr) []Frame {
    frames := []Frame{}

    for _, pc := range pcs {
        frame := Frame{ProgramCounter: pc}
        fn := runtime.FuncForPC(pc)
        if fn == nil {
            return frames
        }
        frame.Name = trimPkgName(fn)

        frame.File, frame.LineNumber = fn.FileLine(pc - 1)
        frames = append(frames, frame)
    }
    return frames
}

// package名を取り除く
func trimPkgName(fn *runtime.Func) string {
    name := fn.Name()
    if ld := strings.LastIndex(name, "."); ld >= 0 {
        name = name[ld+1:]
    }
    return name
}

あとはerrorインターフェースを満たす構造体に[]Frameを保持しておけば、スタックトレース情報を含んだ独自errorの定義の完成です(fmt.Stringer、fmt.Formatterインターフェースも実装しておくとよいでしょう)。次の出力は大雑把にError()メソッドを実装したMyErrorの出力です。

大雑把にスタックトレースを出力する独自error:
Cause: custom error
Trace:
/Users/budougumi0617/go/src/github.com/budougumi0617/errors-example/root/sub/sub.go:15 ReturnError
/Users/budougumi0617/go/src/github.com/budougumi0617/errors-example/root/root.go:16 secondFunc
/Users/budougumi0617/go/src/github.com/budougumi0617/errors-example/root/root.go:11 FirstFunc
/Users/budougumi0617/go/src/github.com/budougumi0617/errors-example/main.go:12 main

私のプロダクトでは[]Frameに更にRubyから取得したスタックトレース情報を付与したりしています。

今回は独自定義のFrame型を用意しましたが、例えばBugSnagを利用している場合、bugsnag-go/errors.StackFrame構造体にフレーム情報を格納し、bugsnag-go/errors.ErrorWithStackFramesインターフェースを実装すれば「細工したスタックトレース」をBugSnagのWebビューに表示することもできます。

// bugsnag-go/errors.StackFrame の定義
type StackFrame struct {
    File           string
    LineNumber     int
    Name           string
    Package        string
    ProgramCounter uintptr
}

// bugsnag-go/errors.ErrorWithStackFrame の定義
type ErrorWithStackFrames interface {
    Error() string
    StackFrames() []StackFrame
}