finish re-adding message logging, add durations to debug done logs

Signed-off-by: Kit Patella <[email protected]>

src/cmd/root.go

@@ -208,7 +208,12 @@ func setupMessage(cfg messageCfg) error {
 	// HACK(mkcp): Discard message logs if feature is disabled. message calls InitializePTerm once in its init() fn so
 	//             this ends up being a messy solution.
 	if cfg.featureDisabled {
+		// Discard all* PTerm messages. *see below
 		message.InitializePTerm(io.Discard)
+		// Disable all progress bars and spinners
+		message.NoProgress = true
+		// Ensures no user input is needed while we maintain backwards compatibility with message
+		config.CommonOptions.Confirm = true
 		return nil
 	}
 

src/internal/packager/helm/repo.go

@@ -13,6 +13,7 @@ import (
 	"os"
 	"path/filepath"
 	"strings"
+	"time"
 
 	"github.com/defenseunicorns/pkg/helpers/v2"
 	"helm.sh/helm/v3/pkg/action"
@@ -164,6 +165,7 @@ func (h *Helm) DownloadPublishedChart(ctx context.Context, cosignKeyPath string)
 		"version", h.chart.Version,
 		"repo", h.chart.URL,
 	)
+	start := time.Now()
 	// TODO(mkcp): Remove message on logger release
 	spinner := message.NewProgressSpinner("Processing helm chart %s:%s from repo %s", h.chart.Name, h.chart.Version, h.chart.URL)
 	defer spinner.Stop()
@@ -267,7 +269,12 @@ func (h *Helm) DownloadPublishedChart(ctx context.Context, cosignKeyPath string)
 	}
 
 	spinner.Success()
-	l.Debug("done downloading helm chart")
+	l.Debug("done downloading helm chart",
+		"name", h.chart.Name,
+		"version", h.chart.Version,
+		"repo", h.chart.URL,
+		"duration", time.Since(start),
+	)
 	return nil
 }
 

src/internal/packager/images/pull.go

@@ -17,6 +17,7 @@ import (
 	"strings"
 	"sync"
 	"sync/atomic"
+	"time"
 
 	"github.com/avast/retry-go/v4"
 	"github.com/defenseunicorns/pkg/helpers/v2"
@@ -65,6 +66,8 @@ func checkForIndex(refInfo transform.Image, desc *remote.Descriptor) error {
 func Pull(ctx context.Context, cfg PullConfig) (map[transform.Image]v1.Image, error) {
 	l := logger.From(ctx)
 	var longer string
+	pullStart := time.Now()
+
 	imageCount := len(cfg.ImageList)
 	// Give some additional user feedback on larger image sets
 	if imageCount > 15 {
@@ -83,18 +86,19 @@ func Pull(ctx context.Context, cfg PullConfig) (map[transform.Image]v1.Image, er
 	}
 
 	// Give some additional user feedback on larger image sets
+	imageFetchStart := time.Now()
 	// 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)
+		l.Info("fetching info for images. This step may take a couple of minutes to complete", "count", c, "destination", cfg.DestinationDirectory)
 		break
 	case c > 5:
-		l.Info("fetching info for images. This step may take several seconds to complete", "count", c)
+		l.Info("fetching info for images. This step may take several seconds to complete", "count", c, "destination", cfg.DestinationDirectory)
 		break
 	default:
-		l.Info("fetching info for images", "count", c)
+		l.Info("fetching info for images", "count", c, "destination", cfg.DestinationDirectory)
 	}
 
 	logs.Warn.SetOutput(&message.DebugWriter{})
@@ -240,7 +244,7 @@ func Pull(ctx context.Context, cfg PullConfig) (map[transform.Image]v1.Image, er
 
 	// TODO(mkcp): Remove message on logger release
 	spinner.Successf("Fetched info for %d images", imageCount)
-	l.Debug("done fetching info for images", "count", len(cfg.ImageList))
+	l.Debug("done fetching info for images", "count", len(cfg.ImageList), "duration", time.Since(imageFetchStart))
 
 	doneSaving := make(chan error)
 	updateText := fmt.Sprintf("Pulling %d images", imageCount)
@@ -303,6 +307,8 @@ func Pull(ctx context.Context, cfg PullConfig) (map[transform.Image]v1.Image, er
 		return nil, err
 	}
 
+	l.Debug("done pulling images", "count", len(cfg.ImageList), "duration", time.Since(pullStart))
+
 	return fetched, nil
 }
 

src/internal/packager/sbom/catalog.go

@@ -8,11 +8,13 @@ import (
 	"context"
 	"embed"
 	"fmt"
-	"github.com/zarf-dev/zarf/src/pkg/logger"
 	"os"
 	"path/filepath"
 	"regexp"
 
+	"github.com/zarf-dev/zarf/src/pkg/logger"
+	"github.com/zarf-dev/zarf/src/pkg/message"
+
 	"github.com/anchore/stereoscope/pkg/file"
 	"github.com/anchore/stereoscope/pkg/image"
 	"github.com/anchore/syft/syft"
@@ -37,6 +39,7 @@ import (
 
 // Builder is the main struct used to build SBOM artifacts.
 type Builder struct {
+	spinner    *message.Spinner
 	cachePath  string
 	imagesPath string
 	outputDir  string
@@ -59,10 +62,13 @@ func Catalog(ctx context.Context, componentSBOMs map[string]*layout.ComponentSBO
 		return err
 	}
 	builder := Builder{
+		// TODO(mkcp): Remove message on logger release
+		spinner:    message.NewProgressSpinner("Creating SBOMs for %d images and %d components with files.", imageCount, componentCount),
 		cachePath:  cachePath,
 		imagesPath: paths.Images.Base,
 		outputDir:  paths.SBOMs.Path,
 	}
+	defer builder.spinner.Stop()
 	l.Info("creating SBOMs for images and components with files", "images", imageCount, "components", componentCount)
 
 	// Ensure the sbom directory exists
@@ -71,25 +77,34 @@ func Catalog(ctx context.Context, componentSBOMs map[string]*layout.ComponentSBO
 	// Generate a list of images and files for the sbom viewer
 	json, err := builder.generateJSONList(componentSBOMs, imageList)
 	if err != nil {
+		// TODO(mkcp): Remove message on logger release
+		builder.spinner.Errorf(err, "Unable to generate the SBOM image list")
 		l.Error("unable to generate the SBOM image list", "error", err.Error())
 		return err
 	}
 	builder.jsonList = json
 
 	// Generate SBOM for each image
+	currImage := 1
 	l.Info("creating SBOMs for images", "images", imageCount)
 	for _, refInfo := range imageList {
+		// TODO(mkcp): Remove message on logger release
+		builder.spinner.Updatef("Creating image SBOMs (%d of %d): %s", currImage, imageCount, refInfo.Reference)
 		l.Info("creating image SBOMs", "reference", refInfo.Reference)
 
 		// Get the image that we are creating an SBOM for
 		img, err := utils.LoadOCIImage(paths.Images.Base, refInfo)
 		if err != nil {
+			// TODO(mkcp): Remove message on logger release
+			builder.spinner.Errorf(err, "Unable to load the image to generate an SBOM")
 			l.Error("unable to load the image to generate an SBOM", "error", err.Error())
 			return err
 		}
 
 		jsonData, err := builder.createImageSBOM(ctx, img, refInfo.Reference)
 		if err != nil {
+			// TODO(mkcp): Remove message on logger release
+			builder.spinner.Errorf(err, "Unable to create SBOM for image %s", refInfo.Reference)
 			l.Error("unable to create SBOM for image",
 				"reference", refInfo.Reference,
 				"error", err.Error(),
@@ -98,48 +113,71 @@ func Catalog(ctx context.Context, componentSBOMs map[string]*layout.ComponentSBO
 		}
 
 		if err = builder.createSBOMViewerAsset(refInfo.Reference, jsonData); err != nil {
+			// TODO(mkcp): Remove message on logger release
+			builder.spinner.Errorf(err, "Unable to create SBOM viewer for image %s", refInfo.Reference)
 			l.Error("unable to create SBOM viewer for image",
 				"reference", refInfo.Reference,
 			)
 			return err
 		}
+
+		currImage++
 	}
 
+	currComponent := 1
+
 	// Generate SBOM for each component
 	l.Info("creating SBOMs for components", "components", componentCount)
 	for component := range componentSBOMs {
+		// TODO(mkcp): Remove message on logger release
+		builder.spinner.Updatef("Creating component file SBOMs (%d of %d): %s", currComponent, componentCount, component)
 		l.Info("creating component file SBOMs", "component", component)
 
 		if componentSBOMs[component] == nil {
+			// TODO(mkcp): Remove message on logger release
+			message.Debugf("Component %s has invalid SBOM, skipping", component)
 			l.Debug("component has invalid SBOM, skipping", "component", component)
 			continue
 		}
 
 		jsonData, err := builder.createFileSBOM(ctx, *componentSBOMs[component], component)
 		if err != nil {
+			// TODO(mkcp): Remove message on logger release
+			builder.spinner.Errorf(err, "Unable to create SBOM for component %s", component)
 			l.Error("unable to create SBOM for component", "component", component, "error", err.Error())
 			return err
 		}
 
 		if err = builder.createSBOMViewerAsset(fmt.Sprintf("%s%s", componentPrefix, component), jsonData); err != nil {
+			// TODO(mkcp): Remove message on logger release
+			builder.spinner.Errorf(err, "Unable to create SBOM viewer for component %s", component)
 			l.Error("unable to create SBOM for component", "component", component, "error", err.Error())
 			return err
 		}
+
+		currComponent++
 	}
 
 	// Include the compare tool if there are any image SBOMs OR component SBOMs
 	if len(componentSBOMs) > 0 || len(imageList) > 0 {
 		if err := builder.createSBOMCompareAsset(); err != nil {
+			// TODO(mkcp): Remove message on logger release
+			builder.spinner.Errorf(err, "Unable to create SBOM compare tool")
 			l.Error("unable to create SBOM compare tool", "error", err.Error())
 			return err
 		}
 	}
 
 	if err := paths.SBOMs.Archive(); err != nil {
+		// TODO(mkcp): Remove message on logger release
+		builder.spinner.Errorf(err, "Unable to archive SBOMs")
 		l.Error("unable to archive SBOMs", "error", err.Error())
 		return err
 	}
 
+	// TODO(mkcp): Remove message on logger release
+	builder.spinner.Success()
+
 	l.Debug("done building catalog")
 	return nil
 }

src/internal/packager/template/template.go

@@ -8,7 +8,6 @@ import (
 	"context"
 	"encoding/base64"
 	"fmt"
-	"github.com/zarf-dev/zarf/src/pkg/logger"
 	"strings"
 
 	"github.com/zarf-dev/zarf/src/api/v1alpha1"
@@ -17,6 +16,7 @@ import (
 	"github.com/defenseunicorns/pkg/helpers/v2"
 	"github.com/zarf-dev/zarf/src/config"
 	"github.com/zarf-dev/zarf/src/pkg/interactive"
+	"github.com/zarf-dev/zarf/src/pkg/logger"
 	"github.com/zarf-dev/zarf/src/pkg/message"
 	"github.com/zarf-dev/zarf/src/pkg/utils"
 	"github.com/zarf-dev/zarf/src/pkg/variables"

src/pkg/layout/component.go

@@ -11,11 +11,10 @@ import (
 	"os"
 	"path/filepath"
 
-	"github.com/zarf-dev/zarf/src/pkg/logger"
-
 	"github.com/defenseunicorns/pkg/helpers/v2"
 	"github.com/mholt/archiver/v3"
 	"github.com/zarf-dev/zarf/src/api/v1alpha1"
+	"github.com/zarf-dev/zarf/src/pkg/logger"
 	"github.com/zarf-dev/zarf/src/pkg/message"
 )
 
@@ -65,6 +64,8 @@ func (c *Components) Archive(ctx context.Context, component v1alpha1.ZarfCompone
 	}
 	if size > 0 {
 		tb := fmt.Sprintf("%s.tar", base)
+		// TODO(mkcp): Remove message on logger release
+		message.Debugf("Archiving %q", name)
 		l.Debug("archiving component", "name", name)
 		if err := helpers.CreateReproducibleTarballFromDir(base, name, tb); err != nil {
 			return err
@@ -74,6 +75,8 @@ func (c *Components) Archive(ctx context.Context, component v1alpha1.ZarfCompone
 		}
 		c.Tarballs[name] = tb
 	} else {
+		// TODO(mkcp): Remove message on logger release
+		message.Debugf("Component %q is empty, skipping archiving", name)
 		l.Debug("component is empty, skipping archiving", "name", name)
 	}
 

src/pkg/layout/package.go

@@ -13,15 +13,14 @@ import (
 	"slices"
 	"strings"
 
-	"github.com/zarf-dev/zarf/src/pkg/logger"
-
 	"github.com/Masterminds/semver/v3"
 	"github.com/defenseunicorns/pkg/helpers/v2"
 	"github.com/google/go-containerregistry/pkg/crane"
 	"github.com/mholt/archiver/v3"
 	ocispec "github.com/opencontainers/image-spec/specs-go/v1"
 	"github.com/zarf-dev/zarf/src/api/v1alpha1"
 	"github.com/zarf-dev/zarf/src/pkg/interactive"
+	"github.com/zarf-dev/zarf/src/pkg/logger"
 	"github.com/zarf-dev/zarf/src/pkg/message"
 	"github.com/zarf-dev/zarf/src/pkg/packager/deprecated"
 	"github.com/zarf-dev/zarf/src/pkg/utils"
@@ -230,56 +229,27 @@ func (pp *PackagePaths) GenerateChecksums() (string, error) {
 // ArchivePackage creates an archive for a Zarf package.
 func (pp *PackagePaths) ArchivePackage(ctx context.Context, destinationTarball string, maxPackageSizeMB int) error {
 	l := logger.From(ctx)
-	l.Info("archiving zarf package", "base", pp.Base, "destination", destinationTarball)
-
-	// Make the archive
-	archiveSrc := []string{pp.Base + string(os.PathSeparator)}
-	if err := archiver.Archive(archiveSrc, destinationTarball); err != nil {
-		return fmt.Errorf("unable to create package: %w", err)
-	}
-	l.Debug("ArchivePackage wrote", "base", pp.Base, "destination", destinationTarball)
-
-	fi, err := os.Stat(destinationTarball)
-	if err != nil {
-		return fmt.Errorf("unable to read the package archive: %w", err)
-	}
-
-	l.Debug("package saved", "destination", destinationTarball)
-
-	// Convert Megabytes to bytes.
-	chunkSize := maxPackageSizeMB * 1000 * 1000
-
-	// If a chunk size was specified and the package is larger than the chunk size, split it into chunks.
-	if maxPackageSizeMB > 0 && fi.Size() > int64(chunkSize) {
-		if fi.Size()/int64(chunkSize) > 999 {
-			return fmt.Errorf("unable to split the package archive into multiple files: must be less than 1,000 files")
-		}
-		l.Info("package is larger than max, splitting into multiple files", "maxPackageSize", maxPackageSizeMB)
-		err := splitFile(destinationTarball, chunkSize)
-		if err != nil {
-			return fmt.Errorf("unable to split the package archive into multiple files: %w", err)
-		}
-	}
-	return nil
-}
-
-// ArchivePackageSpinner creates an archive for a Zarf package and handles displaying a spinner
-func (pp *PackagePaths) ArchivePackageSpinner(destinationTarball string, maxPackageSizeMB int) error {
+	// TODO(mkcp): Remove message on logger release
 	spinner := message.NewProgressSpinner("Writing %s to %s", pp.Base, destinationTarball)
 	defer spinner.Stop()
+	l.Info("archiving zarf package", "base", pp.Base, "destination", destinationTarball)
 
 	// Make the archive
 	archiveSrc := []string{pp.Base + string(os.PathSeparator)}
 	if err := archiver.Archive(archiveSrc, destinationTarball); err != nil {
 		return fmt.Errorf("unable to create package: %w", err)
 	}
+	// TODO(mkcp): Remove message on logger release
 	spinner.Updatef("Wrote %s to %s", pp.Base, destinationTarball)
+	l.Debug("ArchivePackage wrote", "base", pp.Base, "destination", destinationTarball)
 
 	fi, err := os.Stat(destinationTarball)
 	if err != nil {
 		return fmt.Errorf("unable to read the package archive: %w", err)
 	}
+	// TODO(mkcp): Remove message on logger release
 	spinner.Successf("Package saved to %q", destinationTarball)
+	l.Debug("package saved", "destination", destinationTarball)
 
 	// Convert Megabytes to bytes.
 	chunkSize := maxPackageSizeMB * 1000 * 1000
@@ -290,6 +260,7 @@ func (pp *PackagePaths) ArchivePackageSpinner(destinationTarball string, maxPack
 			return fmt.Errorf("unable to split the package archive into multiple files: must be less than 1,000 files")
 		}
 		message.Notef("Package is larger than %dMB, splitting into multiple files", maxPackageSizeMB)
+		l.Info("package is larger than max, splitting into multiple files", "maxPackageSize", maxPackageSizeMB)
 		err := splitFile(destinationTarball, chunkSize)
 		if err != nil {
 			return fmt.Errorf("unable to split the package archive into multiple files: %w", err)

src/pkg/logger/logger.go

@@ -67,8 +67,7 @@ func ParseLevel(s string) (Level, error) {
 
 // Format declares the kind of logging handler to use.
 // NOTE(mkcp): An empty Format defaults to "none" while logger is being worked on, but this is intended to use "text"
-//
-//	on release.
+// on release.
 type Format string
 
 // ToLower takes a Format string and converts it to lowercase for case-agnostic validation. Users shouldn't have to care