integration: log goroutine trace on test timeout

Add maximum timeout to each test and log all buildkitd
goroutines when a test gets stuck. Currently tests can time out
and will print daemon logs but these would already be after
shutdown signal is sent to the daemon.

Signed-off-by: Tonis Tiigi <[email protected]>

Author: tonistiigi

util/testutil/integration/run.go

@@ -39,6 +39,7 @@ type Backend interface {
 	Address() string
 	DockerAddress() string
 	ContainerdAddress() string
+	DebugAddress() string
 
 	Rootless() bool
 	NetNSDetached() bool
@@ -200,7 +201,7 @@ func Run(t *testing.T, testCases []Test, opt ...TestOpt) {
 						ctx, cancel := context.WithCancelCause(ctx)
 						defer func() { cancel(errors.WithStack(context.Canceled)) }()
 
-						sb, closer, err := newSandbox(ctx, br, getMirror(), mv)
+						sb, closer, err := newSandbox(ctx, t, br, getMirror(), mv)
 						require.NoError(t, err)
 						t.Cleanup(func() { _ = closer() })
 						defer func() {

util/testutil/integration/sandbox.go

@@ -5,11 +5,15 @@ import (
 	"bytes"
 	"context"
 	"fmt"
+	"io"
+	"net"
+	"net/http"
 	"os"
 	"os/exec"
 	"path/filepath"
 	"strings"
 	"testing"
+	"time"
 
 	"github.com/google/shlex"
 	"github.com/moby/buildkit/util/bklog"
@@ -18,6 +22,8 @@ import (
 
 const buildkitdConfigFile = "buildkitd.toml"
 
+const maxSandboxTimeout = 5 * time.Minute
+
 type sandbox struct {
 	Backend
 
@@ -79,7 +85,7 @@ func (sb *sandbox) Value(k string) interface{} {
 	return sb.mv.values[k].value
 }
 
-func newSandbox(ctx context.Context, w Worker, mirror string, mv matrixValue) (s Sandbox, cl func() error, err error) {
+func newSandbox(ctx context.Context, t *testing.T, w Worker, mirror string, mv matrixValue) (s Sandbox, cl func() error, err error) {
 	cfg := &BackendConfig{
 		Logs: make(map[string]*bytes.Buffer),
 	}
@@ -110,6 +116,24 @@ func newSandbox(ctx context.Context, w Worker, mirror string, mv matrixValue) (s
 	}
 	deferF.Append(closer)
 
+	ctx, cancel := context.WithCancelCause(ctx)
+
+	go func() {
+		timeoutContext, cancelTimeout := context.WithTimeoutCause(ctx, maxSandboxTimeout, errors.WithStack(context.DeadlineExceeded))
+		defer cancelTimeout()
+		<-timeoutContext.Done()
+		select {
+		case <-ctx.Done():
+			return
+		default:
+			t.Logf("sandbox timeout reached, stopping worker")
+			if addr := b.DebugAddress(); addr != "" {
+				printBuildkitdDebugLogs(t, addr)
+			}
+			cancel(errors.WithStack(context.Canceled))
+		}
+	}()
+
 	return &sandbox{
 		Backend: b,
 		logs:    cfg.Logs,
@@ -120,6 +144,30 @@ func newSandbox(ctx context.Context, w Worker, mirror string, mv matrixValue) (s
 	}, cl, nil
 }
 
+func printBuildkitdDebugLogs(t *testing.T, addr string) {
+	if !strings.HasPrefix(addr, socketScheme) {
+		t.Logf("invalid debug address %q", addr)
+		return
+	}
+
+	client := &http.Client{Transport: &http.Transport{DialContext: func(_ context.Context, _, _ string) (net.Conn, error) {
+		return dialPipe(strings.TrimPrefix(addr, socketScheme))
+	}}}
+
+	resp, err := client.Get("http://localhost/debug/pprof/goroutine?debug=2") //nolint:noctx // never cancel
+	if err != nil {
+		t.Fatalf("failed to get debug logs: %v", err)
+		return
+	}
+	defer resp.Body.Close()
+	dt, err := io.ReadAll(resp.Body)
+	if err != nil {
+		t.Fatalf("failed to read debug logs: %v", err)
+		return
+	}
+	t.Logf("buildkitd debug logs:\n%s", dt)
+}
+
 func RootlessSupported(uid int) bool {
 	cmd := exec.Command("sudo", "-u", fmt.Sprintf("#%d", uid), "-i", "--", "exec", "unshare", "-U", "true") //nolint:gosec // test utility
 	b, err := cmd.CombinedOutput()

util/testutil/workers/backend.go

@@ -9,6 +9,7 @@ type backend struct {
 	address             string
 	dockerAddress       string
 	containerdAddress   string
+	debugAddress        string
 	rootless            bool
 	netnsDetached       bool
 	snapshotter         string
@@ -29,6 +30,10 @@ func (b backend) ContainerdAddress() string {
 	return b.containerdAddress
 }
 
+func (b backend) DebugAddress() string {
+	return b.debugAddress
+}
+
 func (b backend) Rootless() bool {
 	return b.rootless
 }

util/testutil/workers/containerd.go

@@ -232,7 +232,7 @@ disabled_plugins = ["io.containerd.grpc.v1.cri"]
 			"nsenter", "-U", "--preserve-credentials", "-m", "-t", fmt.Sprintf("%d", pid)},
 			append(buildkitdArgs, "--containerd-worker-snapshotter=native")...)
 	}
-	buildkitdSock, stop, err := runBuildkitd(cfg, buildkitdArgs, cfg.Logs, c.UID, c.GID, c.ExtraEnv)
+	buildkitdSock, debugSock, stop, err := runBuildkitd(cfg, buildkitdArgs, cfg.Logs, c.UID, c.GID, c.ExtraEnv)
 	if err != nil {
 		integration.PrintLogs(cfg.Logs, log.Println)
 		return nil, nil, err
@@ -242,6 +242,7 @@ disabled_plugins = ["io.containerd.grpc.v1.cri"]
 	return backend{
 		address:           buildkitdSock,
 		containerdAddress: address,
+		debugAddress:      debugSock,
 		rootless:          rootless,
 		netnsDetached:     false,
 		snapshotter:       c.Snapshotter,

util/testutil/workers/oci.go

@@ -77,14 +77,15 @@ func (s *OCI) New(ctx context.Context, cfg *integration.BackendConfig) (integrat
 	if runtime.GOOS != "windows" && s.Snapshotter != "native" {
 		extraEnv = append(extraEnv, "BUILDKIT_DEBUG_FORCE_OVERLAY_DIFF=true")
 	}
-	buildkitdSock, stop, err := runBuildkitd(cfg, buildkitdArgs, cfg.Logs, s.UID, s.GID, extraEnv)
+	buildkitdSock, debugSock, stop, err := runBuildkitd(cfg, buildkitdArgs, cfg.Logs, s.UID, s.GID, extraEnv)
 	if err != nil {
 		integration.PrintLogs(cfg.Logs, log.Println)
 		return nil, nil, err
 	}
 
 	return backend{
 		address:       buildkitdSock,
+		debugAddress:  debugSock,
 		rootless:      s.UID != 0,
 		netnsDetached: s.NetNSDetached(),
 		snapshotter:   s.Snapshotter,

util/testutil/workers/util.go

@@ -31,7 +31,7 @@ func runBuildkitd(
 	logs map[string]*bytes.Buffer,
 	uid, gid int,
 	extraEnv []string,
-) (address string, cl func() error, err error) {
+) (_, _ string, cl func() error, err error) {
 	deferF := &integration.MultiCloser{}
 	cl = deferF.F()
 
@@ -44,35 +44,36 @@ func runBuildkitd(
 
 	tmpdir, err := os.MkdirTemp("", "bktest_buildkitd")
 	if err != nil {
-		return "", nil, err
+		return "", "", nil, err
 	}
 
 	if err := chown(tmpdir, uid, gid); err != nil {
-		return "", nil, err
+		return "", "", nil, err
 	}
 
 	if err := os.MkdirAll(filepath.Join(tmpdir, "tmp"), 0711); err != nil {
-		return "", nil, err
+		return "", "", nil, err
 	}
 
 	if err := chown(filepath.Join(tmpdir, "tmp"), uid, gid); err != nil {
-		return "", nil, err
+		return "", "", nil, err
 	}
 	deferF.Append(func() error { return os.RemoveAll(tmpdir) })
 
 	cfgfile, err := integration.WriteConfig(
 		append(conf.DaemonConfig, withOTELSocketPath(getTraceSocketPath(tmpdir))))
 	if err != nil {
-		return "", nil, err
+		return "", "", nil, err
 	}
 	deferF.Append(func() error {
 		return os.RemoveAll(filepath.Dir(cfgfile))
 	})
 
 	args = append(args, "--config="+cfgfile)
-	address = getBuildkitdAddr(tmpdir)
+	address := getBuildkitdAddr(tmpdir)
+	debugAddress := getBuildkitdDebugAddr(tmpdir)
 
-	args = append(args, "--root", tmpdir, "--addr", address, "--debug")
+	args = append(args, "--root", tmpdir, "--addr", address, "--debugaddr", debugAddress, "--debug")
 	cmd := exec.Command(args[0], args[1:]...) //nolint:gosec // test utility
 	cmd.Env = append(
 		os.Environ(),
@@ -88,18 +89,18 @@ func runBuildkitd(
 
 	stop, err := integration.StartCmd(cmd, logs)
 	if err != nil {
-		return "", nil, err
+		return "", "", nil, err
 	}
 	deferF.Append(stop)
 
 	if err := integration.WaitSocket(address, 15*time.Second, cmd); err != nil {
-		return "", nil, err
+		return "", "", nil, err
 	}
 
 	// separated out since it's not required in windows
 	deferF.Append(func() error {
 		return mountInfo(tmpdir)
 	})
 
-	return address, cl, err
+	return address, debugAddress, cl, err
 }

util/testutil/workers/util_unix.go

@@ -34,6 +34,10 @@ func getBuildkitdAddr(tmpdir string) string {
 	return "unix://" + filepath.Join(tmpdir, "buildkitd.sock")
 }
 
+func getBuildkitdDebugAddr(tmpdir string) string {
+	return "unix://" + filepath.Join(tmpdir, "buildkitd-debug.sock")
+}
+
 func getTraceSocketPath(tmpdir string) string {
 	return filepath.Join(tmpdir, "otel-grpc.sock")
 }

util/testutil/workers/util_windows.go

@@ -22,6 +22,10 @@ func getBuildkitdAddr(tmpdir string) string {
 	return "npipe:////./pipe/buildkitd-" + filepath.Base(tmpdir)
 }
 
+func getBuildkitdDebugAddr(tmpdir string) string {
+	return "npipe:////./pipe/buildkitd-debug-" + filepath.Base(tmpdir)
+}
+
 func getTraceSocketPath(tmpdir string) string {
 	return `\\.\pipe\buildkit-otel-grpc-` + filepath.Base(tmpdir)
 }