From 192bcc3f0e286b978d174a798ffbb712770e3acf Mon Sep 17 00:00:00 2001 From: The Magician Date: Mon, 16 Mar 2020 11:36:53 -0700 Subject: [PATCH] Initial retry transport (#3196) (#5902) * retry transport * lint * remove import, comments * Rename copyRequest, change comments, remove redundant line * refactor test * clarifications, defers * lint/fmt Signed-off-by: Modular Magician --- .changelog/3196.txt | 3 + google/config.go | 28 +++- google/error_retry_predicates.go | 17 +- google/retry_transport.go | 203 ++++++++++++++++++++++++ google/retry_transport_test.go | 261 +++++++++++++++++++++++++++++++ 5 files changed, 491 insertions(+), 21 deletions(-) create mode 100644 .changelog/3196.txt create mode 100644 google/retry_transport.go create mode 100644 google/retry_transport_test.go diff --git a/.changelog/3196.txt b/.changelog/3196.txt new file mode 100644 index 00000000000..d70d88a87b1 --- /dev/null +++ b/.changelog/3196.txt @@ -0,0 +1,3 @@ +```release-note:enhancement +provider: Added provider-wide request retries for common temporary GCP error codes and network errors +``` diff --git a/google/config.go b/google/config.go index ce85f1fa910..ffa26e5b811 100644 --- a/google/config.go +++ b/google/config.go @@ -8,10 +8,12 @@ import ( "regexp" "time" + "github.com/hashicorp/go-cleanhttp" "github.com/hashicorp/terraform-plugin-sdk/helper/logging" "github.com/hashicorp/terraform-plugin-sdk/helper/pathorcontents" "github.com/hashicorp/terraform-plugin-sdk/httpclient" "github.com/terraform-providers/terraform-provider-google/version" + "google.golang.org/api/option" "golang.org/x/oauth2" googleoauth "golang.org/x/oauth2/google" @@ -39,7 +41,6 @@ import ( "google.golang.org/api/iam/v1" iamcredentials "google.golang.org/api/iamcredentials/v1" cloudlogging "google.golang.org/api/logging/v2" - "google.golang.org/api/option" "google.golang.org/api/pubsub/v1" runtimeconfig "google.golang.org/api/runtimeconfig/v1beta1" "google.golang.org/api/servicemanagement/v1" @@ -267,8 +268,23 @@ func (c *Config) LoadAndValidate(ctx context.Context) error { } c.tokenSource = tokenSource - client := oauth2.NewClient(context.Background(), tokenSource) - client.Transport = logging.NewTransport("Google", client.Transport) + cleanCtx := context.WithValue(ctx, oauth2.HTTPClient, cleanhttp.DefaultClient()) + + // 1. OAUTH2 TRANSPORT/CLIENT - sets up proper auth headers + client := oauth2.NewClient(cleanCtx, tokenSource) + + // 2. Logging Transport - ensure we log HTTP requests to GCP APIs. + loggingTransport := logging.NewTransport("Google", client.Transport) + + // 3. Retry Transport - retries common temporary errors + // Keep order for wrapping logging so we log each retried request as well. + // This value should be used if needed to create shallow copies with additional retry predicates. + // See ClientWithAdditionalRetries + retryTransport := NewTransportWithDefaultRetries(loggingTransport) + + // Set final transport value. + client.Transport = retryTransport + // This timeout is a timeout per HTTP request, not per logical operation. client.Timeout = c.synchronousTimeout() @@ -377,7 +393,8 @@ func (c *Config) LoadAndValidate(ctx context.Context) error { pubsubClientBasePath := removeBasePathVersion(c.PubsubBasePath) log.Printf("[INFO] Instantiating Google Pubsub client for path %s", pubsubClientBasePath) - c.clientPubsub, err = pubsub.NewService(ctx, option.WithHTTPClient(client)) + wrappedPubsubClient := ClientWithAdditionalRetries(client, retryTransport, pubsubTopicProjectNotReady) + c.clientPubsub, err = pubsub.NewService(ctx, option.WithHTTPClient(wrappedPubsubClient)) if err != nil { return err } @@ -476,7 +493,8 @@ func (c *Config) LoadAndValidate(ctx context.Context) error { bigQueryClientBasePath := c.BigQueryBasePath log.Printf("[INFO] Instantiating Google Cloud BigQuery client for path %s", bigQueryClientBasePath) - c.clientBigQuery, err = bigquery.NewService(ctx, option.WithHTTPClient(client)) + wrappedBigQueryClient := ClientWithAdditionalRetries(client, retryTransport, iamMemberMissing) + c.clientBigQuery, err = bigquery.NewService(ctx, option.WithHTTPClient(wrappedBigQueryClient)) if err != nil { return err } diff --git a/google/error_retry_predicates.go b/google/error_retry_predicates.go index 77cd3160810..c1c72ae0c6b 100644 --- a/google/error_retry_predicates.go +++ b/google/error_retry_predicates.go @@ -8,7 +8,6 @@ import ( "net/url" "strings" - "golang.org/x/oauth2" "google.golang.org/api/googleapi" ) @@ -72,21 +71,7 @@ const connectionResetByPeerErr = ": connection reset by peer" func isConnectionResetNetworkError(err error) (bool, string) { if strings.HasSuffix(err.Error(), connectionResetByPeerErr) { - //TODO(emilymye, TPG#3957): Remove these debug logs - log.Printf("[DEBUG] Found connection reset by peer error of type %T", err) - switch err.(type) { - case *url.Error: - case *net.OpError: - log.Printf("[DEBUG] Connection reset error returned from net/url") - case *googleapi.Error: - log.Printf("[DEBUG] Connection reset error wrapped by googleapi.Error") - case *oauth2.RetrieveError: - log.Printf("[DEBUG] Connection reset error wrapped by oauth2") - default: - log.Printf("[DEBUG] Connection reset error wrapped by %T", err) - } - - return true, fmt.Sprintf("reset connection") + return true, fmt.Sprintf("reset connection error: %v", err) } return false, "" } diff --git a/google/retry_transport.go b/google/retry_transport.go new file mode 100644 index 00000000000..d9293a59fcf --- /dev/null +++ b/google/retry_transport.go @@ -0,0 +1,203 @@ +// A http.RoundTripper that retries common errors, with convenience constructors. +// +// NOTE: This meant for TEMPORARY, TRANSIENT ERRORS. +// Do not use for waiting on operations or polling of resource state, +// especially if the expected state (operation done, resource ready, etc) +// takes longer to reach than the default client Timeout. +// In those cases, retryTimeDuration(...)/resource.Retry with appropriate timeout +// and error predicates/handling should be used as a wrapper around the request +// instead. +// +// Example Usage: +// For handwritten/Go clients, the retry transport should be provided via +// the main client or a shallow copy of the HTTP resources, depending on the +// API-specific retry predicates. +// Example Usage in Terraform Config: +// client := oauth2.NewClient(ctx, tokenSource) +// // Create with default retry predicates +// client.Transport := NewTransportWithDefaultRetries(client.Transport, defaultTimeout) +// +// // If API uses just default retry predicates: +// c.clientCompute, err = compute.NewService(ctx, option.WithHTTPClient(client)) +// ... +// // If API needs custom additional retry predicates: +// sqlAdminHttpClient := ClientWithAdditionalRetries(client, retryTransport, +// isTemporarySqlError1, +// isTemporarySqlError2) +// c.clientSqlAdmin, err = compute.NewService(ctx, option.WithHTTPClient(sqlAdminHttpClient)) +// ... + +package google + +import ( + "bytes" + "context" + "errors" + "fmt" + "github.com/hashicorp/errwrap" + "github.com/hashicorp/terraform-plugin-sdk/helper/resource" + "google.golang.org/api/googleapi" + "io/ioutil" + "log" + "net/http" + "net/http/httputil" + "time" +) + +const defaultRetryTransportTimeoutSec = 30 + +// NewTransportWithDefaultRetries constructs a default retryTransport that will retry common temporary errors +func NewTransportWithDefaultRetries(t http.RoundTripper) *retryTransport { + return &retryTransport{ + retryPredicates: defaultErrorRetryPredicates, + internal: t, + } +} + +// Helper method to create a shallow copy of an HTTP client with a shallow-copied retryTransport +// s.t. the base HTTP transport is the same (i.e. client connection pools are shared, retryPredicates are different) +func ClientWithAdditionalRetries(baseClient *http.Client, baseRetryTransport *retryTransport, predicates ...RetryErrorPredicateFunc) *http.Client { + copied := *baseClient + if baseRetryTransport == nil { + baseRetryTransport = NewTransportWithDefaultRetries(baseClient.Transport) + } + copied.Transport = baseRetryTransport.WithAddedPredicates(predicates...) + return &copied +} + +// Returns a shallow copy of the retry transport with additional retry +// predicates but same wrapped http.RoundTripper +func (t *retryTransport) WithAddedPredicates(predicates ...RetryErrorPredicateFunc) *retryTransport { + copyT := *t + copyT.retryPredicates = append(t.retryPredicates, predicates...) + return ©T +} + +type retryTransport struct { + retryPredicates []RetryErrorPredicateFunc + internal http.RoundTripper +} + +// RoundTrip implements the RoundTripper interface method. +// It retries the given HTTP request based on the retry predicates +// registered under the retryTransport. +func (t *retryTransport) RoundTrip(req *http.Request) (resp *http.Response, respErr error) { + // Set timeout to default value. + ctx := req.Context() + var ccancel context.CancelFunc + if _, ok := ctx.Deadline(); !ok { + ctx, ccancel = context.WithTimeout(ctx, defaultRetryTransportTimeoutSec*time.Second) + defer func() { + if ctx.Err() == nil { + // Cleanup child context created for retry loop if ctx not done. + ccancel() + } + }() + } + + attempts := 0 + backoff := time.Millisecond * 500 + nextBackoff := time.Millisecond * 500 + + log.Printf("[DEBUG] Retry Transport: starting RoundTrip retry loop") +Retry: + for { + log.Printf("[DEBUG] Retry Transport: request attempt %d", attempts) + + // Copy the request - we dont want to use the original request as + // RoundTrip contract says request body can/will be consumed + newRequest, copyErr := copyHttpRequest(req) + if copyErr != nil { + respErr = errwrap.Wrapf("unable to copy invalid http.Request for retry: {{err}}", copyErr) + break Retry + } + + // Do the wrapped Roundtrip. This is one request in the retry loop. + resp, respErr = t.internal.RoundTrip(newRequest) + attempts++ + + retryErr := t.checkForRetryableError(resp, respErr) + if retryErr == nil { + log.Printf("[DEBUG] Retry Transport: Stopping retries, last request was successful") + break Retry + } + if !retryErr.Retryable { + log.Printf("[DEBUG] Retry Transport: Stopping retries, last request failed with non-retryable error: %s", retryErr.Err) + break Retry + } + + log.Printf("[DEBUG] Retry Transport: Waiting %s before trying request again", backoff) + select { + case <-ctx.Done(): + log.Printf("[DEBUG] Retry Transport: Stopping retries, context done: %v", ctx.Err()) + break Retry + case <-time.After(backoff): + log.Printf("[DEBUG] Retry Transport: Finished waiting %s before next retry", backoff) + + // Fibonnaci backoff - 0.5, 1, 1.5, 2.5, 4, 6.5, 10.5, ... + lastBackoff := backoff + backoff = backoff + nextBackoff + nextBackoff = lastBackoff + continue + } + } + + log.Printf("[DEBUG] Retry Transport: Returning after %d attempts", attempts) + return resp, respErr +} + +// copyHttpRequest provides an copy of the given HTTP request for one RoundTrip. +// If the request has a non-empty body (io.ReadCloser), the body is deep copied +// so it can be consumed. +func copyHttpRequest(req *http.Request) (*http.Request, error) { + newRequest := *req + + if req.Body == nil || req.Body == http.NoBody { + return &newRequest, nil + } + + // Helpers like http.NewRequest add a GetBody for copying. + // If not given, we should reject the request. + if req.GetBody == nil { + return nil, errors.New("invalid HTTP request for transport, expected request.GetBody for non-empty Body") + } + + bd, err := req.GetBody() + if err != nil { + return nil, err + } + + newRequest.Body = bd + return &newRequest, nil +} + +// checkForRetryableError uses the googleapi.CheckResponse util to check for +// errors in the response, and determines whether there is a retryable error. +// in response/response error. +func (t *retryTransport) checkForRetryableError(resp *http.Response, respErr error) *resource.RetryError { + var errToCheck error + + if respErr != nil { + errToCheck = respErr + } else { + respToCheck := *resp + // The RoundTrip contract states that the HTTP response/response error + // returned cannot be edited. We need to consume the Body to check for + // errors, so we need to create a copy if the Response has a body. + if resp.Body != nil && resp.Body != http.NoBody { + // Use httputil.DumpResponse since the only important info is + // error code and messages in the response body. + dumpBytes, err := httputil.DumpResponse(resp, true) + if err != nil { + return resource.NonRetryableError(fmt.Errorf("unable to check response for error: %v", err)) + } + respToCheck.Body = ioutil.NopCloser(bytes.NewReader(dumpBytes)) + } + errToCheck = googleapi.CheckResponse(&respToCheck) + } + + if isRetryableError(errToCheck, t.retryPredicates...) { + return resource.RetryableError(errToCheck) + } + return resource.NonRetryableError(errToCheck) +} diff --git a/google/retry_transport_test.go b/google/retry_transport_test.go new file mode 100644 index 00000000000..617528ca5fe --- /dev/null +++ b/google/retry_transport_test.go @@ -0,0 +1,261 @@ +package google + +import ( + "bytes" + "context" + "fmt" + "google.golang.org/api/googleapi" + "io/ioutil" + "net/http" + "net/http/httptest" + "strings" + "sync" + "testing" + "time" +) + +const testRetryTransportCodeRetry = 500 +const testRetryTransportCodeSuccess = 200 +const testRetryTransportCodeFailure = 400 + +func setUpRetryTransportServerClient(hf http.Handler) (*httptest.Server, *http.Client) { + ts := httptest.NewServer(hf) + + client := ts.Client() + client.Transport = &retryTransport{ + internal: http.DefaultTransport, + retryPredicates: []RetryErrorPredicateFunc{testRetryTransportRetryPredicate}, + } + return ts, client +} + +// Check for no errors if the request succeeds the first time +func TestRetryTransport_SingleRequestSuccess(t *testing.T) { + ts, client := setUpRetryTransportServerClient( + // Request succeeds immediately + testRetryTransportHandler_noRetries(t, testRetryTransportCodeSuccess)) + defer ts.Close() + + resp, err := client.Get(ts.URL) + testRetryTransport_checkSuccess(t, resp, err) +} + +// Check for error if the request fails the first time +func TestRetryTransport_SingleRequestError(t *testing.T) { + ts, client := setUpRetryTransportServerClient( + // Request fails immediately + testRetryTransportHandler_noRetries(t, testRetryTransportCodeFailure)) + defer ts.Close() + + resp, err := client.Get(ts.URL) + testRetryTransport_checkFailure(t, resp, err, 400) +} + +func TestRetryTransport_SuccessAfterRetries(t *testing.T) { + ts, client := setUpRetryTransportServerClient( + // Request succeeds after a certain amount of time + testRetryTransportHandler_returnAfter(t, time.Second*1, testRetryTransportCodeSuccess)) + defer ts.Close() + + ctx, cc := context.WithTimeout(context.Background(), time.Second*2) + defer cc() + req, err := http.NewRequestWithContext(ctx, "GET", ts.URL, nil) + if err != nil { + t.Fatalf("unable to construct err: %v", err) + } + + resp, err := client.Do(req) + testRetryTransport_checkSuccess(t, resp, err) +} + +func TestRetryTransport_FailAfterRetries(t *testing.T) { + ts, client := setUpRetryTransportServerClient( + // Request fails after a certain amount of time + testRetryTransportHandler_returnAfter(t, time.Second*1, testRetryTransportCodeFailure)) + defer ts.Close() + + ctx, cc := context.WithTimeout(context.Background(), time.Second*2) + defer cc() + req, err := http.NewRequestWithContext(ctx, "GET", ts.URL, nil) + if err != nil { + t.Fatalf("unable to construct err: %v", err) + } + + resp, err := client.Do(req) + testRetryTransport_checkFailure(t, resp, err, 400) +} + +func TestRetryTransport_ContextTimeout(t *testing.T) { + ts, client := setUpRetryTransportServerClient( + // Request succeeds after a certain amount of time + testRetryTransportHandler_returnAfter(t, time.Second*4, testRetryTransportCodeSuccess)) + defer ts.Close() + + ctx, cc := context.WithTimeout(context.Background(), time.Second*2) + defer cc() + req, err := http.NewRequestWithContext(ctx, "GET", ts.URL, nil) + if err != nil { + t.Fatalf("unable to construct err: %v", err) + } + + resp, err := client.Do(req) + // Last failure should have been a retryable error since we timed out + testRetryTransport_checkFailedWhileRetrying(t, resp, err) +} + +// Check for no errors if the request succeeds after a certain amount of time +func TestRetryTransport_SuccessWithBody(t *testing.T) { + ts, client := setUpRetryTransportServerClient( + // Request succeeds after a certain amount of time and returns the body + testRetryTransportHandler_returnAfter(t, time.Second*1, testRetryTransportCodeSuccess)) + defer ts.Close() + + body := "body for successful request" + ctx, cc := context.WithTimeout(context.Background(), time.Second*2) + defer cc() + req, err := http.NewRequestWithContext(ctx, "GET", ts.URL, bytes.NewReader([]byte(body))) + if err != nil { + t.Fatalf("unable to construct err: %v", err) + } + + resp, err := client.Do(req) + testRetryTransport_checkSuccess(t, resp, err) + testRetryTransport_checkBody(t, resp, body) +} + +// handlers +func testRetryTransportHandler_noRetries(t *testing.T, code int) http.Handler { + return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + w.WriteHeader(code) + if _, err := w.Write([]byte(fmt.Sprintf("Code: %d", code))); err != nil { + t.Errorf("[ERROR] unable to write to response writer: %v", err) + } + }) +} + +func testRetryTransportHandler_returnAfter(t *testing.T, interval time.Duration, code int) http.Handler { + var firstReqTime time.Time + var testOnce sync.Once + + return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + testOnce.Do(func() { + firstReqTime = time.Now() + }) + + var slurp []byte + if r.Body != nil && r.Body != http.NoBody { + var err error + slurp, err = ioutil.ReadAll(r.Body) + if err != nil { + w.WriteHeader(testRetryTransportCodeFailure) + if _, err := w.Write([]byte(fmt.Sprintf("unable to read request body: %v", err))); err != nil { + t.Errorf("[ERROR] unable to write to response writer: %v", err) + } + return + } + } + + if time.Since(firstReqTime) < interval { + w.WriteHeader(testRetryTransportCodeRetry) + resp := fmt.Sprintf("Code: %d\nRequest Body: %s", testRetryTransportCodeRetry, string(slurp)) + if _, err := w.Write([]byte(resp)); err != nil { + t.Errorf("[ERROR] unable to write to response writer: %v", err) + } + return + } + + w.WriteHeader(code) + resp := fmt.Sprintf("Code: %d\nRequest Body: %s", code, string(slurp)) + if _, err := w.Write([]byte(resp)); err != nil { + t.Errorf("[ERROR] unable to write to response writer: %v", err) + } + }) +} + +// Utils for checking +func testRetryTransport_checkSuccess(t *testing.T, resp *http.Response, respErr error) { + if respErr != nil { + t.Fatalf("expected no error, got: %v", respErr) + } + + err := googleapi.CheckResponse(resp) + if err != nil { + t.Fatalf("expected no error, got response error: %v", err) + } + + if resp.StatusCode != testRetryTransportCodeSuccess { + t.Fatalf("got unexpected error code %d, expected %d", resp.StatusCode, testRetryTransportCodeSuccess) + } +} + +func testRetryTransport_checkFailure(t *testing.T, resp *http.Response, respErr error, expectedCode int) { + if respErr != nil { + t.Fatalf("expected response error, got actual error for doing request: %v", respErr) + } + + err := googleapi.CheckResponse(resp) + if err == nil { + t.Fatalf("expected googleapi error, got no error") + } + + gerr, ok := err.(*googleapi.Error) + if !ok { + t.Fatalf("expected error to be googleapi error: %v", err) + } + + if gerr.Code != expectedCode { + t.Errorf("expected error code %d, got error: %v", expectedCode, err) + } + + expectedMsg := fmt.Sprintf("Code: %d", expectedCode) + if !strings.Contains(gerr.Body, expectedMsg) { + t.Errorf("expected error message %q, got: %v", expectedMsg, err) + } +} + +func testRetryTransport_checkFailedWhileRetrying(t *testing.T, resp *http.Response, respErr error) { + if respErr != nil { + t.Fatalf("expected response error, got actual error for doing request: %v", respErr) + } + + err := googleapi.CheckResponse(resp) + if err == nil { + t.Fatalf("expected googleapi error, got no error") + } + + gerr, ok := err.(*googleapi.Error) + if !ok { + t.Fatalf("expected error to be googleapi error: %v", err) + } + + if gerr.Code != testRetryTransportCodeRetry { + t.Errorf("expected error code %d, got error: %v", testRetryTransportCodeRetry, err) + } +} + +func testRetryTransport_checkBody(t *testing.T, resp *http.Response, expectedMsg string) { + if resp == nil { + t.Fatal("expected non-empty response") + } + + actualBody, err := ioutil.ReadAll(resp.Body) + if err != nil { + t.Fatalf("expected no error, unable to read response body: %v", err) + } + + expectedBody := fmt.Sprintf("Request Body: %s", expectedMsg) + if !strings.HasSuffix(string(actualBody), expectedBody) { + t.Fatalf(expectedBody) + } +} + +// ERROR RETRY PREDICATE +// Retries 500. +func testRetryTransportRetryPredicate(err error) (bool, string) { + if gerr, ok := err.(*googleapi.Error); ok { + if gerr.Code == testRetryTransportCodeRetry { + return true, "retryable error" + } + } + return false, "" +}