Strange behaviour when using ticker in select loop

[leosunmo]

Hello! First of all, thanks for this library, it's a really nice balance of simplicity and features!

I am running in to an issue when using the Ticker with a select loop and I'm convinced I'm doing something stupid.

Here's a quick example taken from the range loop example:

func main() {
	// An operation that may fail.
	operation := func() error {
		return fmt.Errorf("failed")
	}

	b := backoff.NewExponentialBackOff()
	b.MaxElapsedTime = 10 * time.Second // I want to limit the maximum time it will wait to 10 seconds
	ticker := backoff.NewTicker(b)

	var err error
	for {
		select {
		case t := <-ticker.C:
			if err = operation(); err != nil {
				log.Printf("ticker time: %s\tNext tick: %s\n", t, b.NextBackOff())
                                time.Sleep(1 * time.Second)
			}
		}
	}
	// Operation is successful.
}

What I want to have happen is for the Ticker to stop sending timestamps when it exceeds MaxElapsedTime, instead I am seeing a massive spam of zero timestamps and a NextBackOff of -1ns

go build && ./test
2019/11/30 09:43:50 ticker time: 2019-11-30 09:43:50.712964693 +1300 NZDT m=+0.000274499        Next tick: 1.080381816s
2019/11/30 09:43:51 ticker time: 2019-11-30 09:43:51.265902607 +1300 NZDT m=+0.553212487        Next tick: 1.31013006s
2019/11/30 09:43:53 ticker time: 2019-11-30 09:43:53.296598454 +1300 NZDT m=+2.583908309        Next tick: 4.506218855s
2019/11/30 09:43:55 ticker time: 2019-11-30 09:43:55.637339103 +1300 NZDT m=+4.924648958        Next tick: 5.608623477s
2019/11/30 09:43:58 ticker time: 2019-11-30 09:43:58.858993827 +1300 NZDT m=+8.146303723        Next tick: 15.394871241s
2019/11/30 09:44:06 ticker time: 2019-11-30 09:44:06.509425175 +1300 NZDT m=+15.796735081       Next tick: -1ns
2019/11/30 09:44:07 ticker time: 0001-01-01 00:00:00 +0000 UTC  Next tick: -1ns
2019/11/30 09:44:08 ticker time: 0001-01-01 00:00:00 +0000 UTC  Next tick: -1ns
2019/11/30 09:44:09 ticker time: 0001-01-01 00:00:00 +0000 UTC  Next tick: -1ns
2019/11/30 09:44:10 ticker time: 0001-01-01 00:00:00 +0000 UTC  Next tick: -1ns

Any pointers greatly appreciated!

[cenkalti]

Hello @leosunmo,

There is a ticker usage example in docs: https://godoc.org/gopkg.in/cenkalti/backoff.v3#Ticker

There are some problems with your usage of the library:

• First of all there is no need for you to time.Sleep(1 * time.Second) in your code. That's what ticker is for.
• Ticker closes the Ticker.C channel when backoff has stopped. You don't check for that and your code gets stuck in infinite loop. Example uses a range loop to break automatically when the ticker channel is closed.
• After Ticker has stopped you still need to check the last error to see if your operation function worked.

Here is your code after these changes are made:

func main() {
	// An operation that may fail.
	operation := func() error {
		return fmt.Errorf("failed")
	}

	b := backoff.NewExponentialBackOff()
	b.MaxElapsedTime = 10 * time.Second // I want to limit the maximum time it will wait to 10 seconds
	ticker := backoff.NewTicker(b)

	var err error
LOOP:
	for {
		select {
		case t, ok := <-ticker.C:
			if !ok {
				log.Println("ticker has stopped")
				break LOOP
			}
			if err = operation(); err != nil {
				log.Printf("ticker time: %s\tNext tick: %s\n", t, b.NextBackOff())
				continue
			}
		}
	}
	if err != nil {
		log.Printf("operation failed. last error: %s", err)
		return
	}
	// Operation is successful.
}

I recommend using range loop if you don't have other cases in your select, it looks simpler with range. Here it is:

func main() {
	// An operation that may fail.
	operation := func() error {
		return fmt.Errorf("failed")
	}

	b := backoff.NewExponentialBackOff()
	b.MaxElapsedTime = 10 * time.Second // I want to limit the maximum time it will wait to 10 seconds
	ticker := backoff.NewTicker(b)

	var err error
	for t := range ticker.C {
		if err = operation(); err != nil {
			log.Printf("ticker time: %s\tNext tick: %s\n", t, b.NextBackOff())
			continue
		}
	}
	log.Println("ticker has stopped")
	if err != nil {
		log.Printf("operation failed. last error: %s", err)
		return
	}
	// Operation is successful.
}

[leosunmo]

Thanks for your reply!

Adding a close check seems to have solved my problem. The reason for a Sleep was so it was possible to observe the behaviour, otherwise it fills your terminal so fast you can't see what's going on.

The reason I am using a select loop in the first place and not range is because I also need to be able to break on context.Done(), but I wasn't able to get WithContext working before.

I am using backoff.WithContext now and simplified it to a for range loop instead, a lot cleaner as you said!

[cenkalti]

I'm glad that it is resolved. Cheers!