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("Output() didn't log properly:\n", output)
-	}
+	c.Assert(output, gocheck.Matches, expected)
  }

  // -----------------------------------------------------------------------


Index: gocheck.go
=== modified file 'gocheck.go'
--- gocheck.go	2012-02-25 18:28:36 +0000
+++ gocheck.go	2012-03-22 13:59:07 +0000
@@ -15,6 +15,7 @@
  	"strconv"
  	"strings"
  	"sync"
+	"time"
  )

  // -----------------------------------------------------------------------
@@ -54,22 +55,31 @@
  }

  type C struct {
-	method   *methodType
-	kind     funcKind
-	status   funcStatus
-	logb     *bytes.Buffer
-	logw     io.Writer
-	done     chan *C
-	reason   string
-	mustFail bool
-	tempDir  *tempDir
+	method    *methodType
+	kind      funcKind
+	status    funcStatus
+	logb      *bytes.Buffer
+	logw      io.Writer
+	done      chan *C
+	reason    string
+	mustFail  bool
+	tempDir   *tempDir
+	startTime time.Time
  }

  func newC(method *methodType, kind funcKind, logb *bytes.Buffer, logw  
io.Writer, tempDir *tempDir) *C {
  	if logb == nil {
  		logb = bytes.NewBuffer(nil)
  	}
-	return &C{method: method, kind: kind, logb: logb, logw: logw, tempDir:  
tempDir, done: make(chan *C, 1)}
+	return &C{
+		method:    method,
+		kind:      kind,
+		logb:      logb,
+		logw:      logw,
+		tempDir:   tempDir,
+		done:      make(chan *C, 1),
+		startTime: time.Now(),
+	}
  }

  func (c *C) stopNow() {
@@ -112,7 +122,7 @@
  	if td._path != "" {
  		err := os.RemoveAll(td._path)
  		if err != nil {
-			fmt.Fprintf(os.Stderr, "WARNING: Error cleaning up temporaries: " +  
err.Error())
+			fmt.Fprintf(os.Stderr, "WARNING: Error cleaning up  
temporaries: "+err.Error())
  		}
  	}
  }
@@ -190,7 +200,7 @@
  	i := 0
  	n := len(s)
  	for i < n {
-		j := i+1
+		j := i + 1
  		for j < n && s[j-1] != '\n' {
  			j++
  		}


Index: gocheck_test.go
=== modified file 'gocheck_test.go'
--- gocheck_test.go	2012-02-17 01:57:02 +0000
+++ gocheck_test.go	2012-03-22 13:59:07 +0000
@@ -4,13 +4,13 @@
  package gocheck_test

  import (
-	"launchpad.net/gocheck"
-	"testing"
-	"runtime"
-	"regexp"
  	"flag"
  	"fmt"
+	"launchpad.net/gocheck"
  	"os"
+	"regexp"
+	"runtime"
+	"testing"
  )

  // We count the number of suites run at least to get a vague hint that the


Index: helpers.go
=== modified file 'helpers.go'
--- helpers.go	2012-02-25 16:58:37 +0000
+++ helpers.go	2012-03-22 13:59:07 +0000
@@ -92,9 +92,8 @@
  // 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)
+	c.Logf("[LOG] %-10v %s", d, s)
  	return nil
  }



Index: helpers_test.go
=== modified file 'helpers_test.go'
--- helpers_test.go	2012-02-25 18:28:36 +0000
+++ helpers_test.go	2012-03-22 13:59:07 +0000
@@ -126,7 +126,7 @@
  	testHelperFailure(c, "Check(1, checker, 2, msg)", false, false, log,
  		func() interface{} {
  			// Nice leading comment.
-			return c.Check(1, checker, 2)  // Hello there
+			return c.Check(1, checker, 2) // Hello there
  		})
  }

@@ -379,7 +379,6 @@
  		})
  }

-
  // -----------------------------------------------------------------------
  // MakeDir() tests.



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

  import (
-	"testing"
  	"flag"
  	"fmt"
+	"testing"
  )

  // -----------------------------------------------------------------------


Index: run_test.go
=== modified file 'run_test.go'
--- run_test.go	2012-02-25 13:01:18 +0000
+++ run_test.go	2012-03-22 13:59:07 +0000
@@ -99,21 +99,21 @@

  func (s *RunS) TestAdd(c *C) {
  	result := &Result{
-		Succeeded: 1,
-		Skipped: 2,
-		Failed: 3,
-		Panicked: 4,
-		FixturePanicked: 5,
-		Missed: 6,
+		Succeeded:        1,
+		Skipped:          2,
+		Failed:           3,
+		Panicked:         4,
+		FixturePanicked:  5,
+		Missed:           6,
  		ExpectedFailures: 7,
  	}
  	result.Add(&Result{
-		Succeeded: 10,
-		Skipped: 20,
-		Failed: 30,
-		Panicked: 40,
-		FixturePanicked: 50,
-		Missed: 60,
+		Succeeded:        10,
+		Skipped:          20,
+		Failed:           30,
+		Panicked:         40,
+		FixturePanicked:  50,
+		Missed:           60,
  		ExpectedFailures: 70,
  	})
  	c.Check(result.Succeeded, Equals, 11)