2020-02-05 22:16:58 +00:00
|
|
|
// Copyright (c) 2020 Tailscale Inc & AUTHORS All rights reserved.
|
|
|
|
// Use of this source code is governed by a BSD-style
|
|
|
|
// license that can be found in the LICENSE file.
|
|
|
|
|
2020-08-09 05:03:20 +01:00
|
|
|
// Package backoff provides a back-off timer type.
|
2020-02-05 22:16:58 +00:00
|
|
|
package backoff
|
|
|
|
|
|
|
|
import (
|
|
|
|
"context"
|
|
|
|
"math/rand"
|
|
|
|
"time"
|
Add tstest.PanicOnLog(), and fix various problems detected by this.
If a test calls log.Printf, 'go test' horrifyingly rearranges the
output to no longer be in chronological order, which makes debugging
virtually impossible. Let's stop that from happening by making
log.Printf panic if called from any module, no matter how deep, during
tests.
This required us to change the default error handler in at least one
http.Server, as well as plumbing a bunch of logf functions around,
especially in magicsock and wgengine, but also in logtail and backoff.
To add insult to injury, 'go test' also rearranges the output when a
parent test has multiple sub-tests (all the sub-test's t.Logf is always
printed after all the parent tests t.Logf), so we need to screw around
with a special Logf that can point at the "current" t (current_t.Logf)
in some places. Probably our entire way of using subtests is wrong,
since 'go test' would probably like to run them all in parallel if you
called t.Parallel(), but it definitely can't because the're all
manipulating the shared state created by the parent test. They should
probably all be separate toplevel tests instead, with common
setup/teardown logic. But that's a job for another time.
Signed-off-by: Avery Pennarun <apenwarr@tailscale.com>
2020-05-14 03:59:54 +01:00
|
|
|
|
|
|
|
"tailscale.com/types/logger"
|
2020-02-05 22:16:58 +00:00
|
|
|
)
|
|
|
|
|
2020-08-09 05:03:20 +01:00
|
|
|
// Backoff tracks state the history of consecutive failures and sleeps
|
|
|
|
// an increasing amount of time, up to a provided limit.
|
2020-02-05 22:16:58 +00:00
|
|
|
type Backoff struct {
|
2020-08-09 05:03:20 +01:00
|
|
|
n int // number of consecutive failures
|
|
|
|
maxBackoff time.Duration
|
|
|
|
|
2020-04-29 10:41:39 +01:00
|
|
|
// Name is the name of this backoff timer, for logging purposes.
|
Add tstest.PanicOnLog(), and fix various problems detected by this.
If a test calls log.Printf, 'go test' horrifyingly rearranges the
output to no longer be in chronological order, which makes debugging
virtually impossible. Let's stop that from happening by making
log.Printf panic if called from any module, no matter how deep, during
tests.
This required us to change the default error handler in at least one
http.Server, as well as plumbing a bunch of logf functions around,
especially in magicsock and wgengine, but also in logtail and backoff.
To add insult to injury, 'go test' also rearranges the output when a
parent test has multiple sub-tests (all the sub-test's t.Logf is always
printed after all the parent tests t.Logf), so we need to screw around
with a special Logf that can point at the "current" t (current_t.Logf)
in some places. Probably our entire way of using subtests is wrong,
since 'go test' would probably like to run them all in parallel if you
called t.Parallel(), but it definitely can't because the're all
manipulating the shared state created by the parent test. They should
probably all be separate toplevel tests instead, with common
setup/teardown logic. But that's a job for another time.
Signed-off-by: Avery Pennarun <apenwarr@tailscale.com>
2020-05-14 03:59:54 +01:00
|
|
|
name string
|
|
|
|
// logf is the function used for log messages when backing off.
|
|
|
|
logf logger.Logf
|
2020-08-09 05:03:20 +01:00
|
|
|
|
|
|
|
// NewTimer is the function that acts like time.NewTimer.
|
|
|
|
// It's for use in unit tests.
|
|
|
|
NewTimer func(time.Duration) *time.Timer
|
|
|
|
|
2020-04-29 10:41:39 +01:00
|
|
|
// LogLongerThan sets the minimum time of a single backoff interval
|
|
|
|
// before we mention it in the log.
|
|
|
|
LogLongerThan time.Duration
|
2020-02-05 22:16:58 +00:00
|
|
|
}
|
|
|
|
|
2020-08-09 05:03:20 +01:00
|
|
|
// NewBackoff returns a new Backoff timer with the provided name (for logging), logger,
|
|
|
|
// and max backoff time. By default, all failures (calls to BackOff with a non-nil err)
|
|
|
|
// are logged unless the returned Backoff.LogLongerThan is adjusted.
|
|
|
|
func NewBackoff(name string, logf logger.Logf, maxBackoff time.Duration) *Backoff {
|
|
|
|
return &Backoff{
|
|
|
|
name: name,
|
|
|
|
logf: logf,
|
|
|
|
maxBackoff: maxBackoff,
|
|
|
|
NewTimer: time.NewTimer,
|
Add tstest.PanicOnLog(), and fix various problems detected by this.
If a test calls log.Printf, 'go test' horrifyingly rearranges the
output to no longer be in chronological order, which makes debugging
virtually impossible. Let's stop that from happening by making
log.Printf panic if called from any module, no matter how deep, during
tests.
This required us to change the default error handler in at least one
http.Server, as well as plumbing a bunch of logf functions around,
especially in magicsock and wgengine, but also in logtail and backoff.
To add insult to injury, 'go test' also rearranges the output when a
parent test has multiple sub-tests (all the sub-test's t.Logf is always
printed after all the parent tests t.Logf), so we need to screw around
with a special Logf that can point at the "current" t (current_t.Logf)
in some places. Probably our entire way of using subtests is wrong,
since 'go test' would probably like to run them all in parallel if you
called t.Parallel(), but it definitely can't because the're all
manipulating the shared state created by the parent test. They should
probably all be separate toplevel tests instead, with common
setup/teardown logic. But that's a job for another time.
Signed-off-by: Avery Pennarun <apenwarr@tailscale.com>
2020-05-14 03:59:54 +01:00
|
|
|
}
|
|
|
|
}
|
|
|
|
|
2020-08-09 05:03:20 +01:00
|
|
|
// Backoff sleeps an increasing amount of time if err is non-nil.
|
|
|
|
// and the context is not a
|
|
|
|
// It resets the backoff schedule once err is nil.
|
2020-02-05 22:16:58 +00:00
|
|
|
func (b *Backoff) BackOff(ctx context.Context, err error) {
|
2020-08-09 05:03:20 +01:00
|
|
|
if err == nil {
|
|
|
|
// No error. Reset number of consecutive failures.
|
2020-02-05 22:16:58 +00:00
|
|
|
b.n = 0
|
2020-08-09 05:03:20 +01:00
|
|
|
return
|
|
|
|
}
|
|
|
|
if ctx.Err() != nil {
|
|
|
|
// Fast path.
|
|
|
|
return
|
|
|
|
}
|
|
|
|
|
|
|
|
b.n++
|
|
|
|
// n^2 backoff timer is a little smoother than the
|
|
|
|
// common choice of 2^n.
|
|
|
|
d := time.Duration(b.n*b.n) * 10 * time.Millisecond
|
|
|
|
if d > b.maxBackoff {
|
|
|
|
d = b.maxBackoff
|
|
|
|
}
|
|
|
|
// Randomize the delay between 0.5-1.5 x msec, in order
|
|
|
|
// to prevent accidental "thundering herd" problems.
|
|
|
|
d = time.Duration(float64(d) * (rand.Float64() + 0.5))
|
|
|
|
|
|
|
|
if d >= b.LogLongerThan {
|
|
|
|
b.logf("%s: backoff: %d msec", b.name, d.Milliseconds())
|
|
|
|
}
|
|
|
|
t := b.NewTimer(d)
|
|
|
|
select {
|
|
|
|
case <-ctx.Done():
|
|
|
|
t.Stop()
|
|
|
|
case <-t.C:
|
2020-02-05 22:16:58 +00:00
|
|
|
}
|
|
|
|
}
|