REP-5329: Rework retryer internals to compute duration from a start time.

Author: FGasper

internal/retry/error.go

@@ -0,0 +1,27 @@
+package retry
+
+import (
+	"fmt"
+	"time"
+
+	"github.com/10gen/migration-verifier/internal/reportutils"
+)
+
+type RetryDurationLimitExceededErr struct {
+	lastErr  error
+	attempts int
+	duration time.Duration
+}
+
+func (rde RetryDurationLimitExceededErr) Error() string {
+	return fmt.Sprintf(
+		"retryable function did not succeed after %d attempt(s) over %s; last error was: %v",
+		rde.attempts,
+		reportutils.DurationToHMS(rde.duration),
+		rde.lastErr,
+	)
+}
+
+func (rde RetryDurationLimitExceededErr) Unwrap() error {
+	return rde.lastErr
+}

internal/retry/retry.go

@@ -6,9 +6,7 @@ import (
 	"time"
 
 	"github.com/10gen/migration-verifier/internal/logger"
-	"github.com/10gen/migration-verifier/internal/reportutils"
 	"github.com/10gen/migration-verifier/internal/util"
-	"github.com/pkg/errors"
 )
 
 // Run retries f() whenever a transient error happens, up to the retryer's
@@ -41,48 +39,49 @@ func (r *Retryer) runRetryLoop(
 
 	ri := &Info{
 		durationLimit: r.retryLimit,
+		lastResetTime: time.Now(),
 	}
 	sleepTime := minSleepTime
 
-	for ri.durationSoFar <= ri.durationLimit {
-		retryStartTime := time.Now()
-
-		// Run f() with the current collection name.
+	for {
 		err = f(ri)
 
 		// If f() returned a transient error, sleep and increase the sleep
 		// time for the next retry, maxing out at the maxSleepTime.
-		if r.shouldRetryWithSleep(logger, sleepTime, err) {
-			select {
-			case <-ctx.Done():
-				logger.Error().Err(ctx.Err()).Msg("Context was canceled. Aborting retry loop.")
-				return ctx.Err()
-			case <-time.After(sleepTime):
-				sleepTime *= sleepTimeMultiplier
-				if sleepTime > maxSleepTime {
-					sleepTime = maxSleepTime
-				}
-			}
+		if err == nil {
+			return nil
+		}
 
-			ri.attemptNumber++
+		if !r.shouldRetryWithSleep(logger, sleepTime, err) {
+			return err
+		}
 
-			if ri.shouldResetDuration {
-				ri.durationSoFar = 0
-				ri.shouldResetDuration = false
-			} else {
-				ri.durationSoFar += time.Since(retryStartTime)
+		select {
+		case <-ctx.Done():
+			logger.Error().Err(ctx.Err()).Msg("Context was canceled. Aborting retry loop.")
+			return ctx.Err()
+		case <-time.After(sleepTime):
+			sleepTime *= sleepTimeMultiplier
+			if sleepTime > maxSleepTime {
+				sleepTime = maxSleepTime
 			}
-			continue
 		}
 
-		return err
-	}
+		ri.attemptNumber++
 
-	return errors.Wrapf(err,
-		"retryable function did not succeed after %d attempt(s) over %s",
-		ri.attemptNumber,
-		reportutils.DurationToHMS(ri.durationSoFar),
-	)
+		if ri.shouldResetDuration {
+			ri.lastResetTime = time.Now()
+			ri.shouldResetDuration = false
+		}
+
+		if ri.GetDurationSoFar() > ri.durationLimit {
+			return RetryDurationLimitExceededErr{
+				attempts: ri.attemptNumber,
+				duration: ri.GetDurationSoFar(),
+				lastErr:  err,
+			}
+		}
+	}
 }
 
 //

internal/retry/retry_info.go

@@ -15,7 +15,7 @@ import (
 type Info struct {
 	attemptNumber int
 
-	durationSoFar time.Duration
+	lastResetTime time.Time
 	durationLimit time.Duration
 
 	// Used to reset the time elapsed for long running operations.
@@ -52,7 +52,7 @@ func (ri *Info) Log(logger *zerolog.Logger, cmdName string, clientType string, d
 	}
 	event.Str("context", msg).
 		Int("attemptNumber", ri.attemptNumber).
-		Str("durationSoFar", reportutils.DurationToHMS(ri.durationSoFar)).
+		Str("durationSoFar", reportutils.DurationToHMS(ri.GetDurationSoFar())).
 		Str("durationLimit", reportutils.DurationToHMS(ri.durationLimit)).
 		Msg("Running retryable function")
 }
@@ -65,7 +65,7 @@ func (ri *Info) GetAttemptNumber() int {
 // GetDurationSoFar returns the Info's current duration so far. This duration
 // applies to the duration of retrying for transient errors only.
 func (ri *Info) GetDurationSoFar() time.Duration {
-	return ri.durationSoFar
+	return time.Since(ri.lastResetTime)
 }
 
 // IterationSuccess is used to tell the retry util to reset its measurement

internal/retry/retryer_test.go

@@ -73,7 +73,7 @@ func (suite *UnitTestSuite) TestRetryerDurationLimitIsZero() {
 	retryer := New(0)
 
 	attemptNumber := -1
-	cmdErr := mongo.CommandError{
+	cmdErr := &mongo.CommandError{
 		Labels: []string{"NetworkError"},
 		Name:   "NetworkError",
 	}
@@ -83,8 +83,8 @@ func (suite *UnitTestSuite) TestRetryerDurationLimitIsZero() {
 	}
 
 	err := retryer.Run(suite.Context(), suite.Logger(), f)
-	suite.Equal(cmdErr, err)
-	suite.Equal(0, attemptNumber)
+	suite.Assert().ErrorIs(err, cmdErr)
+	suite.Assert().Equal(0, attemptNumber)
 }
 
 func (suite *UnitTestSuite) TestRetryerDurationReset() {
@@ -95,7 +95,7 @@ func (suite *UnitTestSuite) TestRetryerDurationReset() {
 	// to execute. (f will artificially advance the time to greater than the
 	// durationLimit.)
 
-	transientNetworkError := mongo.CommandError{
+	transientNetworkError := &mongo.CommandError{
 		Labels: []string{"NetworkError"},
 		Name:   "NetworkError",
 	}
@@ -105,7 +105,7 @@ func (suite *UnitTestSuite) TestRetryerDurationReset() {
 	noSuccessIterations := 0
 	f1 := func(ri *Info) error {
 		// Artificially advance how much time was taken.
-		ri.durationSoFar += 2 * ri.durationLimit
+		ri.lastResetTime = ri.lastResetTime.Add(-2 * ri.durationLimit)
 
 		noSuccessIterations++
 		if noSuccessIterations == 1 {
@@ -116,17 +116,19 @@ func (suite *UnitTestSuite) TestRetryerDurationReset() {
 	}
 
 	err := retryer.Run(suite.Context(), logger, f1)
-	// err is not nil and err is not the network error thrown by the function.
-	suite.Error(err)
-	suite.NotEqual(err, transientNetworkError)
+
+	// The error should be the limit-exceeded error, with the
+	// last-noted error being the transient error.
+	suite.Assert().ErrorAs(err, &RetryDurationLimitExceededErr{})
+	suite.Assert().ErrorIs(err, transientNetworkError)
 	suite.Equal(1, noSuccessIterations)
 
 	// 2) Calling IterationSuccess() means f will run more than once because the
 	// duration should be reset.
 	successIterations := 0
 	f2 := func(ri *Info) error {
 		// Artificially advance how much time was taken.
-		ri.durationSoFar += 2 * ri.durationLimit
+		ri.lastResetTime = ri.lastResetTime.Add(-2 * ri.durationLimit)
 
 		ri.IterationSuccess()
 
@@ -139,8 +141,8 @@ func (suite *UnitTestSuite) TestRetryerDurationReset() {
 	}
 
 	err = retryer.Run(suite.Context(), logger, f2)
-	suite.NoError(err)
-	suite.Equal(2, successIterations)
+	suite.Assert().NoError(err)
+	suite.Assert().Equal(2, successIterations)
 }
 
 func (suite *UnitTestSuite) TestCancelViaContext() {