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

Proposed by Roger Peppe
Status: Merged
Merged at revision: 87
Proposed branch: lp:~rogpeppe/gocheck/monotonic-time-stamps
Merge into: lp:gocheck
Diff against target: 207 lines (+38/-40)
8 files modified
benchmark_test.go (+6/-6)
bootstrap_test.go (+1/-1)
foundation_test.go (+2/-7)
gocheck.go (+10/-9)
gocheck_test.go (+7/-7)
helpers.go (+6/-3)
run.go (+5/-5)
run_test.go (+1/-2)
To merge this branch: bzr merge lp:~rogpeppe/gocheck/monotonic-time-stamps
Reviewer Review Type Date Requested Status
Gustavo Niemeyer Pending
Review via email: mp+98841@code.launchpad.net

Description of the change

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/

To post a comment you must log in.
Revision history for this message
Roger Peppe (rogpeppe) wrote :
Download full text (7.5 KiB)

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...

Read more...

Revision history for this message
Roger Peppe (rogpeppe) wrote :
Revision history for this message
Gustavo Niemeyer (niemeyer) wrote :

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/

Revision history for this message
Roger Peppe (rogpeppe) wrote :
Revision history for this message
Gustavo Niemeyer (niemeyer) wrote :

Preview Diff

[H/L] Next/Prev Comment, [J/K] Next/Prev File, [N/P] Next/Prev Hunk
1=== modified file 'benchmark_test.go'
2--- benchmark_test.go 2013-03-02 02:47:45 +0000
3+++ benchmark_test.go 2014-02-18 17:08:13 +0000
4@@ -40,10 +40,10 @@
5 helper := FixtureHelper{sleep: 100000}
6 output := String{}
7 runConf := RunConf{
8- Output: &output,
9- Benchmark: true,
10+ Output: &output,
11+ Benchmark: true,
12 BenchmarkTime: 10000000,
13- Filter: "Benchmark1",
14+ Filter: "Benchmark1",
15 }
16 Run(&helper, &runConf)
17 c.Check(helper.calls[0], Equals, "SetUpSuite")
18@@ -63,10 +63,10 @@
19 helper := FixtureHelper{sleep: 100000}
20 output := String{}
21 runConf := RunConf{
22- Output: &output,
23- Benchmark: true,
24+ Output: &output,
25+ Benchmark: true,
26 BenchmarkTime: 10000000,
27- Filter: "Benchmark2",
28+ Filter: "Benchmark2",
29 }
30 Run(&helper, &runConf)
31
32
33=== modified file 'bootstrap_test.go'
34--- bootstrap_test.go 2012-02-28 15:14:09 +0000
35+++ bootstrap_test.go 2014-02-18 17:08:13 +0000
36@@ -1,7 +1,7 @@
37 // These initial tests are for bootstrapping. They verify that we can
38 // basically use the testing infrastructure itself to check if the test
39 // system is working.
40-//
41+//
42 // These tests use will break down the test runner badly in case of
43 // errors because if they simply fail, we can't be sure the developer
44 // will ever see anything (because failing means the failing system
45
46=== modified file 'foundation_test.go'
47--- foundation_test.go 2013-03-01 22:15:07 +0000
48+++ foundation_test.go 2014-02-18 17:08:13 +0000
49@@ -301,14 +301,9 @@
50 logger = log.New(os.Stderr, "", 0)
51 logger = c
52 logger.Output(0, "Hello there")
53- expected := "\\[LOG\\] [.0-9]+ Hello there\n"
54+ expected := `\[LOG\] [0-9]+:[0-9][0-9]\.[0-9][0-9][0-9] +Hello there\n`
55 output := c.GetTestLog()
56- matched, err := regexp.MatchString(expected, output)
57- if err != nil {
58- c.Error("Bad expression: ", expected)
59- } else if !matched {
60- c.Error("Output() didn't log properly:\n", output)
61- }
62+ c.Assert(output, gocheck.Matches, expected)
63 }
64
65 // -----------------------------------------------------------------------
66
67=== modified file 'gocheck.go'
68--- gocheck.go 2013-03-02 02:47:45 +0000
69+++ gocheck.go 2014-02-18 17:08:13 +0000
70@@ -62,7 +62,7 @@
71 }
72
73 func (method *methodType) String() string {
74- return method.suiteName()+"."+method.Info.Name
75+ return method.suiteName() + "." + method.Info.Name
76 }
77
78 func (method *methodType) matches(re *regexp.Regexp) bool {
79@@ -81,6 +81,7 @@
80 reason string
81 mustFail bool
82 tempDir *tempDir
83+ startTime time.Time
84 timer
85 }
86
87@@ -613,13 +614,14 @@
88 logb = new(logger)
89 }
90 c := &C{
91- method: method,
92- kind: kind,
93- logb: logb,
94- logw: logw,
95- tempDir: runner.tempDir,
96- done: make(chan *C, 1),
97- timer: timer{benchTime: runner.benchTime},
98+ method: method,
99+ kind: kind,
100+ logb: logb,
101+ logw: logw,
102+ tempDir: runner.tempDir,
103+ done: make(chan *C, 1),
104+ timer: timer{benchTime: runner.benchTime},
105+ startTime: time.Now(),
106 }
107 runner.tracker.expectCall(c)
108 go (func() {
109@@ -913,4 +915,3 @@
110 return fmt.Sprintf("%s%s: %s: %s%s", prefix, label, niceFuncPath(pc),
111 niceFuncName(pc), suffix)
112 }
113-
114
115=== modified file 'gocheck_test.go'
116--- gocheck_test.go 2013-03-02 02:47:45 +0000
117+++ gocheck_test.go 2014-02-18 17:08:13 +0000
118@@ -94,13 +94,13 @@
119 // Helper suite for testing ordering and behavior of fixture.
120
121 type FixtureHelper struct {
122- calls []string
123- panicOn string
124- skip bool
125- skipOnN int
126- sleepOn string
127- sleep time.Duration
128- bytes int64
129+ calls []string
130+ panicOn string
131+ skip bool
132+ skipOnN int
133+ sleepOn string
134+ sleep time.Duration
135+ bytes int64
136 }
137
138 func (s *FixtureHelper) trace(name string, c *gocheck.C) {
139
140=== modified file 'helpers.go'
141--- helpers.go 2012-02-25 16:58:37 +0000
142+++ helpers.go 2014-02-18 17:08:13 +0000
143@@ -92,9 +92,12 @@
144 // Output enables *C to be used as a logger in functions that require only
145 // the minimum interface of *log.Logger.
146 func (c *C) Output(calldepth int, s string) error {
147- ns := time.Now().Sub(time.Time{}).Nanoseconds()
148- t := float64(ns%100e9) / 1e9
149- c.Logf("[LOG] %.05f %s", t, s)
150+ d := time.Now().Sub(c.startTime)
151+ msec := d / time.Millisecond
152+ sec := d / time.Second
153+ min := d / time.Minute
154+
155+ c.Logf("[LOG] %d:%02d.%03d %s", min, sec%60, msec%1000, s)
156 return nil
157 }
158
159
160=== modified file 'run.go'
161--- run.go 2013-03-01 22:15:07 +0000
162+++ run.go 2014-02-18 17:08:13 +0000
163@@ -30,7 +30,7 @@
164 verboseFlag = flag.Bool("gocheck.v", false, "Verbose mode")
165 streamFlag = flag.Bool("gocheck.vv", false, "Super verbose mode (disables output caching)")
166 benchFlag = flag.Bool("gocheck.b", false, "Run benchmarks")
167- benchTime = flag.Duration("gocheck.btime", 1 * time.Second, "approximate run time for each benchmark")
168+ benchTime = flag.Duration("gocheck.btime", 1*time.Second, "approximate run time for each benchmark")
169 listFlag = flag.Bool("gocheck.list", false, "List the names of all tests that will be run")
170 )
171
172@@ -39,10 +39,10 @@
173 // module.
174 func TestingT(testingT *testing.T) {
175 conf := &RunConf{
176- Filter: *filterFlag,
177- Verbose: *verboseFlag,
178- Stream: *streamFlag,
179- Benchmark: *benchFlag,
180+ Filter: *filterFlag,
181+ Verbose: *verboseFlag,
182+ Stream: *streamFlag,
183+ Benchmark: *benchFlag,
184 BenchmarkTime: *benchTime,
185 }
186 if *listFlag {
187
188=== modified file 'run_test.go'
189--- run_test.go 2013-03-02 02:47:45 +0000
190+++ run_test.go 2014-02-18 17:08:13 +0000
191@@ -2,7 +2,6 @@
192
193 package gocheck_test
194
195-
196 import (
197 "errors"
198 . "launchpad.net/gocheck"
199@@ -299,7 +298,7 @@
200 }
201
202 // -----------------------------------------------------------------------
203-// Verify that verbose mode prints tests which pass as well.
204+// Verify that verbose mode prints tests which pass as well.
205
206 func (s *RunS) TestVerboseMode(c *C) {
207 helper := FixtureHelper{}

Subscribers

People subscribed via source and target branches