From 40434bc26afec011fa76881c9a1ae0169b764cdd Mon Sep 17 00:00:00 2001 From: Leo Di Donato <120051+leodido@users.noreply.github.com> Date: Thu, 13 Nov 2025 17:15:18 +0000 Subject: [PATCH] fix(build): improve logging and status reporting for cache operations - Set package status after download completes, not before - Add VerificationFailedError to distinguish verification failures from missing artifacts - Add comprehensive dependency build logging - Add build summary showing cached/downloaded/built package counts - Track and report packages that failed verification/download - Add new status indicators for verification and download failures - Enhance SLSA verification logging with structured fields This addresses critical issues where status was reported before operations completed, making it impossible to debug SLSA verification failures. Users previously saw 'downloaded' for packages that failed verification and were rebuilt locally. Co-authored-by: Ona --- pkg/leeway/build.go | 136 ++++++++++++++++++++++++++++++++-- pkg/leeway/cache/remote/s3.go | 41 ++++++++++ pkg/leeway/reporter.go | 15 ++-- 3 files changed, 182 insertions(+), 10 deletions(-) diff --git a/pkg/leeway/build.go b/pkg/leeway/build.go index 7087195..911ba66 100644 --- a/pkg/leeway/build.go +++ b/pkg/leeway/build.go @@ -57,6 +57,10 @@ const ( PackageDownloaded PackageBuildStatus = "downloaded" // PackageInRemoteCache means the package has been built but currently only exists in the remote cache PackageInRemoteCache PackageBuildStatus = "built-remotely" + // PackageVerificationFailed means the package download was attempted but SLSA verification failed + PackageVerificationFailed PackageBuildStatus = "verification-failed" + // PackageDownloadFailed means the package download was attempted but failed + PackageDownloadFailed PackageBuildStatus = "download-failed" ) type buildContext struct { @@ -621,6 +625,7 @@ func Build(pkg *Package, opts ...BuildOption) (err error) { pkgsWillBeDownloaded := make(map[*Package]struct{}) pkg.packagesToDownload(pkgsInLocalCache, pkgsInRemoteCacheMap, pkgsWillBeDownloaded) + // Set initial status before download pkgstatus := make(map[*Package]PackageBuildStatus) unresolvedArgs := make(map[string][]string) for _, dep := range allpkg { @@ -633,7 +638,8 @@ func Build(pkg *Package, opts ...BuildOption) (err error) { } else if existsInLocalCache { pkgstatus[dep] = PackageBuilt } else if willBeDownloaded { - pkgstatus[dep] = PackageDownloaded + // Don't set to `PackageDownloaded` yet as we haven't downloaded it! + pkgstatus[dep] = PackageInRemoteCache } else if existsInRemoteCache { pkgstatus[dep] = PackageInRemoteCache } else { @@ -669,9 +675,27 @@ func Build(pkg *Package, opts ...BuildOption) (err error) { pkgsToDownloadCache[i] = p } + // Errors are logged but don't fail the build err = ctx.RemoteCache.Download(context.Background(), ctx.LocalCache, pkgsToDownloadCache) if err != nil { - return err + // Download errors are already logged by the cache implementation + // We continue with local builds for packages that failed to download + log.WithError(err).Debug("Remote cache download completed with some errors") + } + + // Update status based on actual outcome - check what's actually in local cache now + for _, p := range pkgsToDownload { + if _, nowInCache := ctx.LocalCache.Location(p); nowInCache { + // Successfully downloaded and verified + pkgstatus[p] = PackageDownloaded + } else { + // Download failed or verification failed: we will need to build locally + // TODO: Distinguish between download failures and verification failures. + // Currently can't tell because Download() returns nil on errors (by design for graceful fallback). + // To fix: Change RemoteCache.Download() to return map[string]DownloadResult with typed status, + // then use PackageDownloadFailed vs PackageVerificationFailed appropriately. + pkgstatus[p] = PackageNotBuiltYet + } } ctx.Reporter.BuildStarted(pkg, pkgstatus) @@ -737,9 +761,86 @@ func Build(pkg *Package, opts ...BuildOption) (err error) { } } + // Print build summary + printBuildSummary(ctx, pkg, allpkg, pkgstatus, pkgsToDownload) + return nil } +// printBuildSummary prints a summary of the build showing what was cached, downloaded, and built +func printBuildSummary(ctx *buildContext, targetPkg *Package, allpkg []*Package, initialStatus map[*Package]PackageBuildStatus, pkgsToDownload []*Package) { + var ( + builtLocally int + downloaded int + alreadyCached int + total int + ) + + newlyBuilt := ctx.GetNewPackagesForCache() + newlyBuiltMap := make(map[string]bool) + for _, p := range newlyBuilt { + newlyBuiltMap[p.FullName()] = true + } + + // Track packages that were supposed to be downloaded but weren't + // These likely failed verification or download + var failedDownloads []*Package + pkgsToDownloadMap := make(map[string]bool) + for _, p := range pkgsToDownload { + pkgsToDownloadMap[p.FullName()] = true + } + + for _, p := range allpkg { + total++ + + // Check actual state in local cache + _, inCache := ctx.LocalCache.Location(p) + + if !inCache { + // Package not in cache (shouldn't happen if build succeeded) + continue + } + + // Determine what happened to this package + if newlyBuiltMap[p.FullName()] { + // Package was built during this build + builtLocally++ + + // Check if this was supposed to be downloaded but wasn't + // This indicates verification or download failure + if pkgsToDownloadMap[p.FullName()] && initialStatus[p] != PackageDownloaded { + failedDownloads = append(failedDownloads, p) + } + } else if initialStatus[p] == PackageDownloaded { + // Package was downloaded + downloaded++ + } else if initialStatus[p] == PackageBuilt { + // Package was already cached + alreadyCached++ + } else { + // Package was in cache but we're not sure how it got there + // This could happen if it was built as a dependency + alreadyCached++ + } + } + + log.WithFields(log.Fields{ + "target": targetPkg.FullName(), + "total": total, + "cached_locally": alreadyCached, + "downloaded": downloaded, + "built_locally": builtLocally, + }).Info("Build completed") + + // Highlight packages that failed verification/download + if len(failedDownloads) > 0 { + log.WithField("count", len(failedDownloads)).Warn("Some packages failed verification or download and were rebuilt locally") + for _, p := range failedDownloads { + log.WithField("package", p.FullName()).Warn(" - failed to download/verify, rebuilt locally") + } + } +} + func writeBuildPlan(out io.Writer, pkg *Package, status map[*Package]PackageBuildStatus) error { // BuildStep is a list of packages that can be built in parallel type BuildStep []string @@ -797,6 +898,11 @@ func (p *Package) buildDependencies(buildctx *buildContext) error { return nil } + log.WithFields(log.Fields{ + "package": p.FullName(), + "dependencies": len(deps), + }).Debug("building dependencies") + // Use errgroup to simplify error handling and synchronization g := new(errgroup.Group) @@ -809,7 +915,18 @@ func (p *Package) buildDependencies(buildctx *buildContext) error { } // Wait for all goroutines to complete, returning the first error encountered - return g.Wait() + err := g.Wait() + if err != nil { + log.WithFields(log.Fields{ + "package": p.FullName(), + }).Error("dependency build failed") + return err + } + + log.WithFields(log.Fields{ + "package": p.FullName(), + }).Debug("all dependencies built successfully") + return nil } func (p *Package) build(buildctx *buildContext) (err error) { @@ -817,21 +934,30 @@ func (p *Package) build(buildctx *buildContext) (err error) { doBuild := buildctx.ObtainBuildLock(p) if !doBuild { // Another goroutine is already building this package + log.WithField("package", p.FullName()).Debug("another goroutine is building this package") return nil } defer buildctx.ReleaseBuildLock(p) + // Check if already built before building dependencies + if _, alreadyBuilt := buildctx.LocalCache.Location(p); !p.Ephemeral && alreadyBuilt { + log.WithField("package", p.FullName()).Debug("package already in local cache, skipping") + return nil + } + // Build dependencies first if err := p.buildDependencies(buildctx); err != nil { return err } - // Skip if package is already built (except for ephemeral packages) + // Check again after dependencies - might have been built as a dependency if _, alreadyBuilt := buildctx.LocalCache.Location(p); !p.Ephemeral && alreadyBuilt { - log.WithField("package", p.FullName()).Debug("already built") + log.WithField("package", p.FullName()).Info("package was built as dependency, skipping") return nil } + log.WithField("package", p.FullName()).Info("building package locally") + // Initialize package build report pkgRep := &PackageBuildReport{ phaseEnter: make(map[PackageBuildPhase]time.Time), diff --git a/pkg/leeway/cache/remote/s3.go b/pkg/leeway/cache/remote/s3.go index e25c21d..a879174 100644 --- a/pkg/leeway/cache/remote/s3.go +++ b/pkg/leeway/cache/remote/s3.go @@ -44,6 +44,16 @@ type downloadResult struct { kind string // "artifact" or "attestation" } +// VerificationFailedError is returned when SLSA verification fails +type VerificationFailedError struct { + Package string + Reason string +} + +func (e VerificationFailedError) Error() string { + return fmt.Sprintf("SLSA verification failed for %s: %s", e.Package, e.Reason) +} + // S3Config holds the configuration for S3Cache type S3Config struct { BucketName string @@ -462,6 +472,10 @@ func (s *S3Cache) downloadWithSLSAVerification(ctx context.Context, p cache.Pack {".tar", 2}, } + // Track whether we attempted verification and it failed + var verificationAttempted bool + var lastVerificationError error + for _, attempt := range downloadAttempts { artifactKey := fmt.Sprintf("%s%s", version, attempt.extension) attestationKey := slsa.AttestationKey(artifactKey) @@ -527,11 +541,19 @@ func (s *S3Cache) downloadWithSLSAVerification(ctx context.Context, p cache.Pack } // Step 4: Verify the artifact against attestation + log.WithFields(log.Fields{ + "package": p.FullName(), + "artifact": artifactKey, + "attestation": attestationKey, + }).Debug("Starting SLSA verification") + verifyStart := time.Now() verifyErr := s.slsaVerifier.VerifyArtifact(ctx, tmpArtifactPath, tmpAttestationPath) verifyDuration := time.Since(verifyStart) if verifyErr != nil { + verificationAttempted = true + lastVerificationError = verifyErr log.WithError(verifyErr).WithFields(log.Fields{ "package": p.FullName(), "artifact": artifactKey, @@ -543,6 +565,12 @@ func (s *S3Cache) downloadWithSLSAVerification(ctx context.Context, p cache.Pack continue } + log.WithFields(log.Fields{ + "package": p.FullName(), + "artifact": artifactKey, + "duration": verifyDuration, + }).Debug("SLSA verification succeeded") + // Step 5: Atomically move verified artifact to final location if err := s.atomicMove(tmpArtifactPath, localPath); err != nil { log.WithError(err).WithField("package", p.FullName()).Warn("Failed to move verified artifact") @@ -567,6 +595,19 @@ func (s *S3Cache) downloadWithSLSAVerification(ctx context.Context, p cache.Pack } // All attempts failed + if verificationAttempted { + // Verification was attempted but failed - return error to distinguish from "no artifacts" + log.WithFields(log.Fields{ + "package": p.FullName(), + "version": version, + }).Warn("SLSA verification failed for all attempts, will build locally") + return VerificationFailedError{ + Package: p.FullName(), + Reason: fmt.Sprintf("verification failed: %v", lastVerificationError), + } + } + + // No artifacts found or no verification attempted log.WithFields(log.Fields{ "package": p.FullName(), "version": version, diff --git a/pkg/leeway/reporter.go b/pkg/leeway/reporter.go index a5ebe61..3afc80b 100644 --- a/pkg/leeway/reporter.go +++ b/pkg/leeway/reporter.go @@ -160,13 +160,18 @@ func (r *ConsoleReporter) BuildStarted(pkg *Package, status map[*Package]Package } format := "%s\t%s\t%s\n" - if status == PackageBuilt { + switch status { + case PackageBuilt: lines[i] = fmt.Sprintf(format, color.Green.Sprint("📦\tcached locally"), pkg.FullName(), color.Gray.Sprintf("(version %s)", version)) - } else if status == PackageInRemoteCache { - lines[i] = fmt.Sprintf(format, color.Green.Sprint("🌎\tcached remotely (ignored)"), pkg.FullName(), color.Gray.Sprintf("(version %s)", version)) - } else if status == PackageDownloaded { + case PackageInRemoteCache: + lines[i] = fmt.Sprintf(format, color.Green.Sprint("🌎\tcached remotely (available)"), pkg.FullName(), color.Gray.Sprintf("(version %s)", version)) + case PackageDownloaded: lines[i] = fmt.Sprintf(format, color.Green.Sprint("📥\tcached remotely (downloaded)"), pkg.FullName(), color.Gray.Sprintf("(version %s)", version)) - } else { + case PackageVerificationFailed: + lines[i] = fmt.Sprintf(format, color.Yellow.Sprint("⚠️\tverification failed (will rebuild)"), pkg.FullName(), color.Gray.Sprintf("(version %s)", version)) + case PackageDownloadFailed: + lines[i] = fmt.Sprintf(format, color.Yellow.Sprint("⚠️\tdownload failed (will rebuild)"), pkg.FullName(), color.Gray.Sprintf("(version %s)", version)) + default: lines[i] = fmt.Sprintf(format, color.Yellow.Sprint("🔧\tbuild"), pkg.FullName(), color.Gray.Sprintf("(version %s)", version)) } i++