Merge pull request #5568 from tonistiigi/intergration-test-timeout-tr…

…aces

integration: log goroutine trace on test timeout

client/client_test.go

@@ -149,7 +149,7 @@ var allTests = []func(t *testing.T, sb integration.Sandbox){
 	testHostnameSpecifying,
 	testPushByDigest,
 	testBasicInlineCacheImportExport,
-	testBasicGhaCacheImportExport,
+	testBasicGhaCacheImportExportExtraTimeout,
 	testExportBusyboxLocal,
 	testBridgeNetworking,
 	testCacheMountNoCache,
@@ -6060,7 +6060,7 @@ func testBasicInlineCacheImportExport(t *testing.T, sb integration.Sandbox) {
 	require.EqualValues(t, unique, unique3)
 }
 
-func testBasicGhaCacheImportExport(t *testing.T, sb integration.Sandbox) {
+func testBasicGhaCacheImportExportExtraTimeout(t *testing.T, sb integration.Sandbox) {
 	workers.CheckFeatureCompat(t, sb,
 		workers.FeatureCacheExport,
 		workers.FeatureCacheImport,

cmd/buildkitd/debug.go

@@ -2,10 +2,11 @@ package main
 
 import (
 	"expvar"
-	"net"
 	"net/http"
 	"net/http/pprof"
+	"os"
 	"runtime"
+	"strings"
 	"time"
 
 	"github.com/moby/buildkit/util/bklog"
@@ -38,7 +39,10 @@ func setupDebugHandlers(addr string) error {
 		return true, true
 	}
 
-	l, err := net.Listen("tcp", addr)
+	if !strings.Contains(addr, "://") {
+		addr = "tcp://" + addr
+	}
+	l, err := getListener(addr, os.Getuid(), os.Getgid(), "", nil, false)
 	if err != nil {
 		return err
 	}

cmd/buildkitd/main.go

@@ -431,7 +431,7 @@ func newGRPCListeners(cfg config.GRPCConfig) ([]net.Listener, error) {
 
 	listeners := make([]net.Listener, 0, len(addrs))
 	for _, addr := range addrs {
-		l, err := getListener(addr, *cfg.UID, *cfg.GID, sd, tlsConfig)
+		l, err := getListener(addr, *cfg.UID, *cfg.GID, sd, tlsConfig, true)
 		if err != nil {
 			for _, l := range listeners {
 				l.Close()
@@ -670,7 +670,7 @@ func groupToGid(group string) (int, error) {
 	return id, nil
 }
 
-func getListener(addr string, uid, gid int, secDescriptor string, tlsConfig *tls.Config) (net.Listener, error) {
+func getListener(addr string, uid, gid int, secDescriptor string, tlsConfig *tls.Config, warnTLS bool) (net.Listener, error) {
 	addrSlice := strings.SplitN(addr, "://", 2)
 	if len(addrSlice) < 2 {
 		return nil, errors.Errorf("address %s does not contain proto, you meant unix://%s ?",
@@ -696,7 +696,9 @@ func getListener(addr string, uid, gid int, secDescriptor string, tlsConfig *tls
 		}
 
 		if tlsConfig == nil {
-			bklog.L.Warnf("TLS is not enabled for %s. enabling mutual TLS authentication is highly recommended", addr)
+			if warnTLS {
+				bklog.L.Warnf("TLS is not enabled for %s. enabling mutual TLS authentication is highly recommended", addr)
+			}
 			return l, nil
 		}
 		return tls.NewListener(l, tlsConfig), nil

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,28 @@ func newSandbox(ctx context.Context, w Worker, mirror string, mv matrixValue) (s
 	}
 	deferF.Append(closer)
 
+	ctx, cancel := context.WithCancelCause(ctx)
+
+	go func() {
+		timeout := maxSandboxTimeout
+		if strings.Contains(t.Name(), "ExtraTimeout") {
+			timeout *= 3
+		}
+		timeoutContext, cancelTimeout := context.WithTimeoutCause(ctx, timeout, 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 +148,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)
 }