From f74b0542797b4b189b72b55dc18548d31f7b93f7 Mon Sep 17 00:00:00 2001 From: Kyle Brennan Date: Thu, 16 May 2024 09:37:54 -0400 Subject: [PATCH] [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 | 8 ++++++- .../pkg/orchestrator/orchestrator.go | 23 +++++++++++++++---- .../image-builder-mk3/pkg/resolve/resolve.go | 4 ++++ dev/gpctl/cmd/imagebuilds-build-batch.go | 15 +++++++++--- dev/gpctl/cmd/imagebuilds-list.go | 1 + gitpod-ws.code-workspace | 3 +++ 6 files changed, 46 insertions(+), 8 deletions(-) diff --git a/components/image-builder-mk3/pkg/auth/auth.go b/components/image-builder-mk3/pkg/auth/auth.go index 8270f04c1e3d85..cdef4d2c40c510 100644 --- a/components/image-builder-mk3/pkg/auth/auth.go +++ b/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 { diff --git a/components/image-builder-mk3/pkg/orchestrator/orchestrator.go b/components/image-builder-mk3/pkg/orchestrator/orchestrator.go index 628fef8d33ef99..8931a0fe2b86ce 100644 --- a/components/image-builder-mk3/pkg/orchestrator/orchestrator.go +++ b/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 { diff --git a/components/image-builder-mk3/pkg/resolve/resolve.go b/components/image-builder-mk3/pkg/resolve/resolve.go index 0599548cbd4eeb..ada240b0cfac83 100644 --- a/components/image-builder-mk3/pkg/resolve/resolve.go +++ b/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 } diff --git a/dev/gpctl/cmd/imagebuilds-build-batch.go b/dev/gpctl/cmd/imagebuilds-build-batch.go index b1b1bfa5d96a90..1b8f19200de3e7 100644 --- a/dev/gpctl/cmd/imagebuilds-build-batch.go +++ b/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: diff --git a/dev/gpctl/cmd/imagebuilds-list.go b/dev/gpctl/cmd/imagebuilds-list.go index ddf1f6cfa7aeae..14bb6900ccd2ba 100644 --- a/dev/gpctl/cmd/imagebuilds-list.go +++ b/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{}) diff --git a/gitpod-ws.code-workspace b/gitpod-ws.code-workspace index 4580d342fe3c62..b0adfc0e0c5849 100644 --- a/gitpod-ws.code-workspace +++ b/gitpod-ws.code-workspace @@ -63,6 +63,9 @@ { "path": "components/ws-manager-api" }, + { + "path": "components/ws-manager-bridge" + }, { "path": "components/ws-manager-mk2" },