2018年にもなって xargs でハマった
BSD と GNU 版の挙動の違いにハマった。
以下、ミニマムに試した結果。
環境
BSD xargs: macOS 10.12.6
GNU xargs: ubuntu 18.04 xargs (GNU findutils) 4.7.0-git
同じ
BSD xargs
$ echo "a b c" | xargs -n1 a b c
GNU xargs
$ echo "a b c" | xargs -n1 a b c
異なる
BSD xargs
$ echo "a b c" | xargs -n1 -I {} echo {} a b c
GNU xargs
$ echo "a b c" | xargs -n1 -I {} echo {} a b c
このように異なるおかげで、a, b, c と1つずつ処理しているつもりが、GNU版では一度に処理されてしまって、意図しない動きになっていた。
macOS では動くのに CI で動かない状態だったので、気づくのにすこし時間がかかった。つらい。
man をみたところ、GNU版は、-I
を使うとセパレータが改行になるらしい。ヘー。
面倒くさくなったので、xargs を使わないように改修した。
gcloud コマンドを使って Datastore から BigQuery にシュッとする
特定の Datastore Kind を適当に BigQuery へ持っていきたいとき、gcloud コマンドを使うと便利だった。
gcloud コマンドのインストールはドキュメントのとおり。
Export
エクスポートする App Engine プロジェクトは mcz で、Datastore の Kind は User, UserActionLog とする。
まず GCS(Cloud Storage) にエクスポート先バケットをつくる。
プロジェクトとバケットのリージョンが異なると怒られたので、要注意。
ここでは mcz_export というバケットをつくったことにする。
エクスポートコマンドは次のようになる。
gcloud --project=mcz beta datastore export --kinds="User,UserActionLog" gs://mcz_export/backup20171215
beta コマンドだけどちゃんと動く。
これで mcz_export/backup20171215 に User, UserActionLog のデータがエクスポートされる。
Import
続いて BigQuery にインポートする。
インポート先の dataset は mcz_data とする。
インポートコマンドは次のようになる。
bq load --project_id=mcz --replace --source_format=DATASTORE_BACKUP mcz_data.User gs://mcz_export/backup20171215/all_namespaces/kind_User/all_namespaces_kind_User.export_metadata
--replace
はなくても良いが、つけないと BigQuery にテーブルが既に存在するときインポート失敗するようになる。
適当に試したところ、1つずつしかインポートできないようだった。
ググり力が足りないのかもしれない。
ただコマンドを見ればお分かりのとおり、フォーマットが決まっている。
なので、Kind名のところを随時変えてあげれば、まとめてシュッともっていける。
次のようなスクリプトを書くと便利。
#!/bin/bash BACKUP_NAME="backup"`date '+%Y%m%d'` KINDS="User,UserActionLog" gcloud --project=mcz beta datastore export --kinds="${KINDS}" gs://mcz_export/${BACKUP_NAME} KINDS=`echo $KINDS | tr ',' ' '` for kind in ${KINDS}; do echo "${kind} importing..." bq load --project_id=mcz --replace --source_format=DATASTORE_BACKUP mcz_data.${kind} gs://mcz_export/${BACKUP_NAME}/all_namespaces/kind_${kind}/all_namespaces_kind_${kind}.export_metadata done
もっとしっかりやるなら Cloud Dataflow というものがあるのでそれを使うと良いらしい。
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してると想定する妥協もありなのかなーと思ってます。
何か良い案あれば教えてください。