GAE/Goで書いたアプリのテストが何故か固まるのでgo testのコードをチラ見した話
この記事はGo2 Advent Calendar 2017の8日目の記事です。
とある日、GAE/Goで書いたアプリのテストがなぜか途中で固まり、強制終了しないと戻ってこない現象に遭遇しました。
今回の記事は、その調査と原因をまとめたものです。
tl;dr
Goのテストはパッケージ毎に並列で動き、すべての終了を待機する。
テストプロセスの子プロセスがpanicするとそのテストは終了を検知できない。
テスト、一生おわらない!
解決策はみつけられませんでした。
実行環境
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)) } //... 略 ...
ちなみにここでいう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 packageのM.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
つまり、
- テストメソッド(Test_Foo)は、実はTestMainと異なるgoroutineで動いてた
- 異なる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してると想定する妥協もありなのかなーと思ってます。
何か良い案あれば教えてください。
参考
Clean Architectureについて
Google App Engine / Goで作っている個人プロジェクトにClean Architectureを適用してみた中で思ったことのメモです。
この記事ではClean ArchitectureとDIPとDIについて書いてます。
いわゆるDDDは意識してません。あくまでレイヤーについての感想です。
Clean Architecture とは
いくつかあるレイヤードアーキテクチャのうちのひとつです。
目的は関心の分離で、関心の分離をすると何が嬉しいかというと、のちの設計理解や維持管理が楽になることです。
図のように4層の円で構成されていて、それぞれ異なる役割(関心事)を表しています。
外側にいくほど実装の詳細を表現し、内側にいくほど抽象を表現します。
ちなみに層は4つのみという決まりはなく、必要であれば増やしても良いです。
依存関係は、外側から内側への一方向になります。
これは必ず従うべきルールで、内側から外側のコードを直接呼び出したらダメです。
依存関係は大事で、ここをしっかり押さえないとたぶん何を選択してもダメです。
以下、各層について私の解釈です。
External Interfaces
技術の詳細を担当します。
例えば、データの永続化にMySQLを使うのかSQLiteを使うのか、技術的な選択を内側の層で意識しなくて良いように薄くラッピングします。
ここにはロジックを書きません。
Interface Adapters
外側の層と内側の層をうまく取り持つ役割を担当します。
例えば、HTTPリクエストを受け取るControllerは、受け取ったHTTPリクエストを内層で扱える形に変換して渡す役目です。
基本それ以上のことはしません。
よく言われていることですが、仮にHTTPリクエストを内層(Use Cases)にそのまま渡すと、そのUse Casesは外界に依存することになり、依存関係は一方向というルールに反します。
使い回しという側面もありますが、そもそもの依存関係が破綻しているのでもうダメです。
Use Cases
ロジックの取りまとめとトランザクション管理を担当します。
繰り返しになりますが、WebやCommandなど外層の世界に依存しないように注意します。
1ファイルにつき1つの振る舞いを書くと見通しがよくて個人的に好みです。
Entities
技術的な関心から離れたロジックを担当します。
このロジックは、use case(用途)に限定しない一般的なものと解釈してます。
どこにも依存しない孤高の存在です。
依存関係逆転の原則(DIP)について
Clean Architectureを適用するにあたって、DIPの原則に従います。
(解説) 上位のモジュールは下位のモジュールに依存してはならない。 どちらのモジュールも「抽象」に依存すべきである。
雑にまとめると、interface(抽象)を用意して、処理の呼び出しをinterface経由にすると、実装の差し替えとか簡単になって便利!というものです。
内層から外層のコードを呼び出すときは、interfaceを経由します。
作用として、テストが書きやすくなり、DIと合わせることでcycle importsの解消にも役立ちます。
interfaceの置き場には議論の余地がありますが、私はEntities層に置くことが多いです。
依存性の注入(DI)について
コンストラクタやセッターメソッドでinterfaceを引数に取り、外部から実装を渡すパターンです。
実装の差し替えが簡単になり、融通の効くソースコードになります。
Use Cases層でよく使ってます
まとめ
大体Clean Architecture 翻訳と言ってることは同じ(でも自分の言葉にしておきたい)。
Clean Architectureは図が分かりやすくて、ソースコードに落とし込みやすい。
interfaceとDIを半ば強制されるので、自然とテストが書きやすいコードになる。
依存関係と合わせて単一責務の原則を守れば、酷いコードになりにくい。
コード量は増える。
続く。
Signing commits with GPG をした
GitHub のヘルプ を参考に設定した。
プログラミング初心者な人に .gitconfig の設定を参考にしてもらおうと雑に渡したら user.name と email をそのまま使われてしまって、成りすましのようになってしまったことが発端。
どう防ぐのかいいか少し悩んだけど、僕の方で署名しておくのが妥当かなと思い至った。
設定したので Verified マークがついた図。
設定メモ
gpg コマンドインストール
$ brew install gpg
GPG key を作成
日本語だと文字化けして何を言ってるんだお前は状態になったので、英語指定してる。
$ LANG=en_US.utf-8 gpg --full-gen-key $ gpg --list-secret-keys --keyid-format LONG Users/utahta/.gnupg/pubring.kbx -------------------------------- sec rsa4096/<サインキー> 2017-11-09 [SC] [有効期限: 2019-11-07] ... 略 ... $ gpg --armor --export <サインキー> | pbcopy
コピーした GPG key を GitHub アカウントに追加
https://github.com/settings/keys
GPG Key ID を .gitconfig に追加
家と仕事場でキーを変えてみようと思い、.gitconfig.local に設定して include するようにした。
$ vi ~/.gitconfig.local [user] signingkey = <サインキー>
共用したければ export & import すれば良い。
$ gpg -o secret.key --export-secret-key <メールアドレス> ... 持ち運び ... $ gpg --import secret.key
その他細かい設定
必要だったので追加した(ちゃんと調べてない)。
$ vi ~/.zshrc export GPG_TTY=$(tty)
毎回 git commit -S したくない場合。
$ vi ~/.gitconfig [commit] gpgsign = true
ちなみに
GPG Key 作成時に、自分の GitHub アカウントで認証していないメールアドレスを使うと Unverified になる。
全ての commit に署名をつけるのは悪手という話もみたけど、今回の意図とはそぐわないのでみなかったことにした。