diff --git a/src/cmd/root.go b/src/cmd/root.go index b66ba4926a..c1661b2dd0 100644 --- a/src/cmd/root.go +++ b/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 } diff --git a/src/internal/packager/helm/repo.go b/src/internal/packager/helm/repo.go index 36fbc0686d..7791771282 100644 --- a/src/internal/packager/helm/repo.go +++ b/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 } diff --git a/src/internal/packager/images/pull.go b/src/internal/packager/images/pull.go index 1e10f867fd..7e869c232d 100644 --- a/src/internal/packager/images/pull.go +++ b/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 } diff --git a/src/internal/packager/sbom/catalog.go b/src/internal/packager/sbom/catalog.go index c5051b4856..81010877e4 100755 --- a/src/internal/packager/sbom/catalog.go +++ b/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 } diff --git a/src/internal/packager/template/template.go b/src/internal/packager/template/template.go index 662e7a2647..ec53877db1 100644 --- a/src/internal/packager/template/template.go +++ b/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" diff --git a/src/pkg/layout/component.go b/src/pkg/layout/component.go index e82409aa68..3e524852fe 100644 --- a/src/pkg/layout/component.go +++ b/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) } diff --git a/src/pkg/layout/package.go b/src/pkg/layout/package.go index ac2f4d875d..2141de586f 100644 --- a/src/pkg/layout/package.go +++ b/src/pkg/layout/package.go @@ -13,8 +13,6 @@ 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" @@ -22,6 +20,7 @@ import ( 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) diff --git a/src/pkg/logger/logger.go b/src/pkg/logger/logger.go index 79d8a01259..8008129462 100644 --- a/src/pkg/logger/logger.go +++ b/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 diff --git a/src/pkg/packager/actions/actions.go b/src/pkg/packager/actions/actions.go index b70446864b..e688e0b6ce 100644 --- a/src/pkg/packager/actions/actions.go +++ b/src/pkg/packager/actions/actions.go @@ -7,6 +7,7 @@ package actions import ( "context" "fmt" + "github.com/zarf-dev/zarf/src/pkg/logger" "regexp" "runtime" "strings" @@ -23,7 +24,7 @@ import ( // Run runs all provided actions. func Run(ctx context.Context, defaultCfg v1alpha1.ZarfComponentActionDefaults, actions []v1alpha1.ZarfComponentAction, variableConfig *variables.VariableConfig) error { - // FIXME(mkcp): Interactive + // TODO(mkcp): Remove interactive on logger release if variableConfig == nil { variableConfig = template.GetZarfVariableConfig(ctx) } @@ -37,12 +38,13 @@ func Run(ctx context.Context, defaultCfg v1alpha1.ZarfComponentActionDefaults, a } // Run commands that a component has provided. -// TODO(mkcp): Migrate actions to logger func runAction(ctx context.Context, defaultCfg v1alpha1.ZarfComponentActionDefaults, action v1alpha1.ZarfComponentAction, variableConfig *variables.VariableConfig) error { var cmdEscaped string var out string var err error cmd := action.Cmd + l := logger.From(ctx) + start := time.Now() // If the action is a wait, convert it to a command. if action.Wait != nil { @@ -78,14 +80,17 @@ func runAction(ctx context.Context, defaultCfg v1alpha1.ZarfComponentActionDefau cmdEscaped = helpers.Truncate(cmd, 60, false) } + // TODO(mkcp): Remove message on logger release spinner := message.NewProgressSpinner("Running \"%s\"", cmdEscaped) // Persist the spinner output so it doesn't get overwritten by the command output. spinner.EnablePreserveWrites() + l.Info("running command", "cmd", cmdEscaped) actionDefaults := actionGetCfg(ctx, defaultCfg, action, variableConfig.GetAllTemplates()) if cmd, err = actionCmdMutation(ctx, cmd, actionDefaults.Shell); err != nil { spinner.Errorf(err, "Error mutating command: %s", cmdEscaped) + l.Error("error mutating command", "cmd", cmdEscaped, "err", err.Error()) } duration := time.Duration(actionDefaults.MaxTotalSeconds) * time.Second @@ -115,10 +120,13 @@ retryCmd: // If the action has a wait, change the spinner message to reflect that on success. if action.Wait != nil { spinner.Successf("Wait for \"%s\" succeeded", cmdEscaped) - } else { - spinner.Successf("Completed \"%s\"", cmdEscaped) + l.Debug("wait for action succeeded", "cmd", cmdEscaped, "duration", time.Since(start)) + return nil } + spinner.Successf("Completed \"%s\"", cmdEscaped) + l.Debug("completed action", "cmd", cmdEscaped, "duration", time.Since(start)) + // If the command ran successfully, continue to the next action. return nil } @@ -126,6 +134,7 @@ retryCmd: // If no timeout is set, run the command and return or continue retrying. if actionDefaults.MaxTotalSeconds < 1 { spinner.Updatef("Waiting for \"%s\" (no timeout)", cmdEscaped) + l.Info("waiting for action (no timeout)", "cmd", cmdEscaped) //TODO (schristoff): Make it so tryCmd can take a normal ctx if err := tryCmd(context.Background()); err != nil { continue retryCmd @@ -136,6 +145,7 @@ retryCmd: // Run the command on repeat until success or timeout. spinner.Updatef("Waiting for \"%s\" (timeout: %ds)", cmdEscaped, actionDefaults.MaxTotalSeconds) + l.Info("waiting for action", "cmd", cmdEscaped, "timeout", actionDefaults.MaxTotalSeconds) select { // On timeout break the loop to abort. case <-timeout: @@ -204,7 +214,7 @@ func convertWaitToCmd(_ context.Context, wait v1alpha1.ZarfComponentActionWait, } // Perform some basic string mutations to make commands more useful. -func actionCmdMutation(_ context.Context, cmd string, shellPref v1alpha1.Shell) (string, error) { +func actionCmdMutation(ctx context.Context, cmd string, shellPref v1alpha1.Shell) (string, error) { zarfCommand, err := utils.GetFinalExecutableCommand() if err != nil { return cmd, err @@ -226,7 +236,9 @@ func actionCmdMutation(_ context.Context, cmd string, shellPref v1alpha1.Shell) get, err := helpers.MatchRegex(envVarRegex, cmd) if err == nil { newCmd := strings.ReplaceAll(cmd, get("envIndicator"), fmt.Sprintf("$Env:%s", get("varName"))) + // TODO(mkcp): Remove message on logger release message.Debugf("Converted command \"%s\" to \"%s\" t", cmd, newCmd) + logger.From(ctx).Debug("converted command", "cmd", cmd, "newCmd", newCmd) cmd = newCmd } } @@ -275,9 +287,12 @@ func actionGetCfg(_ context.Context, cfg v1alpha1.ZarfComponentActionDefaults, a } func actionRun(ctx context.Context, cfg v1alpha1.ZarfComponentActionDefaults, cmd string, shellPref v1alpha1.Shell, spinner *message.Spinner) (string, error) { + l := logger.From(ctx) shell, shellArgs := exec.GetOSShell(shellPref) + // TODO(mkcp): Remove message on logger release message.Debugf("Running command in %s: %s", shell, cmd) + l.Debug("running command", "shell", shell, "cmd", cmd) execCfg := exec.Config{ Env: cfg.Env, @@ -292,7 +307,9 @@ func actionRun(ctx context.Context, cfg v1alpha1.ZarfComponentActionDefaults, cm out, errOut, err := exec.CmdWithContext(ctx, execCfg, shell, append(shellArgs, cmd)...) // Dump final complete output (respect mute to prevent sensitive values from hitting the logs). if !cfg.Mute { + // TODO(mkcp): Remove message on logger release message.Debug(cmd, out, errOut) + l.Debug("action complete", "cmd", cmd, "out", out, "errOut", errOut) } return out, err diff --git a/src/pkg/packager/common.go b/src/pkg/packager/common.go index 5be125b337..e664455b5c 100644 --- a/src/pkg/packager/common.go +++ b/src/pkg/packager/common.go @@ -98,6 +98,8 @@ func New(cfg *types.PackagerConfig, mods ...Modifier) (*Packager, error) { if config.CommonOptions.TempDirectory != "" { // If the cache directory is within the temp directory, warn the user if strings.HasPrefix(cacheDir, tmpDir) { + // TODO(mkcp): Remove message on logger release + message.Warnf("The cache directory (%q) is within the temp directory (%q) and will be removed when the temp directory is cleaned up", config.CommonOptions.CachePath, config.CommonOptions.TempDirectory) l.Warn("the cache directory is within the temp directory and will be removed when the temp directory is cleaned up", "cacheDir", cacheDir, "tmpDir", tmpDir) } } @@ -116,6 +118,8 @@ func New(cfg *types.PackagerConfig, mods ...Modifier) (*Packager, error) { if err != nil { return nil, fmt.Errorf("unable to create package temp paths: %w", err) } + // TODO(mkcp): Remove message on logger release + message.Debug("Using temporary directory:", dir) l.Debug("using temporary directory", "tmpDir", dir) pkgr.layout = layout.New(dir) } diff --git a/src/pkg/packager/create.go b/src/pkg/packager/create.go index ac2a148277..b832aa2364 100755 --- a/src/pkg/packager/create.go +++ b/src/pkg/packager/create.go @@ -8,19 +8,23 @@ import ( "context" "fmt" "os" + "time" "github.com/zarf-dev/zarf/src/config" + "github.com/zarf-dev/zarf/src/pkg/layout" "github.com/zarf-dev/zarf/src/pkg/logger" + "github.com/zarf-dev/zarf/src/pkg/message" + "github.com/zarf-dev/zarf/src/pkg/packager/creator" "github.com/defenseunicorns/pkg/helpers/v2" - "github.com/zarf-dev/zarf/src/pkg/layout" - "github.com/zarf-dev/zarf/src/pkg/packager/creator" ) // Create generates a Zarf package tarball for a given PackageConfig and optional base directory. func (p *Packager) Create(ctx context.Context) error { l := logger.From(ctx) l.Info("starting package create") + cStart := time.Now() + // Begin setup cwd, err := os.Getwd() if err != nil { @@ -34,6 +38,8 @@ func (p *Packager) Create(ctx context.Context) error { if err := os.Chdir(baseDir); err != nil { return fmt.Errorf("unable to access directory %q: %w", baseDir, err) } + // TODO(mkcp): Remove message on logger release + message.Note(fmt.Sprintf("Using build directory %s", p.cfg.CreateOpts.BaseDir)) l.Info("using build directory", "baseDir", baseDir) // Setup package creator @@ -44,7 +50,6 @@ func (p *Packager) Create(ctx context.Context) error { } // Load package def - l.Debug("loading package definition", "layout", lo) pkg, warnings, err := pc.LoadPackageDefinition(p.ctx, lo) if err != nil { return err @@ -60,25 +65,27 @@ func (p *Packager) Create(ctx context.Context) error { "description", pkg.Metadata.Description, ) - // TODO(mkcp): Remove interactive when + // TODO(mkcp): Remove interactive on logger release if !p.confirmAction(config.ZarfCreateStage, warnings, nil) { return fmt.Errorf("package creation canceled") } + aStart := time.Now() l.Debug("starting package assembly", "kind", pkg.Kind) - // TODO(mkcp): Migrate to logger - if err := pc.Assemble(p.ctx, p.layout, pkg.Components, pkg.Metadata.Architecture); err != nil { + if err := pc.Assemble(ctx, p.layout, pkg.Components, pkg.Metadata.Architecture); err != nil { return err } + l.Debug("done package assembly", "kind", pkg.Kind, "duration", time.Since(aStart)) // cd back for output if err := os.Chdir(cwd); err != nil { return err } - // TODO(mkcp): migrate pc.Output to logger - if err = pc.Output(p.ctx, p.layout, &p.cfg.Pkg); err != nil { + if err = pc.Output(ctx, p.layout, &pkg); err != nil { return err } + + l.Debug("done creating package", "kind", pkg.Kind, "duration", time.Since(cStart)) return nil } diff --git a/src/pkg/packager/creator/normal.go b/src/pkg/packager/creator/normal.go index e04c2957a1..1a5b88a7f5 100644 --- a/src/pkg/packager/creator/normal.go +++ b/src/pkg/packager/creator/normal.go @@ -15,9 +15,6 @@ import ( "strings" "time" - "github.com/zarf-dev/zarf/src/pkg/logger" - "github.com/zarf-dev/zarf/src/pkg/message" - "github.com/defenseunicorns/pkg/helpers/v2" "github.com/defenseunicorns/pkg/oci" "github.com/mholt/archiver/v3" @@ -30,6 +27,8 @@ import ( "github.com/zarf-dev/zarf/src/internal/packager/kustomize" "github.com/zarf-dev/zarf/src/internal/packager/sbom" "github.com/zarf-dev/zarf/src/pkg/layout" + "github.com/zarf-dev/zarf/src/pkg/logger" + "github.com/zarf-dev/zarf/src/pkg/message" "github.com/zarf-dev/zarf/src/pkg/packager/actions" "github.com/zarf-dev/zarf/src/pkg/packager/filters" "github.com/zarf-dev/zarf/src/pkg/packager/sources" @@ -64,6 +63,10 @@ func NewPackageCreator(createOpts types.ZarfCreateOptions, cwd string) *PackageC // LoadPackageDefinition loads and configures a zarf.yaml file during package create. func (pc *PackageCreator) LoadPackageDefinition(ctx context.Context, src *layout.PackagePaths) (pkg v1alpha1.ZarfPackage, warnings []string, err error) { + l := logger.From(ctx) + start := time.Now() + l.Debug("start loading package definiton", "src", src.ZarfYAML) + pkg, warnings, err = src.ReadZarfYAML() if err != nil { return v1alpha1.ZarfPackage{}, nil, err @@ -118,6 +121,7 @@ func (pc *PackageCreator) LoadPackageDefinition(ctx context.Context, src *layout return v1alpha1.ZarfPackage{}, nil, err } + l.Debug("done loading package definition", "src", src.ZarfYAML, "duration", time.Since(start)) return pkg, warnings, nil } @@ -134,11 +138,12 @@ func (pc *PackageCreator) Assemble(ctx context.Context, dst *layout.PackagePaths onFailure := func() { if err := actions.Run(ctx, onCreate.Defaults, onCreate.OnFailure, nil); err != nil { + // TODO(mkcp): Remove message on logger release + message.Debugf("unable to run component failure action: %s", err.Error()) l.Debug("unable to run component failure action", "error", err.Error()) } } - // TODO(mkcp): Migrate to logger if err := pc.addComponent(ctx, component, dst); err != nil { onFailure() return fmt.Errorf("unable to add component %q: %w", component.Name, err) @@ -151,7 +156,6 @@ func (pc *PackageCreator) Assemble(ctx context.Context, dst *layout.PackagePaths } if !skipSBOMFlagUsed { - // TODO(mkcp): Migrate to logger componentSBOM, err := pc.getFilesToSBOM(component, dst) if err != nil { return fmt.Errorf("unable to create component SBOM: %w", err) @@ -162,7 +166,6 @@ func (pc *PackageCreator) Assemble(ctx context.Context, dst *layout.PackagePaths } // Combine all component images into a single entry for efficient layer reuse. - // TODO(mkcp): Migrate to logger for _, src := range component.Images { refInfo, err := transform.ParseImageRef(src) if err != nil { @@ -180,6 +183,8 @@ func (pc *PackageCreator) Assemble(ctx context.Context, dst *layout.PackagePaths // Images are handled separately from other component assets. if len(imageList) > 0 { + // TODO(mkcp): Remove message on logger release + message.HeaderInfof("📦 PACKAGE IMAGES") dst.AddImages() cachePath, err := config.GetAbsCachePath() @@ -194,7 +199,6 @@ func (pc *PackageCreator) Assemble(ctx context.Context, dst *layout.PackagePaths CacheDirectory: filepath.Join(cachePath, layout.ImagesDir), } - // TODO(mkcp): Migrate to logger pulled, err := images.Pull(ctx, pullCfg) if err != nil { return err @@ -222,6 +226,8 @@ func (pc *PackageCreator) Assemble(ctx context.Context, dst *layout.PackagePaths // Ignore SBOM creation if the flag is set. if skipSBOMFlagUsed { + // TODO(mkcp): Remove message on logger release + message.Debug("Skipping image SBOM processing per --skip-sbom flag") l.Debug("skipping image SBOM processing per --skip-sbom flag") return nil } @@ -247,6 +253,10 @@ func (pc *PackageCreator) Assemble(ctx context.Context, dst *layout.PackagePaths // - writes the Zarf package as a tarball to a local directory, // or an OCI registry based on the --output flag func (pc *PackageCreator) Output(ctx context.Context, dst *layout.PackagePaths, pkg *v1alpha1.ZarfPackage) (err error) { + l := logger.From(ctx) + start := time.Now() + l.Debug("starting package output", "kind", pkg.Kind) + // Process the component directories into compressed tarballs // NOTE: This is purposefully being done after the SBOM cataloging for _, component := range pkg.Components { @@ -282,6 +292,7 @@ func (pc *PackageCreator) Output(ctx context.Context, dst *layout.PackagePaths, if err != nil { return err } + // TODO(mkcp): Port zoci.NewRemote to new logger remote, err := zoci.NewRemote(ref, oci.PlatformForArch(config.GetArch())) if err != nil { return err @@ -298,6 +309,7 @@ func (pc *PackageCreator) Output(ctx context.Context, dst *layout.PackagePaths, if config.CommonOptions.InsecureSkipTLSVerify { flags = append(flags, "--insecure-skip-tls-verify") } + // TODO(mkcp): Remove message on logger release message.Title("To inspect/deploy/pull:", "") message.ZarfCommand("package inspect %s %s", helpers.OCIURLPrefix+remote.Repo().Reference.String(), strings.Join(flags, " ")) message.ZarfCommand("package deploy %s %s", helpers.OCIURLPrefix+remote.Repo().Reference.String(), strings.Join(flags, " ")) @@ -308,7 +320,10 @@ func (pc *PackageCreator) Output(ctx context.Context, dst *layout.PackagePaths, tarballPath := filepath.Join(pc.createOpts.Output, packageName) // Try to remove the package if it already exists. - _ = os.Remove(tarballPath) + err = os.Remove(tarballPath) + if err != nil { + logger.From(ctx).Error(err.Error()) + } // Create the package tarball. if err := dst.ArchivePackage(ctx, tarballPath, pc.createOpts.MaxPackageSizeMB); err != nil { @@ -340,6 +355,7 @@ func (pc *PackageCreator) Output(ctx context.Context, dst *layout.PackagePaths, } } } + l.Debug("done package output", "kind", pkg.Kind, "duration", time.Since(start)) return nil } @@ -347,7 +363,10 @@ func (pc *PackageCreator) Output(ctx context.Context, dst *layout.PackagePaths, // if/elses that can be de-nested. func (pc *PackageCreator) addComponent(ctx context.Context, component v1alpha1.ZarfComponent, dst *layout.PackagePaths) error { l := logger.From(ctx) - l.Info("adding component", "component", component.Name) + // TODO(mkcp): Remove message on logger release + message.HeaderInfof("📦 %s COMPONENT", strings.ToUpper(component.Name)) + l.Info("adding component", "name", component.Name) + start := time.Now() componentPaths, err := dst.Components.Create(component) if err != nil { @@ -435,10 +454,15 @@ func (pc *PackageCreator) addComponent(ctx context.Context, component v1alpha1.Z // Run data injections injectionsCount := len(component.DataInjections) if injectionsCount > 0 { + injectStart := time.Now() + // TODO(mkcp): Remove message on logger release + spinner := message.NewProgressSpinner("Loading data injections") + defer spinner.Stop() l.Info("data injections found, running", "injections", injectionsCount) for dataIdx, data := range component.DataInjections { target := data.Target + spinner.Updatef("Copying data injection %s for %s", target.Path, target.Selector) l.Info("copying data injection", "path", target.Path, "selector", target.Selector) rel := filepath.Join(layout.DataInjectionsDir, strconv.Itoa(dataIdx), filepath.Base(target.Path)) @@ -455,11 +479,13 @@ func (pc *PackageCreator) addComponent(ctx context.Context, component v1alpha1.Z } } } - l.Debug("done loading data injections") + spinner.Success() + l.Debug("done loading data injections", "duration", injectStart) } // Process k8s manifests if len(component.Manifests) > 0 { + manifestStart := time.Now() // Get the proper count of total manifests to add. manifestCount := 0 @@ -468,6 +494,9 @@ func (pc *PackageCreator) addComponent(ctx context.Context, component v1alpha1.Z manifestCount += len(manifest.Kustomizations) } + // TODO(mkcp): Remove message on logger release + spinner := message.NewProgressSpinner("Loading %d K8s manifests", manifestCount) + defer spinner.Stop() l.Info("processing k8s manifests", "component", component.Name, "manifests", manifestCount) // Iterate over all manifests. @@ -477,6 +506,8 @@ func (pc *PackageCreator) addComponent(ctx context.Context, component v1alpha1.Z dst := filepath.Join(componentPaths.Base, rel) // Copy manifests without any processing. + // TODO(mkcp): Remove message on logger release + spinner.Updatef("Copying manifest %s", path) l.Info("copying manifest", "path", path) if helpers.IsURL(path) { if err := utils.DownloadToFile(ctx, path, dst, component.DeprecatedCosignKeyPath); err != nil { @@ -491,6 +522,8 @@ func (pc *PackageCreator) addComponent(ctx context.Context, component v1alpha1.Z for kustomizeIdx, path := range manifest.Kustomizations { // Generate manifests from kustomizations and place in the package. + // TODO(mkcp): Remove message on logger release + spinner.Updatef("Building kustomization for %s", path) l.Info("building kustomization", "path", path) kname := fmt.Sprintf("kustomization-%s-%d.yaml", manifest.Name, kustomizeIdx) @@ -502,12 +535,19 @@ func (pc *PackageCreator) addComponent(ctx context.Context, component v1alpha1.Z } } } - l.Debug("done building k8s manifests", "component", component.Name) + spinner.Success() + l.Debug("done building k8s manifests", + "component", component.Name, + "duration", time.Since(manifestStart)) } // Load all specified git repos. reposCount := len(component.Repos) if reposCount > 0 { + reposStart := time.Now() + // TODO(mkcp): Remove message on logger release + spinner := message.NewProgressSpinner("Loading %d git repos", len(component.Repos)) + defer spinner.Stop() l.Info("loading git repos", "component", component.Name, "repos", reposCount) for _, url := range component.Repos { @@ -517,14 +557,15 @@ func (pc *PackageCreator) addComponent(ctx context.Context, component v1alpha1.Z return fmt.Errorf("unable to pull git repo %s: %w", url, err) } } - l.Debug("done loading git repos", "component", component.Name) + spinner.Success() + l.Debug("done loading git repos", "component", component.Name, "duration", time.Since(reposStart)) } if err := actions.Run(ctx, onCreate.Defaults, onCreate.After, nil); err != nil { return fmt.Errorf("unable to run component after action: %w", err) } - l.Debug("done adding component", "component", component.Name) + l.Debug("done adding component", "name", component.Name, "duration", time.Since(start)) return nil } diff --git a/src/pkg/utils/network.go b/src/pkg/utils/network.go index 016cf3d255..ca076915f5 100644 --- a/src/pkg/utils/network.go +++ b/src/pkg/utils/network.go @@ -14,11 +14,12 @@ import ( "os" "path/filepath" "strings" - - "github.com/zarf-dev/zarf/src/pkg/logger" + "time" "github.com/defenseunicorns/pkg/helpers/v2" "github.com/zarf-dev/zarf/src/config/lang" + "github.com/zarf-dev/zarf/src/pkg/logger" + "github.com/zarf-dev/zarf/src/pkg/message" ) func parseChecksum(src string) (string, string, error) { @@ -99,6 +100,7 @@ func DownloadToFile(ctx context.Context, src, dst, cosignKeyPath string) (err er func httpGetFile(ctx context.Context, url string, destinationFile *os.File) (err error) { l := logger.From(ctx) l.Info("download start", "url", url) + start := time.Now() // Get the data resp, err := http.Get(url) @@ -115,11 +117,18 @@ func httpGetFile(ctx context.Context, url string, destinationFile *os.File) (err return fmt.Errorf("bad HTTP status: %s", resp.Status) } - // Write contents to file - if _, err = io.Copy(destinationFile, resp.Body); err != nil { + // Setup progress bar + // TODO(mkcp): Remove message on logger release + title := fmt.Sprintf("Downloading %s", filepath.Base(url)) + progressBar := message.NewProgressBar(resp.ContentLength, title) + reader := io.TeeReader(resp.Body, progressBar) + // Copy response body to file + if _, err = io.Copy(destinationFile, reader); err != nil { + progressBar.Failf("Unable to save the file %s: %s", destinationFile.Name(), err.Error()) l.Error("unable to save the file %s: %s", destinationFile.Name(), err.Error()) return err } - l.Debug("download successful", "url", url) + progressBar.Successf("Downloaded %s", url) + l.Debug("download successful", "url", url, "size", resp.ContentLength, "duration", time.Since(start)) return nil }