client-go: wrap error from previous attempt to provide more context

Kubernetes-commit: 868b5a31d382b325f49e1b831e6b094282d50cc7

rest/request.go

@@ -620,7 +620,7 @@ func (r *Request) Watch(ctx context.Context) (watch.Interface, error) {
 		}
 
 		if err := r.retry.Before(ctx, r); err != nil {
-			return nil, err
+			return nil, r.retry.WrapPreviousError(err)
 		}
 
 		resp, err := client.Do(req)
@@ -655,7 +655,7 @@ func (r *Request) Watch(ctx context.Context) (watch.Interface, error) {
 				// we need to return the error object from that.
 				err = transformErr
 			}
-			return nil, err
+			return nil, r.retry.WrapPreviousError(err)
 		}
 	}
 }
@@ -865,7 +865,7 @@ func (r *Request) request(ctx context.Context, fn func(*http.Request, *http.Resp
 		}
 
 		if err := r.retry.Before(ctx, r); err != nil {
-			return err
+			return r.retry.WrapPreviousError(err)
 		}
 		resp, err := client.Do(req)
 		updateURLMetrics(ctx, r, resp, err)
@@ -895,7 +895,7 @@ func (r *Request) request(ctx context.Context, fn func(*http.Request, *http.Resp
 			return true
 		}()
 		if done {
-			return err
+			return r.retry.WrapPreviousError(err)
 		}
 	}
 }

rest/request_test.go

@@ -2614,6 +2614,30 @@ func TestRequestWatchWithRetryInvokeOrder(t *testing.T) {
 	})
 }
 
+func TestRequestWatchWithWrapPreviousError(t *testing.T) {
+	testWithWrapPreviousError(t, func(ctx context.Context, r *Request) error {
+		w, err := r.Watch(ctx)
+		if err == nil {
+			// in this test the the response body returned by the server is always empty,
+			// this will cause StreamWatcher.receive() to:
+			// - return an io.EOF to indicate that the watch closed normally and
+			// - then close the io.Reader
+			// since we assert on the number of times 'Close' has been called on the
+			// body of the response object, we need to wait here to avoid race condition.
+			<-w.ResultChan()
+		}
+		return err
+	})
+}
+
+func TestRequestDoWithWrapPreviousError(t *testing.T) {
+	// both request.Do and request.DoRaw have the same behavior and expectations
+	testWithWrapPreviousError(t, func(ctx context.Context, r *Request) error {
+		result := r.Do(ctx)
+		return result.err
+	})
+}
+
 func testRequestWithRetry(t *testing.T, key string, doFunc func(ctx context.Context, r *Request)) {
 	type expected struct {
 		attempts  int
@@ -3126,6 +3150,208 @@ func testWithRetryInvokeOrder(t *testing.T, key string, doFunc func(ctx context.
 	}
 }
 
+func testWithWrapPreviousError(t *testing.T, doFunc func(ctx context.Context, r *Request) error) {
+	var (
+		containsFormatExpected = "- error from a previous attempt: %s"
+		nonRetryableErr        = errors.New("non retryable error")
+	)
+
+	tests := []struct {
+		name             string
+		maxRetries       int
+		serverReturns    []responseErr
+		expectedErr      error
+		wrapped          bool
+		attemptsExpected int
+		contains         string
+	}{
+		{
+			name:       "success at first attempt",
+			maxRetries: 2,
+			serverReturns: []responseErr{
+				{response: &http.Response{StatusCode: http.StatusOK}, err: nil},
+			},
+			attemptsExpected: 1,
+			expectedErr:      nil,
+		},
+		{
+			name:       "success after a series of retry-after from the server",
+			maxRetries: 2,
+			serverReturns: []responseErr{
+				{response: retryAfterResponse(), err: nil},
+				{response: retryAfterResponse(), err: nil},
+				{response: &http.Response{StatusCode: http.StatusOK}, err: nil},
+			},
+			attemptsExpected: 3,
+			expectedErr:      nil,
+		},
+		{
+			name:       "success after a series of retryable errors",
+			maxRetries: 2,
+			serverReturns: []responseErr{
+				{response: nil, err: io.EOF},
+				{response: nil, err: io.EOF},
+				{response: &http.Response{StatusCode: http.StatusOK}, err: nil},
+			},
+			attemptsExpected: 3,
+			expectedErr:      nil,
+		},
+		{
+			name:       "request errors out with a non retryable error",
+			maxRetries: 2,
+			serverReturns: []responseErr{
+				{response: nil, err: nonRetryableErr},
+			},
+			attemptsExpected: 1,
+			expectedErr:      nonRetryableErr,
+		},
+		{
+			name:       "request times out after retries, but no previous error",
+			maxRetries: 2,
+			serverReturns: []responseErr{
+				{response: retryAfterResponse(), err: nil},
+				{response: retryAfterResponse(), err: nil},
+				{response: nil, err: context.Canceled},
+			},
+			attemptsExpected: 3,
+			expectedErr:      context.Canceled,
+		},
+		{
+			name:       "request times out after retries, and we have a relevant previous error",
+			maxRetries: 3,
+			serverReturns: []responseErr{
+				{response: nil, err: io.EOF},
+				{response: retryAfterResponse(), err: nil},
+				{response: retryAfterResponse(), err: nil},
+				{response: nil, err: context.Canceled},
+			},
+			attemptsExpected: 4,
+			wrapped:          true,
+			expectedErr:      context.Canceled,
+			contains:         fmt.Sprintf(containsFormatExpected, io.EOF),
+		},
+		{
+			name:       "interleaved retry-after responses with retryable errors",
+			maxRetries: 8,
+			serverReturns: []responseErr{
+				{response: retryAfterResponse(), err: nil},
+				{response: retryAfterResponse(), err: nil},
+				{response: nil, err: io.ErrUnexpectedEOF},
+				{response: retryAfterResponse(), err: nil},
+				{response: retryAfterResponse(), err: nil},
+				{response: nil, err: io.EOF},
+				{response: retryAfterResponse(), err: nil},
+				{response: retryAfterResponse(), err: nil},
+				{response: nil, err: context.Canceled},
+			},
+			attemptsExpected: 9,
+			wrapped:          true,
+			expectedErr:      context.Canceled,
+			contains:         fmt.Sprintf(containsFormatExpected, io.EOF),
+		},
+		{
+			name:       "request errors out with a retryable error, followed by a non-retryable one",
+			maxRetries: 3,
+			serverReturns: []responseErr{
+				{response: nil, err: io.EOF},
+				{response: nil, err: nonRetryableErr},
+			},
+			attemptsExpected: 2,
+			wrapped:          true,
+			expectedErr:      nonRetryableErr,
+			contains:         fmt.Sprintf(containsFormatExpected, io.EOF),
+		},
+		{
+			name:       "use the most recent error",
+			maxRetries: 2,
+			serverReturns: []responseErr{
+				{response: nil, err: io.ErrUnexpectedEOF},
+				{response: nil, err: io.EOF},
+				{response: nil, err: context.Canceled},
+			},
+			attemptsExpected: 3,
+			wrapped:          true,
+			expectedErr:      context.Canceled,
+			contains:         fmt.Sprintf(containsFormatExpected, io.EOF),
+		},
+	}
+
+	for _, test := range tests {
+		t.Run(test.name, func(t *testing.T) {
+			var attempts int
+			client := clientForFunc(func(req *http.Request) (*http.Response, error) {
+				defer func() {
+					attempts++
+				}()
+
+				resp := test.serverReturns[attempts].response
+				if resp != nil {
+					resp.Body = ioutil.NopCloser(bytes.NewReader([]byte{}))
+				}
+				return resp, test.serverReturns[attempts].err
+			})
+
+			base, err := url.Parse("http://foo.bar")
+			if err != nil {
+				t.Fatalf("Failed to create new HTTP request - %v", err)
+			}
+			req := &Request{
+				verb: "GET",
+				body: bytes.NewReader([]byte{}),
+				c: &RESTClient{
+					base:    base,
+					content: defaultContentConfig(),
+					Client:  client,
+				},
+				pathPrefix:  "/api/v1",
+				rateLimiter: flowcontrol.NewFakeAlwaysRateLimiter(),
+				backoff:     &noSleepBackOff{},
+				retry:       &withRetry{maxRetries: test.maxRetries},
+			}
+
+			err = doFunc(context.Background(), req)
+			if test.attemptsExpected != attempts {
+				t.Errorf("Expected attempts: %d, but got: %d", test.attemptsExpected, attempts)
+			}
+
+			switch {
+			case test.expectedErr == nil:
+				if err != nil {
+					t.Errorf("Expected a nil error, but got: %v", err)
+					return
+				}
+			case test.expectedErr != nil:
+				if !strings.Contains(err.Error(), test.contains) {
+					t.Errorf("Expected error message to contain %q, but got: %v", test.contains, err)
+				}
+
+				urlErrGot, _ := err.(*url.Error)
+				if test.wrapped {
+					// we expect the url.Error from net/http to be wrapped by WrapPreviousError
+					unwrapper, ok := err.(interface {
+						Unwrap() error
+					})
+					if !ok {
+						t.Errorf("Expected error to implement Unwrap method, but got: %v", err)
+						return
+					}
+					urlErrGot, _ = unwrapper.Unwrap().(*url.Error)
+				}
+				// we always get a url.Error from net/http
+				if urlErrGot == nil {
+					t.Errorf("Expected error to be url.Error, but got: %v", err)
+					return
+				}
+
+				errGot := urlErrGot.Unwrap()
+				if test.expectedErr != errGot {
+					t.Errorf("Expected error %v, but got: %v", test.expectedErr, errGot)
+				}
+			}
+		})
+	}
+}
+
 func TestReuseRequest(t *testing.T) {
 	var tests = []struct {
 		name        string

rest/with_retry.go

@@ -22,6 +22,7 @@ import (
 	"io"
 	"io/ioutil"
 	"net/http"
+	"net/url"
 	"time"
 
 	"k8s.io/klog/v2"
@@ -83,6 +84,22 @@ type WithRetry interface {
 
 	// After should be invoked immediately after an attempt is made.
 	After(ctx context.Context, r *Request, resp *http.Response, err error)
+
+	// WrapPreviousError wraps the error from any previous attempt into
+	// the final error specified in 'finalErr', so the user has more
+	// context why the request failed.
+	// For example, if a request times out after multiple retries then
+	// we see a generic context.Canceled or context.DeadlineExceeded
+	// error which is not very useful in debugging. This function can
+	// wrap any error from previous attempt(s) to provide more context to
+	// the user. The error returned in 'err' must satisfy the
+	// following conditions:
+	//  a: errors.Unwrap(err) = errors.Unwrap(finalErr) if finalErr
+	//     implements Unwrap
+	//  b: errors.Unwrap(err) = finalErr if finalErr does not
+	//     implements Unwrap
+	//  c: errors.Is(err, otherErr) = errors.Is(finalErr, otherErr)
+	WrapPreviousError(finalErr error) (err error)
 }
 
 // RetryAfter holds information associated with the next retry.
@@ -111,6 +128,16 @@ type withRetry struct {
 	//  - for consecutive attempts, it is non nil and holds the
 	//    retry after parameters for the next attempt to be made.
 	retryAfter *RetryAfter
+
+	// we keep track of two most recent errors, if the most
+	// recent attempt is labeled as 'N' then:
+	//  - currentErr represents the error returned by attempt N, it
+	//    can be nil if attempt N did not return an error.
+	//  - previousErr represents an error from an attempt 'M' which
+	//    precedes attempt 'N' (N - M >= 1), it is non nil only when:
+	//      - for a sequence of attempt(s) 1..n (n>1), there
+	//        is an attempt k (k<n) that returned an error.
+	previousErr, currentErr error
 }
 
 func (r *withRetry) SetMaxRetries(maxRetries int) {
@@ -120,7 +147,17 @@ func (r *withRetry) SetMaxRetries(maxRetries int) {
 	r.maxRetries = maxRetries
 }
 
+func (r *withRetry) trackPreviousError(err error) {
+	// keep track of two most recent errors
+	if r.currentErr != nil {
+		r.previousErr = r.currentErr
+	}
+	r.currentErr = err
+}
+
 func (r *withRetry) IsNextRetry(ctx context.Context, restReq *Request, httpReq *http.Request, resp *http.Response, err error, f IsRetryableErrorFunc) bool {
+	defer r.trackPreviousError(err)
+
 	if httpReq == nil || (resp == nil && err == nil) {
 		// bad input, we do nothing.
 		return false
@@ -191,6 +228,7 @@ func (r *withRetry) prepareForNextRetry(ctx context.Context, request *Request) e
 
 func (r *withRetry) Before(ctx context.Context, request *Request) error {
 	if ctx.Err() != nil {
+		r.trackPreviousError(ctx.Err())
 		return ctx.Err()
 	}
 
@@ -221,6 +259,7 @@ func (r *withRetry) Before(ctx context.Context, request *Request) error {
 	// apiserver at least once before. This request should
 	// also be throttled with the client-internal rate limiter.
 	if err := request.tryThrottleWithInfo(ctx, r.retryAfter.Reason); err != nil {
+		r.trackPreviousError(ctx.Err())
 		return err
 	}
 
@@ -245,6 +284,45 @@ func (r *withRetry) After(ctx context.Context, request *Request, resp *http.Resp
 	}
 }
 
+func (r *withRetry) WrapPreviousError(currentErr error) error {
+	if currentErr == nil || r.previousErr == nil {
+		return currentErr
+	}
+
+	// if both previous and current error objects represent the error,
+	// then there is no need to wrap the previous error.
+	if currentErr.Error() == r.previousErr.Error() {
+		return currentErr
+	}
+
+	previousErr := r.previousErr
+	// net/http wraps the underlying error with an url.Error, if the
+	// previous err object is an instance of url.Error, then we can
+	// unwrap it to get to the inner error object, this is so we can
+	// avoid error message like:
+	//  Error: Get "http://foo.bar/api/v1": context deadline exceeded - error \
+	//  from a previous attempt: Error: Get "http://foo.bar/api/v1": EOF
+	if urlErr, ok := r.previousErr.(*url.Error); ok && urlErr != nil {
+		if urlErr.Unwrap() != nil {
+			previousErr = urlErr.Unwrap()
+		}
+	}
+
+	return &wrapPreviousError{
+		currentErr:    currentErr,
+		previousError: previousErr,
+	}
+}
+
+type wrapPreviousError struct {
+	currentErr, previousError error
+}
+
+func (w *wrapPreviousError) Unwrap() error { return w.currentErr }
+func (w *wrapPreviousError) Error() string {
+	return fmt.Sprintf("%s - error from a previous attempt: %s", w.currentErr.Error(), w.previousError.Error())
+}
+
 // checkWait returns true along with a number of seconds if
 // the server instructed us to wait before retrying.
 func checkWait(resp *http.Response) (int, bool) {

rest/with_retry_test.go

@@ -20,9 +20,12 @@ import (
 	"bytes"
 	"context"
 	"errors"
+	"fmt"
+	"io"
 	"net/http"
 	"net/url"
 	"reflect"
+	"strings"
 	"testing"
 	"time"
 
@@ -233,3 +236,166 @@ func TestIsNextRetry(t *testing.T) {
 		})
 	}
 }
+
+func TestWrapPreviousError(t *testing.T) {
+	const (
+		attempt                = 2
+		previousAttempt        = 1
+		containsFormatExpected = "- error from a previous attempt: %s"
+	)
+	var (
+		wrappedCtxDeadlineExceededErr = &url.Error{
+			Op:  "GET",
+			URL: "http://foo.bar",
+			Err: context.DeadlineExceeded,
+		}
+		wrappedCtxCanceledErr = &url.Error{
+			Op:  "GET",
+			URL: "http://foo.bar",
+			Err: context.Canceled,
+		}
+		urlEOFErr = &url.Error{
+			Op:  "GET",
+			URL: "http://foo.bar",
+			Err: io.EOF,
+		}
+	)
+
+	tests := []struct {
+		name        string
+		previousErr error
+		currentErr  error
+		expectedErr error
+		wrapped     bool
+		contains    string
+	}{
+		{
+			name: "current error is nil, previous error is nil",
+		},
+		{
+			name:        "current error is nil",
+			previousErr: errors.New("error from a previous attempt"),
+		},
+		{
+			name:        "previous error is nil",
+			currentErr:  urlEOFErr,
+			expectedErr: urlEOFErr,
+			wrapped:     false,
+		},
+		{
+			name:        "both current and previous errors represent the same error",
+			currentErr:  urlEOFErr,
+			previousErr: &url.Error{Op: "GET", URL: "http://foo.bar", Err: io.EOF},
+			expectedErr: urlEOFErr,
+		},
+		{
+			name:        "current and previous errors are not same",
+			currentErr:  urlEOFErr,
+			previousErr: errors.New("unknown error"),
+			expectedErr: urlEOFErr,
+			wrapped:     true,
+			contains:    fmt.Sprintf(containsFormatExpected, "unknown error"),
+		},
+		{
+			name:        "current error is context.Canceled",
+			currentErr:  context.Canceled,
+			previousErr: io.EOF,
+			expectedErr: context.Canceled,
+			wrapped:     true,
+			contains:    fmt.Sprintf(containsFormatExpected, io.EOF.Error()),
+		},
+		{
+			name:        "current error is context.DeadlineExceeded",
+			currentErr:  context.DeadlineExceeded,
+			previousErr: io.EOF,
+			expectedErr: context.DeadlineExceeded,
+			wrapped:     true,
+			contains:    fmt.Sprintf(containsFormatExpected, io.EOF.Error()),
+		},
+		{
+			name:        "current error is a wrapped context.DeadlineExceeded",
+			currentErr:  wrappedCtxDeadlineExceededErr,
+			previousErr: io.EOF,
+			expectedErr: wrappedCtxDeadlineExceededErr,
+			wrapped:     true,
+			contains:    fmt.Sprintf(containsFormatExpected, io.EOF.Error()),
+		},
+		{
+			name:        "current error is a wrapped context.Canceled",
+			currentErr:  wrappedCtxCanceledErr,
+			previousErr: io.EOF,
+			expectedErr: wrappedCtxCanceledErr,
+			wrapped:     true,
+			contains:    fmt.Sprintf(containsFormatExpected, io.EOF.Error()),
+		},
+		{
+			name:        "previous error should be unwrapped if it is url.Error",
+			currentErr:  urlEOFErr,
+			previousErr: &url.Error{Err: io.ErrUnexpectedEOF},
+			expectedErr: urlEOFErr,
+			wrapped:     true,
+			contains:    fmt.Sprintf(containsFormatExpected, io.ErrUnexpectedEOF.Error()),
+		},
+		{
+			name:        "previous error should not be unwrapped if it is not url.Error",
+			currentErr:  urlEOFErr,
+			previousErr: fmt.Errorf("should be included in error message - %w", io.EOF),
+			expectedErr: urlEOFErr,
+			wrapped:     true,
+			contains:    fmt.Sprintf(containsFormatExpected, "should be included in error message - EOF"),
+		},
+	}
+
+	for _, test := range tests {
+		t.Run(test.name, func(t *testing.T) {
+			retry := &withRetry{
+				previousErr: test.previousErr,
+			}
+
+			err := retry.WrapPreviousError(test.currentErr)
+			switch {
+			case test.expectedErr == nil:
+				if err != nil {
+					t.Errorf("Expected a nil error, but got: %v", err)
+					return
+				}
+			case test.expectedErr != nil:
+				// make sure the message from the returned error contains
+				// message from the "previous" error from retries.
+				if !strings.Contains(err.Error(), test.contains) {
+					t.Errorf("Expected error message to contain %q, but got: %v", test.contains, err)
+				}
+
+				currentErrGot := err
+				if test.wrapped {
+					currentErrGot = errors.Unwrap(err)
+				}
+				if test.expectedErr != currentErrGot {
+					t.Errorf("Expected current error %v, but got: %v", test.expectedErr, currentErrGot)
+				}
+			}
+		})
+	}
+
+	t.Run("Before should track previous error", func(t *testing.T) {
+		retry := &withRetry{
+			currentErr: io.EOF,
+		}
+
+		ctx, cancel := context.WithCancel(context.Background())
+		cancel()
+
+		// we pass zero Request object since we expect 'Before'
+		// to check the context for error at the very beginning.
+		err := retry.Before(ctx, &Request{})
+		if err != context.Canceled {
+			t.Errorf("Expected error: %v, but got: %v", context.Canceled, err)
+		}
+		if retry.currentErr != context.Canceled {
+			t.Errorf("Expected current error: %v, but got: %v", context.Canceled, retry.currentErr)
+		}
+		if retry.previousErr != io.EOF {
+			t.Errorf("Expected previous error: %v, but got: %v", io.EOF, retry.previousErr)
+		}
+	})
+}