Repository: buildpacks/lifecycle
Pull request #1230 (2023-10-30 19:30:58)

Print `Timer` logs in debug mode only
<!-- 🎉🎉🎉 Thank you for the PR!!! 🎉🎉🎉 -->

### Summary
<!-- Please describe your changes at a high level. -->
The default of emitting timings to info is too noisy.  This change lets platforms that want to see timings do so by setting the log level to debug.


#### 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 -->
- `lifecycle` now only emits timing to the debug logs.


---

### Context
<!-- Add any other context that may help reviewers (e.g., code that requires special attention, etc.). -->

https://cloud-native.slack.com/archives/C0331B5QS02/p1698686716010529


Patch:
diff --git a/log/timelog.go b/log/timelog.go
index 3c168e82..b3fcd3b2 100644
--- a/log/timelog.go
+++ b/log/timelog.go
@@ -22,12 +22,12 @@ func NewMeasurement(funcName string, lager Logger) func() {
 // 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))
+	c.Log.Debugf("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))
+	c.Log.Debugf("Timer: %s ran for %v and ended at %s", c.FunctionName, c.EndTime.Sub(c.StartTime), c.EndTime.Format(time.RFC3339))
 }
diff --git a/phase/save.go b/phase/save.go
index b2e4a891..92f36b8e 100644
--- a/phase/save.go
+++ b/phase/save.go
@@ -20,6 +20,7 @@ func saveImageAs(image imgutil.Image, name string, additionalNames []string, log
 	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 {


Test patch:
diff --git a/.github/workflows/check-latest-release.yml b/.github/workflows/check-latest-release.yml
index d0e6766b..5bf1ea93 100644
--- a/.github/workflows/check-latest-release.yml
+++ b/.github/workflows/check-latest-release.yml
@@ -9,6 +9,8 @@ jobs:
   check-release:
     runs-on:
       - ubuntu-latest
+    permissions:
+      id-token: write
     steps:
       - uses: actions/checkout@v4
       - uses: actions/setup-go@v4
diff --git a/log/timelog_test.go b/log/timelog_test.go
index 4cac702b..29a99601 100644
--- a/log/timelog_test.go
+++ b/log/timelog_test.go
@@ -64,20 +64,20 @@ func testTimeLog(t *testing.T, when spec.G, it spec.S) {
 
 			c1.Log = logger
 			c1.RecordStart()
-			h.AssertEq(t, logger.callCount["Info"], 1)
+			h.AssertEq(t, logger.callCount["Debug"], 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, logger.callCount["Debug"], 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)
+			h.AssertEq(t, logger.callCount["Debug"], 1)
 			endfunc()
-			h.AssertEq(t, logger.callCount["Info"], 2)
+			h.AssertEq(t, logger.callCount["Debug"], 2)
 		})
 	})
 }
diff --git a/phase/cache_test.go b/phase/cache_test.go
index b97ccf8a..03971e7c 100644
--- a/phase/cache_test.go
+++ b/phase/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), 5)
+				h.AssertEq(t, len(logHandler.Entries), 3)
 			})
 
 			it("warns when there is a cache=true layer without contents", func() {
-				h.AssertStringContains(t, logHandler.Entries[1].Message, "Failed to cache layer 'buildpack.id:cache-true-no-contents' because it has no contents")
+				h.AssertStringContains(t, logHandler.Entries[0].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[2].Message, "Failed to cache layer 'buildpack.id:layer-1': creating layer 'buildpack.id:layer-1': test error")
+				h.AssertStringContains(t, logHandler.Entries[1].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[3].Message, "Adding cache layer 'buildpack.id:layer-2'")
+				h.AssertStringContains(t, logHandler.Entries[2].Message, "Adding cache layer 'buildpack.id:layer-2'")
 				assertCacheHasLayer(t, testCache, "buildpack.id:layer-2")
 			})
 		})