loading...
Cover image for My stupid mistake about goroutine/defer

My stupid mistake about goroutine/defer

mattn profile image Yasuhiro Matsumoto ・3 min read

Today, I found small program that can be show colors like green or red from output of go test (ex: PASS/FAIL).

https://github.com/rakyll/gotest

gotest

This is good to see easily pass or fail of the test. After playing with this for a while, I met a strange behavior of gotest. The part of output often was not displayed. But I could figure out cause in soon.

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

When external command is exited, and finish to call cmd.Run(), goroutine consume must be finished to read until calling os.Exit(). So I patched like below.

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

Added sync.WaitGroup to wait groutine consume, and return with exit code. I expected this should work as intended. But this goes 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

At the first, I thought this is a bug of Go. So I was going to file this issue on GitHub. But this was simply my fault. wg.Wait() is called at exiting function gotest. And w which is opened by io.Pipe() is closed at the next. But reader.ReadLine() is blocking until w.Close() is called. So this is cleanly deadlock (as the message says above). Correct fixes must be below.

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

The teachings of Gopher.

Read the error message well.

Discussion

pic
Editor guide