Zenn
🧰

t.Cleanupでpanicした場合の挙動（runtime.Goexitでpanicキャンセリング？）

2022/10/04に公開
Go
Go
Test
tech

testing.TBインターフェースを実装していて気づいたのでメモ。

t.Cleanup中のpanicはテストを失敗させる

次のコードのように、t.Cleanupでセットした関数がpanicするとテストが失敗します。

func TestPanicOnCleanup(t *testing.T) {
	t.Cleanup(func() {
		panic("panic on cleanup")
	})
}
結果
$ go test .
--- FAIL: TestPanicOnCleanup (0.00s)
panic: panic on cleanup [recovered]
	panic: panic on cleanup

goroutine 18 [running]:
testing.tRunner.func1.2({0x503120, 0x551c00})
	/usr/local/go/src/testing/testing.go:1396 +0x24e
testing.tRunner.func1()
	/usr/local/go/src/testing/testing.go:1399 +0x39f
panic({0x503120, 0x551c00})
	/usr/local/go/src/runtime/panic.go:884 +0x212
test.TestPanicOnCleanup.func1()
	/go/panic/panic_test.go:8 +0x27
testing.(*common).Cleanup.func1()
	/usr/local/go/src/testing/testing.go:1041 +0x11f
testing.(*common).runCleanup(0xc000082b60, 0x52f5d8?)
	/usr/local/go/src/testing/testing.go:1210 +0x95
testing.tRunner.func2()
	/usr/local/go/src/testing/testing.go:1440 +0x29
testing.tRunner(0xc000082b60, 0x52f5e0)
	/usr/local/go/src/testing/testing.go:1452 +0x135
created by testing.(*T).Run
	/usr/local/go/src/testing/testing.go:1493 +0x35f
FAIL	test	0.004s
FAIL

ではt.Cleanupを追加してテストをスキップさせてみます。

func TestPanicOnCleanup(t *testing.T) {
        t.Cleanup(func() {
                panic("panic on cleanup")
        })
        t.Cleanup(func() {
                t.SkipNow()
        })
}

結果は先ほどと変わらず、panicが原因でテストが失敗します。

結果
$ go test .
--- FAIL: TestPanicOnCleanup (0.00s)
panic: panic on cleanup [recovered]
	panic: panic on cleanup

ここからが本題

では2つのt.Cleanupの順序を変えてみるとどうなるでしょうか。

func TestPanicOnCleanup(t *testing.T) {
        t.Cleanup(func() {
                t.SkipNow()
        })
        t.Cleanup(func() {
                panic("panic on cleanup")
        })
}

気になる結果は…

結果
$ go test . -v
=== RUN   TestPanicOnCleanup
--- SKIP: TestPanicOnCleanup (0.00s)
PASS
ok  	test	0.002s

なんと（スキップに）成功してしまいました。
panicの前にt.Logを入れると、panicする関数も確かにコールされていることがわかります（t.Cleanupはdeferと同様LIFOで処理されるので、t.SkipNowに先行してpanicします）。

なぜpanicが消えたか

t.FailNowやt.SkipNowでは、テスト失敗/スキップのフラグをセットしたあとにruntime.Goexitをコールします。runtime.Goexitはコールした時点で関数の処理を中断し、それまでにdeferでセットされた関数を実行したあとにgoroutineを停止させます。これによってテストコードを中断させることができるわけですね。

今回の現象を理解するにはt.Cleanupでセットされた関数がどのようにコールされるのかも見た方が良いのですがそこは飛ばしてしまいます。

今回起こったことは、以下のコードで再現させることができます。

panicで失敗したケース　
func main() {
	go func() {
		defer func() {
			panic("oops")
		}()
		runtime.Goexit()
	}()
	time.Sleep(time.Second)
}
スキップに成功したケース
func main() {
	go func() {
		defer func() {
			runtime.Goexit()
		}()
		panic("oops")
	}()
	time.Sleep(time.Second)
}

main関数のgoroutineでruntime.Goexitするとエラー終了するので新しいgoroutineをつくり、また先にmain関数を抜けてしまうとどちらもエラーにならないのでスリープを入れています。

前者と後者ではpanicとruntime.Goexitの順番？が異なり、前者はpanicしてエラー終了しますが後者はエラーが発生しません。

panicするとスタックを遡り、gorountineのなかで最後までrecoverされなかった場合にプログラムがエラー終了します。先ほど確認したように、スタックを遡っていくのはruntime.Goexitも同様です。
どうやら、遡っていく道中で panicとruntime.Goexitのどちらが最後にコールされたかで結果が変わるようです。

試しに前者のエラー終了したコードに以下のようにコードを加えてみると、エラーが発生しなくなりました。

*部分を追加　
func main() {
	go func() {
		defer func() {
			defer func() { runtime.Goexit() }() // *
			panic("oops")
		}()
		runtime.Goexit()
	}()
	time.Sleep(time.Second)
}

🤔🤔🤔

今回の発見が何かに応用できるかというとすぐには思いつきませんが、goroutineの操作テクニックの一つとして覚えておくといつかいいことがあるかもしれません。

t.Cleanupは途中でt.FailNowしてもpanicしても全て実行してくれて宣言的に書けるのが良いところだと思っていますが、順番でテストの結果が変わるのは…ちょっと微妙かもしれません。
まあでも、t.Cleanupした関数の中でt.FailNowやt.SkipNowする場合なんてほとんどなさそうではあります。

Discussion