Merge pull request #1160 from joe-kimmel-vmw/so-many-loggers-we-ran-o…

…ut-of-flannel-shirts

timestamp logs for entry/exit for all the top-level Lifecycle package…

analyzer.go

@@ -190,6 +190,7 @@ func (f *AnalyzerFactory) setRun(analyzer *Analyzer, imageRef string) error {
 
 // Analyze fetches the layers metadata from the previous image and writes analyzed.toml.
 func (a *Analyzer) Analyze() (files.Analyzed, error) {
+	defer log.NewMeasurement("Analyzer", a.Logger)()
 	var (
 		err              error
 		appMeta          files.LayersMetadata

builder.go

@@ -49,7 +49,7 @@ type Builder struct {
 }
 
 func (b *Builder) Build() (*files.BuildMetadata, error) {
-	b.Logger.Debug("Starting build")
+	defer log.NewMeasurement("Builder", b.Logger)()
 
 	// ensure layers SBOM directory is removed
 	if err := os.RemoveAll(filepath.Join(b.LayersDir, "sbom")); err != nil {
@@ -142,7 +142,6 @@ func (b *Builder) Build() (*files.BuildMetadata, error) {
 		b.Group.GroupExtensions[i] = ext.NoExtension().NoOpt()
 	}
 
-	b.Logger.Debug("Finished build")
 	return &files.BuildMetadata{
 		BOM:                         launchBOM,
 		Buildpacks:                  b.Group.Group,

cache.go

@@ -19,6 +19,7 @@ type LayerDir interface {
 }
 
 func (e *Exporter) Cache(layersDir string, cacheStore Cache) error {
+	defer log.NewMeasurement("Cache", e.Logger)()
 	var err error
 	if !cacheStore.Exists() {
 		e.Logger.Info("Layer cache not found")

cache_test.go

@@ -269,19 +269,19 @@ func testCache(t *testing.T, when spec.G, it spec.S) {
 					AnyTimes()
 				layersDir = filepath.Join("testdata", "cacher", "invalid-layers")
 				h.AssertNil(t, exporter.Cache(layersDir, testCache))
-				h.AssertEq(t, len(logHandler.Entries), 3)
+				h.AssertEq(t, len(logHandler.Entries), 5)
 			})
 
 			it("warns when there is a cache=true layer without contents", func() {
-				h.AssertStringContains(t, logHandler.Entries[0].Message, "Failed to cache layer 'buildpack.id:cache-true-no-contents' because it has no contents")
+				h.AssertStringContains(t, logHandler.Entries[1].Message, "Failed to cache layer 'buildpack.id:cache-true-no-contents' because it has no contents")
 			})
 
 			it("warns when there is an error adding a layer", func() {
-				h.AssertStringContains(t, logHandler.Entries[1].Message, "Failed to cache layer 'buildpack.id:layer-1': creating layer 'buildpack.id:layer-1': test error")
+				h.AssertStringContains(t, logHandler.Entries[2].Message, "Failed to cache layer 'buildpack.id:layer-1': creating layer 'buildpack.id:layer-1': test error")
 			})
 
 			it("continues caching valid layers", func() {
-				h.AssertStringContains(t, logHandler.Entries[2].Message, "Adding cache layer 'buildpack.id:layer-2'")
+				h.AssertStringContains(t, logHandler.Entries[3].Message, "Adding cache layer 'buildpack.id:layer-2'")
 				assertCacheHasLayer(t, testCache, "buildpack.id:layer-2")
 			})
 		})

detector.go

@@ -126,6 +126,7 @@ func (f *DetectorFactory) verifyAPIs(orderBp buildpack.Order, orderExt buildpack
 }
 
 func (d *Detector) Detect() (buildpack.Group, files.Plan, error) {
+	defer log.NewMeasurement("Detector", d.Logger)()
 	group, plan, detectErr := d.DetectOrder(d.Order)
 	for _, e := range d.memHandler.Entries {
 		if detectErr != nil || e.Level >= d.Logger.LogLevel() {

exporter.go

@@ -88,6 +88,7 @@ type ExportOptions struct {
 
 func (e *Exporter) Export(opts ExportOptions) (files.Report, error) {
 	var err error
+	defer log.NewMeasurement("Exporter", e.Logger)()
 
 	if e.PlatformAPI.AtLeast("0.11") {
 		if err = e.copyBuildpacksioSBOMs(opts); err != nil {

extender.go

@@ -285,6 +285,7 @@ const (
 )
 
 func (e *Extender) extend(kind string, baseImage v1.Image, logger log.Logger) (v1.Image, error) {
+	defer log.NewMeasurement("Extender", logger)()
 	logger.Debugf("Extending base image for %s: %s", kind, e.ImageRef)
 	dockerfiles, err := e.dockerfilesFor(kind, logger)
 	if err != nil {

generator.go

@@ -118,6 +118,7 @@ type GenerateResult struct {
 }
 
 func (g *Generator) Generate() (GenerateResult, error) {
+	defer log.NewMeasurement("Generator", g.Logger)()
 	inputs := g.getGenerateInputs()
 	extensionOutputParentDir, err := os.MkdirTemp("", "cnb-extensions-generated.")
 	if err != nil {

log/logger.go

@@ -1,3 +1,4 @@
+// Package log has logging interfaces for convenience in lifecycle
 package log
 
 import "github.com/apex/log"

log/timelog.go

@@ -0,0 +1,33 @@
+package log
+
+import "time"
+
+// Chronit is, I guess, short for chronological unit because it measures time or something
+type Chronit struct {
+	StartTime    time.Time
+	EndTime      time.Time
+	Log          Logger
+	FunctionName string
+}
+
+// NewMeasurement initializes a chronological measuring tool, logs out the start time, and returns a function you can defer that will log the end time
+func NewMeasurement(funcName string, lager Logger) func() {
+	c := Chronit{Log: lager, FunctionName: funcName}
+	c.RecordStart()
+	return func() {
+		c.RecordEnd()
+	}
+}
+
+// RecordStart grabs the current time and logs it, but it will be called for you if you use the NewMeasurement convenience function.
+func (c *Chronit) RecordStart() {
+	c.StartTime = time.Now()
+	c.Log.Infof("Timer: %s started at %s", c.FunctionName, c.StartTime.Format(time.RFC3339))
+}
+
+// RecordEnd is called in the function returned by NewMeasurement.
+// the EndTime will be populated just in case you'll keep the object in scope for later.
+func (c *Chronit) RecordEnd() {
+	c.EndTime = time.Now()
+	c.Log.Infof("Timer: %s ran for %v and ended at %s", c.FunctionName, c.EndTime.Sub(c.StartTime), c.EndTime.Format(time.RFC3339))
+}

log/timelog_test.go

@@ -0,0 +1,83 @@
+package log_test
+
+import (
+	"testing"
+	"time"
+
+	"github.com/sclevine/spec"
+	"github.com/sclevine/spec/report"
+
+	"github.com/buildpacks/lifecycle/log"
+	h "github.com/buildpacks/lifecycle/testhelpers"
+)
+
+type mockLog struct {
+	callCount map[string]int
+}
+
+func (m mockLog) incr(key string) {
+	val, ok := m.callCount[key]
+	if !ok {
+		m.callCount[key] = 1
+	} else {
+		m.callCount[key] = val + 1
+	}
+}
+
+func (m mockLog) Debug(msg string) {
+	m.incr("Debug")
+}
+func (m mockLog) Debugf(fmt string, v ...interface{}) {
+	m.incr("Debug")
+}
+func (m mockLog) Info(msg string) {
+	m.incr("Info")
+}
+func (m mockLog) Infof(fmt string, v ...interface{}) {
+	m.incr("Info")
+}
+func (m mockLog) Warn(msg string) {
+	m.incr("Warn")
+}
+func (m mockLog) Warnf(fmt string, v ...interface{}) {
+	m.incr("Warn")
+}
+func (m mockLog) Error(msg string) {
+	m.incr("Error")
+}
+func (m mockLog) Errorf(fmt string, v ...interface{}) {
+	m.incr("Error")
+}
+
+func TestTimeLog(t *testing.T) {
+	spec.Run(t, "Exporter", testTimeLog, spec.Parallel(), spec.Report(report.Terminal{}))
+}
+
+func testTimeLog(t *testing.T, when spec.G, it spec.S) {
+	when("we use the time log", func() {
+		it("the granular api works step by step", func() {
+			logger := mockLog{callCount: map[string]int{}}
+			c1 := log.Chronit{}
+			nullTime := time.Time{}
+			h.AssertEq(t, c1.StartTime, nullTime)
+			h.AssertEq(t, c1.EndTime, nullTime)
+
+			c1.Log = logger
+			c1.RecordStart()
+			h.AssertEq(t, logger.callCount["Info"], 1)
+			h.AssertEq(t, c1.StartTime == nullTime, false)
+			h.AssertEq(t, c1.EndTime, nullTime)
+
+			c1.RecordEnd()
+			h.AssertEq(t, logger.callCount["Info"], 2)
+			h.AssertEq(t, c1.EndTime == nullTime, false)
+		})
+		it("the convenience functions call the logger", func() {
+			logger := mockLog{callCount: map[string]int{}}
+			endfunc := log.NewMeasurement("value", logger)
+			h.AssertEq(t, logger.callCount["Info"], 1)
+			endfunc()
+			h.AssertEq(t, logger.callCount["Info"], 2)
+		})
+	})
+}

rebaser.go

@@ -36,6 +36,7 @@ type RebaseReport struct {
 }
 
 func (r *Rebaser) Rebase(workingImage imgutil.Image, newBaseImage imgutil.Image, outputImageRef string, additionalNames []string) (RebaseReport, error) {
+	defer log.NewMeasurement("Rebaser", r.Logger)()
 	appPlatformAPI, err := workingImage.Env(platform.EnvPlatformAPI)
 	if err != nil {
 		return RebaseReport{}, fmt.Errorf("failed to get app image platform API: %w", err)

restorer.go

@@ -28,6 +28,7 @@ type Restorer struct {
 // Restore restores metadata for launch and cache layers into the layers directory and attempts to restore layer data for cache=true layers, removing the layer when unsuccessful.
 // If a usable cache is not provided, Restore will not restore any cache=true layer metadata.
 func (r *Restorer) Restore(cache Cache) error {
+	defer log.NewMeasurement("Restorer", r.Logger)()
 	cacheMeta, err := retrieveCacheMetadata(cache, r.Logger)
 	if err != nil {
 		return err

save.go

@@ -17,9 +17,9 @@ func saveImage(image imgutil.Image, additionalNames []string, logger log.Logger)
 }
 
 func saveImageAs(image imgutil.Image, name string, additionalNames []string, logger log.Logger) (files.ImageReport, error) {
+	defer log.NewMeasurement("Saving "+name+"...", logger)()
 	var saveErr error
 	imageReport := files.ImageReport{}
-	logger.Infof("Saving %s...\n", name)
 	if err := image.SaveAs(name, additionalNames...); err != nil {
 		var ok bool
 		if saveErr, ok = err.(imgutil.SaveError); !ok {