Intermittent failures

NB: This page is linked to from an error message logged in github.com/juju/testing/clock.go.

testing.Clock

While working on lp:1607044 at the September 2016 quality sprint we determined that there are some timing issues when advancing a clock concurrently with relying on it for timing.

To fix this we've added a clock.WaitAdvance method. This method simply waits until there is something in clock.waiting before advancing. In the case of a happy (common, expected) path, this doesn't wait at all. Only in the case of the unhappy (unexpected, rare) path does it pause to allow clock.waiting to be populated.

To help suss out other cases where this behavior might cause intermittent failures clock.Advance now logs an entry if it is advancing a clock with an empty clock.waiting slice.

To illustrate the issue in the linked bug we've outlined the happy and unhappy paths in the following ASCII diagrams.

Happy path

           Test creates and starts a
         / worker, https://goo.gl/LQNepS    
        |
        |                    clock.Advance(duration) https://goo.gl/hbpAvp
       /                   / moves time forward.
      |                   |
      |                   |          
      |                   |         
      |                   |        
      |                   |                      Happy clock.Advance called  
      |                   |                    / second, clock.waiting conatains        
      |                   |                   |  alarm 
      |                   |                   |          Test passes
      |                   |                  /         / 
|-----+-------+-----+-----+-------+---------+--+------+-----> 
              |     |             |             \
              |     |             |               Worker receives struct on channel
              |     |             |               calls worker function
              |     |              \_worker select loop now 
              |     |                listens on channel with real 
              |     |                delay: https://goo.gl/RHlfVC
              |     |
              |      \_first run through loop has zero delay and
              |        immediately fires https://goo.gl/FbJ3KD
              |
              worker sets up a select 
              loop https://goo.gl/FbJ3KD
              listening on <-clock.After(delay)

Unhappy path

           Test creates and starts a
         / worker, https://goo.gl/LQNepS    
        |
        |                    clock.Advance(duration) https://goo.gl/hbpAvp
       /                   / moves time forward.
      |                   |
      |                   |         
      |                   |        
      |                   |                       
      |                   |            Unhappy path clock.Advance happens first        
      |                   |          / So nothing in clock.waiting when alarms  
      |                   |         |  notified.
      |                   |         |                       Test times out.
      |                   |        /                      /  
|-----+-------+-----+-----+-------+------+-------+-------+------->  
              |     |                    |        \ 
              |     |                    |          worker continues waiting on select    
              |     |                    |          
              |     |                     \ worker select loop now 
              |     |                       listens on channel with real 
              |     |                       delay: https://goo.gl/RHlfVC
              |     |
              |      \_first run through loop has zero delay and
              |        immediately fires https://goo.gl/FbJ3KD
              |
              worker sets up a select 
              loop https://goo.gl/FbJ3KD
              listening on <-clock.After(delay)