Several tweaks to 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)