DSAS開発者の部屋

Goのランタイムのバグを踏んで解決しました。解決までの過程を記事にします。

同じようなランタイムのバグを踏んで、小さい再現コードを作れない場合の参考にしてください。

自分のプログラムを疑う

あるSlackチャンネルで Go で書かれたサーバーのクラッシュが話題になっているのを見つけました。その時に共有してもらったトレースバックです。

runtime: pointer 0xc007b8af97 to unused region of span span.base()=0xc004000000 span.limit=0xc004002000 span.state=1
fatal error: found bad pointer in Go heap (incorrect use of unsafe or cgo?)
runtime stack:
runtime.throw(0xc046ca, 0x3e)
        /usr/local/Cellar/go/1.11.2/libexec/src/runtime/panic.go:608 +0x72 fp=0xc0001dff00 sp=0xc0001dfed0 pc=0x42bf02
runtime.findObject(0xc007b8af97, 0x0, 0x0, 0xc005eb4780, 0x7f3d1915b7b8, 0x5)
        /usr/local/Cellar/go/1.11.2/libexec/src/runtime/mbitmap.go:399 +0x3b6 fp=0xc0001dff50 sp=0xc0001dff00 pc=0x413bf6
runtime.wbBufFlush1(0xc000047900)

(長いバージョン)

エラーメッセージに "incorrect use of unsafe or cgo?" って言われてるので、まずはそれを疑います。

cgoは使っていませんでした。 unsafe は使わないようにビルドするのは大変なので、コードをチェックアウトして怪しいところを探します。 プロジェクトのコードには見当たりません。vendoringしているコードにはたくさんありますが、このプログラムで実際に利用されてそうな部分で怪しいものはありませんでした。

また、 race はすでに疑っていて、 -race オプション付きで見つけたレースコンディションを全て潰したあとだったようです。

これでランタイムバグの可能性が高くなってきました。

修正済みバグの可能性と、最近のリグレッションの可能性を調べるため、Go 1.11.4 と Go 1.10.5 で試してもらいました。 1.11.4 ですぐに再現し、 1.10.5 では再現しなかったそうです。 もちろん再現確率が違うだけの可能性も残ってるので、リグレッションだと確定したわけではありません。

Goのデバッグ機能を利用して原因特定を試みる

時系列的には上と同時になりますが、Goが標準で持っているデバッグ機能をつかって原因特定できないか試行錯誤をします。

まず大事なのは、スタックトレースとコードを読みクラッシュした状況を理解することです。

今回のケースは、ライトバリアの実装の中で（性能のために）一旦バッファリングしていたポインタを処理する前に有効な（ヒープ内を指している）ポインタかどうかチェックしている箇所で、無効なポインタを見つけたというものです。

悪いポインタがバッファの中から見つかっているために、そのポインタがどの変数に書かれていたのかとか、どのコードによって書かれたのかがわかりません。そこで試してもらったのが、 GODEBUG 環境変数のうち invalidptr=0 と GODEBUG=gcstoptheworld=1 です。

invalidptr=0 を使うと、このポインタのチェックがなくなります。それでクラッシュしなくなれば、問題解決に時間がかかったときのワークアラウンドになります。クラッシュすれば、今度はその悪いポインタが入っている変数を特定するヒントが得られる可能性が高いです。

gcstoptheworld=1 はコンカレントGC自体を無効にするもので、ライトバリアが使われなくなるので同じく悪いポインタを利用している箇所の近くでクラッシュすることが期待できます。

結果として、どちらのオプションを使ってもクラッシュしなくなりました。ここまでの状況を整理した上で、一旦バグ報告しておきました。

https://github.com/golang/go/issues/29362

ローカルでの再現できるようにする

そろそろ手詰まり感が出てきました。腰を落ち着けて、自分で自由に使える再現環境を作ります。

docker-compose を使った開発環境構築手順を教えてもらい、現象を再現できるようになるまで試験環境との差異を調べて減らしていきます。ログの量を同じにしたところで、１日に数回クラッシュをさせられるようになりました。

反省点として、これは手詰まりになる前にさっさとやっておくべきでした。

print & throw デバッグ

runtime.wbBufFlush1 はライトバリア・バッファの中のポインタを処理する関数なので、ライトバリア・バッファにポインタを書き込む場所を探します。 runtime/mwbbuf.go はたった311行の小さいコードなので、すぐに (*wbBuf).putFast() という関数が見つかりました。ここに、 fatal error の原因になっているチェックと throw を仕込んでみます。

runtime: bad pinter: 0xc007435e93
fatal error: XXXXXX

runtime stack:
runtime.throw(0xbeaeb3, 0x6)
    /home/ubuntu/local/go/src/runtime/panic.go:608 +0x72
runtime.(*wbBuf).putFast(0xc00003b290, 0xc007435e93, 0xc007435e93, 0x7f4b766b6d88)
    /home/ubuntu/local/go/src/runtime/mwbbuf.go:143 +0x1f8
runtime.bulkBarrierBitmap(0xc0038a6fd8, 0xc0038a6fd8, 0x8, 0x0, 0xc19258)
    /home/ubuntu/local/go/src/runtime/mbitmap.go:682 +0x12d
runtime.newproc1(0xc194f0, 0xc0002c8708, 0x8, 0xc00222e780, 0x7f1edd)
    /home/ubuntu/local/go/src/runtime/proc.go:3373 +0x441
runtime.newproc.func1()
    /home/ubuntu/local/go/src/runtime/proc.go:3309 +0x4f
runtime.systemstack(0x0)
    /home/ubuntu/local/go/src/runtime/asm_amd64.s:351 +0x66
runtime.mstart()
    /home/ubuntu/local/go/src/runtime/proc.go:1229

goroutine 66219 [running]:
runtime.systemstack_switch()
    /home/ubuntu/local/go/src/runtime/asm_amd64.s:311 fp=0xc0002c86b0 sp=0xc0002c86a8 pc=0x45bb70
runtime.newproc(0xc000000008, 0xc194f0)
    /home/ubuntu/local/go/src/runtime/proc.go:3308 +0x6e fp=0xc0002c86f8 sp=0xc0002c86b0 pc=0x43750e
XXX/game/connection.Keep(0x7435e93)

これで、プロジェクトの connection.Keep 関数から runtime.newproc が呼び出され、そこから bad pointer がライトバリア・バッファに書き込まれていることがわかります。 また、よくみてみると、 bad pointer の壊れている下位バイトが、 Keep 関数の引数と完全に一致していますね。

throw を仕込む前の完全なスタックダンプ（クラッシュしたgoroutine以外の全部のgoroutineが、引数付きで書き出される）を見直してみると、さらに面白い事がわかりました。

runtime: pointer 0xc00659e432 to unused region of span span.base()=0xc004000000 span.limit=0xc004001f80 span.state=1
fatal error: found bad pointer in Go heap (incorrect use of unsafe or cgo?)

runtime stack:
runtime.throw(0xc0f417, 0x3e)
    /home/ubuntu/local/go/src/runtime/panic.go:608 +0x72 fp=0x7ff10e99fd98 sp=0x7ff10e99fd68 pc=0x42dec2
runtime.findObject(0xc00659e432, 0x0, 0x0, 0xc004ab0180, 0x7ff10d5f3e70, 0x1)

...

goroutine 29115 [runnable]:
XXX/game/connection.Keep.func1(0xc00659e432)
    XXX/game/connection/connection.go:22 fp=0xc0044a97d8 sp=0xc0044a97d0 pc=0x7f1ff0
runtime.goexit()
    /home/ubuntu/local/go/src/runtime/asm_amd64.s:1333 +0x1 fp=0xc0044a97e0 sp=0xc0044a97d8 pc=0x45dc51
created by XXX/game/connection.Keep
    XXX/game/connection/connection.go:22 +0x3d

bad pointer のアドレスと Keep.func1 の引数が完全に一致しています。 Keep 関数のコードを見てみましょう。

func Keep(playerID int32) {
    go func() { // この無名関数が Keep.func1
        err := updateAliveTime(playerID)
        if err != nil {
            logger.Errorf("Failed to keep connection. err=[%v]", err)
        }
    }()
}

なんとなく、スタックに残っていたポインタ (64bit) の下位 32bit を int32 の変数で上書きして bad pointer が生成されてそうなのがわかります。とはいえ、 int32 の変数がある場所をポインタとして扱っているのはコンパイラかランタイムのどちらかのバグのはずです。

ここまで追い詰めたら、この部分に詳しい人ならすぐに解析できるでしょう。一旦ここまでをまとめて報告しておきます。

コードリーディング＆バグ修正

ここまでくれば待っていても誰かが直してくれると思いますが、クリスマスを過ぎてしまって欧米の開発者は holiday に入ってしまっている時期だし、何より楽しいので、 newproc ... putFast までのコードを読んでいきます。

newproc1 が新しい goroutine のための G オブジェクトを用意し、親 goroutine のスタックから新しい goroutine のスタックに最初の関数の引数をコピーした上で、ライトバリアが有効なら bulkBarrierBitmap を呼び出しています。 bulkBarrierBitmap は渡されたビットマップを使ってメモリ中のポインタをライトバリア・バッファに putFast していきます。

本来なら、 Keep.func1 の引数は（クロージャ変数の） playerID int32 一つだけなので、 putFast が呼び出されるはずがありません。 bulkBarrierBitmap の呼び出しの前に print を仕込んでビットマップの内容を表示してみます。すると、 Keep.func1 は引数の長さが１ワードなのに、引数のビットマップは長さが 0 になっていました。

このスタック用のビットマップに関連するコードを読んでみると、該当するスタックの中にポインタが１つもない時は空のビットマップが使われるようでした。なので、 bulkBarrierBitmap はオーバーランして別のデータ（多分実行バイナリ上で隣に配置された別のビットマップ）を参照してしまい、int32 の変数が入っている箇所を間違えて処理しているようです。

bulkBarrierBitmap を呼び出す前にビットマップの長さが 0 でないかテストする事で問題が解消することを確認し、報告しました。

https://github.com/golang/go/issues/29362#issuecomment-449964832

パッチ送信＆再現コード作成

runtime の他の場所で似たことをしている場所を探し、自分の書いた if 文が他の場所と(> 0 か != 0 かのスタイルまで)同一であることを確認した上で、 Gerrit にパッチを送信します。

https://go-review.googlesource.com/c/go/+/155779

また、レビューアーが確認できるように、クラッシュの小さい再現コードも作ってみます。ライトバリアが常に有効になるように、ヒープ上にポインタ変数をたくさん作った上で runtime.GC() をループで呼び出します。また、スタック上に残っていたゴミポインタと int32 の値の合体で偶然 bad pointer を作るのでなく、意図的に bad pointer を作った上で、それを整数型の引数として関数を呼び出します。

残る再現条件は、長さ0のビットマップをオーバーランしたときにたまたまその場所のビットが1になっていることなのですが、この条件は Go プログラムで意図的に作り出すことが難しい。確率を上げるためにとりあえず引数を１つではなく４つにしてみたら、あっさり再現できました。

https://gist.github.com/methane/b61dcfb504d54de5bced1c6e3209a91d

理想的にはこの再現コードをリグレッション・テストに落とし込むなり、 newproc1 に対するユニットテストが書ければ完璧なのですが、この辺は Go のプログラムから直接呼び出されるのではなく Go コンパイラが呼び出しコードを生成する部分でテストが難しいので今後レビューアーと相談します。