jonboulle
After() appears to not reliable work in for select with channels construct
Hi All,
First of all thank you for a great package, that makes unit testing actually possible when dealing with time dependent code logic.
I've come across the issue in my unit tests which appears that fakeClock.After() time not reliably called when part of the for-select code. I've replicated the issue with the code below which I THINK should work, but it doesn't.
For the code below, I expect otherCount to be 3 (which it is), and then I expect timerFired to be true, which it's not.
This is on go 1.23.4 on MacOS 15.3.1
package main
import (
"context"
"fmt"
"time"
"github.com/jonboulle/clockwork"
)
func main() {
clock := clockwork.NewFakeClock()
timerFired := false
done := make(chan struct{})
otherChan := make(chan struct{})
otherCount := 0
fmt.Println(clock.Now().Format(time.StampMilli), "starting")
go func() {
for {
select {
case <-done:
fmt.Println(clock.Now().Format(time.StampMilli), "exiting")
case <-otherChan:
otherCount++
fmt.Println(clock.Now().Format(time.StampMilli), "received from otherChan")
clock.Sleep(1 * time.Second)
case <-clock.After(200 * time.Millisecond):
timerFired = true
fmt.Println(clock.Now().Format(time.StampMilli), "timer fired")
}
}
}()
ctx, cancelFn := context.WithTimeout(context.Background(), 3*time.Second)
defer cancelFn()
clock.BlockUntilContext(ctx, 1)
otherChan <- struct{}{}
time.Sleep(10 * time.Millisecond) // time for goroutine to read
clock.Advance(1 * time.Second) // advance to cover clock.Sleep()
otherChan <- struct{}{}
time.Sleep(10 * time.Millisecond) // time for goroutine to read
clock.Advance(1 * time.Second) // advance to cover clock.Sleep()
otherChan <- struct{}{}
time.Sleep(10 * time.Millisecond) // time for goroutine to read
clock.Advance(1 * time.Second) // advance to cover clock.Sleep()
clock.Advance(250 * time.Millisecond) // advance to cover clock.After()
time.Sleep(50 * time.Millisecond)
done <- struct{}{}
time.Sleep(100 * time.Millisecond)
fmt.Println("other count", otherCount, "timer fired", timerFired)
if timerFired && otherCount == 3 {
fmt.Println("PASSED")
} else {
fmt.Println("FAILED")
}
}
Output:
% go run main.go
Feb 20 21:02:00.917 starting
Feb 20 21:02:00.917 received from otherChan
Feb 20 21:02:01.917 received from otherChan
Feb 20 21:02:02.917 received from otherChan
Feb 20 21:02:04.117 exiting
other count 3 timer fired false
FAILED
I don't think your sample code does what you believe it does. To demonstrate, let's print the time where After is armed:
go func() {
for {
ch := clock.After(200 * time.Millisecond)
fmt.Printf("%s armed 200ms timer ", clock.Now().Format(time.StampMilli))
select {
case <-done:
fmt.Println(clock.Now().Format(time.StampMilli), "exiting")
return
case <-otherChan:
otherCount++
fmt.Println(clock.Now().Format(time.StampMilli), "received from otherChan")
clock.Sleep(1 * time.Second)
case <-ch:
timerFired = true
fmt.Println(clock.Now().Format(time.StampMilli), "timer fired")
}
}
}()
Running this shows that the loop always continues before After has a chance to fire:
Mar 11 11:18:06.644 starting
Mar 11 11:18:06.644 armed 200ms timer Mar 11 11:18:06.644 received from otherChan
Mar 11 11:18:07.644 armed 200ms timer Mar 11 11:18:07.644 received from otherChan
Mar 11 11:18:08.644 armed 200ms timer Mar 11 11:18:08.644 received from otherChan
Mar 11 11:18:09.894 armed 200ms timer Mar 11 11:18:09.894 exiting
other count 3 timer fired false
FAILED
All created Afters do fire eventually, you can verify this by replacing clock.After in your code with
func instrumentedAfter(c clockwork.Clock, d time.Duration) <-chan time.Time {
fired := make(chan time.Time, 1)
ch := c.After(d)
go func() {
fired <- <-ch
fmt.Println("After did fire")
}()
return fired
}
Mar 11 11:22:11.181 starting
Mar 11 11:22:11.181 armed 200ms timer Mar 11 11:22:11.181 received from otherChan
After did fire
Mar 11 11:22:12.181 armed 200ms timer Mar 11 11:22:12.181 received from otherChan
Mar 11 11:22:13.181 armed 200ms timer Mar 11 11:22:13.181 received from otherChan
After did fire
Mar 11 11:22:14.431 armed 200ms timer After did fire
Mar 11 11:22:14.431 exiting
other count 3 timer fired false
FAILED
Hi TheSven73, thanks for looking into this. If I understood you correctly my code didn't give enough "real time" (through time.Sleep()) to clockwork.After() to execute (which separate go-routine takes care of since it just waits until execution happens however long that takes).
I've added another time.Sleep() statement into test:
package main
import (
"context"
"fmt"
"time"
"github.com/jonboulle/clockwork"
)
func main() {
clock := clockwork.NewFakeClock()
timerFired := false
done := make(chan struct{})
otherChan := make(chan struct{})
otherCount := 0
fmt.Println(clock.Now().Format(time.StampMicro), "starting")
go func() {
for {
select {
case <-done:
fmt.Println(clock.Now().Format(time.StampMicro), "exiting")
case <-otherChan:
otherCount++
fmt.Println(clock.Now().Format(time.StampMicro), "received from otherChan")
clock.Sleep(1 * time.Second)
case <-clock.After(200 * time.Millisecond):
timerFired = true
fmt.Println(clock.Now().Format(time.StampMicro), "timer fired")
}
}
}()
ctx, cancelFn := context.WithTimeout(context.Background(), 3*time.Second)
defer cancelFn()
clock.BlockUntilContext(ctx, 1)
otherChan <- struct{}{}
time.Sleep(10 * time.Millisecond) // time for goroutine to read
clock.Advance(1 * time.Second) // advance to cover clock.Sleep()
otherChan <- struct{}{}
time.Sleep(10 * time.Millisecond) // time for goroutine to read
clock.Advance(1 * time.Second) // advance to cover clock.Sleep()
otherChan <- struct{}{}
time.Sleep(10 * time.Millisecond) // time for goroutine to read
clock.Advance(1 * time.Second) // advance to cover clock.Sleep()
time.Sleep(50 * time.Millisecond) // <-- this has been added
clock.Advance(250 * time.Millisecond) // advance to cover clock.After()
time.Sleep(50 * time.Millisecond)
done <- struct{}{}
time.Sleep(100 * time.Millisecond)
fmt.Println("other count", otherCount, "timer fired", timerFired)
if timerFired && otherCount == 3 {
fmt.Println("PASSED")
} else {
fmt.Println("FAILED")
}
}
And the results are now:
% go run main.go
Mar 26 20:01:04.212714 starting
Mar 26 20:01:04.212714 received from otherChan
Mar 26 20:01:05.212714 received from otherChan
Mar 26 20:01:06.212714 received from otherChan
Mar 26 20:01:07.462714 timer fired
Mar 26 20:01:07.462714 exiting
other count 3 timer fired true
PASSED