From 413b56c3e2b5fbea7de17ba8ccd71bb3f3105b2b Mon Sep 17 00:00:00 2001 From: Kit Patella Date: Fri, 25 Oct 2024 12:07:35 -0700 Subject: [PATCH] feat: migrate package create to slog (#3132) Signed-off-by: Kit Patella Co-authored-by: Austin Abro <37223396+AustinAbro321@users.noreply.github.com> --- .golangci.yaml | 3 + go.mod | 2 + go.sum | 4 + src/cmd/package.go | 11 ++- src/cmd/root.go | 67 +++++++++++++---- src/cmd/tools/zarf.go | 2 +- src/internal/packager/helm/repo.go | 63 +++++++++++++++- src/internal/packager/images/pull.go | 30 +++++++- src/internal/packager/sbom/catalog.go | 40 +++++++--- src/internal/packager/template/template.go | 10 +-- src/pkg/layout/component.go | 9 ++- src/pkg/layout/package.go | 12 ++- src/pkg/logger/logger.go | 55 ++++++++++---- src/pkg/packager/actions/actions.go | 38 +++++++--- src/pkg/packager/common.go | 52 +++++++++---- src/pkg/packager/create.go | 53 +++++++++++--- src/pkg/packager/creator/normal.go | 85 ++++++++++++++++++---- src/pkg/packager/creator/skeleton.go | 4 +- src/pkg/utils/network.go | 25 ++++--- src/types/packager.go | 10 ++- 20 files changed, 458 insertions(+), 117 deletions(-) diff --git a/.golangci.yaml b/.golangci.yaml index c947d98999..5aac2153f3 100644 --- a/.golangci.yaml +++ b/.golangci.yaml @@ -66,6 +66,9 @@ linters-settings: - (*github.com/spf13/cobra.Command).MarkFlagRequired - (*github.com/spf13/pflag.FlagSet).MarkHidden - (*github.com/spf13/pflag.FlagSet).MarkDeprecated + sloglint: + no-mixed-args: true + key-naming-case: camel issues: # Revive rules that are disabled by default. include: diff --git a/go.mod b/go.mod index cc4c212bb9..e4d665aff2 100644 --- a/go.mod +++ b/go.mod @@ -29,12 +29,14 @@ require ( github.com/go-git/go-git/v5 v5.12.0 github.com/goccy/go-yaml v1.12.0 github.com/gofrs/flock v0.12.1 + github.com/golang-cz/devslog v0.0.11 github.com/google/go-containerregistry v0.20.2 github.com/gosuri/uitable v0.0.4 github.com/invopop/jsonschema v0.12.0 github.com/mholt/archiver/v3 v3.5.1 github.com/moby/moby v27.3.1+incompatible github.com/opencontainers/image-spec v1.1.0 + github.com/phsym/console-slog v0.3.1 github.com/pkg/errors v0.9.1 github.com/prometheus/client_golang v1.20.5 github.com/pterm/pterm v0.12.79 diff --git a/go.sum b/go.sum index 9838c921fb..565d719355 100644 --- a/go.sum +++ b/go.sum @@ -869,6 +869,8 @@ github.com/gofrs/uuid v4.2.0+incompatible/go.mod h1:b2aQJv3Z4Fp6yNu3cdSllBxTCLRx github.com/gogo/protobuf v1.1.1/go.mod h1:r8qH/GZQm5c6nD/R0oafs1akxWv10x8SbQlK7atdtwQ= github.com/gogo/protobuf v1.3.2 h1:Ov1cvc58UF3b5XjBnZv7+opcTcQFZebYjWzi34vdm4Q= github.com/gogo/protobuf v1.3.2/go.mod h1:P1XiOD3dCwIKUDQYPy72D8LYyHL2YPYrpS2s69NZV8Q= +github.com/golang-cz/devslog v0.0.11 h1:v4Yb9o0ZpuZ/D8ZrtVw1f9q5XrjnkxwHF1XmWwO8IHg= +github.com/golang-cz/devslog v0.0.11/go.mod h1:bSe5bm0A7Nyfqtijf1OMNgVJHlWEuVSXnkuASiE1vV8= github.com/golang-jwt/jwt/v4 v4.0.0/go.mod h1:/xlHOz8bRuivTWchD4jCa+NbatV+wEUSzwAxVc6locg= github.com/golang-jwt/jwt/v4 v4.2.0/go.mod h1:/xlHOz8bRuivTWchD4jCa+NbatV+wEUSzwAxVc6locg= github.com/golang-jwt/jwt/v4 v4.5.0 h1:7cYmW1XlMY7h7ii7UhUyChSgS5wUJEnm9uZVTGqOWzg= @@ -1420,6 +1422,8 @@ github.com/petergtz/pegomock v2.9.0+incompatible h1:BKfb5XfkJfehe5T+O1xD4Zm26Sb9 github.com/petergtz/pegomock v2.9.0+incompatible/go.mod h1:nuBLWZpVyv/fLo56qTwt/AUau7jgouO1h7bEvZCq82o= github.com/phayes/freeport v0.0.0-20220201140144-74d24b5ae9f5 h1:Ii+DKncOVM8Cu1Hc+ETb5K+23HdAMvESYE3ZJ5b5cMI= github.com/phayes/freeport v0.0.0-20220201140144-74d24b5ae9f5/go.mod h1:iIss55rKnNBTvrwdmkUpLnDpZoAHvWaiq5+iMmen4AE= +github.com/phsym/console-slog v0.3.1 h1:Fuzcrjr40xTc004S9Kni8XfNsk+qrptQmyR+wZw9/7A= +github.com/phsym/console-slog v0.3.1/go.mod h1:oJskjp/X6e6c0mGpfP8ELkfKUsrkDifYRAqJQgmdDS0= github.com/pierrec/lz4/v4 v4.1.2/go.mod h1:gZWDp/Ze/IJXGXf23ltt2EXimqmTUXEy0GFuRQyBid4= github.com/pierrec/lz4/v4 v4.1.21 h1:yOVMLb6qSIDP67pl/5F7RepeKYu/VmTyEXvuMI5d9mQ= github.com/pierrec/lz4/v4 v4.1.21/go.mod h1:gZWDp/Ze/IJXGXf23ltt2EXimqmTUXEy0GFuRQyBid4= diff --git a/src/cmd/package.go b/src/cmd/package.go index 58e714a543..91b46a2243 100644 --- a/src/cmd/package.go +++ b/src/cmd/package.go @@ -14,6 +14,8 @@ import ( "runtime" "strings" + "github.com/zarf-dev/zarf/src/pkg/logger" + "github.com/AlecAivazis/survey/v2" "github.com/defenseunicorns/pkg/helpers/v2" "github.com/spf13/cobra" @@ -47,11 +49,14 @@ var packageCreateCmd = &cobra.Command{ Short: lang.CmdPackageCreateShort, Long: lang.CmdPackageCreateLong, RunE: func(cmd *cobra.Command, args []string) error { + l := logger.From(cmd.Context()) pkgConfig.CreateOpts.BaseDir = setBaseDirectory(args) var isCleanPathRegex = regexp.MustCompile(`^[a-zA-Z0-9\_\-\/\.\~\\:]+$`) if !isCleanPathRegex.MatchString(config.CommonOptions.CachePath) { + // TODO(mkcp): Remove message on logger release message.Warnf(lang.CmdPackageCreateCleanPathErr, config.ZarfDefaultCachePath) + l.Warn("invalid characters in Zarf cache path, using default", "cfg", config.ZarfDefaultCachePath, "default", config.ZarfDefaultCachePath) config.CommonOptions.CachePath = config.ZarfDefaultCachePath } @@ -59,13 +64,17 @@ var packageCreateCmd = &cobra.Command{ pkgConfig.CreateOpts.SetVariables = helpers.TransformAndMergeMap( v.GetStringMapString(common.VPkgCreateSet), pkgConfig.CreateOpts.SetVariables, strings.ToUpper) - pkgClient, err := packager.New(&pkgConfig) + pkgClient, err := packager.New(&pkgConfig, + packager.WithContext(cmd.Context()), + ) if err != nil { return err } defer pkgClient.ClearTempPaths() err = pkgClient.Create(cmd.Context()) + + // NOTE(mkcp): LintErrors are rendered with a table var lintErr *lint.LintError if errors.As(err, &lintErr) { common.PrintFindings(lintErr) diff --git a/src/cmd/root.go b/src/cmd/root.go index f72358e288..7899388317 100644 --- a/src/cmd/root.go +++ b/src/cmd/root.go @@ -82,10 +82,6 @@ func preRun(cmd *cobra.Command, _ []string) error { if cmd.Parent() == nil { skipLogFile = true } - err := setupMessage(LogLevelCLI, skipLogFile, NoColor) - if err != nil { - return err - } // Configure logger and add it to cmd context. l, err := setupLogger(LogLevelCLI, LogFormat) @@ -95,6 +91,21 @@ func preRun(cmd *cobra.Command, _ []string) error { ctx := logger.WithContext(cmd.Context(), l) cmd.SetContext(ctx) + // Configure the global message instance. + var disableMessage bool + if LogFormat != "" { + disableMessage = true + } + err = setupMessage(messageCfg{ + level: LogLevelCLI, + skipLogFile: skipLogFile, + noColor: NoColor, + featureDisabled: disableMessage, + }) + if err != nil { + return err + } + // Print out config location common.PrintViperConfigUsed(cmd.Context()) return nil @@ -116,14 +127,22 @@ func Execute(ctx context.Context) { if err == nil { return } + + // Check if we need to use the default err printer defaultPrintCmds := []string{"helm", "yq", "kubectl"} comps := strings.Split(cmd.CommandPath(), " ") if len(comps) > 1 && comps[1] == "tools" && slices.Contains(defaultPrintCmds, comps[2]) { cmd.PrintErrln(cmd.ErrPrefix(), err.Error()) - } else { - errParagraph := message.Paragraph(err.Error()) - pterm.Error.Println(errParagraph) + os.Exit(1) } + + // TODO(mkcp): Remove message on logger release + errParagraph := message.Paragraph(err.Error()) + pterm.Error.Println(errParagraph) + + // NOTE(mkcp): The default logger is set with user flags downstream in rootCmd's preRun func, so we don't have + // access to it on Execute's ctx. + logger.Default().Error(err.Error()) os.Exit(1) } @@ -184,14 +203,34 @@ func setupLogger(level, format string) (*slog.Logger, error) { return l, nil } +type messageCfg struct { + level string + skipLogFile bool + noColor bool + // featureDisabled is a feature flag that disables it + featureDisabled bool +} + // setupMessage configures message while we migrate over to logger. -func setupMessage(logLevel string, skipLogFile, noColor bool) error { - // TODO(mkcp): Delete no-color - if noColor { +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 + } + + if cfg.noColor { message.DisableColor() } - if logLevel != "" { + level := cfg.level + if cfg.level != "" { match := map[string]message.LogLevel{ // NOTE(mkcp): Add error for forwards compatibility with logger "error": message.WarnLevel, @@ -200,12 +239,12 @@ func setupMessage(logLevel string, skipLogFile, noColor bool) error { "debug": message.DebugLevel, "trace": message.TraceLevel, } - lvl, ok := match[logLevel] + lvl, ok := match[level] if !ok { return errors.New("invalid log level, valid options are warn, info, debug, error, and trace") } message.SetLogLevel(lvl) - message.Debug("Log level set to " + logLevel) + message.Debug("Log level set to " + level) } // Disable progress bars for CI envs @@ -214,7 +253,7 @@ func setupMessage(logLevel string, skipLogFile, noColor bool) error { message.NoProgress = true } - if !skipLogFile { + if !cfg.skipLogFile { ts := time.Now().Format("2006-01-02-15-04-05") f, err := os.CreateTemp("", fmt.Sprintf("zarf-%s-*.log", ts)) if err != nil { diff --git a/src/cmd/tools/zarf.go b/src/cmd/tools/zarf.go index df516f9506..1bf56fd574 100644 --- a/src/cmd/tools/zarf.go +++ b/src/cmd/tools/zarf.go @@ -173,7 +173,7 @@ var updateCredsCmd = &cobra.Command{ } // Update Zarf 'init' component Helm releases if present - h := helm.NewClusterOnly(&types.PackagerConfig{}, template.GetZarfVariableConfig(), newState, c) + h := helm.NewClusterOnly(&types.PackagerConfig{}, template.GetZarfVariableConfig(cmd.Context()), newState, c) if slices.Contains(args, message.RegistryKey) && newState.RegistryInfo.IsInternal() { err = h.UpdateZarfRegistryValues(ctx) diff --git a/src/internal/packager/helm/repo.go b/src/internal/packager/helm/repo.go index 249f19f0f2..7791771282 100644 --- a/src/internal/packager/helm/repo.go +++ b/src/internal/packager/helm/repo.go @@ -8,9 +8,12 @@ import ( "context" "errors" "fmt" + "github.com/zarf-dev/zarf/src/pkg/logger" + "log/slog" "os" "path/filepath" "strings" + "time" "github.com/defenseunicorns/pkg/helpers/v2" "helm.sh/helm/v3/pkg/action" @@ -38,7 +41,9 @@ func (h *Helm) PackageChart(ctx context.Context, cosignKeyPath string) error { // check if the chart is a git url with a ref (if an error is returned url will be empty) isGitURL := strings.HasSuffix(url, ".git") if err != nil { + // TODO(mkcp): Remove message on logger release message.Debugf("unable to parse the url, continuing with %s", h.chart.URL) + logger.From(ctx).Debug("unable to parse the url, continuing", "url", h.chart.URL) } if isGitURL { @@ -68,6 +73,13 @@ func (h *Helm) PackageChart(ctx context.Context, cosignKeyPath string) error { // PackageChartFromLocalFiles creates a chart archive from a path to a chart on the host os. func (h *Helm) PackageChartFromLocalFiles(ctx context.Context, cosignKeyPath string) error { + l := logger.From(ctx) + l.Info("processing local helm chart", + "name", h.chart.Name, + "version", h.chart.Version, + "path", h.chart.LocalPath, + ) + // TODO(mkcp): Remove message on logger release spinner := message.NewProgressSpinner("Processing helm chart %s:%s from %s", h.chart.Name, h.chart.Version, h.chart.LocalPath) defer spinner.Stop() @@ -94,7 +106,12 @@ func (h *Helm) PackageChartFromLocalFiles(ctx context.Context, cosignKeyPath str saved = filepath.Join(temp, filepath.Base(h.chart.LocalPath)) err = helpers.CreatePathAndCopy(h.chart.LocalPath, saved) } - defer os.RemoveAll(temp) + defer func(l *slog.Logger) { + err := os.RemoveAll(temp) + if err != nil { + l.Error(err.Error()) + } + }(l) if err != nil { return fmt.Errorf("unable to save the archive and create the package %s: %w", saved, err) @@ -108,11 +125,19 @@ func (h *Helm) PackageChartFromLocalFiles(ctx context.Context, cosignKeyPath str spinner.Success() + l.Debug("done processing local helm chart", + "name", h.chart.Name, + "version", h.chart.Version, + "path", h.chart.LocalPath, + ) return nil } // PackageChartFromGit is a special implementation of chart archiving that supports the https://p1.dso.mil/#/products/big-bang/ model. func (h *Helm) PackageChartFromGit(ctx context.Context, cosignKeyPath string) error { + l := logger.From(ctx) + l.Info("processing helm chart", "name", h.chart.Name) + // TODO(mkcp): Remove message on logger release spinner := message.NewProgressSpinner("Processing helm chart %s", h.chart.Name) defer spinner.Stop() @@ -121,7 +146,11 @@ func (h *Helm) PackageChartFromGit(ctx context.Context, cosignKeyPath string) er if err != nil { return err } - defer os.RemoveAll(gitPath) + defer func(l *slog.Logger) { + if err := os.RemoveAll(gitPath); err != nil { + l.Error(err.Error()) + } + }(l) // Set the directory for the chart and package it h.chart.LocalPath = filepath.Join(gitPath, h.chart.GitPath) @@ -130,6 +159,14 @@ func (h *Helm) PackageChartFromGit(ctx context.Context, cosignKeyPath string) er // DownloadPublishedChart loads a specific chart version from a remote repo. func (h *Helm) DownloadPublishedChart(ctx context.Context, cosignKeyPath string) error { + l := logger.From(ctx) + l.Info("processing helm chart", + "name", h.chart.Name, + "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() @@ -146,7 +183,12 @@ func (h *Helm) DownloadPublishedChart(ctx context.Context, cosignKeyPath string) // Not returning the error here since the repo file is only needed if we are pulling from a repo that requires authentication if err != nil { + // TODO(mkcp): Remove message on logger release message.Debugf("Unable to load the repo file at %q: %s", pull.Settings.RepositoryConfig, err.Error()) + l.Debug("unable to load the repo file", + "path", pull.Settings.RepositoryConfig, + "error", err.Error(), + ) } var username string @@ -202,7 +244,12 @@ func (h *Helm) DownloadPublishedChart(ctx context.Context, cosignKeyPath string) if err = helpers.CreateDirectory(temp, helpers.ReadWriteExecuteUser); err != nil { return fmt.Errorf("unable to create helm chart temp directory: %w", err) } - defer os.RemoveAll(temp) + defer func(l *slog.Logger) { + err := os.RemoveAll(temp) + if err != nil { + l.Error(err.Error()) + } + }(l) saved, _, err := chartDownloader.DownloadTo(chartURL, pull.Version, temp) if err != nil { @@ -222,7 +269,12 @@ func (h *Helm) DownloadPublishedChart(ctx context.Context, cosignKeyPath string) } spinner.Success() - + l.Debug("done downloading helm chart", + "name", h.chart.Name, + "version", h.chart.Version, + "repo", h.chart.URL, + "duration", time.Since(start), + ) return nil } @@ -304,13 +356,16 @@ func (h *Helm) buildChartDependencies() error { var notFoundErr *downloader.ErrRepoNotFound if errors.As(err, ¬FoundErr) { // If we encounter a repo not found error point the user to `zarf tools helm repo add` + // TODO(mkcp): Remove message on logger release message.Warnf("%s. Please add the missing repo(s) via the following:", notFoundErr.Error()) for _, repository := range notFoundErr.Repos { + // TODO(mkcp): Remove message on logger release message.ZarfCommand(fmt.Sprintf("tools helm repo add %s", repository)) } return err } if err != nil { + // TODO(mkcp): Remove message on logger release message.ZarfCommand("tools helm dependency build --verify") message.Warnf("Unable to perform a rebuild of Helm dependencies: %s", err.Error()) return err diff --git a/src/internal/packager/images/pull.go b/src/internal/packager/images/pull.go index a11b6097d7..2bd39862a6 100644 --- a/src/internal/packager/images/pull.go +++ b/src/internal/packager/images/pull.go @@ -9,6 +9,7 @@ import ( "encoding/json" "errors" "fmt" + "github.com/zarf-dev/zarf/src/pkg/logger" "io/fs" "maps" "os" @@ -16,6 +17,7 @@ import ( "strings" "sync" "sync/atomic" + "time" "github.com/avast/retry-go/v4" "github.com/defenseunicorns/pkg/helpers/v2" @@ -60,9 +62,12 @@ func checkForIndex(refInfo transform.Image, desc *remote.Descriptor) error { return nil } -// Pull pulls all of the images from the given config. +// Pull pulls all images from the given config. 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 { @@ -80,8 +85,19 @@ func Pull(ctx context.Context, cfg PullConfig) (map[transform.Image]v1.Image, er return nil, err } + // 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, "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) + } logs.Warn.SetOutput(&message.DebugWriter{}) logs.Progress.SetOutput(&message.DebugWriter{}) @@ -101,7 +117,9 @@ func Pull(ctx context.Context, cfg PullConfig) (map[transform.Image]v1.Image, er 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) ref := refInfo.Reference for k, v := range cfg.RegistryOverrides { @@ -130,6 +148,7 @@ func Pull(ctx context.Context, cfg PullConfig) (map[transform.Image]v1.Image, er return fmt.Errorf("rate limited by registry: %w", err) } + // TODO(mkcp): Remove message on logger release message.Warnf("Falling back to local 'docker', failed to find the manifest on a remote: %s", err.Error()) // Attempt to connect to the local docker daemon. @@ -221,11 +240,15 @@ func Pull(ctx context.Context, cfg PullConfig) (map[transform.Image]v1.Image, er return nil, err } + // 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), "duration", time.Since(imageFetchStart)) doneSaving := make(chan error) updateText := fmt.Sprintf("Pulling %d images", imageCount) + // TODO(mkcp): Remove progress bar on logger release go utils.RenderProgressBarForLocalDirWrite(cfg.DestinationDirectory, totalBytes.Load(), doneSaving, updateText, updateText) + l.Info("pulling images", "count", len(cfg.ImageList)) toPull := maps.Clone(fetched) @@ -237,7 +260,9 @@ func Pull(ctx context.Context, cfg PullConfig) (map[transform.Image]v1.Image, er return err }, 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()) + l.Warn("failed to save images in parallel, falling back to sequential save", "error", err.Error()) err = retry.Do(func() error { saved, err := SaveSequential(ctx, cranePath, toPull) for k := range saved { @@ -251,6 +276,7 @@ func Pull(ctx context.Context, cfg PullConfig) (map[transform.Image]v1.Image, er } // Send a signal to the progress bar that we're done and wait for the thread to finish + // TODO(mkcp): Remove progress bar on logger release doneSaving <- nil <-doneSaving @@ -279,6 +305,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 65c32c039b..8d96f66628 100755 --- a/src/internal/packager/sbom/catalog.go +++ b/src/internal/packager/sbom/catalog.go @@ -12,6 +12,9 @@ import ( "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" @@ -30,7 +33,6 @@ import ( v1 "github.com/google/go-containerregistry/pkg/v1" "github.com/zarf-dev/zarf/src/config" "github.com/zarf-dev/zarf/src/pkg/layout" - "github.com/zarf-dev/zarf/src/pkg/message" "github.com/zarf-dev/zarf/src/pkg/transform" "github.com/zarf-dev/zarf/src/pkg/utils" ) @@ -52,6 +54,7 @@ var componentPrefix = "zarf-component-" // Catalog catalogs the given components and images to create an SBOM. func Catalog(ctx context.Context, componentSBOMs map[string]*layout.ComponentSBOM, imageList []transform.Image, paths *layout.PackagePaths) error { + l := logger.From(ctx) imageCount := len(imageList) componentCount := len(componentSBOMs) cachePath, err := config.GetAbsCachePath() @@ -59,6 +62,7 @@ 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, @@ -72,32 +76,39 @@ 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") - return err + return fmt.Errorf("unable to generate the SBOM image list: %w", err) } builder.jsonList = json // Generate SBOM for each image currImage := 1 + l.Info("creating SBOMs for images", "count", 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") - return err + return fmt.Errorf("unable to load the image to generate an SBOM: %w", 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) - return err + return fmt.Errorf("unable to create SBOM for image=%s: %w", refInfo.Reference, err) } 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) - return err + return fmt.Errorf("unable to create SBOM viewer for image=%s: %w", refInfo.Reference, err) } currImage++ @@ -106,23 +117,30 @@ func Catalog(ctx context.Context, componentSBOMs map[string]*layout.ComponentSBO currComponent := 1 // Generate SBOM for each component + l.Info("creating SBOMs for components", "count", 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) - return err + return fmt.Errorf("unable to create SBOM for component=%s: %w", component, 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) - return err + return fmt.Errorf("unable to create SBOM for component=%s: %w", component, err) } currComponent++ @@ -131,18 +149,22 @@ func Catalog(ctx context.Context, componentSBOMs map[string]*layout.ComponentSBO // 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") - return err + return fmt.Errorf("unable to create SBOM compare tool: %w", err) } } if err := paths.SBOMs.Archive(); err != nil { + // TODO(mkcp): Remove message on logger release builder.spinner.Errorf(err, "Unable to archive SBOMs") - return err + return fmt.Errorf("unable to archive SBOMs: %w", 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 872754ce4d..ec53877db1 100644 --- a/src/internal/packager/template/template.go +++ b/src/internal/packager/template/template.go @@ -5,9 +5,9 @@ package template import ( + "context" "encoding/base64" "fmt" - "log/slog" "strings" "github.com/zarf-dev/zarf/src/api/v1alpha1" @@ -16,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" @@ -26,7 +27,7 @@ const ( ) // GetZarfVariableConfig gets a variable configuration specific to Zarf -func GetZarfVariableConfig() *variables.VariableConfig { +func GetZarfVariableConfig(ctx context.Context) *variables.VariableConfig { prompt := func(variable v1alpha1.InteractiveVariable) (value string, err error) { if config.CommonOptions.Confirm { return variable.Default, nil @@ -34,10 +35,7 @@ func GetZarfVariableConfig() *variables.VariableConfig { return interactive.PromptVariable(variable) } - return variables.New( - "zarf", - prompt, - slog.New(message.ZarfHandler{})) + return variables.New("zarf", prompt, logger.From(ctx)) } // GetZarfTemplates returns the template keys and values to be used for templating. diff --git a/src/pkg/layout/component.go b/src/pkg/layout/component.go index 9a3735b54b..3e524852fe 100644 --- a/src/pkg/layout/component.go +++ b/src/pkg/layout/component.go @@ -5,6 +5,7 @@ package layout import ( + "context" "fmt" "io/fs" "os" @@ -13,6 +14,7 @@ import ( "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" ) @@ -39,7 +41,8 @@ type Components struct { var ErrNotLoaded = fmt.Errorf("not loaded") // Archive archives a component. -func (c *Components) Archive(component v1alpha1.ZarfComponent, cleanupTemp bool) error { +func (c *Components) Archive(ctx context.Context, component v1alpha1.ZarfComponent, cleanupTemp bool) error { + l := logger.From(ctx) name := component.Name if _, ok := c.Dirs[name]; !ok { return &fs.PathError{ @@ -61,7 +64,9 @@ func (c *Components) Archive(component v1alpha1.ZarfComponent, cleanupTemp bool) } 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 } @@ -70,7 +75,9 @@ func (c *Components) Archive(component v1alpha1.ZarfComponent, cleanupTemp bool) } 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) } delete(c.Dirs, name) diff --git a/src/pkg/layout/package.go b/src/pkg/layout/package.go index 7824d34ba9..2141de586f 100644 --- a/src/pkg/layout/package.go +++ b/src/pkg/layout/package.go @@ -5,6 +5,7 @@ package layout import ( + "context" "errors" "fmt" "os" @@ -19,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" @@ -225,22 +227,29 @@ func (pp *PackagePaths) GenerateChecksums() (string, error) { } // ArchivePackage creates an archive for a Zarf package. -func (pp *PackagePaths) ArchivePackage(destinationTarball string, maxPackageSizeMB int) error { +func (pp *PackagePaths) ArchivePackage(ctx context.Context, destinationTarball string, maxPackageSizeMB int) error { + l := logger.From(ctx) + // 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 @@ -251,6 +260,7 @@ func (pp *PackagePaths) ArchivePackage(destinationTarball string, maxPackageSize 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 aa0d4b7f07..ccbddf7901 100644 --- a/src/pkg/logger/logger.go +++ b/src/pkg/logger/logger.go @@ -12,6 +12,10 @@ import ( "os" "strings" "sync/atomic" + + "github.com/phsym/console-slog" + + "github.com/golang-cz/devslog" ) var defaultLogger atomic.Pointer[slog.Logger] @@ -61,7 +65,9 @@ func ParseLevel(s string) (Level, error) { return l, nil } -// Format declares the kind of logging handler to use. An empty Format defaults to text. +// 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. type Format string // ToLower takes a Format string and converts it to lowercase for case-agnostic validation. Users shouldn't have to care @@ -70,19 +76,19 @@ func (f Format) ToLower() Format { return Format(strings.ToLower(string(f))) } -// TODO(mkcp): Add dev format var ( // FormatText uses the standard slog TextHandler FormatText Format = "text" // FormatJSON uses the standard slog JSONHandler FormatJSON Format = "json" + // FormatConsole uses console-slog to provide prettier colorful messages + FormatConsole Format = "console" + // FormatDev uses a verbose and prettyprinting devslog handler + FormatDev Format = "dev" // FormatNone sends log writes to DestinationNone / io.Discard FormatNone Format = "none" ) -// More printers would be great, like dev format https://github.com/golang-cz/devslog -// and a pretty console slog https://github.com/phsym/console-slog - // Destination declares an io.Writer to send logs to. type Destination io.Writer @@ -127,17 +133,22 @@ func New(cfg Config) (*slog.Logger, error) { opts.Level = slog.Level(cfg.Level) switch cfg.Format.ToLower() { - // Use Text handler if no format provided - case "", FormatText: + case FormatText: handler = slog.NewTextHandler(cfg.Destination, &opts) case FormatJSON: handler = slog.NewJSONHandler(cfg.Destination, &opts) - // TODO(mkcp): Add dev format - // case FormatDev: - // handler = slog.NewTextHandler(DestinationNone, &slog.HandlerOptions{ - // AddSource: true, - // }) - case FormatNone: + case FormatConsole: + handler = console.NewHandler(cfg.Destination, &console.HandlerOptions{ + Level: slog.Level(cfg.Level), + }) + case FormatDev: + opts.AddSource = true + handler = devslog.NewHandler(DestinationDefault, &devslog.Options{ + HandlerOptions: &opts, + NewLineAfterLog: true, + }) + // Use discard handler if no format provided + case "", FormatNone: handler = slog.NewTextHandler(DestinationNone, &slog.HandlerOptions{}) // Format not found, let's error out default: @@ -162,20 +173,32 @@ func WithContext(ctx context.Context, logger *slog.Logger) context.Context { // From takes a context and reads out a *slog.Logger. If From does not find a value it will return a discarding logger // similar to log-format "none". func From(ctx context.Context) *slog.Logger { + // Check that we have a ctx + if ctx == nil { + return newEmpty() + } // Grab value from key log := ctx.Value(defaultCtxKey) + if log == nil { + return newEmpty() + } // Ensure our value is a *slog.Logger before we cast. switch l := log.(type) { case *slog.Logger: return l default: - // Value is empty or not a *slog.Logger, pass back a Discard logger. - h := slog.NewTextHandler(DestinationNone, &slog.HandlerOptions{}) - return slog.New(h) + // Not reached + panic(fmt.Sprintf("unexpected value type on context key: %T", log)) } } +// newDiscard returns a logger without any settings that goes to io.Discard +func newEmpty() *slog.Logger { + h := slog.NewTextHandler(DestinationNone, &slog.HandlerOptions{}) + return slog.New(h) +} + // Default retrieves a logger from the package default. This is intended as a fallback when a logger cannot easily be // passed in as a dependency, like when developing a new function. Use it like you would use context.TODO(). func Default() *slog.Logger { diff --git a/src/pkg/packager/actions/actions.go b/src/pkg/packager/actions/actions.go index dbef82b613..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,8 +24,9 @@ import ( // Run runs all provided actions. func Run(ctx context.Context, defaultCfg v1alpha1.ZarfComponentActionDefaults, actions []v1alpha1.ZarfComponentAction, variableConfig *variables.VariableConfig) error { + // TODO(mkcp): Remove interactive on logger release if variableConfig == nil { - variableConfig = template.GetZarfVariableConfig() + variableConfig = template.GetZarfVariableConfig(ctx) } for _, a := range actions { @@ -37,13 +39,12 @@ func Run(ctx context.Context, defaultCfg v1alpha1.ZarfComponentActionDefaults, a // Run commands that a component has provided. func runAction(ctx context.Context, defaultCfg v1alpha1.ZarfComponentActionDefaults, action v1alpha1.ZarfComponentAction, variableConfig *variables.VariableConfig) error { - var ( - cmdEscaped string - out string - err error - - cmd = action.Cmd - ) + 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 { @@ -79,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 @@ -116,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 } @@ -127,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 @@ -137,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: @@ -205,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 @@ -227,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 } } @@ -276,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, @@ -293,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 1325a70b46..442335cec0 100644 --- a/src/pkg/packager/common.go +++ b/src/pkg/packager/common.go @@ -8,6 +8,7 @@ import ( "context" "errors" "fmt" + "github.com/zarf-dev/zarf/src/pkg/logger" "os" "slices" "strings" @@ -30,6 +31,7 @@ import ( // Packager is the main struct for managing packages. type Packager struct { + ctx context.Context cfg *types.PackagerConfig variableConfig *variables.VariableConfig state *types.ZarfState @@ -65,36 +67,43 @@ func WithTemp(base string) Modifier { } } +// WithContext sets the packager's context +func WithContext(ctx context.Context) Modifier { + return func(p *Packager) { + p.ctx = ctx + } +} + /* New creates a new package instance with the provided config. Note: This function creates a tmp directory that should be cleaned up with p.ClearTempPaths(). */ func New(cfg *types.PackagerConfig, mods ...Modifier) (*Packager, error) { + var err error if cfg == nil { return nil, fmt.Errorf("no config provided") } - var ( - err error - pkgr = &Packager{ - cfg: cfg, - } - ) + pkgr := &Packager{cfg: cfg} + for _, mod := range mods { + mod(pkgr) + } - pkgr.variableConfig = template.GetZarfVariableConfig() + l := logger.From(pkgr.ctx) + pkgr.variableConfig = template.GetZarfVariableConfig(pkgr.ctx) + cacheDir := config.CommonOptions.CachePath + tmpDir := config.CommonOptions.TempDirectory if config.CommonOptions.TempDirectory != "" { // If the cache directory is within the temp directory, warn the user - if strings.HasPrefix(config.CommonOptions.CachePath, config.CommonOptions.TempDirectory) { + 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) } } - for _, mod := range mods { - mod(pkgr) - } - // Fill the source if it wasn't provided - note source can be nil if the package is being created if pkgr.source == nil && pkgr.cfg.CreateOpts.BaseDir == "" { pkgr.source, err = sources.New(&pkgr.cfg.PkgOpts) @@ -109,7 +118,9 @@ 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) } @@ -118,9 +129,20 @@ func New(cfg *types.PackagerConfig, mods ...Modifier) (*Packager, error) { // ClearTempPaths removes the temp directory and any files within it. func (p *Packager) ClearTempPaths() { - // Remove the temp directory, but don't throw an error if it fails - _ = os.RemoveAll(p.layout.Base) - _ = os.RemoveAll(layout.SBOMDir) + // Remove the temp directory + l := logger.From(p.ctx) + l.Debug("clearing temp paths", + "basePath", p.layout.Base, + "SBOMDir", layout.SBOMDir, + ) + err := os.RemoveAll(p.layout.Base) + if err != nil { + l.Error(err.Error(), "basePath", p.layout.Base) + } + err2 := os.RemoveAll(layout.SBOMDir) + if err2 != nil { + l.Error(err2.Error(), "SBOMDir", layout.SBOMDir) + } } // GetVariableConfig returns the variable configuration for the packager. diff --git a/src/pkg/packager/create.go b/src/pkg/packager/create.go index 517726eba4..125dd002d3 100755 --- a/src/pkg/packager/create.go +++ b/src/pkg/packager/create.go @@ -8,51 +8,84 @@ import ( "context" "fmt" "os" + "time" - "github.com/defenseunicorns/pkg/helpers/v2" "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" ) // 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 { return err } + cfg := p.cfg - if err := os.Chdir(p.cfg.CreateOpts.BaseDir); err != nil { - return fmt.Errorf("unable to access directory %q: %w", p.cfg.CreateOpts.BaseDir, err) + // Set basedir + createOpts := cfg.CreateOpts + baseDir := createOpts.BaseDir + 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) - pc := creator.NewPackageCreator(p.cfg.CreateOpts, cwd) - - if err := helpers.CreatePathAndCopy(layout.ZarfYAML, p.layout.ZarfYAML); err != nil { + // Setup package creator + lo := p.layout + pc := creator.NewPackageCreator(createOpts, cwd) + if err := helpers.CreatePathAndCopy(layout.ZarfYAML, lo.ZarfYAML); err != nil { return err } - pkg, warnings, err := pc.LoadPackageDefinition(ctx, p.layout) + // Load package def + pkg, warnings, err := pc.LoadPackageDefinition(p.ctx, lo) if err != nil { return err } + // Store on packager config p.cfg.Pkg = pkg + for _, warning := range warnings { + l.Warn(warning) + } + l.Info("package loaded", + "kind", pkg.Kind, + "name", pkg.Metadata.Name, + "description", pkg.Metadata.Description, + ) + // TODO(mkcp): Remove interactive on logger release if !p.confirmAction(config.ZarfCreateStage, warnings, nil) { return fmt.Errorf("package creation canceled") } - if err := pc.Assemble(ctx, p.layout, p.cfg.Pkg.Components, p.cfg.Pkg.Metadata.Architecture); err != nil { + aStart := time.Now() + l.Debug("starting package assembly", "kind", pkg.Kind) + if err := pc.Assemble(ctx, p.layout, pkg.Components, pkg.Metadata.Architecture); err != nil { return err } + l.Debug("done assembling package", "kind", pkg.Kind, "duration", time.Since(aStart)) // cd back for output if err := os.Chdir(cwd); err != nil { return err } - return pc.Output(ctx, p.layout, &p.cfg.Pkg) + 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 3b7d4a7698..89bbf64537 100644 --- a/src/pkg/packager/creator/normal.go +++ b/src/pkg/packager/creator/normal.go @@ -27,6 +27,7 @@ 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" @@ -62,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 @@ -116,12 +121,14 @@ 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 } -// Assemble assembles all of the package assets into Zarf's tmp directory layout. +// Assemble copies all package assets into Zarf's tmp directory layout. func (pc *PackageCreator) Assemble(ctx context.Context, dst *layout.PackagePaths, components []v1alpha1.ZarfComponent, arch string) error { var imageList []transform.Image + l := logger.From(ctx) skipSBOMFlagUsed := pc.createOpts.SkipSBOM componentSBOMs := map[string]*layout.ComponentSBOM{} @@ -131,7 +138,9 @@ 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()) } } @@ -140,6 +149,7 @@ func (pc *PackageCreator) Assemble(ctx context.Context, dst *layout.PackagePaths return fmt.Errorf("unable to add component %q: %w", component.Name, err) } + // TODO(mkcp): Migrate to logger if err := actions.Run(ctx, onCreate.Defaults, onCreate.OnSuccess, nil); err != nil { onFailure() return fmt.Errorf("unable to run component success action: %w", err) @@ -173,8 +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() @@ -216,12 +226,15 @@ 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") - } else { - dst.AddSBOMs() - if err := sbom.Catalog(ctx, componentSBOMs, sbomImageList, dst); err != nil { - return fmt.Errorf("unable to create an SBOM catalog for the package: %w", err) - } + l.Debug("skipping image SBOM processing per --skip-sbom flag") + return nil + } + + dst.AddSBOMs() + if err := sbom.Catalog(ctx, componentSBOMs, sbomImageList, dst); err != nil { + return fmt.Errorf("unable to create an SBOM catalog for the package: %w", err) } return nil @@ -240,11 +253,15 @@ 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 { // Make the component a tar archive - if err := dst.Components.Archive(component, true); err != nil { + if err := dst.Components.Archive(ctx, component, true); err != nil { return fmt.Errorf("unable to archive component: %s", err.Error()) } } @@ -275,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 @@ -291,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, " ")) @@ -301,10 +320,13 @@ 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(tarballPath, pc.createOpts.MaxPackageSizeMB); err != nil { + if err := dst.ArchivePackage(ctx, tarballPath, pc.createOpts.MaxPackageSizeMB); err != nil { return fmt.Errorf("unable to archive package: %w", err) } } @@ -333,11 +355,18 @@ func (pc *PackageCreator) Output(ctx context.Context, dst *layout.PackagePaths, } } } + l.Debug("done package output", "kind", pkg.Kind, "duration", time.Since(start)) return nil } +// TODO(mkcp): Refactor addComponent to better segment component handling logic by its type. There's also elaborate +// 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) + // 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 { @@ -422,18 +451,26 @@ func (pc *PackageCreator) addComponent(ctx context.Context, component v1alpha1.Z } } - if len(component.DataInjections) > 0 { + // 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 { - spinner.Updatef("Copying data injection %s for %s", data.Target.Path, data.Target.Selector) + 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(data.Target.Path)) + rel := filepath.Join(layout.DataInjectionsDir, strconv.Itoa(dataIdx), filepath.Base(target.Path)) dst := filepath.Join(componentPaths.Base, rel) if helpers.IsURL(data.Source) { - if err := utils.DownloadToFile(ctx, data.Source, dst, component.DeprecatedCosignKeyPath); err != nil { + err := utils.DownloadToFile(ctx, data.Source, dst, component.DeprecatedCosignKeyPath) + if err != nil { return fmt.Errorf(lang.ErrDownloading, data.Source, err.Error()) } } else { @@ -443,9 +480,12 @@ func (pc *PackageCreator) addComponent(ctx context.Context, component v1alpha1.Z } } spinner.Success() + l.Debug("done loading data injections", "duration", time.Since(injectStart)) } + // Process k8s manifests if len(component.Manifests) > 0 { + manifestStart := time.Now() // Get the proper count of total manifests to add. manifestCount := 0 @@ -454,8 +494,10 @@ 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. for _, manifest := range component.Manifests { @@ -464,7 +506,9 @@ 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 { return fmt.Errorf(lang.ErrDownloading, path, err.Error()) @@ -478,7 +522,9 @@ 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) rel := filepath.Join(layout.ManifestsDir, kname) @@ -490,12 +536,19 @@ func (pc *PackageCreator) addComponent(ctx context.Context, component v1alpha1.Z } } spinner.Success() + l.Debug("done processing k8s manifests", + "component", component.Name, + "duration", time.Since(manifestStart)) } // Load all specified git repos. - if len(component.Repos) > 0 { + 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 { // Pull all the references if there is no `@` in the string. @@ -505,12 +558,14 @@ func (pc *PackageCreator) addComponent(ctx context.Context, component v1alpha1.Z } } 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", "name", component.Name, "duration", time.Since(start)) return nil } diff --git a/src/pkg/packager/creator/skeleton.go b/src/pkg/packager/creator/skeleton.go index 8d1acbdf34..9792230f0b 100644 --- a/src/pkg/packager/creator/skeleton.go +++ b/src/pkg/packager/creator/skeleton.go @@ -96,9 +96,9 @@ func (sc *SkeletonCreator) Assemble(_ context.Context, dst *layout.PackagePaths, // - writes the loaded zarf.yaml to disk // // - signs the package -func (sc *SkeletonCreator) Output(_ context.Context, dst *layout.PackagePaths, pkg *v1alpha1.ZarfPackage) (err error) { +func (sc *SkeletonCreator) Output(ctx context.Context, dst *layout.PackagePaths, pkg *v1alpha1.ZarfPackage) (err error) { for _, component := range pkg.Components { - if err := dst.Components.Archive(component, false); err != nil { + if err := dst.Components.Archive(ctx, component, false); err != nil { return err } } diff --git a/src/pkg/utils/network.go b/src/pkg/utils/network.go index 17aa9a6ac3..fa70237dde 100644 --- a/src/pkg/utils/network.go +++ b/src/pkg/utils/network.go @@ -14,9 +14,11 @@ import ( "os" "path/filepath" "strings" + "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" ) @@ -75,7 +77,7 @@ func DownloadToFile(ctx context.Context, src, dst, cosignKeyPath string) (err er return fmt.Errorf("unable to download file with sget: %s: %w", src, err) } } else { - err = httpGetFile(src, file) + err = httpGetFile(ctx, src, file) if err != nil { return err } @@ -95,7 +97,11 @@ func DownloadToFile(ctx context.Context, src, dst, cosignKeyPath string) (err er return nil } -func httpGetFile(url string, destinationFile *os.File) (err error) { +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) if err != nil { @@ -111,16 +117,17 @@ func httpGetFile(url string, destinationFile *os.File) (err error) { return fmt.Errorf("bad HTTP status: %s", resp.Status) } - // Writer the body to file + // Setup progress bar + // TODO(mkcp): Remove message on logger release title := fmt.Sprintf("Downloading %s", filepath.Base(url)) progressBar := message.NewProgressBar(resp.ContentLength, title) - - if _, err = io.Copy(destinationFile, io.TeeReader(resp.Body, progressBar)); err != nil { + 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()) - return err + return fmt.Errorf("unable to save the file %s: %w", destinationFile.Name(), err) } - - title = fmt.Sprintf("Downloaded %s", url) - progressBar.Successf("%s", title) + progressBar.Successf("Downloaded %s", url) + l.Debug("download successful", "url", url, "size", resp.ContentLength, "duration", time.Since(start)) return nil } diff --git a/src/types/packager.go b/src/types/packager.go index fb3f68bfd5..840d05242a 100644 --- a/src/types/packager.go +++ b/src/types/packager.go @@ -4,10 +4,18 @@ // Package types contains all the types used by Zarf. package types -import "github.com/zarf-dev/zarf/src/api/v1alpha1" +import ( + "context" + + "github.com/zarf-dev/zarf/src/api/v1alpha1" +) // PackagerConfig is the main struct that the packager uses to hold high-level options. type PackagerConfig struct { + // Context provides deadlines, cancellations, and values throughout the API. + // NOTE(mkcp): Storing ctx on structs is not recommended, but this is intended as a temporary workaround. + Context context.Context + // CreateOpts tracks the user-defined options used to create the package CreateOpts ZarfCreateOptions