Adjust exporter App Layer log output (#1399)

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)
````

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.

Signed-off-by: Jesse Brown <[email protected]>

phase/exporter.go

@@ -446,13 +446,16 @@ 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")
 	}
 
 	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
 }

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() {