From 2065e73d0b14872c9631a9801215248879b1b3d8 Mon Sep 17 00:00:00 2001 From: Nick Craig-Wood Date: Thu, 21 Mar 2019 11:24:13 +0000 Subject: [PATCH] cmd: implement RetryAfter errors which cause a sleep before a retry Use NewRetryAfterError to return an error which will cause a high level retry after the delay specified. --- cmd/cmd.go | 19 ++++++++--- fs/accounting/stats.go | 20 +++++++++++ fs/accounting/stats_test.go | 68 +++++++++++++++++++++++++++++++++++++ fs/fserrors/error.go | 53 +++++++++++++++++++++++++++++ fs/fserrors/error_test.go | 19 +++++++++++ fs/sync/sync_test.go | 5 +-- 6 files changed, 177 insertions(+), 7 deletions(-) diff --git a/cmd/cmd.go b/cmd/cmd.go index b174f3fa4..b8a8e6f62 100644 --- a/cmd/cmd.go +++ b/cmd/cmd.go @@ -230,22 +230,31 @@ func Run(Retry bool, showStats bool, cmd *cobra.Command, f func() error) { SigInfoHandler() for try := 1; try <= *retries; try++ { err = f() - if !Retry || (err == nil && !accounting.Stats.Errored()) { + fs.CountError(err) + if !Retry || !accounting.Stats.Errored() { if try > 1 { fs.Errorf(nil, "Attempt %d/%d succeeded", try, *retries) } break } - if fserrors.IsFatalError(err) || accounting.Stats.HadFatalError() { + if accounting.Stats.HadFatalError() { fs.Errorf(nil, "Fatal error received - not attempting retries") break } - if fserrors.IsNoRetryError(err) || (accounting.Stats.Errored() && !accounting.Stats.HadRetryError()) { + if accounting.Stats.Errored() && !accounting.Stats.HadRetryError() { fs.Errorf(nil, "Can't retry this error - not attempting retries") break } - if err != nil { - fs.Errorf(nil, "Attempt %d/%d failed with %d errors and: %v", try, *retries, accounting.Stats.GetErrors(), err) + if retryAfter := accounting.Stats.RetryAfter(); !retryAfter.IsZero() { + d := retryAfter.Sub(time.Now()) + if d > 0 { + fs.Logf(nil, "Received retry after error - sleeping until %s (%v)", retryAfter.Format(time.RFC3339Nano), d) + time.Sleep(d) + } + } + lastErr := accounting.Stats.GetLastError() + if lastErr != nil { + fs.Errorf(nil, "Attempt %d/%d failed with %d errors and: %v", try, *retries, accounting.Stats.GetErrors(), lastErr) } else { fs.Errorf(nil, "Attempt %d/%d failed with %d errors", try, *retries, accounting.Stats.GetErrors()) } diff --git a/fs/accounting/stats.go b/fs/accounting/stats.go index 565d16327..752cb8b00 100644 --- a/fs/accounting/stats.go +++ b/fs/accounting/stats.go @@ -74,6 +74,7 @@ type StatsInfo struct { lastError error fatalError bool retryError bool + retryAfter time.Time checks int64 checking *stringSet checkQueue int @@ -373,6 +374,7 @@ func (s *StatsInfo) ResetCounters() { s.lastError = nil s.fatalError = false s.retryError = false + s.retryAfter = time.Time{} s.checks = 0 s.transfers = 0 s.deletes = 0 @@ -386,6 +388,7 @@ func (s *StatsInfo) ResetErrors() { s.lastError = nil s.fatalError = false s.retryError = false + s.retryAfter = time.Time{} } // Errored returns whether there have been any errors @@ -397,6 +400,9 @@ func (s *StatsInfo) Errored() bool { // Error adds a single error into the stats, assigns lastError and eventually sets fatalError or retryError func (s *StatsInfo) Error(err error) { + if err == nil { + return + } s.mu.Lock() defer s.mu.Unlock() s.errors++ @@ -404,11 +410,25 @@ func (s *StatsInfo) Error(err error) { switch { case fserrors.IsFatalError(err): s.fatalError = true + case fserrors.IsRetryAfterError(err): + retryAfter := fserrors.RetryAfterErrorTime(err) + if s.retryAfter.IsZero() || retryAfter.Sub(s.retryAfter) > 0 { + s.retryAfter = retryAfter + } + s.retryError = true case !fserrors.IsNoRetryError(err): s.retryError = true } } +// RetryAfter returns the time to retry after if it is set. It will +// be Zero if it isn't set. +func (s *StatsInfo) RetryAfter() time.Time { + s.mu.Lock() + defer s.mu.Unlock() + return s.retryAfter +} + // Checking adds a check into the stats func (s *StatsInfo) Checking(remote string) { s.checking.add(remote) diff --git a/fs/accounting/stats_test.go b/fs/accounting/stats_test.go index d7f5e852f..af5eeebcd 100644 --- a/fs/accounting/stats_test.go +++ b/fs/accounting/stats_test.go @@ -2,9 +2,12 @@ package accounting import ( "fmt" + "io" "testing" "time" + "github.com/ncw/rclone/fs/fserrors" + "github.com/pkg/errors" "github.com/stretchr/testify/assert" ) @@ -49,3 +52,68 @@ func TestPercentage(t *testing.T) { assert.Equal(t, percent(-100, 100), "-") assert.Equal(t, percent(-100, -100), "-") } + +func TestStatsError(t *testing.T) { + s := NewStats() + assert.Equal(t, int64(0), s.GetErrors()) + assert.False(t, s.HadFatalError()) + assert.False(t, s.HadRetryError()) + assert.Equal(t, time.Time{}, s.RetryAfter()) + assert.Equal(t, nil, s.GetLastError()) + assert.False(t, s.Errored()) + + t0 := time.Now() + t1 := t0.Add(time.Second) + + s.Error(nil) + assert.Equal(t, int64(0), s.GetErrors()) + assert.False(t, s.HadFatalError()) + assert.False(t, s.HadRetryError()) + assert.Equal(t, time.Time{}, s.RetryAfter()) + assert.Equal(t, nil, s.GetLastError()) + assert.False(t, s.Errored()) + + s.Error(io.EOF) + assert.Equal(t, int64(1), s.GetErrors()) + assert.False(t, s.HadFatalError()) + assert.True(t, s.HadRetryError()) + assert.Equal(t, time.Time{}, s.RetryAfter()) + assert.Equal(t, io.EOF, s.GetLastError()) + assert.True(t, s.Errored()) + + e := fserrors.ErrorRetryAfter(t0) + s.Error(e) + assert.Equal(t, int64(2), s.GetErrors()) + assert.False(t, s.HadFatalError()) + assert.True(t, s.HadRetryError()) + assert.Equal(t, t0, s.RetryAfter()) + assert.Equal(t, e, s.GetLastError()) + + err := errors.Wrap(fserrors.ErrorRetryAfter(t1), "potato") + s.Error(err) + assert.Equal(t, int64(3), s.GetErrors()) + assert.False(t, s.HadFatalError()) + assert.True(t, s.HadRetryError()) + assert.Equal(t, t1, s.RetryAfter()) + assert.Equal(t, t1, fserrors.RetryAfterErrorTime(err)) + + s.Error(fserrors.FatalError(io.EOF)) + assert.Equal(t, int64(4), s.GetErrors()) + assert.True(t, s.HadFatalError()) + assert.True(t, s.HadRetryError()) + assert.Equal(t, t1, s.RetryAfter()) + + s.ResetErrors() + assert.Equal(t, int64(0), s.GetErrors()) + assert.False(t, s.HadFatalError()) + assert.False(t, s.HadRetryError()) + assert.Equal(t, time.Time{}, s.RetryAfter()) + assert.Equal(t, nil, s.GetLastError()) + assert.False(t, s.Errored()) + + s.Error(fserrors.NoRetryError(io.EOF)) + assert.Equal(t, int64(1), s.GetErrors()) + assert.False(t, s.HadFatalError()) + assert.False(t, s.HadRetryError()) + assert.Equal(t, time.Time{}, s.RetryAfter()) +} diff --git a/fs/fserrors/error.go b/fs/fserrors/error.go index 39fd9fb64..e5eb89d49 100644 --- a/fs/fserrors/error.go +++ b/fs/fserrors/error.go @@ -7,6 +7,7 @@ import ( "net/http" "reflect" "strings" + "time" "github.com/pkg/errors" ) @@ -166,6 +167,58 @@ func IsNoRetryError(err error) bool { return false } +// RetryAfter is an optional interface for error as to whether the +// operation should be retried after a given delay +// +// This should be returned from Update or Put methods as required and +// will cause the entire sync to be retried after a delay. +type RetryAfter interface { + error + RetryAfter() time.Time +} + +// ErrorRetryAfter is an error which expresses a time that should be +// waited for until trying again +type ErrorRetryAfter time.Time + +// NewErrorRetryAfter returns an ErrorRetryAfter with the given +// duration as an endpoint +func NewErrorRetryAfter(d time.Duration) ErrorRetryAfter { + return ErrorRetryAfter(time.Now().Add(d)) +} + +// Error returns the textual version of the error +func (e ErrorRetryAfter) Error() string { + return fmt.Sprintf("try again after %v (%v)", time.Time(e).Format(time.RFC3339Nano), time.Time(e).Sub(time.Now())) +} + +// RetryAfter returns the time the operation should be retried at or +// after +func (e ErrorRetryAfter) RetryAfter() time.Time { + return time.Time(e) +} + +// Check interface +var _ RetryAfter = ErrorRetryAfter{} + +// RetryAfterErrorTime returns the time that the RetryAfter error +// indicates or a Zero time.Time +func RetryAfterErrorTime(err error) time.Time { + if err == nil { + return time.Time{} + } + _, err = Cause(err) + if do, ok := err.(RetryAfter); ok { + return do.RetryAfter() + } + return time.Time{} +} + +// IsRetryAfterError returns true if err is an ErrorRetryAfter +func IsRetryAfterError(err error) bool { + return !RetryAfterErrorTime(err).IsZero() +} + // Cause is a souped up errors.Cause which can unwrap some standard // library errors too. It returns true if any of the intermediate // errors had a Timeout() or Temporary() method which returned true. diff --git a/fs/fserrors/error_test.go b/fs/fserrors/error_test.go index 67f217ed3..93ffcaa67 100644 --- a/fs/fserrors/error_test.go +++ b/fs/fserrors/error_test.go @@ -8,6 +8,7 @@ import ( "os" "syscall" "testing" + "time" "github.com/pkg/errors" "github.com/stretchr/testify/assert" @@ -143,3 +144,21 @@ func TestShouldRetry(t *testing.T) { assert.Equal(t, test.want, got, fmt.Sprintf("test #%d: %v", i, test.err)) } } + +func TestRetryAfter(t *testing.T) { + e := NewErrorRetryAfter(time.Second) + after := e.RetryAfter() + dt := after.Sub(time.Now()) + assert.True(t, dt >= 900*time.Millisecond && dt <= 1100*time.Millisecond) + assert.True(t, IsRetryAfterError(e)) + assert.False(t, IsRetryAfterError(io.EOF)) + assert.Equal(t, time.Time{}, RetryAfterErrorTime(io.EOF)) + assert.False(t, IsRetryAfterError(nil)) + assert.Contains(t, e.Error(), "try again after") + + t0 := time.Now() + err := errors.Wrap(ErrorRetryAfter(t0), "potato") + assert.Equal(t, t0, RetryAfterErrorTime(err)) + assert.True(t, IsRetryAfterError(err)) + assert.Contains(t, e.Error(), "try again after") +} diff --git a/fs/sync/sync_test.go b/fs/sync/sync_test.go index 9472be1e0..0456945ef 100644 --- a/fs/sync/sync_test.go +++ b/fs/sync/sync_test.go @@ -15,6 +15,7 @@ import ( "github.com/ncw/rclone/fs/hash" "github.com/ncw/rclone/fs/operations" "github.com/ncw/rclone/fstest" + "github.com/pkg/errors" "github.com/stretchr/testify/assert" "github.com/stretchr/testify/require" "golang.org/x/text/unicode/norm" @@ -468,7 +469,7 @@ func TestSyncIgnoreErrors(t *testing.T) { ) accounting.Stats.ResetCounters() - fs.CountError(nil) + fs.CountError(errors.New("boom")) assert.NoError(t, Sync(r.Fremote, r.Flocal, false)) fstest.CheckListingWithPrecision( @@ -778,7 +779,7 @@ func TestSyncAfterRemovingAFileAndAddingAFileSubDirWithErrors(t *testing.T) { ) accounting.Stats.ResetCounters() - fs.CountError(nil) + fs.CountError(errors.New("boom")) err := Sync(r.Fremote, r.Flocal, false) assert.Equal(t, fs.ErrorNotDeleting, err)