GAE/Goで書いたアプリのテストが何故か固まるのでgo testのコードをチラ見した話

この記事はGo2 Advent Calendar 2017の8日目の記事です。

とある日、GAE/Goで書いたアプリのテストがなぜか途中で固まり、強制終了しないと戻ってこない現象に遭遇しました。
今回の記事は、その調査と原因をまとめたものです。

実行環境

macOS Sierra 10.12.6
$ gcloud version
Google Cloud SDK 180.0.1
app-engine-go
app-engine-python 1.9.63
$ goapp version
go version 1.8.3 (appengine-1.9.63) darwin/amd64

再現コード

https://github.com/utahta/go-test-hangs-sample

問題

App Engine Testインスタンスを使用したテストの最中にpanicすると起こります。
単にApp Engine Testインスタンスを使うだけではダメで、次のようにTestMainを使ってApp Engine Testインスタンスを使いまわしているときに起こります。

var inst aetest.Instance

func TestMain(m *testing.M) {
    os.Exit(run(m))
}
//... 略 ...

(TestMainについて)

ちなみにここでいうApp Engine Testインスタンスとは、Google App Engineのローカル開発サーバ(google-cloud-sdk/platform/google_appengine/dev_appserver.py)を指します。
aetest.NewInstance(nil)と書くと、内部でdev_appserver.pyが子プロセスとして起動します。

調査

テストが固まった後、試しにpsコマンドを打ってみると、dev_appserver.pyが生き残っていることに気付きました。
このプロセスはTestMainで立ち上げたものですが、deferを使ってcloseするように書いているので、生き残ってしまっているのは不思議です。
試しにdeferが呼ばれているかログを仕込んでみると、どうも呼ばれている気配がありません。
よく分からないのでgo testのソースコードを読んでみることにしました。

TestMain

現在Goの最新バージョンは1.9.2ですが、GAE/Goで使用されているバージョンは1.8.3なので、そちらのバージョンをみていきます。

testing packageM.Run()がTestMainの実行箇所です。

// Run runs the tests. It returns an exit code to pass to os.Exit.
func (m *M) Run() int {
    // TestMain may have already called flag.Parse.
    if !flag.Parsed() {
        flag.Parse()
    }
//... 略 ...

その中でrunTestsが呼ばれ、さらにt.Run()が呼ばれることで、各テストが実行されていきます。

func runTests(matchString func(pat, str string) (bool, error), tests []InternalTest) (ran, ok bool) {
    //... 略 ...
    for _, test := range tests {
        t.Run(test.Name, test.F)
    }
    //... 略 ... 

t.Run()の中をみるとgo tRunner(t, f)と書かれていて、テストメソッドが別のgoroutineで動いてることが分かります。

// Run runs f as a subtest of t called name. It reports whether f succeeded.
// Run will block until all its parallel subtests have completed.
//
// Run may be called simultaneously from multiple goroutines, but all such
// calls must happen before the outer test function for t returns.
func (t *T) Run(name string, f func(t *T)) bool {
    //... 略 ...
    go tRunner(t, f)
    //... 略 ...

原因

deferは、同一goroutineでpanicした場合は呼ばれますが、異なるgoroutineでpanicした場合に呼ばれません。
呼ばれないサンプルコード
Defer is not run if another goroutine panics #14542

つまり、

  1. テストメソッド(Test_Foo)は、実はTestMainと異なるgoroutineで動いてた
  2. 異なるgoroutine(Test_Foo)でpanicしてたため、TestMainのdeferは呼ばれなかった。

そして終了処理が適切に実行されず、dev_appserver.pyが生き残ってしまっていたのでした。
(dev_appserver.pyは、親プロセスがpanicでお亡くなりになったので、/sbin/launchdの養子になりました)

つらい...。

調査2

TestMainのdeferが呼ばれない原因は分かりました。
しかし、テストが固まる原因はまだ謎です。

引き続き調べていると、次のようにテストを実行するとうまくいくことに気付きました。

$ goapp test -v -p 1 ./...

テストは、複数のパッケージを指定すると、CPUのコア数に応じて、パッケージ毎にパラレルに実行されます。
前述のオプション-p 1を指定することで、シリアルに実行できます。詳細は次のとおりです。

 -p n
        the number of programs, such as build commands or
        test binaries, that can be run in parallel.
        The default is the number of CPUs available.

シリアルに実行して動くということは、パラレルに実行するときの何かしらに問題が潜んでいそうです。
よく分からないのでgo testのソースコードをもう少し読んでみることにしました。

go test

go testのソースコードはここにあります。
ここで渡されているrunTestが開始地点のようです。

// Break init loop.
func init() {
    cmdTest.Run = runTest
}
//... 略 ...
func runTest(cmd *Command, args []string) {

諸々と中身を見て、testStreamOutputがあやしいと目星をつけました。

   testStreamOutput = len(pkgArgs) == 0 || testBench ||
        (testShowPass && (len(pkgs) == 1 || buildP == 1))

このフラグは、テストを実行したときの出力をバッファリングするかどうか決めるものです。
シリアル実行の場合、trueになりos.Stdout, os.Stderrに出力します。
パラレル実行の場合、falseになりバッファリングします。

   var buf bytes.Buffer
    if testStreamOutput {
        cmd.Stdout = os.Stdout
        cmd.Stderr = os.Stderr
    } else {
        cmd.Stdout = &buf
        cmd.Stderr = &buf
    }

テストは次のような子プロセスで実行されます。

/var/folders/r6/06c734bj1zxcrx7wm_nzfccm0000gn/T/go-build580566412/github.com/utahta/go-test-hangs-sample/bar/_test/bar.test -test.v=true
/var/folders/r6/06c734bj1zxcrx7wm_nzfccm0000gn/T/go-build941332729/github.com/utahta/go-test-hangs-sample/foo/_test/foo.test -test.v=true

runTestは、この子プロセスを作るためにCmd.Startを実行します。
その際、必要であれば子プロセスとつながるパイプを作ります。

os.Stdout, os.Stderrに出力する場合は、作りません
バッファリングする場合は、作ります
(os/execパッケージの処理)

func (c *Cmd) stdout() (f *os.File, err error) {
    return c.writerDescriptor(c.Stdout)
}
//... 略 ...
func (c *Cmd) writerDescriptor(w io.Writer) (f *os.File, err error) {
    //... 略 ...

    // os.Stdoutの場合、ここでリターン
    if f, ok := w.(*os.File); ok {
        return f, nil
    }

    // bytes.Bufferの場合、ここにくる
    pr, pw, err := os.Pipe()
    if err != nil {
        return
    }
    //... 略 ...
    c.goroutine = append(c.goroutine, func() error {
        _, err := io.Copy(w, pr) // 読み取り続ける
        pr.Close() // in case io.Copy stopped due to write error
        return err
    })
    return pw, nil
}

子プロセスとつながるパイプを作ると、その読み取り完了を待つようになります。

func (c *Cmd) Wait() error {
    //... 略 ...
    var copyError error
    for range c.goroutine {
        if err := <-c.errch; err != nil && copyError == nil {
            copyError = err
        }
    }
    // ... 略 ...
    return copyError
}

確認

App Engine Testインスタンス(dev_appserver.py)もfoo.testの子プロセスで動きパイプでつながります。
その様子をpstreeやlsofを使って確認してみます。

$ pstree
... 略 ...
-+= 01279 utahta -zsh
 | | \-+= 10526 utahta /Users/utahta/opt/google-cloud-sdk/platform/google_appengine/goroot-1.8/bin/goapp test -v ./bar ./foo
 | |   \-+- 10587 utahta /var/folders/r6/06c734bj1zxcrx7wm_nzfccm0000gn/T/go-build174524749/github.com/utahta/go-test-hangs-sample/foo/_test/foo.test -test.v=true
 | |     \--- 10588 utahta /usr/local/Cellar/python/2.7.14/Frameworks/Python.framework/Versions/2.7/Resources/Python.app/Contents/MacOS/Python /Users/utahta/opt/google-cloud-sdk/platform/google_appengine/dev_appserver.py --port=0 --api_port=0 --admin_port=0 --automatic
... 略 ...

$ lsof -p 10526
COMMAND   PID   USER   FD   TYPE             DEVICE SIZE/OFF     NODE NAME
goapp   10526 utahta  cwd    DIR                1,4      442 18270226 /Users/utahta/.go/src/github.com/utahta/go-test-hangs-sample
goapp   10526 utahta  txt    REG                1,4  9996912 18304598 /Users/utahta/opt/google-cloud-sdk/platform/google_appengine/goroot-1.8/bin/goapp
goapp   10526 utahta  txt    REG                1,4   698896 16752810 /usr/lib/dyld
goapp   10526 utahta    0u   CHR               16,3  0t65950      727 /dev/ttys003
goapp   10526 utahta    1u   CHR               16,3  0t65950      727 /dev/ttys003
goapp   10526 utahta    2u   CHR               16,3  0t65950      727 /dev/ttys003
goapp   10526 utahta    4   PIPE 0xfb6bae1f3bd0eedd    16384          ->0xfb6bae1f3bd0ee1d

$ lsof -p 10587
COMMAND    PID   USER   FD   TYPE             DEVICE SIZE/OFF     NODE NAME
foo.test 10587 utahta  cwd    DIR                1,4      102 18270294 /Users/utahta/.go/src/github.com/utahta/go-test-hangs-sample/foo
foo.test 10587 utahta  txt    REG                1,4  5431552 18462168 /private/var/folders/r6/06c734bj1zxcrx7wm_nzfccm0000gn/T/go-build174524749/github.com/utahta/go-test-hangs-sample/foo/_test/foo.test
foo.test 10587 utahta  txt    REG                1,4   698896 16752810 /usr/lib/dyld
foo.test 10587 utahta    0r   CHR                3,2      0t0      304 /dev/null
foo.test 10587 utahta    1   PIPE 0xfb6bae1f3bd0ee1d    16384          ->0xfb6bae1f3bd0eedd
foo.test 10587 utahta    2   PIPE 0xfb6bae1f3bd0ee1d    16384          ->0xfb6bae1f3bd0eedd
foo.test 10587 utahta    3   PIPE 0xfb6bae1f3bd0c35d    16384          ->0xfb6bae1f3bd0c89d

$ lsof -p 10588
COMMAND   PID   USER   FD    TYPE             DEVICE  SIZE/OFF     NODE NAME
Python  10588 utahta  cwd     DIR                1,4       102 18270294 /Users/utahta/.go/src/github.com/utahta/go-test-hangs-sample/foo
... 略 ...
Python  10588 utahta    0r    CHR                3,2       0t0      304 /dev/null
Python  10588 utahta    1    PIPE 0xfb6bae1f3bd0ee1d     16384          ->0xfb6bae1f3bd0eedd
Python  10588 utahta    2    PIPE 0xfb6bae1f3bd0c89d     16384          ->0xfb6bae1f3bd0c35d
... 略 ...

0xfb6bae1f3bd0eeddと0xfb6bae1f3bd0ee1dでつながっていることがそれとなく分かります。

原因

go testは、子プロセス(foo.test, dev_appserver.py)の終了を待機します。
バッファリングが有効になると、パイプが閉じるまで待機します。
しかし、前述のとおりテスト中にpanicして終了処理が実行されないと、dev_appserver.pyはいつまで経っても終わりません。
その結果、go testは待機し続けることになり、テストが固まってみえるようでした。

一応、何の解決にもなりませんが、dev_appserver.pyをkillしてあげると、固まったテストが動きます。

解決策...

App Engine Testインスタンスの使い回しをやめると、手っ取り早く解決します。
しかし、そもそもインスタンスの起動が遅いから使いまわしていたわけで、、😂

Test_Caseで発生したpanicをうまいことTestMainまで伝搬してあげる仕組みがあると良いのかもしれません。

もしくはテストが固まる現象を受け入れて、固まったときはpanicしてると想定する妥協もありなのかなーと思ってます。

何か良い案あれば教えてください。

参考

Go言語で知るプロセス(2)