お題

Go 1.13 で %w によるログのラップが可能になった。
が、その方式でログ出力すると（エラー時の）スタックトレースが吐けない。
ので、スタックトレース吐くために xerrorsパッケージが用意されている。
これで、エラー時にスタックトレース付きでログが吐ける。
といった話は、既にたくさん記事があるので、このxerrorsパッケージをこうやって間違って使ってしまったという事例を２つほど。

開発環境

# OS - Linux(Ubuntu)

$ cat /etc/os-release 
NAME="Ubuntu"
VERSION="18.04.4 LTS (Bionic Beaver)"

# バックエンド

# 言語 - Golang

$ go version
go version go1.13.9 linux/amd64

IDE - Goland

GoLand 2020.1.2
Build #GO-201.7223.97, built on May 1, 2020

今回の全ソース

実践

%w を使ってエラーをラップ

まずは、Go1.13 から導入された %w を使った表現でエラーログをラップしてみる。

構成

$ tree
.
├── fna
│   └── fn_a.go
├── fnb
│   └── fn_b.go
├── fnc
│   └── fn_c.go
├── fnd
│   └── fn_d.go
├── go.mod
└── main.go

main から fna -> fnb -> fnc -> fnd の順でメソッドコールし、fnd で起きたエラーをラップしつつ上位に戻し、main でログ出力。

実行結果

以下のように、全ラップ箇所のログが出力されている。
ただし、ラップ箇所のスタックトレースは吐かれない。

[before]main error occurred: fna.Exec error occurred: fnb.Exec error occurred: fnc.Exec error occurred: fnd.Exec error occurred: unexpected error occurred

ソース群

main.go

package main

import (
	"fmt"

	"github.com/sky0621/tips-go/try/xerrors/before/fna"
)

func main() {
	e := fna.Exec()
	if e != nil {
		lastErr := fmt.Errorf("[before]main error occurred: %w", e)
		fmt.Printf("%+v\n", lastErr)
	}
}

その他のソース

fna/fn_a.go

package fna

import (
	"fmt"

	"github.com/sky0621/tips-go/try/xerrors/before/fnb"
)

func Exec() error {
	e := fnb.Exec()
	if e != nil {
		return fmt.Errorf("fna.Exec error occurred: %w", e)
	}
	return nil
}

fnb/fn_b.go

package fnb

import (
	"fmt"

	"github.com/sky0621/tips-go/try/xerrors/before/fnc"
)

func Exec() error {
	e := fnc.Exec()
	if e != nil {
		return fmt.Errorf("fnb.Exec error occurred: %w", e)
	}
	return nil
}

fnc/fn_c.go

package fnc

import (
	"fmt"

	"github.com/sky0621/tips-go/try/xerrors/before/fnd"
)

func Exec() error {
	e := fnd.Exec()
	if e != nil {
		return fmt.Errorf("fnc.Exec error occurred: %w", e)
	}
	return nil
}

fnd/fn_d.go

package fnd

import (
	"errors"
	"fmt"
)

func Exec() error {
	e := errors.New("unexpected error occurred")
	return fmt.Errorf("fnd.Exec error occurred: %w", e)
}

"github.com/pkg/errors"パッケージを使用

そもそもGoではgithub.com/pkg/errorsパッケージのWrap関数を使うことでエラーのラップが可能だった。

実行結果

以下のようにスタックトレース付きでログ出力される。（なんか過剰に出てる気がするけど）

unexpected error occurred
github.com/sky0621/tips-go/try/xerrors/before2/fnd.Exec
        /home/sky0621/work/src/github.com/sky0621/tips-go/try/xerrors/before2/fnd/fn_d.go:8
github.com/sky0621/tips-go/try/xerrors/before2/fnc.Exec
        /home/sky0621/work/src/github.com/sky0621/tips-go/try/xerrors/before2/fnc/fn_c.go:9
github.com/sky0621/tips-go/try/xerrors/before2/fnb.Exec
        /home/sky0621/work/src/github.com/sky0621/tips-go/try/xerrors/before2/fnb/fn_b.go:9
github.com/sky0621/tips-go/try/xerrors/before2/fna.Exec
        /home/sky0621/work/src/github.com/sky0621/tips-go/try/xerrors/before2/fna/fn_a.go:9
main.main
        /home/sky0621/work/src/github.com/sky0621/tips-go/try/xerrors/before2/main.go:11
runtime.main
        /usr/local/go/src/runtime/proc.go:203
runtime.goexit
        /usr/local/go/src/runtime/asm_amd64.s:1357
fnd.Exec error occurred
github.com/sky0621/tips-go/try/xerrors/before2/fnd.Exec
        /home/sky0621/work/src/github.com/sky0621/tips-go/try/xerrors/before2/fnd/fn_d.go:9
github.com/sky0621/tips-go/try/xerrors/before2/fnc.Exec
        /home/sky0621/work/src/github.com/sky0621/tips-go/try/xerrors/before2/fnc/fn_c.go:9
github.com/sky0621/tips-go/try/xerrors/before2/fnb.Exec
        /home/sky0621/work/src/github.com/sky0621/tips-go/try/xerrors/before2/fnb/fn_b.go:9
github.com/sky0621/tips-go/try/xerrors/before2/fna.Exec
        /home/sky0621/work/src/github.com/sky0621/tips-go/try/xerrors/before2/fna/fn_a.go:9
main.main
        /home/sky0621/work/src/github.com/sky0621/tips-go/try/xerrors/before2/main.go:11
runtime.main
        /usr/local/go/src/runtime/proc.go:203
runtime.goexit
        /usr/local/go/src/runtime/asm_amd64.s:1357
fnc.Exec error occurred
github.com/sky0621/tips-go/try/xerrors/before2/fnc.Exec
        /home/sky0621/work/src/github.com/sky0621/tips-go/try/xerrors/before2/fnc/fn_c.go:11
github.com/sky0621/tips-go/try/xerrors/before2/fnb.Exec
        /home/sky0621/work/src/github.com/sky0621/tips-go/try/xerrors/before2/fnb/fn_b.go:9
github.com/sky0621/tips-go/try/xerrors/before2/fna.Exec
        /home/sky0621/work/src/github.com/sky0621/tips-go/try/xerrors/before2/fna/fn_a.go:9
main.main
        /home/sky0621/work/src/github.com/sky0621/tips-go/try/xerrors/before2/main.go:11
runtime.main
        /usr/local/go/src/runtime/proc.go:203
runtime.goexit
        /usr/local/go/src/runtime/asm_amd64.s:1357
fnb.Exec error occurred
github.com/sky0621/tips-go/try/xerrors/before2/fnb.Exec
        /home/sky0621/work/src/github.com/sky0621/tips-go/try/xerrors/before2/fnb/fn_b.go:11
github.com/sky0621/tips-go/try/xerrors/before2/fna.Exec
        /home/sky0621/work/src/github.com/sky0621/tips-go/try/xerrors/before2/fna/fn_a.go:9
main.main
        /home/sky0621/work/src/github.com/sky0621/tips-go/try/xerrors/before2/main.go:11
runtime.main
        /usr/local/go/src/runtime/proc.go:203
runtime.goexit
        /usr/local/go/src/runtime/asm_amd64.s:1357
fna.Exec error occurred
github.com/sky0621/tips-go/try/xerrors/before2/fna.Exec
        /home/sky0621/work/src/github.com/sky0621/tips-go/try/xerrors/before2/fna/fn_a.go:11
main.main
        /home/sky0621/work/src/github.com/sky0621/tips-go/try/xerrors/before2/main.go:11
runtime.main
        /usr/local/go/src/runtime/proc.go:203
runtime.goexit
        /usr/local/go/src/runtime/asm_amd64.s:1357
[before2]main error occurred

ソース群

main.go

package main

import (
	"fmt"

	"github.com/pkg/errors"
	"github.com/sky0621/tips-go/try/xerrors/before2/fna"
)

func main() {
	e := fna.Exec()
	if e != nil {
		lastErr := errors.Wrap(e, "[before2]main error occurred")
		fmt.Printf("%+v\n", errors.Unwrap(lastErr))
	}
}

その他のソース

fna/fn_a.go

package fna

import (
	"github.com/pkg/errors"
	"github.com/sky0621/tips-go/try/xerrors/before2/fnb"
)

func Exec() error {
	e := fnb.Exec()
	if e != nil {
		return errors.Wrap(e, "fna.Exec error occurred")
	}
	return nil
}

fnb/fn_b.go

package fnb

import (
	"github.com/pkg/errors"
	"github.com/sky0621/tips-go/try/xerrors/before2/fnc"
)

func Exec() error {
	e := fnc.Exec()
	if e != nil {
		return errors.Wrap(e, "fnb.Exec error occurred")
	}
	return nil
}

fnc/fn_c.go

package fnc

import (
	"github.com/pkg/errors"
	"github.com/sky0621/tips-go/try/xerrors/before2/fnd"
)

func Exec() error {
	e := fnd.Exec()
	if e != nil {
		return errors.Wrap(e, "fnc.Exec error occurred")
	}
	return nil
}

fnd/fn_d.go

package fnd

import (
	"github.com/pkg/errors"
)

func Exec() error {
	e := errors.New("unexpected error occurred")
	return errors.Wrap(e, "fnd.Exec error occurred")
}

"golang.org/x/xerrors"パッケージを使用

Go1.13で %w を使いつつスタックトレースも吐きたい場合、golang.org/x/xerrorsを使う。

実行結果

なんだかすごくきれいにスタックトレースを表示してくれてる。

[after]main error occurred:
    main.main
        /home/sky0621/work/src/github.com/sky0621/tips-go/try/xerrors/after/main.go:13
  - fna.Exec error occurred:
    github.com/sky0621/tips-go/try/xerrors/after/fna.Exec
        /home/sky0621/work/src/github.com/sky0621/tips-go/try/xerrors/after/fna/fn_a.go:11
  - fnb.Exec error occurred:
    github.com/sky0621/tips-go/try/xerrors/after/fnb.Exec
        /home/sky0621/work/src/github.com/sky0621/tips-go/try/xerrors/after/fnb/fn_b.go:11
  - fnc.Exec error occurred:
    github.com/sky0621/tips-go/try/xerrors/after/fnc.Exec
        /home/sky0621/work/src/github.com/sky0621/tips-go/try/xerrors/after/fnc/fn_c.go:11
  - fnd.Exec error occurred:
    github.com/sky0621/tips-go/try/xerrors/after/fnd.Exec
        /home/sky0621/work/src/github.com/sky0621/tips-go/try/xerrors/after/fnd/fn_d.go:9
  - unexpected error occurred:
    github.com/sky0621/tips-go/try/xerrors/after/fnd.Exec
        /home/sky0621/work/src/github.com/sky0621/tips-go/try/xerrors/after/fnd/fn_d.go:8

ソース群

main.go

package main

import (
	"fmt"

	"github.com/sky0621/tips-go/try/xerrors/after/fna"
	"golang.org/x/xerrors"
)

func main() {
	e := fna.Exec()
	if e != nil {
		lastErr := xerrors.Errorf("[after]main error occurred: %w", e)
		fmt.Printf("%+v\n", lastErr)
	}
}

その他のソース

fna/fn_a.go

package fna

import (
	"github.com/sky0621/tips-go/try/xerrors/after/fnb"
	"golang.org/x/xerrors"
)

func Exec() error {
	e := fnb.Exec()
	if e != nil {
		return xerrors.Errorf("fna.Exec error occurred: %w", e)
	}
	return nil
}

fnb/fn_b.go

package fnb

import (
	"github.com/sky0621/tips-go/try/xerrors/after/fnc"
	"golang.org/x/xerrors"
)

func Exec() error {
	e := fnc.Exec()
	if e != nil {
		return xerrors.Errorf("fnb.Exec error occurred: %w", e)
	}
	return nil
}

fnc/fn_c.go

package fnc

import (
	"github.com/sky0621/tips-go/try/xerrors/after/fnd"
	"golang.org/x/xerrors"
)

func Exec() error {
	e := fnd.Exec()
	if e != nil {
		return xerrors.Errorf("fnc.Exec error occurred: %w", e)
	}
	return nil
}

fnd/fn_d.go

package fnd

import (
	"golang.org/x/xerrors"
)

func Exec() error {
	e := xerrors.New("unexpected error occurred")
	return xerrors.Errorf("fnd.Exec error occurred: %w", e)
}

xerrorsの誤った使い方事例１

エラーをラップしつつ呼び出し元に返していったログを最終的に出力する箇所で、"github.com/pkg/errors"を使っていた時に Unwrap 関数を使ったりしていたのだけど、同じように Unwrap した結果をログ出力するようにした。
すると、最後のラップしたログが出力されなかった。

実行結果

一見、ちゃんとスタックトレース出てるし、いいかなと思ったんだけど、実は最後にラップした「[after3]main error occurred: 〜〜」のログが出力されていない。

fna.Exec error occurred:
    github.com/sky0621/tips-go/try/xerrors/after3/fna.Exec
        /home/sky0621/work/src/github.com/sky0621/tips-go/try/xerrors/after3/fna/fn_a.go:11
  - fnb.Exec error occurred:
    github.com/sky0621/tips-go/try/xerrors/after3/fnb.Exec
        /home/sky0621/work/src/github.com/sky0621/tips-go/try/xerrors/after3/fnb/fn_b.go:11
  - fnc.Exec error occurred:
    github.com/sky0621/tips-go/try/xerrors/after3/fnc.Exec
        /home/sky0621/work/src/github.com/sky0621/tips-go/try/xerrors/after3/fnc/fn_c.go:11
  - fnd.Exec error occurred:
    github.com/sky0621/tips-go/try/xerrors/after3/fnd.Exec
        /home/sky0621/work/src/github.com/sky0621/tips-go/try/xerrors/after3/fnd/fn_d.go:9
  - unexpected error occurred:
    github.com/sky0621/tips-go/try/xerrors/after3/fnd.Exec
        /home/sky0621/work/src/github.com/sky0621/tips-go/try/xerrors/after3/fnd/fn_d.go:8

ソース群

main.go

package main

import (
	"fmt"

	"github.com/sky0621/tips-go/try/xerrors/after3/fna"
	"golang.org/x/xerrors"
)

func main() {
	e := fna.Exec()
	if e != nil {
		lastErr := xerrors.Errorf("[after3]main error occurred: %w", e)
		fmt.Printf("%+v\n", xerrors.Unwrap(lastErr))
	}
}

ログ出力時に xerrors.Unwrap を呼んでるんだけど、これ、やっちゃダメみたい。

その他のソース

fna/fn_a.go

package fna

import (
	"github.com/sky0621/tips-go/try/xerrors/after3/fnb"
	"golang.org/x/xerrors"
)

func Exec() error {
	e := fnb.Exec()
	if e != nil {
		return xerrors.Errorf("fna.Exec error occurred: %w", e)
	}
	return nil
}

fnb/fn_b.go

package fnb

import (
	"github.com/sky0621/tips-go/try/xerrors/after3/fnc"
	"golang.org/x/xerrors"
)

func Exec() error {
	e := fnc.Exec()
	if e != nil {
		return xerrors.Errorf("fnb.Exec error occurred: %w", e)
	}
	return nil
}

fnc/fn_c.go

package fnc

import (
	"github.com/sky0621/tips-go/try/xerrors/after3/fnd"
	"golang.org/x/xerrors"
)

func Exec() error {
	e := fnd.Exec()
	if e != nil {
		return xerrors.Errorf("fnc.Exec error occurred: %w", e)
	}
	return nil
}

fnd/fn_d.go

package fnd

import (
	"golang.org/x/xerrors"
)

func Exec() error {
	e := xerrors.New("unexpected error occurred")
	return xerrors.Errorf("fnd.Exec error occurred: %w", e)
}

xerrorsの誤った使い方事例２

xerrorsを使う前の時点のソースで、ログ出力部分をユーティリティ関数にしていた。
面倒だったので、そのユーティリティ関数の中身を xerrors.Errorf("〜〜: %w", e) のように書き換えた。
すると、ログ出力部分をユーティリティ関数に任せていた箇所のスタックトレースが軒並みユーティリティ関数のものになってしまった。

実行結果

スタックトレースは吐かれているけど、途中すべてが util/log.go の行番号が出ていて、結局、メソッド呼び出し関係がまったくわからない。

[Log] error occurred:
    github.com/sky0621/tips-go/try/xerrors/after2/util.Log
        /home/sky0621/work/src/github.com/sky0621/tips-go/try/xerrors/after2/util/log.go:9
  - [Log] error occurred:
    github.com/sky0621/tips-go/try/xerrors/after2/util.Log
        /home/sky0621/work/src/github.com/sky0621/tips-go/try/xerrors/after2/util/log.go:9
  - [Log] error occurred:
    github.com/sky0621/tips-go/try/xerrors/after2/util.Log
        /home/sky0621/work/src/github.com/sky0621/tips-go/try/xerrors/after2/util/log.go:9
  - [Log] error occurred:
    github.com/sky0621/tips-go/try/xerrors/after2/util.Log
        /home/sky0621/work/src/github.com/sky0621/tips-go/try/xerrors/after2/util/log.go:9
  - [Log] error occurred:
    github.com/sky0621/tips-go/try/xerrors/after2/util.Log
        /home/sky0621/work/src/github.com/sky0621/tips-go/try/xerrors/after2/util/log.go:9
  - unexpected error occurred:
    github.com/sky0621/tips-go/try/xerrors/after2/fnd.Exec
        /home/sky0621/work/src/github.com/sky0621/tips-go/try/xerrors/after2/fnd/fn_d.go:9

ソース群

main.go

package main

import (
	"fmt"

	"github.com/sky0621/tips-go/try/xerrors/after2/util"

	"github.com/sky0621/tips-go/try/xerrors/after2/fna"
)

func main() {
	e := fna.Exec()
	if e != nil {
		lastErr := util.Log(e)
		fmt.Printf("%+v\n", lastErr)
	}
}

その他のソース

fna/fn_a.go

package fna

import (
	"github.com/sky0621/tips-go/try/xerrors/after2/fnb"
	"github.com/sky0621/tips-go/try/xerrors/after2/util"
)

func Exec() error {
	e := fnb.Exec()
	if e != nil {
		return util.Log(e)
	}
	return nil
}

fnb/fn_b.go

package fnb

import (
	"github.com/sky0621/tips-go/try/xerrors/after2/fnc"
	"github.com/sky0621/tips-go/try/xerrors/after2/util"
)

func Exec() error {
	e := fnc.Exec()
	if e != nil {
		return util.Log(e)
	}
	return nil
}

fnc/fn_c.go

package fnc

import (
	"github.com/sky0621/tips-go/try/xerrors/after2/fnd"
	"github.com/sky0621/tips-go/try/xerrors/after2/util"
)

func Exec() error {
	e := fnd.Exec()
	if e != nil {
		return util.Log(e)
	}
	return nil
}

fnd/fn_d.go

package fnd

import (
	"github.com/sky0621/tips-go/try/xerrors/after2/util"
	"golang.org/x/xerrors"
)

func Exec() error {
	e := xerrors.New("unexpected error occurred")
	return util.Log(e)
}

util/log.go

package util

import "golang.org/x/xerrors"

func Log(org error) error {
	if org == nil {
		return nil
	}
	return xerrors.Errorf("[Log] error occurred: %w", org)
}

まとめ

「いや、こんな誤り、しないでしょ？」と思うかもしれないけど、、、実際、やっちゃってるんだよなぁ。。。
早く直したい。