Merge pull request #3 from jameinel/clock-stacks

#3

1) Actually wire up the tests for the testing clock. In moving them out
 of 'util' we missed having the TestAll function.
2) Fix a test that checked the logs, but didn't tell the logging
 infrastructure that it needed to read all Debug level log messages.
3) Change clock.WaitAdvance to not break the time into 10 even slices.
 This is because *many* tests use WaitAdvance(..., LongWait), which
 means that if they aren't ready immediately, then they way 1s before
 checking again, which is way too long. Instead we cap out at 10ms, so
 we don't spin waiting for the right number of waiters, but we also
 don't wait too long. We still stop at the same time, and we still
 stop as soon as we have the expected number of waiters.
4) Track the stack traces of who is waiting for the clock. This makes it
 possible to know *who* has actually called clock.After() and co, so
 you can figure out why there are a particular number of Waiters, and
 whether that is the correct number or not.

Nothing about the interface to the testing clock changes with this, it is just hopefully slightly nicer to debug issues when using the testing clock.

testclock/clock.go

@@ -4,6 +4,8 @@
 package testclock
 
 import (
+	"fmt"
+	"runtime/debug"
 	"sort"
 	"sync"
 	"time"
@@ -21,6 +23,7 @@ type timer struct {
 	// trigger is called when the timer expires. It is
 	// called with the clock mutex held and will not block.
 	trigger func()
+	stack   []byte
 }
 
 // Reset is part of the clock.Timer interface.
@@ -92,6 +95,7 @@ func (clock *Clock) addAlarm(d time.Duration, c chan time.Time, trigger func())
 		deadline: clock.now.Add(d),
 		clock:    clock,
 		trigger:  trigger,
+		stack:    debug.Stack(),
 	}
 	clock.addTimer(t)
 	clock.triggerAll()
@@ -117,22 +121,37 @@ func (clock *Clock) Advance(d time.Duration) {
 // 'w' for 'n' timers to show up in clock.waiting, and if they do we advance
 // 'd'.
 func (clock *Clock) WaitAdvance(d, w time.Duration, n int) error {
-	if w == 0 {
-		w = time.Second
-	}
 	pause := w / 10
-	for i := 0; i < 10; i++ {
-		if clock.hasNWaiters(n) {
-			clock.Advance(d)
-			return nil
+	if pause > 10*time.Millisecond {
+		pause = 10 * time.Millisecond
+	}
+	finalTimeout := time.After(w)
+	next := time.After(0)
+	for {
+		select {
+		case <-finalTimeout:
+                        if clock.hasNWaiters(n) {
+                            clock.Advance(d)
+                            return nil
+                        }
+			clock.mu.Lock()
+			got := len(clock.waiting)
+			var stacks string
+			for _, t := range clock.waiting {
+				stacks += fmt.Sprintf("timer deadline: %v\n%s", t.deadline, string(t.stack))
+			}
+			clock.mu.Unlock()
+			return errors.Errorf(
+				"got %d timers added after waiting %s: wanted %d, stacks:\n%s",
+				got, w.String(), n, stacks)
+		case <-next:
+			if clock.hasNWaiters(n) {
+				clock.Advance(d)
+				return nil
+			}
+			next = time.After(pause)
 		}
-		time.Sleep(pause)
 	}
-	clock.mu.Lock()
-	got := len(clock.waiting)
-	clock.mu.Unlock()
-	return errors.Errorf(
-		"got %d timers added after waiting %s: wanted %d", got, w.String(), n)
 }
 
 // hasNWaiters checks if the clock currently has 'n' timers waiting to fire.

testclock/clock_test.go

@@ -5,8 +5,10 @@ package testclock_test
 
 import (
 	"sync"
+	gotesting "testing"
 	"time"
 
+	"github.com/juju/loggo"
 	"github.com/juju/testing"
 	jc "github.com/juju/testing/checkers"
 	gc "gopkg.in/check.v1"
@@ -18,6 +20,10 @@ type clockSuite struct {
 	testing.LoggingSuite
 }
 
+func TestAll(t *gotesting.T) {
+	gc.TestingT(t)
+}
+
 var _ = gc.Suite(&clockSuite{})
 
 func (*clockSuite) TestNow(c *gc.C) {
@@ -32,6 +38,7 @@ var (
 )
 
 func (*clockSuite) TestAdvanceLogs(c *gc.C) {
+	loggo.GetLogger("juju.clock").SetLogLevel(loggo.DEBUG)
 	t0 := time.Now()
 	cl := testclock.NewClock(t0)
 
@@ -50,9 +57,13 @@ func (*clockSuite) TestWaitAdvance(c *gc.C) {
 	t0 := time.Now()
 	cl := testclock.NewClock(t0)
 
+        // It is legal to just say 'nothing is waiting'
+	err := cl.WaitAdvance(0, 0, 0)
+	c.Check(err, jc.ErrorIsNil)
+
 	// Test that no timers errors out.
-	err := cl.WaitAdvance(time.Millisecond, 10*time.Millisecond, 1)
-	c.Check(err, gc.ErrorMatches, "got 0 timers added after waiting 10ms: wanted 1")
+	err = cl.WaitAdvance(time.Millisecond, 10*time.Millisecond, 1)
+	c.Check(err, gc.ErrorMatches, "got 0 timers added after waiting 10ms: wanted 1, stacks:\n")
 
 	// Test that a timer doesn't error.
 	_ = cl.After(time.Nanosecond)