今日たまたま見つけた gotest というプログラムの修正を行った際にドハマリした。
GitHub - rakyll/gotest: go test with colors
https://github.com/rakyll/gotest
gotest は go test の出力の PASS や FAIL といった定型の文字列を見つけて緑や赤に色付けする小さなプログラム。仕組みも簡単で以下の様なコードになっている。
func main() {
setPalette()
enableOnCI()
gotest(os.Args[1:])
}
func gotest(args []string) {
r, w := io.Pipe()
defer w.Close()
args = append([]string{"test"}, args...)
cmd := exec.Command("go", args...)
cmd.Stderr = w
cmd.Stdout = w
cmd.Env = os.Environ()
go consume(r)
if err := cmd.Run(); err != nil {
if ws, ok := cmd.ProcessState.Sys().(syscall.WaitStatus); ok {
os.Exit(ws.ExitStatus())
}
os.Exit(1)
}
}
func consume(r io.Reader) {
reader := bufio.NewReader(r)
for {
l, _, err := reader.ReadLine()
if err == io.EOF {
return
}
if err != nil {
log.Fatal(err)
}
parse(string(l))
}
}
cmd.Run() はブロックするので gorutine で bufio.Reader を読みながら色付けしてる。ただこれ、cmd.Run() のブロックが解け、os.Exit() が呼び出されるまでに goroutine 側が処理しないと出力をロストしてしまう事になる。そこで僕は以下の様に修正した。
func main() {
setPalette()
enableOnCI()
os.Exit(gotest(os.Args[1:]))
}
func gotest(args []string) int {
r, w := io.Pipe()
defer w.Close()
args = append([]string{"test"}, args...)
cmd := exec.Command("go", args...)
cmd.Stderr = w
cmd.Stdout = w
cmd.Env = os.Environ()
var wg sync.WaitGroup
wg.Add(1)
defer wg.Wait()
go consume(&wg, r)
if err := cmd.Run(); err != nil {
if ws, ok := cmd.ProcessState.Sys().(syscall.WaitStatus); ok {
return ws.ExitStatus()
}
return 1
}
return 0
}
func consume(wg *sync.WaitGroup, r io.Reader) {
defer wg.Done()
reader := bufio.NewReader(r)
for {
l, _, err := reader.ReadLine()
if err == io.EOF {
return
}
if err != nil {
log.Print(err)
return
}
parse(string(l))
}
}
sync.WaitGroup を使い、goroutine の終了を待ち、gotest の関数の戻り値として外部コマンドの終了コードを渡し、main 関数で os.Exit() を呼び出す。Go 言語を良く使う方なら良く見る、そして割かし綺麗と言われるソースの書き方だと思います。ただこのコード、以下の様に panic で落ちます。
fatal error: all goroutines are asleep - deadlock!
goroutine 1 [semacquire]:
sync.runtime_Semacquire(0xc0420083fc)
c:/go/src/runtime/sema.go:56 +0x40
sync.(*WaitGroup).Wait(0xc0420083f0)
c:/go/src/sync/waitgroup.go:129 +0x79
main.gotest(0xc04203e260, 0x0, 0x0, 0x1)
c:/dev/go/src/github.com/rakyll/gotest/main.go:54 +0x3bf
main.main()
c:/dev/go/src/github.com/rakyll/gotest/main.go:33 +0x74
最初これを目にした時には直ぐに原因が分からず「これは Go のバグだ。issue を書くぞ！」という行動を起こす手前で原因に気がついた。
このコード、処理される順に着目して欲しい。io.Pipe() で作られた書き込み用のパイプ w は、関数 gotest を抜ける際に Close される。goroutine consume を待機する為の wg は関数 gotest を抜ける際に Wait が呼び出される。関数 consume 内の reader.ReadLine は、パイプ w が Close されないとブロックを解かない。なので w.Close() が先に呼び出される必要がある。そう、これデッドロックでした。defer 文は、関数内で defer を指定した順とは逆に実行されるので、本来ならば
- cmd.Run() のブロックが解ける
- w.Close() が呼び出される
- wg.Wait() を呼び出す
という順にしないといけない訳です。以下の様に修正して正しく動作する様になりました。
func main() {
setPalette()
enableOnCI()
os.Exit(gotest(os.Args[1:]))
}
func gotest(args []string) int {
var wg sync.WaitGroup
wg.Add(1)
defer wg.Wait()
r, w := io.Pipe()
defer w.Close()
args = append([]string{"test"}, args...)
cmd := exec.Command("go", args...)
cmd.Stderr = w
cmd.Stdout = w
cmd.Env = os.Environ()
go consume(&wg, r)
if err := cmd.Run(); err != nil {
if ws, ok := cmd.ProcessState.Sys().(syscall.WaitStatus); ok {
return ws.ExitStatus()
}
return 1
}
return 0
}
func consume(wg *sync.WaitGroup, r io.Reader) {
defer wg.Done()
reader := bufio.NewReader(r)
for {
l, _, err := reader.ReadLine()
if err == io.EOF {
return
}
if err != nil {
log.Print(err)
return
}
parse(string(l))
}
}
いやはやお恥ずかしいというかなんというか。本来なら無限ループしてもおかしくない所をちゃんと「deadlock」ってメッセージ付きで panic になってくれたんですから、Go 言語素晴らしいって話でした辛い。