gocheck

Code review comment for lp:~rogpeppe/gocheck/monotonic-time-stamps

  1. monotonic-time-stamps
  2. Merge into trunk
Revision history for this message
Roger Peppe (rogpeppe) wrote :

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)

« Back to merge proposal