Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

chore: improve the Info and Debug logging for image pulls #3149

Merged
merged 2 commits into from
Oct 28, 2024
Merged

chore: improve the Info and Debug logging for image pulls #3149

Changes from all commits
Commits
Show all changes
2 commits
Select commit Hold shift + click to select a range
1a17809
improve the Info and Debug logging for image pulls
mkcp Oct 25, 2024
5424d7d
return an error in Pull savesequential/concurrent if we fail to get t…
mkcp Oct 28, 2024
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
52 changes: 41 additions & 11 deletions src/internal/packager/images/pull.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -90,14 +90,7 @@ func Pull(ctx context.Context, cfg PullConfig) (map[transform.Image]v1.Image, er
// TODO(mkcp): Remove message on logger release
spinner := message.NewProgressSpinner("Fetching info for %d images. %s", imageCount, longer)
defer spinner.Stop()
switch c := len(cfg.ImageList); {
case c > 15:
l.Info("fetching info for images. This step may take a couple of minutes to complete", "count", c, "destination", cfg.DestinationDirectory)
case c > 5:
l.Info("fetching info for images. This step may take several seconds to complete", "count", c, "destination", cfg.DestinationDirectory)
default:
l.Info("fetching info for images", "count", c, "destination", cfg.DestinationDirectory)
}
l.Info("fetching info for images", "count", imageCount, "destination", cfg.DestinationDirectory)

logs.Warn.SetOutput(&message.DebugWriter{})
logs.Progress.SetOutput(&message.DebugWriter{})
Expand All @@ -113,13 +106,14 @@ func Pull(ctx context.Context, cfg PullConfig) (map[transform.Image]v1.Image, er

var counter, totalBytes atomic.Int64

// Spawn a goroutine for each
for _, refInfo := range cfg.ImageList {
refInfo := refInfo
eg.Go(func() error {
idx := counter.Add(1)
// TODO(mkcp): Remove message on logger release
spinner.Updatef("Fetching image info (%d of %d)", idx, imageCount)
l.Info("fetching image info", "name", refInfo.Name)
l.Debug("fetching image info", "name", refInfo.Name)

ref := refInfo.Reference
for k, v := range cfg.RegistryOverrides {
Expand Down Expand Up @@ -236,6 +230,7 @@ func Pull(ctx context.Context, cfg PullConfig) (map[transform.Image]v1.Image, er
})
}

// Wait until we're done fetching images
if err := eg.Wait(); err != nil {
return nil, err
}
Expand All @@ -254,11 +249,15 @@ func Pull(ctx context.Context, cfg PullConfig) (map[transform.Image]v1.Image, er

err = retry.Do(func() error {
saved, err := SaveConcurrent(ctx, cranePath, toPull)
// Done save, remove from download list.
for k := range saved {
delete(toPull, k)
}
return err
}, retry.Context(ctx), retry.Attempts(2))
},
retry.Context(ctx),
retry.Attempts(2),
)
if err != nil {
// TODO(mkcp): Remove message on logger release
message.Warnf("Failed to save images in parallel, falling back to sequential save: %s", err.Error())
Expand All @@ -269,7 +268,10 @@ func Pull(ctx context.Context, cfg PullConfig) (map[transform.Image]v1.Image, er
delete(toPull, k)
}
return err
}, retry.Context(ctx), retry.Attempts(2))
},
retry.Context(ctx),
retry.Attempts(2),
)
if err != nil {
return nil, err
}
Expand Down Expand Up @@ -354,24 +356,39 @@ func CleanupInProgressLayers(ctx context.Context, img v1.Image) error {

// SaveSequential saves images sequentially.
func SaveSequential(ctx context.Context, cl clayout.Path, m map[transform.Image]v1.Image) (map[transform.Image]v1.Image, error) {
l := logger.From(ctx)
saved := map[transform.Image]v1.Image{}
for info, img := range m {
annotations := map[string]string{
ocispec.AnnotationBaseImageName: info.Reference,
}
wStart := time.Now()
size, err := img.Size()
if err != nil {
return saved, err
}
l.Info("saving image", "ref", info.Reference, "size", size, "method", "sequential")
if err := cl.AppendImage(img, clayout.WithAnnotations(annotations)); err != nil {
if err := CleanupInProgressLayers(ctx, img); err != nil {
message.WarnErr(err, "failed to clean up in-progress layers, please run `zarf tools clear-cache`")
l.Error("failed to clean up in-progress layers. please run `zarf tools clear-cache`")
AustinAbro321 marked this conversation as resolved.
Show resolved Hide resolved
}
return saved, err
}
saved[info] = img
l.Debug("done saving image",
"ref", info.Reference,
"size", size,
"method", "sequential",
"duration", time.Since(wStart),
)
}
return saved, nil
}

// SaveConcurrent saves images in a concurrent, bounded manner.
func SaveConcurrent(ctx context.Context, cl clayout.Path, m map[transform.Image]v1.Image) (map[transform.Image]v1.Image, error) {
l := logger.From(ctx)
saved := map[transform.Image]v1.Image{}

var mu sync.Mutex
Expand All @@ -391,12 +408,25 @@ func SaveConcurrent(ctx context.Context, cl clayout.Path, m map[transform.Image]
return err
}

size, err := img.Size()
if err != nil {
return err
}
wStart := time.Now()
l.Info("saving image", "ref", info.Reference, "size", size, "method", "concurrent")
if err := cl.WriteImage(img); err != nil {
if err := CleanupInProgressLayers(ectx, img); err != nil {
message.WarnErr(err, "failed to clean up in-progress layers, please run `zarf tools clear-cache`")
l.Error("failed to clean up in-progress layers. please run `zarf tools clear-cache`")
}
return err
}
l.Debug("done saving image",
"ref", info.Reference,
"size", size,
"method", "concurrent",
"duration", time.Since(wStart),
)

mu.Lock()
defer mu.Unlock()
Expand Down