From cb388ca0af9c89fa5a3446cfd811efe0613df7cd Mon Sep 17 00:00:00 2001 From: Jacob Gillespie Date: Tue, 16 Apr 2024 20:37:40 +0100 Subject: [PATCH] Add debug logging --- pkg/buildx/build/build.go | 18 ++++++++++++++++++ pkg/buildx/builder/node.go | 7 +++++++ pkg/buildx/commands/build.go | 3 +++ pkg/buildx/commands/lint.go | 4 ++++ pkg/buildxdriver/driver.go | 7 +++++++ pkg/debuglog/log.go | 26 ++++++++++++++++++++++++++ 6 files changed, 65 insertions(+) create mode 100644 pkg/debuglog/log.go diff --git a/pkg/buildx/build/build.go b/pkg/buildx/build/build.go index 3760cc8b..cc6c7a80 100644 --- a/pkg/buildx/build/build.go +++ b/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 diff --git a/pkg/buildx/builder/node.go b/pkg/buildx/builder/node.go index acff2140..c25658d5 100644 --- a/pkg/buildx/builder/node.go +++ b/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 } diff --git a/pkg/buildx/commands/build.go b/pkg/buildx/commands/build.go index f2fbac75..00069f85 100644 --- a/pkg/buildx/commands/build.go +++ b/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 diff --git a/pkg/buildx/commands/lint.go b/pkg/buildx/commands/lint.go index c9891580..10a77f37 100644 --- a/pkg/buildx/commands/lint.go +++ b/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 } diff --git a/pkg/buildxdriver/driver.go b/pkg/buildxdriver/driver.go index 27bf1ee6..2fba748c 100644 --- a/pkg/buildxdriver/driver.go +++ b/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 } diff --git a/pkg/debuglog/log.go b/pkg/debuglog/log.go new file mode 100644 index 00000000..1e13a23b --- /dev/null +++ b/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") != "" +}