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 <jabrown85@gmail.com>

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

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

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")
 			})
 		})

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 {