Merge lp:~rogpeppe/gocheck/monotonic-time-stamps into lp:gocheck

[Roger Peppe]

Use readable time stamps on log messages.

On long running tests, the time might wrap:

[LOG] 72.15087 JUJU state: opening state; zookeeper addresses: ["ec2-23-20-157-185.compute-1.amazonaws.com:2181"]
[LOG] 78.46405 JUJU state: waiting for state to be initialized
destroy env
[LOG] 13.73135 JUJU environs/ec2: destroying environment "sample-6326978ae3647455"

This CL makes the time stamp format as a duration since
the start of the test in the format agreed before:

[LOG] 0:00.568 DEBUG juju.environs.tools reading v1.* tools
[LOG] 0:00.569 INFO juju environs/testing: uploading FAKE tools 1.17.3-trusty-amd64
[LOG] 0:00.570 INFO juju environs/testing: uploading FAKE tools 1.17.3-precise-amd64
[LOG] 0:00.571 DEBUG juju.environs.tools no architecture specified when finding tools, looking for any

https://codereview.appspot.com/5874049/

[Roger Peppe (rogpeppe)]

Reviewers: mp+98841_code.launchpad.net,

Message:
Please take a look.

Description:
use readable time stamps on log messages.

On long running tests, I was seeing log output like this:

[LOG] 72.15087 JUJU state: opening state; zookeeper addresses:
["ec2-23-20-157-185.compute-1.amazonaws.com:2181"]
[LOG] 78.46405 JUJU state: waiting for state to be initialized
destroy env
[LOG] 13.73135 JUJU environs/ec2: destroying environment
"sample-6326978ae3647455"

This CL makes the time stamp format as a duration
since the start of the test. For instance:

[LOG] 139us JUJU environs/ec2: bootstrapping environment
"sample-92839ff36fe291dd"
[LOG] 7.273315s JUJU environs/ec2: started instance "i-69f7a10d"
[LOG] 14.822193s JUJU environs/ec2: bootstrapping environment
"sample-92839ff36fe291dd"

For consideration: we could also round to milliseconds (nanosecond time
stamps are rarely useful in logs).

https://code.launchpad.net/~rogpeppe/gocheck/monotonic-time-stamps/+merge/98841

(do not edit description out of merge proposal)

Please review this at https://codereview.appspot.com/5874049/

Affected files:
   A [revision details]
   M bootstrap_test.go
   M checkers.go
   M foundation_test.go
   M gocheck.go
   M gocheck_test.go
   M helpers.go
   M helpers_test.go
   M run.go
   M run_test.go

Index: [revision details]
=== added file '[revision details]'
--- [revision details] 2012-01-01 00:00:00 +0000
+++ [revision details] 2012-01-01 00:00:00 +0000
@@ -0,0 +1,2 @@
+Old revision: <email address hidden>
+New revision: <email address hidden>

Index: bootstrap_test.go
=== modified file 'bootstrap_test.go'
--- bootstrap_test.go 2011-11-08 15:09:50 +0000
+++ bootstrap_test.go 2012-03-22 13:59:07 +0000
@@ -13,9 +13,9 @@
  package gocheck_test

  import (
+ "fmt"
   "launchpad.net/gocheck"
   "strings"
- "fmt"
  )

  type BootstrapS struct{}

Index: checkers.go
=== modified file 'checkers.go'
--- checkers.go 2012-02-25 19:01:16 +0000
+++ checkers.go 2012-03-22 13:59:07 +0000
@@ -1,9 +1,9 @@
  package gocheck

  import (
+ "fmt"
   "reflect"
   "regexp"
- "fmt"
  )

  // -----------------------------------------------------------------------
@@ -238,7 +238,6 @@
   return value.Len() == n, ""
  }

-
  // -----------------------------------------------------------------------
  // ErrorMatches checker.

Index: foundation_test.go
=== modified file 'foundation_test.go'
--- foundation_test.go 2012-02-25 16:58:37 +0000
+++ foundation_test.go 2012-03-22 13:59:07 +0000
@@ -7,12 +7,12 @@
  package gocheck_test

  import (
+ "fmt"
   "launchpad.net/gocheck"
- "strings"
- "regexp"
- "fmt"
   "log"
   "os"
+ "regexp"
+ "strings"
  )

  // -----------------------------------------------------------------------
@@ -301,14 +301,9 @@
   logger = log.New(os.Stderr, "", 0)
   logger = c
   logger.Output(0, "Hello there")
- expected := "\\[LOG\\] [.0-9]+ Hello there\n"
+ expected := `\[LOG\] [0-9]+(\.[0-9]+)?[mun]?s +Hello there\n`
   output := c.GetTestLog()
- matched, err := regexp.MatchString(expected, output)
- if err != nil {
- c.Error("Bad expression: ", expected)
- } else if !matched {
- c.Error("Out...

[Roger Peppe (rogpeppe)]

Please take a look.

https://codereview.appspot.com/5874049/

[Gustavo Niemeyer (niemeyer)]

This has already been fixed in the last release, following up a
conversation we had online and a format we both agreed with.

https://codereview.appspot.com/5874049/

[Roger Peppe (rogpeppe)]

Please take a look.

https://codereview.appspot.com/5874049/

[Gustavo Niemeyer (niemeyer)]

LGTM

https://codereview.appspot.com/5874049/

=== modified file 'benchmark_test.go'
--- benchmark_test.go	2013-03-02 02:47:45 +0000
+++ benchmark_test.go	2014-02-18 17:08:13 +0000
@@ -40,10 +40,10 @@
 	helper := FixtureHelper{sleep: 100000}
 	output := String{}
 	runConf := RunConf{
-		Output: &output,
-		Benchmark: true,
+		Output:        &output,
+		Benchmark:     true,
 		BenchmarkTime: 10000000,
-		Filter: "Benchmark1",
+		Filter:        "Benchmark1",
 	}
 	Run(&helper, &runConf)
 	c.Check(helper.calls[0], Equals, "SetUpSuite")
@@ -63,10 +63,10 @@
 	helper := FixtureHelper{sleep: 100000}
 	output := String{}
 	runConf := RunConf{
-		Output: &output,
-		Benchmark: true,
+		Output:        &output,
+		Benchmark:     true,
 		BenchmarkTime: 10000000,
-		Filter: "Benchmark2",
+		Filter:        "Benchmark2",
 	}
 	Run(&helper, &runConf)
 
 
=== modified file 'bootstrap_test.go'
--- bootstrap_test.go	2012-02-28 15:14:09 +0000
+++ bootstrap_test.go	2014-02-18 17:08:13 +0000
@@ -1,7 +1,7 @@
 // These initial tests are for bootstrapping.  They verify that we can
 // basically use the testing infrastructure itself to check if the test
 // system is working.
-// 
+//
 // These tests use will break down the test runner badly in case of
 // errors because if they simply fail, we can't be sure the developer
 // will ever see anything (because failing means the failing system
 
=== modified file 'foundation_test.go'
--- foundation_test.go	2013-03-01 22:15:07 +0000
+++ foundation_test.go	2014-02-18 17:08:13 +0000
@@ -301,14 +301,9 @@
 	logger = log.New(os.Stderr, "", 0)
 	logger = c
 	logger.Output(0, "Hello there")
-	expected := "\\[LOG\\] [.0-9]+ Hello there\n"
+	expected := `\[LOG\] [0-9]+:[0-9][0-9]\.[0-9][0-9][0-9] +Hello there\n`
 	output := c.GetTestLog()
-	matched, err := regexp.MatchString(expected, output)
-	if err != nil {
-		c.Error("Bad expression: ", expected)
-	} else if !matched {
-		c.Error("Output() didn't log properly:\n", output)
-	}
+	c.Assert(output, gocheck.Matches, expected)
 }
 
 // -----------------------------------------------------------------------
 
=== modified file 'gocheck.go'
--- gocheck.go	2013-03-02 02:47:45 +0000
+++ gocheck.go	2014-02-18 17:08:13 +0000
@@ -62,7 +62,7 @@
 }
 
 func (method *methodType) String() string {
-	return method.suiteName()+"."+method.Info.Name
+	return method.suiteName() + "." + method.Info.Name
 }
 
 func (method *methodType) matches(re *regexp.Regexp) bool {
@@ -81,6 +81,7 @@
 	reason    string
 	mustFail  bool
 	tempDir   *tempDir
+	startTime time.Time
 	timer
 }
 
@@ -613,13 +614,14 @@
 		logb = new(logger)
 	}
 	c := &C{
-		method:  method,
-		kind:    kind,
-		logb:    logb,
-		logw:    logw,
-		tempDir: runner.tempDir,
-		done:    make(chan *C, 1),
-		timer:   timer{benchTime: runner.benchTime},
+		method:    method,
+		kind:      kind,
+		logb:      logb,
+		logw:      logw,
+		tempDir:   runner.tempDir,
+		done:      make(chan *C, 1),
+		timer:     timer{benchTime: runner.benchTime},
+		startTime: time.Now(),
 	}
 	runner.tracker.expectCall(c)
 	go (func() {
@@ -913,4 +915,3 @@
 	return fmt.Sprintf("%s%s: %s: %s%s", prefix, label, niceFuncPath(pc),
 		niceFuncName(pc), suffix)
 }
-
 
=== modified file 'gocheck_test.go'
--- gocheck_test.go	2013-03-02 02:47:45 +0000
+++ gocheck_test.go	2014-02-18 17:08:13 +0000
@@ -94,13 +94,13 @@
 // Helper suite for testing ordering and behavior of fixture.
 
 type FixtureHelper struct {
-	calls    []string
-	panicOn  string
-	skip     bool
-	skipOnN  int
-	sleepOn  string
-	sleep    time.Duration
-	bytes    int64
+	calls   []string
+	panicOn string
+	skip    bool
+	skipOnN int
+	sleepOn string
+	sleep   time.Duration
+	bytes   int64
 }
 
 func (s *FixtureHelper) trace(name string, c *gocheck.C) {
 
=== modified file 'helpers.go'
--- helpers.go	2012-02-25 16:58:37 +0000
+++ helpers.go	2014-02-18 17:08:13 +0000
@@ -92,9 +92,12 @@
 // Output enables *C to be used as a logger in functions that require only
 // the minimum interface of *log.Logger.
 func (c *C) Output(calldepth int, s string) error {
-	ns := time.Now().Sub(time.Time{}).Nanoseconds()
-	t := float64(ns%100e9) / 1e9
-	c.Logf("[LOG] %.05f %s", t, s)
+	d := time.Now().Sub(c.startTime)
+	msec := d / time.Millisecond
+	sec := d / time.Second
+	min := d / time.Minute
+
+	c.Logf("[LOG] %d:%02d.%03d %s", min, sec%60, msec%1000, s)
 	return nil
 }
 
 
=== modified file 'run.go'
--- run.go	2013-03-01 22:15:07 +0000
+++ run.go	2014-02-18 17:08:13 +0000
@@ -30,7 +30,7 @@
 	verboseFlag = flag.Bool("gocheck.v", false, "Verbose mode")
 	streamFlag  = flag.Bool("gocheck.vv", false, "Super verbose mode (disables output caching)")
 	benchFlag   = flag.Bool("gocheck.b", false, "Run benchmarks")
-	benchTime   = flag.Duration("gocheck.btime", 1 * time.Second, "approximate run time for each benchmark")
+	benchTime   = flag.Duration("gocheck.btime", 1*time.Second, "approximate run time for each benchmark")
 	listFlag    = flag.Bool("gocheck.list", false, "List the names of all tests that will be run")
 )
 
@@ -39,10 +39,10 @@
 // module.
 func TestingT(testingT *testing.T) {
 	conf := &RunConf{
-		Filter:    *filterFlag,
-		Verbose:   *verboseFlag,
-		Stream:    *streamFlag,
-		Benchmark: *benchFlag,
+		Filter:        *filterFlag,
+		Verbose:       *verboseFlag,
+		Stream:        *streamFlag,
+		Benchmark:     *benchFlag,
 		BenchmarkTime: *benchTime,
 	}
 	if *listFlag {
 
=== modified file 'run_test.go'
--- run_test.go	2013-03-02 02:47:45 +0000
+++ run_test.go	2014-02-18 17:08:13 +0000
@@ -2,7 +2,6 @@
 
 package gocheck_test
 
-
 import (
 	"errors"
 	. "launchpad.net/gocheck"
@@ -299,7 +298,7 @@
 }
 
 // -----------------------------------------------------------------------
-// Verify that verbose mode prints tests which pass as well. 
+// Verify that verbose mode prints tests which pass as well.
 
 func (s *RunS) TestVerboseMode(c *C) {
 	helper := FixtureHelper{}