goroutines leakage in runDialStdio

[andrey-ko]

It looks like function runDialStdio

cli/cli/command/system/dial_stdio.go

Line 29 in c3fc547

func runDialStdio(dockerCli command.Cli) error {

have a goroutines leakage in almost all paths except one, when copier(connHalfCloser, &halfReadCloserWrapper{os.Stdin}, "stdin to stream") completes successfully before another goroutine.
The problem is that in all other 'bad' paths we exit function without listening another channel, in that case writing to the channel will block goroutine forever.

Here the snippet to demonstrate this problem:
https://play.golang.org/p/lVr92dAgPbh

package main

import (
	"errors"
	"fmt"
	"os"
	"runtime/pprof"
	"time"
)

func main() {
	for i := 0; i<=300 ; i++ {
		runDialStdio(i)
		time.Sleep(100 * time.Millisecond)
		if i % 100 == 0 {
			p := pprof.Lookup("goroutine")
			p.WriteTo(os.Stdout, 1)
		}
	}
}

func runDialStdio(i int) error {

	stdin2conn := make(chan error)
	conn2stdout := make(chan error)

	go func() {
		stdin2conn <- errors.New("stdin2conn")
		fmt.Printf("completed [%d], stdin2conn\n", i)
	}()
	go func() {
		time.Sleep(time.Millisecond)
		conn2stdout  <- errors.New("conn2stdout") //nobody listen on conn2stdout so we will be blocked here forever
		fmt.Printf("completed [%d], conn2stdout\n", i)
	}()

	var err error
	select {
	case err = <-stdin2conn:
		if err != nil {
			return err
		}
		err = <-conn2stdout
	case err = <-conn2stdout:
	}
	return err
}

If we run this code, in the end of output we can see:

goroutine profile: total 302
301 @ 0x57280 0x24520 0x244e8 0x24260 0x10f7e0 0x8eb01
#    0x10f7df    main.runDialStdio.func2+0xbf    /tmp/sandbox424713474/main.go:33

1 @ 0x106a40 0x106780 0x1029a0 0x10f2e0 0x56c40 0x8eb01
#    0x106a3f    runtime/pprof.writeRuntimeProfile+0xbf    /usr/local/go/src/runtime/pprof/pprof.go:708
#    0x10677f    runtime/pprof.writeGoroutine+0x9f    /usr/local/go/src/runtime/pprof/pprof.go:670
#    0x10299f    runtime/pprof.(*Profile).WriteTo+0x3bf    /usr/local/go/src/runtime/pprof/pprof.go:329
#    0x10f2df    main.main+0xdf                /tmp/sandbox424713474/main.go:17
#    0x56c3f        runtime.main+0x2df            /usr/local/go/src/runtime/proc.go:200

meaning that there are 301 goroutines blocked at main.go:33

Probably the easiest way to fix it is to create 'buffered' channels:

stdin2conn := make(chan error, 1)
conn2stdout := make(chan error, 1)

not sure if it is the best solution though, so creating this issue for now.

Also it doesn't really very serious issue in our case, as we exit process right after we exit runDialStdio, but it feels wrong to keep code with such problems.

[thaJeztah]

ping @ijc @AkihiroSuda ptal

[AkihiroSuda]

Thanks for reporting this issue

Here the snippet to demonstrate this problem:
https://play.golang.org/p/lVr92dAgPbh

I clicked "Run" button, but it only shows goroutine profile: total 2

[andrey-ko]

Thanks for reporting this issue

Here the snippet to demonstrate this problem:
https://play.golang.org/p/lVr92dAgPbh

I clicked "Run" button, but it only shows goroutine profile: total 2

did you wait till it ends? it calls runDialStdio 300 times with 100ms delay, and displays profile info every 100, starting with 1, so basically output looks like:

completed [0], stdin2conn
goroutine profile: total 2
...
completed [98], stdin2conn
completed [99], stdin2conn
completed [100], stdin2conn
goroutine profile: total 102
...
completed [199], stdin2conn
completed [200], stdin2conn
goroutine profile: total 202
...
completed [299], stdin2conn
completed [300], stdin2conn
goroutine profile: total 302
...

[AkihiroSuda]

PR: #1772