お題
Go 1.13 で %w
によるログのラップが可能になった。
が、その方式でログ出力すると(エラー時の)スタックトレースが吐けない。
ので、スタックトレース吐くために xerrorsパッケージが用意されている。
これで、エラー時にスタックトレース付きでログが吐ける。
といった話は、既にたくさん記事があるので、このxerrors
パッケージをこうやって間違って使ってしまったという事例を2つほど。
開発環境
# 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
ソース群
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)
}
}
その他のソース
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
}
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
}
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
}
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
ソース群
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))
}
}
その他のソース
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
}
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
}
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
}
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
ソース群
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)
}
}
その他のソース
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
}
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
}
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
}
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の誤った使い方事例1
エラーをラップしつつ呼び出し元に返していったログを最終的に出力する箇所で、"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
ソース群
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
を呼んでるんだけど、これ、やっちゃダメみたい。
その他のソース
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
}
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
}
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
}
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の誤った使い方事例2
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
ソース群
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)
}
}
その他のソース
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
}
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
}
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
}
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)
}
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)
}
まとめ
「いや、こんな誤り、しないでしょ?」と思うかもしれないけど、、、実際、やっちゃってるんだよなぁ。。。
早く直したい。