Merge pull request #272 from depot/debug-logging

Add debug logging

pkg/buildx/build/build.go

@@ -28,6 +28,7 @@ import (
 	"github.com/containerd/containerd/platforms"
 	depotbuild "github.com/depot/cli/pkg/build"
 	"github.com/depot/cli/pkg/buildx/imagetools"
+	"github.com/depot/cli/pkg/debuglog"
 	"github.com/distribution/reference"
 	"github.com/docker/buildx/builder"
 	"github.com/docker/buildx/driver"
@@ -214,6 +215,9 @@ func splitToDriverPairs(availablePlatforms map[string]int, opt map[string]Option
 }
 
 func ResolveDrivers(ctx context.Context, nodes []builder.Node, opt map[string]Options, pw progress.Writer) (map[string][]driverPair, []*client.Client, error) {
+	debuglog.Log("ResolveDrivers() called")
+	defer debuglog.Log("ResolveDrivers() done")
+
 	availablePlatforms := map[string]int{}
 	for i, node := range nodes {
 		for _, p := range node.Platforms {
@@ -760,6 +764,7 @@ func BuildWithResultHandler(ctx context.Context, nodes []builder.Node, opt map[s
 		return nil, errors.Errorf("driver required for build")
 	}
 
+	debuglog.Log("Filtering available nodes")
 	nodes, err = FilterAvailableNodes(nodes)
 	if err != nil {
 		return nil, errors.Wrapf(err, "no valid drivers found")
@@ -792,10 +797,12 @@ func BuildWithResultHandler(ctx context.Context, nodes []builder.Node, opt map[s
 		}
 	}
 
+	debuglog.Log("Resolving drivers")
 	m, clients, err := ResolveDrivers(ctx, nodes, opt, w)
 	if err != nil {
 		return nil, err
 	}
+	debuglog.Log("Drivers resolved")
 
 	defers := make([]func(), 0, 2)
 	defer func() {
@@ -811,10 +818,12 @@ func BuildWithResultHandler(ctx context.Context, nodes []builder.Node, opt map[s
 	for k, opt := range opt {
 		multiDriver := len(m[k]) > 1
 		hasMobyDriver := false
+		debuglog.Log("Fetching git attributes")
 		gitattrs, err := getGitAttributes(ctx, opt.Inputs.ContextPath, opt.Inputs.DockerfilePath)
 		if err != nil {
 			logrus.Warn(err)
 		}
+		debuglog.Log("Git attributes fetched")
 		for i, np := range m[k] {
 			node := nodes[np.driverIndex]
 			if node.Driver.IsMobyDriver() {
@@ -829,9 +838,11 @@ func BuildWithResultHandler(ctx context.Context, nodes []builder.Node, opt map[s
 			}
 
 			if dockerfileCallback != nil {
+				debuglog.Log("Calling dockerfile callback")
 				if err := dockerfileCallback.Handle(ctx, k, np.driverIndex, dockerfile, w); err != nil {
 					return nil, err
 				}
+				debuglog.Log("Dockerfile callback called")
 			}
 
 			for k, v := range gitattrs {
@@ -949,6 +960,7 @@ func BuildWithResultHandler(ctx context.Context, nodes []builder.Node, opt map[s
 
 				c := clients[dp.driverIndex]
 				eg2.Go(func() error {
+					debuglog.Log("Preparing to call client Build()")
 					pw = progress.ResetTime(pw)
 
 					if err := waitContextDeps(ctx, dp.driverIndex, results, &so); err != nil {
@@ -982,7 +994,11 @@ func BuildWithResultHandler(ctx context.Context, nodes []builder.Node, opt map[s
 					var printRes map[string][]byte
 					// DEPOT: stop recording the build steps and traces on the server.
 					so.Internal = true
+					debuglog.Log("Calling buildkit client Build()")
 					rr, err := c.Build(ctx, so, "buildx", func(ctx context.Context, c gateway.Client) (*gateway.Result, error) {
+						debuglog.Log("Inside Build() callback")
+						defer debuglog.Log("Build() callback done")
+
 						var isFallback bool
 						var origErr error
 						for {
@@ -997,7 +1013,9 @@ func BuildWithResultHandler(ctx context.Context, nodes []builder.Node, opt map[s
 									req.FrontendOpt["build-arg:BUILDKIT_SYNTAX"] = printFallbackImage
 								}
 							}
+							debuglog.Log("Calling c.Solve()")
 							res, err := c.Solve(ctx, req)
+							debuglog.Log("c.Solve() done")
 							if err != nil {
 								if origErr != nil {
 									return nil, err

pkg/buildx/builder/node.go

@@ -4,6 +4,7 @@ import (
 	"context"
 
 	"github.com/depot/cli/pkg/buildx/imagetools"
+	"github.com/depot/cli/pkg/debuglog"
 	buildxbuilder "github.com/docker/buildx/builder"
 	"github.com/docker/buildx/driver"
 	ctxkube "github.com/docker/buildx/driver/kubernetes/context"
@@ -56,6 +57,9 @@ func (b *Builder) Nodes() []Node {
 // LoadNodes loads and returns nodes for this builder.
 // TODO: this should be a method on a Node object and lazy load data for each driver.
 func (b *Builder) LoadNodes(ctx context.Context, withData bool) (_ []Node, err error) {
+	debuglog.Log("Node LoadNodes() called")
+	defer debuglog.Log("Node LoadNodes() done")
+
 	eg, _ := errgroup.WithContext(ctx)
 	b.nodes = make([]Node, len(b.NodeGroup.Nodes))
 
@@ -184,6 +188,9 @@ func (b *Builder) LoadNodes(ctx context.Context, withData bool) (_ []Node, err e
 }
 
 func (n *Node) loadData(ctx context.Context) error {
+	debuglog.Log("Node loadData() called")
+	defer debuglog.Log("Node loadData() done")
+
 	if n.Driver == nil {
 		return nil
 	}

pkg/buildx/commands/build.go

@@ -24,6 +24,7 @@ import (
 	"github.com/depot/cli/pkg/buildx/builder"
 	"github.com/depot/cli/pkg/ci"
 	"github.com/depot/cli/pkg/cmd/docker"
+	"github.com/depot/cli/pkg/debuglog"
 	"github.com/depot/cli/pkg/helpers"
 	"github.com/depot/cli/pkg/load"
 	depotprogress "github.com/depot/cli/pkg/progress"
@@ -262,11 +263,13 @@ func buildTargets(ctx context.Context, dockerCli command.Cli, nodes []builder.No
 	buildxopts := depotbuildxbuild.BuildxOpts(opts)
 
 	// "Boot" the depot nodes.
+	debuglog.Log("booting depot nodes")
 	_, clients, err := depotbuildxbuild.ResolveDrivers(ctx, buildxNodes, buildxopts, printer)
 	if err != nil {
 		_ = printer.Wait()
 		return nil, nil, err
 	}
+	debuglog.Log("booted depot nodes")
 
 	var (
 		mu  sync.Mutex

pkg/buildx/commands/lint.go

@@ -10,6 +10,7 @@ import (
 	"time"
 
 	"github.com/depot/cli/pkg/buildx/build"
+	"github.com/depot/cli/pkg/debuglog"
 	depotprogress "github.com/depot/cli/pkg/progress"
 	"github.com/docker/buildx/builder"
 	"github.com/docker/buildx/util/progress"
@@ -102,6 +103,9 @@ func NewLinter(printer *depotprogress.Progress, failureMode LintFailure, clients
 }
 
 func (l *Linter) Handle(ctx context.Context, target string, driverIndex int, dockerfile *build.DockerfileInputs, p progress.Writer) error {
+	debuglog.Log("Lint Handle() called")
+	defer debuglog.Log("Lint Handle() done")
+
 	if l.FailureMode == LintSkip {
 		return nil
 	}

pkg/buildxdriver/driver.go

@@ -6,6 +6,7 @@ import (
 	"time"
 
 	depotbuild "github.com/depot/cli/pkg/build"
+	"github.com/depot/cli/pkg/debuglog"
 	"github.com/depot/cli/pkg/machine"
 	"github.com/docker/buildx/driver"
 	"github.com/docker/buildx/util/progress"
@@ -24,6 +25,9 @@ type Driver struct {
 }
 
 func (d *Driver) Bootstrap(ctx context.Context, reporter progress.Logger) error {
+	debuglog.Log("Driver Bootstrap() called")
+	defer debuglog.Log("Driver Bootstrap() done")
+
 	buildID := d.cfg.DriverOpts["buildID"]
 	token := d.cfg.DriverOpts["token"]
 	platform := d.cfg.DriverOpts["platform"]
@@ -77,6 +81,9 @@ func (d *Driver) Bootstrap(ctx context.Context, reporter progress.Logger) error
 }
 
 func (d *Driver) Info(ctx context.Context) (*driver.Info, error) {
+	debuglog.Log("Driver Info() called")
+	defer debuglog.Log("Driver Info() done")
+
 	if d.buildkit == nil {
 		return &driver.Info{Status: driver.Stopped}, nil
 	}

pkg/debuglog/log.go

@@ -0,0 +1,26 @@
+package debuglog
+
+import (
+	"log"
+	"os"
+
+	depotprogress "github.com/depot/cli/pkg/progress"
+)
+
+var Debug bool
+
+func Log(format string, args ...interface{}) {
+	if Debug {
+		log.Printf(format, args...)
+	}
+}
+
+func LogProgress(printer *depotprogress.Progress, message string, err error) {
+	if Debug {
+		printer.Log(message, err)
+	}
+}
+
+func init() {
+	Debug = os.Getenv("DEPOT_DEBUG") != ""
+}