goのerrors.As()でpanicしちゃう話
ドキュメントに書いてあることだけど、渡し方をミスるとerrors.As()はpanicしてしまう。
As panics if target is not a non-nil pointer to either a type that implements error, or to any interface type.
errors.As()の使い方
その前に errors.As()の使い方のおさらい。
errors.As() はエラー値の基底が第二引数で渡された形状の型だったときにtrueを返す関数1。
例えばexampleの例のコードはこんな感じ。
package main import ( "errors" "fmt" "os" ) func main() { if _, err := os.Open("non-existing"); err != nil { var pathError *os.PathError if errors.As(err, &pathError) { fmt.Println("Failed at path:", pathError.Path) } else { fmt.Println(err) } } }
結果。os.PathErrorの方に分岐されている。
Failed at path: non-existing
使いみち
pkg/errors.Cause() や errors.Is() ではエラー値の基底が対象の値かどうかの一致を見るチェックになってしまう。Asは型かどうか(interfaceかどうか)。ポインターで変数を初期化してそれに参照でbindするので結構ユニークな（あまり見慣れない）使い方かもしれない。
ng例
こういうエラーメッセージになる。注意深く見ていけば気付けるがたまに見落とす。見落としたときは実行時エラーになるので辛い。
panic: errors: *target must be interface or implement error
goroutine 1 [running]:
errors.As(0x10ec580, 0xc000104180, 0x10b6180, 0xc0001041b0, 0x0)
/opt/local/lib/go/src/errors/wrap.go:87 +0x513
main.main()
CWD/01errors-as-ng/main.go:12 +0xc5
exit status 2
この様なpanicになるのは以下の様なとき2。
--- 00errors-as-ok/main.go 2020-09-09 14:35:45.000000000 +0900 +++ 01errors-as-ng/main.go 2020-09-09 14:19:36.000000000 +0900 @@ -8,7 +8,7 @@ func main() { if _, err := os.Open("non-existing"); err != nil { - var pathError *os.PathError + var pathError os.PathError if errors.As(err, &pathError) { fmt.Println("Failed at path:", pathError.Path) } else {
--- 00errors-as-ok/main.go 2020-09-09 14:35:45.000000000 +0900 +++ 02errors-as-ng/main.go 2020-09-09 14:25:28.000000000 +0900 @@ -9,7 +9,7 @@ func main() { if _, err := os.Open("non-existing"); err != nil { var pathError *os.PathError - if errors.As(err, &pathError) { + if errors.As(err, pathError) { fmt.Println("Failed at path:", pathError.Path) } else { fmt.Println(err)
実行時エラーなので厳しい。この種のpanicの何が嫌かといえば、滅多にないエラーハンドリングに対する初回のログの失われが起きうること。
interfaceを期待したい場合
丁寧に考えればわかることではあるけれど。interface自体は最初から参照を持つのでinterfaceとして受け取りたい場合には以下の様になる。
--- 00errors-as-ok/main.go 2020-09-09 14:35:45.000000000 +0900 +++ 04errors-as-ok/main.go 2020-09-09 14:35:28.000000000 +0900 @@ -6,11 +6,15 @@ "os" ) +type hasTimeout interface { + Timeout() bool +} + func main() { if _, err := os.Open("non-existing"); err != nil { - var pathError *os.PathError + var pathError hasTimeout if errors.As(err, &pathError) { - fmt.Println("Failed at path:", pathError.Path) + fmt.Println("Failed at path:", pathError, "!!", pathError.Timeout()) } else { fmt.Println(err) }
結果
Failed at path: open non-existing: no such file or directory !! false
もちろん参照を渡していない場合にはエラーになりますね(この逆はbuild時にコンパイルエラーになってくれる)。
--- 04errors-as-ok/main.go 2020-09-09 14:48:45.000000000 +0900 +++ 05errors-as-ng/main.go 2020-09-09 14:48:44.000000000 +0900 @@ -13,7 +13,7 @@ func main() { if _, err := os.Open("non-existing"); err != nil { var pathError hasTimeout - if errors.As(err, &pathError) { + if errors.As(err, pathError) { fmt.Println("Failed at path:", pathError, "!!", pathError.Timeout()) } else { fmt.Println(err)
こういうエラー。
panic: errors: target cannot be nil
goroutine 1 [running]:
errors.As(0x10ec5a0, 0xc000090180, 0x0, 0x0, 0x0)
/opt/local/lib/go/src/errors/wrap.go:79 +0x5d4
main.main()
CWD/05errors-as-ng/main.go:16 +0x98
exit status 2
おわり
エラーハンドリングで実行時エラーはかなりかなしいので、linterか何かが欲しいですね。
ちなみに環境は以下
$ go version go version go1.15.1 darwin/amd64
追記
go vetでチェックしてくれそう。
$ go vet ./01errors-as-ng/ 01errors-as-ng/main.go:12:6: second argument to errors.As must be a non-nil pointer to either a type that implements error, or to any interface type
- 実装はここ https://github.com/golang/tools/blob/master/go/analysis/passes/errorsas/errorsas.go
- go test時にチェックしてくれーというissue https://github.com/golang/go/issues/31213
追記
場合によっては、pkg/errorsのAs()が使われることがある。このようなときに go vet はチェックしてくれない。そんなわけで pkg/errors と併存したコード上でCIを突き抜けての実行時panicが起きうるみたい。
go testのtest.testlogfileフラグが時々便利
test.testlogfileを付けてテストを実行すると、テスト中の以下が分かる。
- os.Stat()したファイル
- os.Open()したファイル
- os.Getenvした環境変数
これは、例えば、net/http.FileSystemが使われた様なテストなどで苦しめられたときに便利に働くことがある。
例
例えば、hello_test.goと以下のようなファイルがあったとして。
. ├── hello_test.go ├── testdata │ └── hello.json └── x.log 1 directory, 3 files
おもむろに以下の様な形でテストを実行してみる。
$ go test -v -test.testlogfile=x.log === RUN TestIt --- PASS: TestIt (0.01s) PASS ok github.com/podhmo/individual-sandbox/daily/20200821/example_go/04file 0.016s
このとき、-test.testlogfileに渡したx.logを覗いてみると以下の様な行が書かれている。
# test log open testdata/hello.json open /etc/mime.types open /etc/apache2/mime.types open /etc/apache/mime.types
testdata/hello.json。。
そうそう、今回のテストではtestdataの中に書かれたhello.jsonを読み込む様なコードを書いていた。
実際のテストコード
ざっくり説明すると、以下の様な感じのテストコード。
GET /helloにアクセスするHello()というメソッドを持ったClient- testdataを見て、
/helloに対してtestdata/hello.jsonを見る様なHandler - net/http.HandlerからRoundTripperをTransportに指定するfake
- (実は、クライアントライブラリのテストにhttptest.Serverではなくhttptest.Recorderも使えるというコード例だったりもする)
package main import ( "bytes" "fmt" "io" "net/http" "net/http/httptest" "strings" "testing" "time" ) type Client struct { BaseURL string HTTPClient *http.Client } func (c *Client) Hello() (*http.Response, error) { hc := c.HTTPClient if hc == nil { hc = http.DefaultClient } return hc.Get(strings.TrimSuffix(c.BaseURL, "/") + "/hello") } type HandlerRoundTripper struct { Before func(*http.Request) Handler http.Handler After func(*http.Response, *http.Request) } func (t *HandlerRoundTripper) RoundTrip(r *http.Request) (*http.Response, error) { if t.Before != nil { t.Before(r) } w := httptest.NewRecorder() t.Handler.ServeHTTP(w, r) res := w.Result() if t.After != nil { t.After(res, r) } return res, nil } func TestIt(t *testing.T) { c := &Client{ HTTPClient: &http.Client{ Timeout: 100 * time.Millisecond, Transport: &HandlerRoundTripper{ Before: func(r *http.Request) { // /hello -> testdata/hello.json r.URL.Path = fmt.Sprintf("%s.json", strings.TrimSuffix(r.URL.Path, "/")) }, Handler: http.FileServer(http.Dir("testdata")), }, }, } res, err := c.Hello() if err != nil { t.Fatal(err) } defer res.Body.Close() var b bytes.Buffer io.Copy(&b, res.Body) if res.StatusCode != 200 { t.Errorf("unexpected: %s", res.Status) } if strings.TrimSpace(b.String()) != strings.TrimSpace(`{"message": "hello"}`) { t.Errorf("unmatch: %s", b.String()) } }
はい。
実際の実装
testing/testing.goを覗くと以下の様な記述がある。
testlog = flag.String("test.testlogfile", "", "write test action log to `file` (for use only by cmd/go)")
ここでtestlogというフラグをonにしている1。
これがonになると、testing.MのRun()の中のbefore()で、m.deps.StartTestLog(f)が呼ばれる。
// before runs before all testing. func (m *M) before() { // ... (ちなみにここでcpuprofileやmemprofileの設定などをしていたりする) if *testlog != "" { // Note: Not using toOutputDir. // This file is for use by cmd/go, not users. var f *os.File var err error if m.numRun == 1 { f, err = os.Create(*testlog) } else { f, err = os.OpenFile(*testlog, os.O_WRONLY, 0) if err == nil { f.Seek(0, io.SeekEnd) } } if err != nil { fmt.Fprintf(os.Stderr, "testing: %s\n", err) os.Exit(2) } m.deps.StartTestLog(f) // <- これ testlogFile = f }
それでは m.deps というものは何者かと言うと、こういうinterface。コメントに書いてある通り、go testで生成されるコードのmainパッケージの中でimportされる。
// testDeps is an internal interface of functionality that is // passed into this package by a test's generated main package. // The canonical implementation of this interface is // testing/internal/testdeps's TestDeps. type testDeps interface { ImportPath() string MatchString(pat, str string) (bool, error) StartCPUProfile(io.Writer) error StopCPUProfile() StartTestLog(io.Writer) StopTestLog() error WriteProfileTo(string, io.Writer, int) error }
testing/internal/testdepsを覗いてみる。それっぽいhookが定義されてきつつありますね。
// testLog implements testlog.Interface, logging actions by package os. type testLog struct { mu sync.Mutex w *bufio.Writer set bool } func (l *testLog) Getenv(key string) { l.add("getenv", key) } func (l *testLog) Open(name string) { l.add("open", name) } func (l *testLog) Stat(name string) { l.add("stat", name) } func (l *testLog) Chdir(name string) { l.add("chdir", name) }
ここでおもむろにos.Stat()あたりの実装を覗いてみましょう。
os/stat.go
import "internal/testlog" // Stat returns a FileInfo describing the named file. // If there is an error, it will be of type *PathError. func Stat(name string) (FileInfo, error) { testlog.Stat(name) return statNolog(name) }
そして internal/testlog/log.go
// logger is the current logger Interface. // We use an atomic.Value in case test startup // is racing with goroutines started during init. // That must not cause a race detector failure, // although it will still result in limited visibility // into exactly what those goroutines do. var logger atomic.Value // SetLogger sets the test logger implementation for the current process. // It must be called only once, at process startup. func SetLogger(impl Interface) { if logger.Load() != nil { panic("testlog: SetLogger must be called only once") } logger.Store(&impl) } // Stat calls Logger().Stat, if a logger has been set. func Stat(name string) { if log := Logger(); log != nil { log.Stat(name) } }
あらためて、testing/internal/testdeps/deps.goを
package testdeps import ( "bufio" "internal/testlog" "io" "regexp" "runtime/pprof" "strings" "sync" ) ... var log testLog func (TestDeps) StartTestLog(w io.Writer) { log.mu.Lock() log.w = bufio.NewWriter(w) if !log.set { // Tests that define TestMain and then run m.Run multiple times // will call StartTestLog/StopTestLog multiple times. // Checking log.set avoids calling testlog.SetLogger multiple times // (which will panic) and also avoids writing the header multiple times. log.set = true testlog.SetLogger(&log) // <- これ! log.w.WriteString("# test log\n") // known to cmd/go/internal/test/test.go } log.mu.Unlock() }
はい。つまりそういうわけでした。おしまい。
gist
-
go testの実行のされ方を追いかけてみると意外と参考になる部分があったりするのでおすすめ。injectされるコード自体は https://github.com/golang/go/blob/master/src/cmd/go/internal/load/test.go あたりにあります。injectするコードはもちろん
go testに関連がある https://github.com/golang/go/blob/master/src/cmd/go/internal/test/test.go あたりですね。↩
