Merge pull request #318 from gitpod-io/wv/sbom-phase-timing

Track SBOM generation time in build output

Author: WVerlaek

pkg/leeway/build.go

@@ -1252,9 +1252,12 @@ func (p *Package) build(buildctx *buildContext) (err error) {
 	// Generate SBOM if enabled (after packaging - written alongside artifact)
 	// SBOM files are stored outside the tar.gz to maintain artifact determinism.
 	if p.C.W.SBOM.Enabled {
+		pkgRep.phaseEnter[PackageBuildPhaseSBOM] = time.Now()
+		pkgRep.Phases = append(pkgRep.Phases, PackageBuildPhaseSBOM)
 		if err := writeSBOMToCache(buildctx, p, builddir); err != nil {
 			return err
 		}
+		pkgRep.phaseDone[PackageBuildPhaseSBOM] = time.Now()
 	}
 
 	// Register newly built package
@@ -1494,6 +1497,7 @@ const (
 	PackageBuildPhaseTest    PackageBuildPhase = "test"
 	PackageBuildPhaseBuild   PackageBuildPhase = "build"
 	PackageBuildPhasePackage PackageBuildPhase = "package"
+	PackageBuildPhaseSBOM    PackageBuildPhase = "sbom"
 )
 
 type packageBuild struct {

pkg/leeway/reporter.go

@@ -234,12 +234,12 @@ func (r *ConsoleReporter) PackageBuildFinished(pkg *Package, rep *PackageBuildRe
 	var phaseDurations []string
 	for _, phase := range rep.Phases {
 		if d := rep.PhaseDuration(phase); d > 0 {
-			phaseDurations = append(phaseDurations, fmt.Sprintf("%s: %.1fs", phase, d.Seconds()))
+			phaseDurations = append(phaseDurations, fmt.Sprintf("%s %.1fs", phase, d.Seconds()))
 		}
 	}
 	phaseDurStr := ""
 	if len(phaseDurations) > 0 {
-		phaseDurStr = color.Sprintf(" [%s]", strings.Join(phaseDurations, " | "))
+		phaseDurStr = color.Sprintf(" (%s)", strings.Join(phaseDurations, ", "))
 	}
 
 	var msg string
@@ -250,7 +250,7 @@ func (r *ConsoleReporter) PackageBuildFinished(pkg *Package, rep *PackageBuildRe
 		if rep.TestCoverageAvailable {
 			coverage = color.Sprintf("<fg=yellow>test coverage: %d%%</> <gray>(%d of %d functions have tests)</>\n", rep.TestCoveragePercentage, rep.FunctionsWithTest, rep.FunctionsWithTest+rep.FunctionsWithoutTest)
 		}
-		msg = color.Sprintf("%s<green>package build succeeded</> <gray>(%.2fs)%s</>\n", coverage, dur.Seconds(), phaseDurStr)
+		msg = color.Sprintf("%s<green>package build succeeded</> <gray>in %.2fs%s</>\n", coverage, dur.Seconds(), phaseDurStr)
 	}
 	//nolint:errcheck
 	io.WriteString(out, msg)

pkg/leeway/reporter_test.go

@@ -38,34 +38,37 @@ func TestConsoleReporter(t *testing.T) {
 				r.PackageBuildStarted(pkg, "/tmp/build")
 
 				r.now = func() time.Time {
-					return start.Add(5 * time.Second)
+					return start.Add(6 * time.Second)
 				}
 				r.PackageBuildFinished(pkg, &PackageBuildReport{
 					Phases: []PackageBuildPhase{
 						PackageBuildPhasePrep,
 						PackageBuildPhasePull,
 						PackageBuildPhaseLint,
 						PackageBuildPhaseTest,
-						PackageBuildPhaseBuild},
+						PackageBuildPhaseBuild,
+						PackageBuildPhaseSBOM},
 					phaseEnter: map[PackageBuildPhase]time.Time{
 						PackageBuildPhasePrep:  start,
 						PackageBuildPhasePull:  start.Add(time.Second),
 						PackageBuildPhaseBuild: start.Add(2 * time.Second),
 						PackageBuildPhaseTest:  start.Add(3 * time.Second),
 						PackageBuildPhaseLint:  start.Add(4 * time.Second),
+						PackageBuildPhaseSBOM:  start.Add(5 * time.Second),
 					},
 					phaseDone: map[PackageBuildPhase]time.Time{
 						PackageBuildPhasePrep:  start.Add(time.Second),
 						PackageBuildPhasePull:  start.Add(2 * time.Second),
 						PackageBuildPhaseBuild: start.Add(3 * time.Second),
 						PackageBuildPhaseTest:  start.Add(4 * time.Second),
 						PackageBuildPhaseLint:  start.Add(5 * time.Second),
+						PackageBuildPhaseSBOM:  start.Add(6 * time.Second),
 					},
 				})
 			},
 			Expect: Expectation{
 				Output: `[test:test] build started (version unknown, builddir /tmp/build)
-[test:test] package build succeeded (5.00s) [prep: 1.0s | pull: 1.0s | lint: 1.0s | test: 1.0s | build: 1.0s]
+[test:test] package build succeeded in 6.00s (prep 1.0s, pull 1.0s, lint 1.0s, test 1.0s, build 1.0s, sbom 1.0s)
 `,
 			},
 		},
@@ -79,7 +82,7 @@ func TestConsoleReporter(t *testing.T) {
 			},
 			Expect: Expectation{
 				Output: `[test:test] build started (version unknown, builddir /tmp/build)
-[test:test] package build succeeded (0.00s)
+[test:test] package build succeeded in 0.00s
 `,
 			},
 		},