[image-builder-mk3] Improve logging and tracing for build (#19734)

* [image-builder-mk3] improve traces and logging

* Add ws-manager-bridge to VS Code workspace

* Setting up  gpctl imagebuilds to help with testing

* Fix merge miss

components/image-builder-mk3/pkg/auth/auth.go

@@ -21,9 +21,11 @@ import (
 	"github.com/distribution/reference"
 	"github.com/docker/cli/cli/config/configfile"
 	"github.com/docker/docker/api/types/registry"
+	"github.com/opentracing/opentracing-go"
 	"golang.org/x/xerrors"
 
 	"github.com/gitpod-io/gitpod/common-go/log"
+	"github.com/gitpod-io/gitpod/common-go/tracing"
 	"github.com/gitpod-io/gitpod/common-go/watch"
 	"github.com/gitpod-io/gitpod/image-builder/api"
 )
@@ -277,7 +279,11 @@ type Resolver struct {
 }
 
 // ResolveRequestAuth computes the allowed authentication for a build based on its request
-func (r Resolver) ResolveRequestAuth(auth *api.BuildRegistryAuth) (authFor AllowedAuthFor) {
+func (r Resolver) ResolveRequestAuth(ctx context.Context, auth *api.BuildRegistryAuth) (authFor AllowedAuthFor) {
+	span, _ := opentracing.StartSpanFromContext(ctx, "ResolveRequestAuth")
+	var err error
+	defer tracing.FinishSpan(span, &err)
+
 	// by default we allow nothing
 	authFor = AllowedAuthForNone()
 	if auth == nil {

components/image-builder-mk3/pkg/orchestrator/orchestrator.go

@@ -159,7 +159,7 @@ func (o *Orchestrator) ResolveBaseImage(ctx context.Context, req *protocol.Resol
 	defer tracing.FinishSpan(span, &err)
 	tracing.LogRequestSafe(span, req)
 
-	reqauth := o.AuthResolver.ResolveRequestAuth(req.Auth)
+	reqauth := o.AuthResolver.ResolveRequestAuth(ctx, req.Auth)
 
 	refstr, err := o.getAbsoluteImageRef(ctx, req.Ref, reqauth)
 	if err != nil {
@@ -177,7 +177,7 @@ func (o *Orchestrator) ResolveWorkspaceImage(ctx context.Context, req *protocol.
 	defer tracing.FinishSpan(span, &err)
 	tracing.LogRequestSafe(span, req)
 
-	reqauth := o.AuthResolver.ResolveRequestAuth(req.Auth)
+	reqauth := o.AuthResolver.ResolveRequestAuth(ctx, req.Auth)
 	baseref, err := o.getBaseImageRef(ctx, req.Source, reqauth)
 	if _, ok := status.FromError(err); err != nil && ok {
 		return nil, err
@@ -227,14 +227,16 @@ func (o *Orchestrator) Build(req *protocol.BuildRequest, resp protocol.ImageBuil
 	}
 
 	// resolve build request authentication
-	reqauth := o.AuthResolver.ResolveRequestAuth(req.Auth)
+	reqauth := o.AuthResolver.ResolveRequestAuth(ctx, req.Auth)
+
+	log.WithField("forceRebuild", req.GetForceRebuild()).WithField("baseImageNameResolved", req.BaseImageNameResolved).Info("build request")
 
 	// resolve to ref to baseImageNameResolved (if it exists)
 	if req.BaseImageNameResolved != "" && !req.GetForceRebuild() {
 		if req.Auth != nil && req.Auth.GetSelective() != nil {
 			// allow access to baseImage repository so we can look it up later
 			req.Auth.GetSelective().AllowBaserep = true
-			reqauth = o.AuthResolver.ResolveRequestAuth(req.Auth)
+			reqauth = o.AuthResolver.ResolveRequestAuth(ctx, req.Auth)
 		}
 
 		wsrefstr, err := o.getWorkspaceImageRef(ctx, req.BaseImageNameResolved)
@@ -272,11 +274,14 @@ func (o *Orchestrator) Build(req *protocol.BuildRequest, resp protocol.ImageBuil
 		}
 	}
 
+	log.Info("falling through to old way of building")
 	baseref, err := o.getBaseImageRef(ctx, req.Source, reqauth)
 	if _, ok := status.FromError(err); err != nil && ok {
+		log.WithError(err).Error("gRPC status error")
 		return err
 	}
 	if err != nil {
+		log.WithError(err).Error("cannot get base image ref")
 		return status.Errorf(codes.Internal, "cannot resolve base image: %s", err.Error())
 	}
 
@@ -597,6 +602,11 @@ func (o *Orchestrator) checkImageExists(ctx context.Context, ref string, authent
 
 // getAbsoluteImageRef returns the "digest" form of an image, i.e. contains no mutable image tags
 func (o *Orchestrator) getAbsoluteImageRef(ctx context.Context, ref string, allowedAuth auth.AllowedAuthFor) (res string, err error) {
+	span, ctx := opentracing.StartSpanFromContext(ctx, "getAbsoluteImageRef")
+	defer tracing.FinishSpan(span, &err)
+	span.LogKV("ref", ref)
+
+	log.WithField("ref", ref).Debug("getAbsoluteImageRef")
 	auth, err := allowedAuth.GetAuthFor(ctx, o.Auth, ref)
 	if err != nil {
 		return "", status.Errorf(codes.InvalidArgument, "cannt resolve base image ref: %v", err)
@@ -607,6 +617,11 @@ func (o *Orchestrator) getAbsoluteImageRef(ctx context.Context, ref string, allo
 		return "", status.Error(codes.NotFound, "cannot resolve image")
 	}
 	if errors.Is(err, resolve.ErrUnauthorized) {
+		if auth == nil {
+			log.WithField("ref", ref).Warn("auth was nil")
+		} else if auth.Auth == "" && auth.Password == "" {
+			log.WithField("ref", ref).Warn("auth was empty")
+		}
 		return "", status.Error(codes.Unauthenticated, "cannot resolve image")
 	}
 	if err != nil {

components/image-builder-mk3/pkg/resolve/resolve.go

@@ -152,6 +152,10 @@ type DockerRefResolverOption func(o *opts)
 
 // WithAuthentication sets a base64 encoded authentication for accessing a Docker registry
 func WithAuthentication(auth *auth.Authentication) DockerRefResolverOption {
+	if auth == nil {
+		log.Debug("WithAuthentication - auth was nil")
+	}
+
 	return func(o *opts) {
 		o.Auth = auth
 	}

dev/gpctl/cmd/imagebuilds-build-batch.go

@@ -19,14 +19,16 @@ import (
 )
 
 // imagebuildsBuildBatch represents the build command
+
 var imagebuildsBuildBatch = &cobra.Command{
 	Use:   "build-batch",
 	Short: "Builds workspace images from base-image refs read from STDIN",
 	Long: `Tip: re-build the workspace images of all workspaces started in the last 30 days.
-	mysql -N -B -u root -p -h 127.0.0.1 gitpod -e 'SELECT ws.baseImageNameResolved FROM d_b_workspace_instance wsi LEFT JOIN d_b_workspace ws ON ws.id = workspaceId WHERE wsi.creationTime > (NOW() - INTERVAL 30 DAY)' | \
+	mysql -N -B -u gitpod -p -h 127.0.0.1 gitpod -e 'SELECT ws.baseImageNameResolved FROM d_b_workspace_instance wsi LEFT JOIN d_b_workspace ws ON ws.id = workspaceId WHERE wsi.creationTime > (NOW() - INTERVAL 30 DAY)' | \
 	sort | \
 	uniq | \
 	gpctl imagebuilds build-batch
+
 `,
 	Args: cobra.ExactArgs(0),
 	Run: func(cmd *cobra.Command, args []string) {
@@ -38,6 +40,7 @@ var imagebuildsBuildBatch = &cobra.Command{
 		if err != nil {
 			log.WithError(err).Fatal("cannot connect")
 		}
+		log.Info("connected to image-builder")
 		defer conn.Close()
 
 		timeBetweenBuilds, _ := cmd.Flags().GetInt("time-between-builds")
@@ -83,6 +86,9 @@ func buildWorkspaceImage(wg *sync.WaitGroup, ctx context.Context, client builder
 				},
 			},
 		},
+		// TODO: this shouldn't be hard coded
+		SupervisorRef: "eu.gcr.io/gitpod-core-dev/build/supervisor:commit-4cb5b6b9c0e993f3964e978e387fb0e7c1c04276",
+		TriggeredBy:   "c0f5dbf1-8d50-4d2a-8cd9-fe563fa53c71",
 	})
 	if err != nil {
 		log.WithField("ref", ref).WithError(err).Warn("cannot build workspace image")
@@ -94,11 +100,14 @@ func buildWorkspaceImage(wg *sync.WaitGroup, ctx context.Context, client builder
 		log.WithField("ref", ref).WithError(err).Warn("cannot receive build response")
 		return
 	}
-	br.CloseSend()
+	err = br.CloseSend()
+	if err != nil {
+		log.WithField("ref", ref).WithError(err).Warn("close send error")
+	}
 
 	switch r.Status {
 	case builder.BuildStatus_done_failure, builder.BuildStatus_done_success:
-		log.WithField("ref", ref).Infof("build done: %s", builder.BuildStatus_name[int32(r.Status)])
+		log.WithField("ref", ref).Infof("build done: %s, message: %s", builder.BuildStatus_name[int32(r.Status)], r.GetMessage())
 	case builder.BuildStatus_unknown:
 		log.WithField("ref", ref).Error("build status unknown")
 	case builder.BuildStatus_running:

dev/gpctl/cmd/imagebuilds-list.go

@@ -27,6 +27,7 @@ var imagebuildsListCmd = &cobra.Command{
 			log.WithError(err).Fatal("cannot connect")
 		}
 		defer conn.Close()
+		log.Info("connected")
 
 		// build did start, print log until done
 		resp, err := client.ListBuilds(ctx, &builder.ListBuildsRequest{})

gitpod-ws.code-workspace

@@ -63,6 +63,9 @@
         {
             "path": "components/ws-manager-api"
         },
+        {
+            "path": "components/ws-manager-bridge"
+        },
         {
             "path": "components/ws-manager-mk2"
         },