Repository: buildpacks/lifecycle
Pull request #1399 (2024-09-11 14:55:29)

Adjust exporter App Layer log output
<!-- 🎉🎉🎉 Thank you for the PR!!! 🎉🎉🎉 -->

### Summary
The 1/N app layer logs are emitted _after_ the layers have been added. This can sometimes be an expensive operation depending on the layer size and export target.

When trying to understand performance during builds, this wording implies the previous log line before the app layers was responsible for the time between the log lines. Adjusting the wording will make it a bit clearer that the time between the two log lines includes both steps.

Before:
```bash
03:50:00 Adding layer 'buildpacksio/lifecycle:launch.sbom'
03:51:00 Adding 5/5 app layer(s)
````

After:
```bash
03:50:00 Adding layer 'buildpacksio/lifecycle:launch.sbom'
03:51:00 Added 5/5 app layer(s)
````



#### Release notes
<!-- Please provide 1-2 sentences for release notes. -->
<!-- Example: When using platform API `0.7` or greater, the `creator` logs the expected phase header for the analyze phase -->
Adjust exporter App Layer log output

---

### Context
<!-- Add any other context that may help reviewers (e.g., code that requires special attention, etc.). -->
If we are more interested in going the other direction, where we keep "Adding 1/N app layers" and emitting multiple times or something I'm happy to iterate.



Patch:
diff --git a/phase/exporter.go b/phase/exporter.go
index 4808e857..75966814 100644
--- a/phase/exporter.go
+++ b/phase/exporter.go
@@ -446,6 +446,8 @@ func (e *Exporter) addLauncherLayers(opts ExportOptions, buildMD *files.BuildMet
 
 func (e *Exporter) addAppLayers(opts ExportOptions, slices []layers.Slice, meta *files.LayersMetadata) error {
 	// creating app layers (slices + app dir)
+	e.Logger.Debugf("Adding app layers")
+
 	sliceLayers, err := e.LayerFactory.SliceLayers(opts.AppDir, slices)
 	if err != nil {
 		return errors.Wrap(err, "creating app layers")
@@ -453,6 +455,7 @@ func (e *Exporter) addAppLayers(opts ExportOptions, slices []layers.Slice, meta
 
 	var numberOfReusedLayers int
 	for _, slice := range sliceLayers {
+		e.Logger.Debugf("Layer '%s' SHA: %s\n", slice.ID, slice.Digest)
 		var err error
 
 		found := false
@@ -471,16 +474,15 @@ func (e *Exporter) addAppLayers(opts ExportOptions, slices []layers.Slice, meta
 		if err != nil {
 			return err
 		}
-		e.Logger.Debugf("Layer '%s' SHA: %s\n", slice.ID, slice.Digest)
 		meta.App = append(meta.App, files.LayerMetadata{SHA: slice.Digest})
 	}
 
 	delta := len(sliceLayers) - numberOfReusedLayers
 	if numberOfReusedLayers > 0 {
-		e.Logger.Infof("Reusing %d/%d app layer(s)\n", numberOfReusedLayers, len(sliceLayers))
+		e.Logger.Infof("Reused %d/%d app layer(s)\n", numberOfReusedLayers, len(sliceLayers))
 	}
 	if delta != 0 {
-		e.Logger.Infof("Adding %d/%d app layer(s)\n", delta, len(sliceLayers))
+		e.Logger.Infof("Added %d/%d app layer(s)\n", delta, len(sliceLayers))
 	}
 	return nil
 }


Test patch:
diff --git a/phase/exporter_test.go b/phase/exporter_test.go
index 96ee824d..63267503 100644
--- a/phase/exporter_test.go
+++ b/phase/exporter_test.go
@@ -227,8 +227,8 @@ func testExporter(t *testing.T, when spec.G, it spec.S) {
 					_, err := exporter.Export(opts)
 					h.AssertNil(t, err)
 					h.AssertContains(t, fakeAppImage.ReusedLayers(), "slice-1-digest")
-					assertLogEntry(t, logHandler, "Reusing 1/3 app layer(s)")
-					assertLogEntry(t, logHandler, "Adding 2/3 app layer(s)")
+					assertLogEntry(t, logHandler, "Reused 1/3 app layer(s)")
+					assertLogEntry(t, logHandler, "Added 2/3 app layer(s)")
 				})
 			})
 
@@ -248,7 +248,7 @@ func testExporter(t *testing.T, when spec.G, it spec.S) {
 				h.AssertNil(t, err)
 
 				assertHasLayer(t, fakeAppImage, "app")
-				assertLogEntry(t, logHandler, "Adding 1/1 app layer(s)")
+				assertLogEntry(t, logHandler, "Added 1/1 app layer(s)")
 			})
 
 			it("creates config layer on Run image", func() {
@@ -873,7 +873,7 @@ version = "4.5.6"
 				it("exports slice layers", func() {
 					_, err := exporter.Export(opts)
 					h.AssertNil(t, err)
-					assertLogEntry(t, logHandler, "Adding 3/3 app layer(s)")
+					assertLogEntry(t, logHandler, "Added 3/3 app layer(s)")
 				})
 			})
 
@@ -906,7 +906,7 @@ version = "4.5.6"
 				h.AssertNil(t, err)
 
 				assertHasLayer(t, fakeAppImage, "app")
-				assertLogEntry(t, logHandler, "Adding 1/1 app layer(s)")
+				assertLogEntry(t, logHandler, "Added 1/1 app layer(s)")
 			})
 
 			it("creates config layer on Run image", func() {