aetestがめちゃ遅いのでどうにかしたかった話

aetestとは

https://cloud.google.com/appengine/docs/standard/go/tools/localunittesting/reference?hl=ja
GAE/Go用のローカルテストのためのパッケージです。
GAEも第2世代へ移り変わり最早今後は新規に使われることもそう無いであろうパッケージですが供養として過去の苦労を記しておきたいと思います。

以下はGAEのテストサンプルコードです。aetestはテスト実行時にGAE特有の機能をローカルで利用する際のサーバーを立ち上げてくれます。そのサーバーの情報を含んだcontextを利用することでテストが可能になります。

サンプルコードではGAEのMemcacheの機能を利用しています。

main_test.go

package main

import (
	"google.golang.org/appengine"
	"google.golang.org/appengine/aetest"
	"google.golang.org/appengine/memcache"
	"testing"
)

func TestAeTest(t *testing.T) {
	inst, err := aetest.NewInstance(nil)
	if err != nil {
		t.Fatal(err)
	}
	defer inst.Close()

	req, err := inst.NewRequest("GET", "/", nil)

	ctx := appengine.NewContext(req)

	it := &memcache.Item{
		Key:   "some-key",
		Value: []byte("some-value"),
	}
	err = memcache.Set(ctx, it)
	if err != nil {
		t.Fatalf("Set err: %v", err)
	}
	it, err = memcache.Get(ctx, "some-key")
	if err != nil {
		t.Fatalf("Get err: %v; want no error", err)
	}
	if g, w := string(it.Value), "some-value" ; g != w {
		t.Errorf("retrieved Item.Value = %q, want %q", g, w)
	}
}

aetest.NewInstance() の中で何が行われているかというと、簡素なGAEアプリケーション設定を一時領域に作っています。

設定は内部に定義されており、GAE/goのアプリケーションとして最低限の設定で起動されています。

const appYAMLTemplate = `
application: %s
version: 1
runtime: go111

handlers:
- url: /.*
  script: _go_app
`

const appSource = `
package main
import "google.golang.org/appengine"
func main() { appengine.Main() }
`

GAEの開発用サーバーのコマンドが組まれ、
dev_appserver.py dev_appserver.py /var/folders/1w/9n3yj1g95g12zgjhm9xxcypc0000gp/T/tmp4C_Mm8appengine-go-bin/app.yml のようなコマンドを子プロセスで立ち上げています。

開発用サーバーが起動するとAPIなどのURLが標準出力にでるので、正規表現ですっぱ抜いてきてそこにdatastore等の命令を投げるようにしています。結構ワイルドな実装ですね。

INFO     2019-10-10 06:39:59,912 devappserver2.py:278] Skipping SDK update check.
WARNING  2019-10-10 06:39:59,912 devappserver2.py:294] DEFAULT_VERSION_HOSTNAME will not be set correctly with --port=0
INFO     2019-10-10 06:40:00,098 datastore_emulator.py:155] Starting Cloud Datastore emulator at: http://localhost:21206
WARNING  2019-10-10 06:40:00,100 simple_search_stub.py:1196] Could not read search indexes from /var/folders/1w/9n3yj1g95g12zgjhm9xxcypc0000gp/T/appengine.testapp.hoshina/search_indexes
INFO     2019-10-10 06:40:01,231 datastore_emulator.py:161] Cloud Datastore emulator responded after 1.132465 seconds
INFO     2019-10-10 06:40:01,232 api_server.py:275] Starting API server at: http://localhost:64020
INFO     2019-10-10 06:40:01,237 api_server.py:265] Starting gRPC API server at: http://localhost:64022
INFO     2019-10-10 06:40:01,312 dispatcher.py:256] Starting module "default" running at: http://localhost:64023
INFO     2019-10-10 06:40:01,316 admin_server.py:150] Starting admin server at: http://localhost:64025
INFO     2019-10-10 06:40:03,328 stub_util.py:357] Applying all pending transactions and saving the datastore
INFO     2019-10-10 06:40:03,328 stub_util.py:360] Saving search indexes
INFO     2019-10-10 06:40:04,252 instance.py:294] Instance PID: 57474

var apiServerAddrRE = regexp.MustCompile(`Starting API server at: (\S+)`)
var adminServerAddrRE = regexp.MustCompile(`Starting admin server at: (\S+)`)

最初勘違いしていたのですが、aetestは対象のアプリケーションを立ち上げてくれるわけではなく、appengineAPIを利用するのに最低限必要なものを用意してくれるだけです。
なのでアプリケーションのルーティングを再現してくれるわけでもないので、テストで実際のアプリケーションを想定したリクエストを作ってhttp.ClientでDo(req)しても動いたりはしないので注意が必要です。

という挙動をしているaetest.NewInstance()ですが、毎回子プロセスを立ち上げるのでかなり遅いです。
下記のテストでは、2件のテストでそれぞれ5秒程度かかってしまい、実行時間の大半はdev_appserver.pyの起動に費やされています。

main_test.go

package main

import (
   "google.golang.org/appengine"
   "google.golang.org/appengine/aetest"
   "testing"
)

func TestAppID(t *testing.T) {
   ctx, done, err := aetest.NewContext()
   if err != nil {
   	t.Fatal(err)
   }
   defer done()
   val := appengine.AppID(ctx)
   if val != "testapp" {
   	t.Fatalf("got: %v\nwant: %v", val, "testapp")
   }
}

func TestDefaultVersionHostname(t *testing.T) {
   ctx, done, err := aetest.NewContext()
   if err != nil {
   	t.Fatal(err)
   }
   defer done()
   val := appengine.DefaultVersionHostname(ctx)
   if val != "" {
   	t.Fatalf("got: %v\nwant: %v", val, "")
   }
}

インスタンスは基本的に使い回せるはずなので、パッケージ変数に作成したインスタンスを保持して、インスタンスを要求された時設定が同じであれば以前に作成したインスタンスを返すことで毎回起動することを避けることができます。

main_test.go

package main

import (
	"context"
	"fmt"
	"google.golang.org/appengine"
	"google.golang.org/appengine/aetest"
	"os"
	"testing"
)

func TestAppID(t *testing.T) {
	ctx, done := NewContext(nil)
	defer done()
	val := appengine.AppID(ctx)
	if val != "testapp" {
		t.Fatalf("got: %v\nwant: %v", val, "testapp")
	}
}

func TestDefaultVersionHostname(t *testing.T) {
	ctx, done := NewContext(nil)
	defer done()
	val := appengine.DefaultVersionHostname(ctx)
	if val != "" {
		t.Fatalf("got: %v\nwant: %v", val, "")
	}
}

var instances map[string]aetest.Instance

func NewContext(opt *aetest.Options) (context.Context, func()) {
	var err error
	key := fmt.Sprintf("%#v", opt)
	//設定が異なる場合違うインスタンスを作成する
	if _, ok := instances[key]; !ok {
		instances[key], err = aetest.NewInstance(opt)
		if err != nil {
			panic(err)
		}
	}

	req, err := instances[key].NewRequest("GET", "/", nil)
	if err != nil {
		panic(err)
	}
	ctx := appengine.NewContext(req)
	return ctx, func() {
    //なにもしない
	}
}

func TestMain(m *testing.M) {
	instances = map[string]aetest.Instance{}
  //パッケージ内のテストを終了
	status := m.Run()

	//goroutineがインスタンスの終了を待っているので最後に終了する
	for _, i := range instances {
		i.Close()
	}
	os.Exit(status)
}

注意が必要なのは、aetest.Instanceは起動した子プロセスが終了するのをgoroutineで待ち続けているため、インスタンスが一つでも起動しているとgoroutineの終了を待ってしまいテストのプロセスを終了することができません。

そのためテストを終了させるためには、必ず最後にインスタンスを終了させる必要があります。

しかしここで問題があります。テスト内でpanicを起こすと、m.Run()の後に行っているインスタンスの終了が行われないため、テストが終了できなくなってしまうのです。

main_test.go

func TestPanic(t *testing.T) {
	panic("from TestPanic")
}

ですのでpanicが起きたらrecover()で捕まえてインスタンスを終了すればいいので、TestMainのdeferすればよいと考え、TestMainを以下のように変更しました。

main_test.go

func TestMain(m *testing.M) {
	status := 0

	defer func() {
		for _, i := range instances {
			i.Close()
		}
		os.Exit(status)
	}()
	instances = map[string]aetest.Instance{}
	status = m.Run()

	//goroutineがインスタンスの終了を待っているので最後に終了する
	for _, i := range instances {
		i.Close()
	}
}

しかしこの変更は無意味です。

通常、テストの中でpanicが起きた場合、テスト結果を出力し即終了しようとしますが、testingとは別のgoroutineでchannelが入力待ちの状態などで停止していると、テストの完了シグナルが送られずにテストプロセス自体が終了できなくなってしまいます。

仮に終了シグナルが返ったとしても、そもそもtestingの各テストはgoroutineで実行されており、goroutineをまたいでrecoverすることはできないので二重に意味のないコードでした。

結局どうしたらいいのかというと、goroutineがサーバーの終了を待たなくて良いようにするか、panicしても制御が戻って来れるようにする必要があります。

前者でやるとすればTestMainで全パターンのサーバーを作成しておくことで解決が可能です。ただし設定のパターンが多いと難しいでしょう。
後はpanicしても明示的にtestingの制御を返すことで親のgoroutineに終了を伝えることができます。

main_test.go

func TearDown(t *testing.T) {
	if err := recover(); err != nil {
		debug.PrintStack() //スタックトレースが出ないので自分で吐いている
		t.Fatal(err)
	}
}

func TestPanic(t *testing.T) {
	defer TearDown(t)
	panic("from TestPanic")
}

マイナーな話なのですが、テストが外部プロセスに依存してテスト実行時にその状態も管理しようとすると似たようなケースに陥るかもしれません。(テスト実行時にデータベースをいろんなパターンで起動したいとか)
その場合、TestMain等で共通の前後処理を行おうとすると例外時にハマることになるというお話でした。