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))
}
//... 略 ...

(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)

Clean Architectureについて

Google App Engine / Goで作っている個人プロジェクトにClean Architectureを適用してみた中で思ったことのメモです。
この記事ではClean ArchitectureとDIPとDIについて書いてます。
いわゆるDDDは意識してません。あくまでレイヤーについての感想です。

Clean Architecture とは

いくつかあるレイヤードアーキテクチャのうちのひとつです。
目的は関心の分離で、関心の分離をすると何が嬉しいかというと、のちの設計理解や維持管理が楽になることです。

f:id:utahta:20171129102106j:plain

図のように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 マークがついた図。 f:id:utahta:20171109235723p:plain

設定メモ

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 になる。
f:id:utahta:20171110011130p:plain

全ての commit に署名をつけるのは悪手という話もみたけど、今回の意図とはそぐわないのでみなかったことにした。