From 1605d803777482e6d63b3c6bfd545e9237d7b7ac Mon Sep 17 00:00:00 2001 From: Kit Patella Date: Mon, 28 Oct 2024 11:31:09 -0700 Subject: [PATCH 1/4] chore: improve the Info and Debug logging for image pulls (#3149) Signed-off-by: Kit Patella --- src/internal/packager/images/pull.go | 52 ++++++++++++++++++++++------ 1 file changed, 41 insertions(+), 11 deletions(-) diff --git a/src/internal/packager/images/pull.go b/src/internal/packager/images/pull.go index 2bd39862a6..8d3b8201ae 100644 --- a/src/internal/packager/images/pull.go +++ b/src/internal/packager/images/pull.go @@ -90,14 +90,7 @@ func Pull(ctx context.Context, cfg PullConfig) (map[transform.Image]v1.Image, er // TODO(mkcp): Remove message on logger release spinner := message.NewProgressSpinner("Fetching info for %d images. %s", imageCount, longer) defer spinner.Stop() - switch c := len(cfg.ImageList); { - case c > 15: - l.Info("fetching info for images. This step may take a couple of minutes to complete", "count", c, "destination", cfg.DestinationDirectory) - case c > 5: - l.Info("fetching info for images. This step may take several seconds to complete", "count", c, "destination", cfg.DestinationDirectory) - default: - l.Info("fetching info for images", "count", c, "destination", cfg.DestinationDirectory) - } + l.Info("fetching info for images", "count", imageCount, "destination", cfg.DestinationDirectory) logs.Warn.SetOutput(&message.DebugWriter{}) logs.Progress.SetOutput(&message.DebugWriter{}) @@ -113,13 +106,14 @@ func Pull(ctx context.Context, cfg PullConfig) (map[transform.Image]v1.Image, er var counter, totalBytes atomic.Int64 + // Spawn a goroutine for each for _, refInfo := range cfg.ImageList { refInfo := refInfo eg.Go(func() error { idx := counter.Add(1) // TODO(mkcp): Remove message on logger release spinner.Updatef("Fetching image info (%d of %d)", idx, imageCount) - l.Info("fetching image info", "name", refInfo.Name) + l.Debug("fetching image info", "name", refInfo.Name) ref := refInfo.Reference for k, v := range cfg.RegistryOverrides { @@ -236,6 +230,7 @@ func Pull(ctx context.Context, cfg PullConfig) (map[transform.Image]v1.Image, er }) } + // Wait until we're done fetching images if err := eg.Wait(); err != nil { return nil, err } @@ -254,11 +249,15 @@ func Pull(ctx context.Context, cfg PullConfig) (map[transform.Image]v1.Image, er err = retry.Do(func() error { saved, err := SaveConcurrent(ctx, cranePath, toPull) + // Done save, remove from download list. for k := range saved { delete(toPull, k) } return err - }, retry.Context(ctx), retry.Attempts(2)) + }, + retry.Context(ctx), + retry.Attempts(2), + ) if err != nil { // TODO(mkcp): Remove message on logger release message.Warnf("Failed to save images in parallel, falling back to sequential save: %s", err.Error()) @@ -269,7 +268,10 @@ func Pull(ctx context.Context, cfg PullConfig) (map[transform.Image]v1.Image, er delete(toPull, k) } return err - }, retry.Context(ctx), retry.Attempts(2)) + }, + retry.Context(ctx), + retry.Attempts(2), + ) if err != nil { return nil, err } @@ -354,24 +356,39 @@ func CleanupInProgressLayers(ctx context.Context, img v1.Image) error { // SaveSequential saves images sequentially. func SaveSequential(ctx context.Context, cl clayout.Path, m map[transform.Image]v1.Image) (map[transform.Image]v1.Image, error) { + l := logger.From(ctx) saved := map[transform.Image]v1.Image{} for info, img := range m { annotations := map[string]string{ ocispec.AnnotationBaseImageName: info.Reference, } + wStart := time.Now() + size, err := img.Size() + if err != nil { + return saved, err + } + l.Info("saving image", "ref", info.Reference, "size", size, "method", "sequential") if err := cl.AppendImage(img, clayout.WithAnnotations(annotations)); err != nil { if err := CleanupInProgressLayers(ctx, img); err != nil { message.WarnErr(err, "failed to clean up in-progress layers, please run `zarf tools clear-cache`") + l.Error("failed to clean up in-progress layers. please run `zarf tools clear-cache`") } return saved, err } saved[info] = img + l.Debug("done saving image", + "ref", info.Reference, + "size", size, + "method", "sequential", + "duration", time.Since(wStart), + ) } return saved, nil } // SaveConcurrent saves images in a concurrent, bounded manner. func SaveConcurrent(ctx context.Context, cl clayout.Path, m map[transform.Image]v1.Image) (map[transform.Image]v1.Image, error) { + l := logger.From(ctx) saved := map[transform.Image]v1.Image{} var mu sync.Mutex @@ -391,12 +408,25 @@ func SaveConcurrent(ctx context.Context, cl clayout.Path, m map[transform.Image] return err } + size, err := img.Size() + if err != nil { + return err + } + wStart := time.Now() + l.Info("saving image", "ref", info.Reference, "size", size, "method", "concurrent") if err := cl.WriteImage(img); err != nil { if err := CleanupInProgressLayers(ectx, img); err != nil { message.WarnErr(err, "failed to clean up in-progress layers, please run `zarf tools clear-cache`") + l.Error("failed to clean up in-progress layers. please run `zarf tools clear-cache`") } return err } + l.Debug("done saving image", + "ref", info.Reference, + "size", size, + "method", "concurrent", + "duration", time.Since(wStart), + ) mu.Lock() defer mu.Unlock() From affdb5b8993c1131f32e386f00e609a1c0c40ef7 Mon Sep 17 00:00:00 2001 From: Kit Patella Date: Mon, 28 Oct 2024 12:21:38 -0700 Subject: [PATCH 2/4] chore: add logger to packager2 Remove (#3151) Signed-off-by: Kit Patella --- src/internal/packager2/remove.go | 6 ++++++ 1 file changed, 6 insertions(+) diff --git a/src/internal/packager2/remove.go b/src/internal/packager2/remove.go index e20382da2d..2d1365b1f8 100644 --- a/src/internal/packager2/remove.go +++ b/src/internal/packager2/remove.go @@ -7,6 +7,7 @@ import ( "context" "errors" "fmt" + "github.com/zarf-dev/zarf/src/pkg/logger" "slices" "helm.sh/helm/v3/pkg/action" @@ -33,6 +34,7 @@ type RemoveOptions struct { // Remove removes a package that was already deployed onto a cluster, uninstalling all installed helm charts. func Remove(ctx context.Context, opt RemoveOptions) error { + l := logger.From(ctx) pkg, err := packageFromSourceOrCluster(ctx, opt.Cluster, opt.Source, opt.SkipSignatureValidation, opt.PublicKeyPath) if err != nil { return err @@ -109,6 +111,7 @@ func Remove(ctx context.Context, opt RemoveOptions) error { } if errors.Is(err, driver.ErrReleaseNotFound) { message.Warnf("Helm release for helm chart '%s' in the namespace '%s' was not found. Was it already removed?", chart.ChartName, chart.Namespace) + l.Warn("helm release was not found. was it already removed?", "name", chart.ChartName, "namespace", chart.Namespace) } // Pop the removed helm chart from the installed charts slice. @@ -119,6 +122,7 @@ func Remove(ctx context.Context, opt RemoveOptions) error { if err != nil { // We warn and ignore errors because we may have removed the cluster that this package was inside of message.Warnf("Unable to update the secret for package %s, this may be normal if the cluster was removed: %s", depPkg.Name, err.Error()) + l.Warn("unable to update secret for package, this may be normal if the cluster was removed", "pkgName", depPkg.Name, "error", err.Error()) } } } @@ -139,6 +143,7 @@ func Remove(ctx context.Context, opt RemoveOptions) error { if err != nil { // We warn and ignore errors because we may have removed the cluster that this package was inside of message.Warnf("Unable to update the secret for package %s, this may be normal if the cluster was removed: %s", depPkg.Name, err.Error()) + l.Warn("unable to update secret package, this may be normal if the cluster was removed", "pkgName", depPkg.Name, "error", err.Error()) } } return nil @@ -157,6 +162,7 @@ func Remove(ctx context.Context, opt RemoveOptions) error { err := opt.Cluster.DeleteDeployedPackage(ctx, depPkg.Name) if err != nil { message.Warnf("Unable to delete the secret for package %s, this may be normal if the cluster was removed: %s", depPkg.Name, err.Error()) + l.Warn("unable to delete secret for package, this may be normal if the cluster was removed", "pkgName", depPkg.Name, "error", err.Error()) } } From d61d099b9adfd795e7c8d96785533d2e16fb34d2 Mon Sep 17 00:00:00 2001 From: Kit Patella Date: Tue, 29 Oct 2024 08:56:22 -0700 Subject: [PATCH 3/4] chore: add logger to packager2 list (#3154) Signed-off-by: Kit Patella --- src/cmd/package.go | 4 ++++ src/pkg/cluster/cluster.go | 3 +++ 2 files changed, 7 insertions(+) diff --git a/src/cmd/package.go b/src/cmd/package.go index 91b46a2243..22e866cdbf 100644 --- a/src/cmd/package.go +++ b/src/cmd/package.go @@ -275,7 +275,11 @@ var packageListCmd = &cobra.Command{ }) } + // NOTE(mkcp): Renders table with message. header := []string{"Package", "Version", "Components"} + // HACK(mkcp): Similar to `package inspect`, we do want to use message here but we have to make sure our feature + // flagging doesn't disable this. Nothing happens after this so it's safe, but still very hacky. + message.InitializePTerm(logger.DestinationDefault) message.Table(header, packageData) // Print out any unmarshalling errors diff --git a/src/pkg/cluster/cluster.go b/src/pkg/cluster/cluster.go index a97b3066bc..73557c4ce2 100644 --- a/src/pkg/cluster/cluster.go +++ b/src/pkg/cluster/cluster.go @@ -18,6 +18,7 @@ import ( "github.com/avast/retry-go/v4" + "github.com/zarf-dev/zarf/src/pkg/logger" "github.com/zarf-dev/zarf/src/pkg/message" "k8s.io/client-go/dynamic" "k8s.io/client-go/tools/clientcmd" @@ -40,8 +41,10 @@ type Cluster struct { // NewClusterWithWait creates a new Cluster instance and waits for the given timeout for the cluster to be ready. func NewClusterWithWait(ctx context.Context) (*Cluster, error) { + l := logger.From(ctx) spinner := message.NewProgressSpinner("Waiting for cluster connection") defer spinner.Stop() + l.Info("waiting for cluster connection") c, err := NewCluster() if err != nil { From 4b7e6e4481ae1615edd648a423f029d56a0c604d Mon Sep 17 00:00:00 2001 From: Kit Patella Date: Tue, 29 Oct 2024 08:56:36 -0700 Subject: [PATCH 4/4] chore: add logger to packager2 inspect (#3153) Signed-off-by: Kit Patella --- src/cmd/package.go | 4 ++++ src/internal/packager/sbom/tools.go | 7 ++++++- src/internal/packager2/inspect.go | 4 ++-- src/pkg/packager/creator/normal.go | 2 +- src/pkg/packager/inspect.go | 2 +- 5 files changed, 14 insertions(+), 5 deletions(-) diff --git a/src/cmd/package.go b/src/cmd/package.go index 22e866cdbf..c0d441a0f0 100644 --- a/src/cmd/package.go +++ b/src/cmd/package.go @@ -201,6 +201,7 @@ var packageInspectCmd = &cobra.Command{ } }, RunE: func(cmd *cobra.Command, args []string) error { + // NOTE(mkcp): Gets user input with message src, err := choosePackage(args) if err != nil { return err @@ -234,6 +235,9 @@ var packageInspectCmd = &cobra.Command{ if err != nil { return fmt.Errorf("failed to inspect package: %w", err) } + // HACK(mkcp): This init call ensures we still can still print Yaml when message is disabled. Remove when we + // release structured logged and don't have to disable message globally in pre-run. + message.InitializePTerm(logger.DestinationDefault) err = utils.ColorPrintYAML(output, nil, false) if err != nil { return err diff --git a/src/internal/packager/sbom/tools.go b/src/internal/packager/sbom/tools.go index 972b709906..ae95ac7486 100644 --- a/src/internal/packager/sbom/tools.go +++ b/src/internal/packager/sbom/tools.go @@ -5,7 +5,9 @@ package sbom import ( + "context" "fmt" + "github.com/zarf-dev/zarf/src/pkg/logger" "path/filepath" "github.com/AlecAivazis/survey/v2" @@ -14,7 +16,8 @@ import ( ) // ViewSBOMFiles opens a browser to view the SBOM files and pauses for user input. -func ViewSBOMFiles(directory string) error { +func ViewSBOMFiles(ctx context.Context, directory string) error { + l := logger.From(ctx) sbomViewFiles, err := filepath.Glob(filepath.Join(directory, "sbom-viewer-*")) if err != nil { return err @@ -22,12 +25,14 @@ func ViewSBOMFiles(directory string) error { if len(sbomViewFiles) == 0 { message.Note("There were no images with software bill-of-materials (SBOM) included.") + l.Info("there were no images with software bill-of-materials (SBOM) included.") return nil } link := sbomViewFiles[0] msg := fmt.Sprintf("This package has %d images with software bill-of-materials (SBOM) included. If your browser did not open automatically you can copy and paste this file location into your browser address bar to view them: %s\n\n", len(sbomViewFiles), link) message.Note(msg) + l.Info("this package has images with software bill-of-materials (SBOM) included. If your browser did not open automatically you can copy and paste this file location into your browser address bar to view them", "SBOMCount", len(sbomViewFiles), "link", link) if err := exec.LaunchURL(link); err != nil { return err } diff --git a/src/internal/packager2/inspect.go b/src/internal/packager2/inspect.go index 0e4c1e0321..ca03d51f4c 100644 --- a/src/internal/packager2/inspect.go +++ b/src/internal/packager2/inspect.go @@ -54,7 +54,7 @@ func InspectList(ctx context.Context, opt ZarfInspectOptions) ([]string, error) if err != nil { return nil, err } - // Only list images if we have have components + // Only list images if we have components if len(pkg.Components) > 0 { for _, component := range pkg.Components { imageList = append(imageList, component.Images...) @@ -104,7 +104,7 @@ func handleSBOMOptions(ctx context.Context, opt ZarfInspectOptions) error { return err } if opt.ViewSBOM { - err := sbom.ViewSBOMFiles(sbomPath) + err := sbom.ViewSBOMFiles(ctx, sbomPath) if err != nil { return err } diff --git a/src/pkg/packager/creator/normal.go b/src/pkg/packager/creator/normal.go index 89bbf64537..d13d05e595 100644 --- a/src/pkg/packager/creator/normal.go +++ b/src/pkg/packager/creator/normal.go @@ -349,7 +349,7 @@ func (pc *PackageCreator) Output(ctx context.Context, dst *layout.PackagePaths, } if pc.createOpts.ViewSBOM { - err := sbom.ViewSBOMFiles(sbomDir) + err := sbom.ViewSBOMFiles(ctx, sbomDir) if err != nil { return err } diff --git a/src/pkg/packager/inspect.go b/src/pkg/packager/inspect.go index 03dee54883..01c6ca4135 100644 --- a/src/pkg/packager/inspect.go +++ b/src/pkg/packager/inspect.go @@ -51,7 +51,7 @@ func (p *Packager) Inspect(ctx context.Context) error { } if p.cfg.InspectOpts.ViewSBOM { - err := sbom.ViewSBOMFiles(sbomDir) + err := sbom.ViewSBOMFiles(ctx, sbomDir) if err != nil { return err }