From 653a46fa26286b60f93c8d27f4340fc173f8bb7f Mon Sep 17 00:00:00 2001 From: Jesse Brown Date: Mon, 30 Oct 2023 16:51:30 -0500 Subject: [PATCH] Print `Timer` logs in debug mode only (#1230) 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. Signed-off-by: Jesse Brown --- log/timelog.go | 4 ++-- log/timelog_test.go | 8 ++++---- phase/cache_test.go | 8 ++++---- phase/save.go | 1 + 4 files changed, 11 insertions(+), 10 deletions(-) diff --git a/log/timelog.go b/log/timelog.go index 3c168e82c..b3fcd3b25 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/log/timelog_test.go b/log/timelog_test.go index 4cac702b5..29a996019 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 b97ccf8a7..03971e7c9 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") }) }) diff --git a/phase/save.go b/phase/save.go index b2e4a891b..92f36b8e3 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 {