Merge pull request #1492 from Azure/better-failure-messages

Improve record/replay tests

hack/generated/pkg/armclient/recordings/Test_NewResourceGroupDeployment_Error.yaml

@@ -2,26 +2,26 @@
 version: 1
 interactions:
 - request:
-    body: '{"name":"k8sinfratest-deployment-mzojax","location":"westus","Properties":{"Error":null,"debugSetting":{"detailLevel":"requestContent,responseContent"},"mode":"Incremental","template":{"$schema":"https://schema.management.azure.com/schemas/2018-05-01/subscriptionDeploymentTemplate.json#","contentVersion":"1.0.0.0","resources":[{"apiVersion":"2020-06-01","name":"k8sinfratest-rg-kheqhf","location":"BadLocation","tags":{"CreatedAt":"2020-11-09T23:03:51Z"},"type":"Microsoft.Resources/resourceGroups"}]}}}'
+    body: '{"name":"k8sinfratest-deployment-mzojax","location":"westus","Properties":{"Error":null,"debugSetting":{"detailLevel":"requestContent,responseContent"},"mode":"Incremental","template":{"$schema":"https://schema.management.azure.com/schemas/2018-05-01/subscriptionDeploymentTemplate.json#","contentVersion":"1.0.0.0","resources":[{"apiVersion":"2020-06-01","name":"k8sinfratest-rg-kheqhf","location":"BadLocation","tags":{"CreatedAt":"2001-02-03T04:05:06Z"},"type":"Microsoft.Resources/resourceGroups"}]}}}'
     form: {}
     headers:
       Content-Type:
       - application/json
-      User-Agent:
-      - Go/go1.15.3 (amd64-linux) go-autorest/v14.1.1 k8sinfra-generated
+      Test-Request-Attempt:
+      - "0"
     url: https://management.azure.com/subscriptions/00000000-0000-0000-0000-000000000000/providers/Microsoft.Resources/deployments/k8sinfratest-deployment-mzojax?api-version=2019-10-01
     method: PUT
   response:
-    body: '{"error":{"code":"LocationNotAvailableForResourceGroup","message":"The provided location ''BadLocation'' is not available for resource group. List of available regions is ''centralus,eastasia,southeastasia,eastus,eastus2,westus,westus2,northcentralus,southcentralus,westcentralus,northeurope,westeurope,japaneast,japanwest,brazilsouth,australiasoutheast,australiaeast,westindia,southindia,centralindia,canadacentral,canadaeast,uksouth,ukwest,koreacentral,koreasouth,francecentral,southafricanorth,uaenorth,australiacentral,switzerlandnorth,germanywestcentral,norwayeast''."}}'
+    body: '{"error":{"code":"LocationNotAvailableForResourceGroup","message":"The
+      provided location ''BadLocation'' is not available for resource group. List
+      of available regions is ''centralus,eastasia,southeastasia,eastus,eastus2,westus,westus2,northcentralus,southcentralus,westcentralus,northeurope,westeurope,japaneast,japanwest,brazilsouth,australiasoutheast,australiaeast,westindia,southindia,centralindia,canadacentral,canadaeast,uksouth,ukwest,koreacentral,koreasouth,francecentral,southafricanorth,uaenorth,australiacentral,switzerlandnorth,germanywestcentral,norwayeast,jioindiawest''."}}'
     headers:
       Cache-Control:
       - no-cache
       Content-Length:
-      - "571"
+      - "584"
       Content-Type:
       - application/json; charset=utf-8
-      Date:
-      - Mon, 09 Nov 2020 23:03:49 GMT
       Expires:
       - "-1"
       Pragma:

hack/generated/pkg/testcommon/counting_roundtripper.go

@@ -0,0 +1,41 @@
+/*
+Copyright (c) Microsoft Corporation.
+Licensed under the MIT license.
+*/
+
+package testcommon
+
+import (
+	"fmt"
+	"net/http"
+)
+
+// Wraps an inner HTTP roundtripper to add a
+// counter for duplicated request URIs. This
+// is then used to match up requests in the recorder
+// - it is needed as we have multiple requests with
+// the same Request URL and it will return the first
+// one that matches.
+type requestCounter struct {
+	inner  http.RoundTripper
+	counts map[string]uint32
+}
+
+func addCountHeader(inner http.RoundTripper) *requestCounter {
+	return &requestCounter{
+		inner:  inner,
+		counts: make(map[string]uint32),
+	}
+}
+
+var COUNT_HEADER string = "TEST-REQUEST-ATTEMPT"
+
+func (rt *requestCounter) RoundTrip(req *http.Request) (*http.Response, error) {
+	key := req.Method + ":" + req.URL.String()
+	count := rt.counts[key]
+	req.Header.Add(COUNT_HEADER, fmt.Sprintf("%v", count))
+	rt.counts[key] = count + 1
+	return rt.inner.RoundTrip(req)
+}
+
+var _ http.RoundTripper = &requestCounter{}

hack/generated/pkg/testcommon/error_translating_roundtripper.go

@@ -0,0 +1,106 @@
+/*
+Copyright (c) Microsoft Corporation.
+Licensed under the MIT license.
+*/
+
+package testcommon
+
+import (
+	"fmt"
+	"io"
+	"net/http"
+	"strings"
+
+	"github.com/dnaeon/go-vcr/cassette"
+	"github.com/dnaeon/go-vcr/recorder"
+	"github.com/google/go-cmp/cmp"
+)
+
+// translateErrors wraps the given Recorder to handle any "Requested interaction not found"
+// and log better information about what the expected request was.
+//
+// By default the error will be returned to the controller which might ignore/retry it
+// and not log any useful information. So instead here we find the recorded request with
+// the body that most closely matches what was sent and report the "expected" body.
+//
+// Ideally we would panic on this error but we don't have a good way to deal with the following
+// problem at the moment:
+// - during record the controller does GET (404), PUT, … GET (OK)
+// - during playback the controller does GET (which now returns OK), DELETE, PUT, …
+//   and fails due to a missing DELETE recording
+func translateErrors(r *recorder.Recorder, cassetteName string) http.RoundTripper {
+	return errorTranslation{r, cassetteName, nil}
+}
+
+type errorTranslation struct {
+	recorder     *recorder.Recorder
+	cassetteName string
+
+	cassette *cassette.Cassette
+}
+
+func (w errorTranslation) ensureCassette() *cassette.Cassette {
+	if w.cassette == nil {
+		cassette, err := cassette.Load(w.cassetteName)
+		if err != nil {
+			panic(fmt.Sprintf("unable to load casette %q", w.cassetteName))
+		}
+
+		w.cassette = cassette
+	}
+
+	return w.cassette
+}
+
+func (w errorTranslation) RoundTrip(req *http.Request) (*http.Response, error) {
+	resp, originalErr := w.recorder.RoundTrip(req)
+	// sorry, go-vcr doesn't expose the error type or message
+	if originalErr == nil || !strings.Contains(originalErr.Error(), "interaction not found") {
+		return resp, originalErr
+	}
+
+	sentBodyString := "<nil>"
+	if req.Body != nil {
+		bodyBytes, bodyErr := io.ReadAll(req.Body)
+		if bodyErr != nil {
+			// see invocation of SetMatcher in the createRecorder, which does this
+			panic("io.ReadAll(req.Body) failed, this should always succeed because req.Body has been replaced by a buffer")
+		}
+
+		sentBodyString = string(bodyBytes)
+	}
+
+	// find all request bodies for the specified method/URL combination
+	matchingBodies := w.findMatchingBodies(req)
+
+	if len(matchingBodies) == 0 {
+		fmt.Printf("\n*** Cannot find go-vcr recording for request (no responses recorded for this method/URL): %s %s (attempt: %s)\n\n", req.Method, req.URL.String(), req.Header.Get(COUNT_HEADER))
+		return nil, originalErr
+	}
+
+	// locate the request body with the shortest diff from the sent body
+	shortestDiff := ""
+	for i, bodyString := range matchingBodies {
+		diff := cmp.Diff(sentBodyString, bodyString)
+		if i == 0 || len(diff) < len(shortestDiff) {
+			shortestDiff = diff
+		}
+	}
+
+	fmt.Printf("\n*** Cannot find go-vcr recording for request (body mismatch): %s %s\nShortest body diff: %s\n\n", req.Method, req.URL.String(), shortestDiff)
+	return nil, originalErr
+}
+
+// finds bodies for interactions where request method, URL, and COUNT_HEADER match
+func (w errorTranslation) findMatchingBodies(r *http.Request) []string {
+	urlString := r.URL.String()
+	var result []string
+	for _, interaction := range w.ensureCassette().Interactions {
+		if urlString == interaction.URL && r.Method == interaction.Request.Method &&
+			r.Header.Get(COUNT_HEADER) == interaction.Request.Headers.Get(COUNT_HEADER) {
+			result = append(result, interaction.Request.Body)
+		}
+	}
+
+	return result
+}

hack/generated/pkg/testcommon/kube_test_context_envtest.go

@@ -9,7 +9,6 @@ import (
 	"fmt"
 	"log"
 	"net"
-	"net/http"
 	"strconv"
 	"time"
 
@@ -137,33 +136,3 @@ func waitForWebhooks(env envtest.Environment) {
 		return
 	}
 }
-
-// Wraps an inner HTTP roundtripper to add a
-// counter for duplicated request URIs. This
-// is then used to match up requests in the recorder
-// - it is needed as we have multiple requests with
-// the same Request URL and it will return the first
-// one that matches.
-type requestCounter struct {
-	inner  http.RoundTripper
-	counts map[string]uint32
-}
-
-func MakeRoundTripper(inner http.RoundTripper) *requestCounter {
-	return &requestCounter{
-		inner:  inner,
-		counts: make(map[string]uint32),
-	}
-}
-
-var COUNT_HEADER string = "TEST-REQUEST-ATTEMPT"
-
-func (rt *requestCounter) RoundTrip(req *http.Request) (*http.Response, error) {
-	key := req.Method + ":" + req.URL.String()
-	count := rt.counts[key]
-	req.Header.Add(COUNT_HEADER, fmt.Sprintf("%v", count))
-	rt.counts[key] = count + 1
-	return rt.inner.RoundTrip(req)
-}
-
-var _ http.RoundTripper = &requestCounter{}

hack/generated/pkg/testcommon/test_context.go

@@ -7,9 +7,10 @@ package testcommon
 
 import (
 	"bytes"
-	"io/ioutil"
+	"io"
 	"log"
 	"net/http"
+	"regexp"
 	"strings"
 	"testing"
 
@@ -56,7 +57,8 @@ func NewTestContext(region string, recordReplay bool) TestContext {
 }
 
 func (tc TestContext) ForTest(t *testing.T) (PerTestContext, error) {
-	authorizer, subscriptionID, recorder, err := createRecorder(t.Name(), tc.RecordReplay)
+	cassetteName := "recordings/" + t.Name()
+	authorizer, subscriptionID, recorder, err := createRecorder(cassetteName, tc.RecordReplay)
 	if err != nil {
 		return PerTestContext{}, errors.Wrapf(err, "creating recorder")
 	}
@@ -68,7 +70,7 @@ func (tc TestContext) ForTest(t *testing.T) (PerTestContext, error) {
 
 	// replace the ARM client transport (a bit hacky)
 	httpClient := armClient.RawClient.Sender.(*http.Client)
-	httpClient.Transport = recorder
+	httpClient.Transport = addCountHeader(translateErrors(recorder, cassetteName))
 
 	t.Cleanup(func() {
 		if !t.Failed() {
@@ -92,9 +94,7 @@ func (tc TestContext) ForTest(t *testing.T) (PerTestContext, error) {
 	}, nil
 }
 
-func createRecorder(testName string, recordReplay bool) (autorest.Authorizer, string, *recorder.Recorder, error) {
-	cassetteName := "recordings/" + testName
-
+func createRecorder(cassetteName string, recordReplay bool) (autorest.Authorizer, string, *recorder.Recorder, error) {
 	var err error
 	var r *recorder.Recorder
 	if recordReplay {
@@ -125,17 +125,26 @@ func createRecorder(testName string, recordReplay bool) (autorest.Authorizer, st
 
 	// check body as well as URL/Method (copied from go-vcr documentation)
 	r.SetMatcher(func(r *http.Request, i cassette.Request) bool {
+		if !cassette.DefaultMatcher(r, i) {
+			return false
+		}
+
+		// verify custom request count header (see counting_roundtripper.go)
+		if r.Header.Get(COUNT_HEADER) != i.Headers.Get(COUNT_HEADER) {
+			return false
+		}
+
 		if r.Body == nil {
-			return cassette.DefaultMatcher(r, i)
+			return i.Body == ""
 		}
 
 		var b bytes.Buffer
 		if _, err := b.ReadFrom(r.Body); err != nil {
-			return false
+			panic(err)
 		}
 
-		r.Body = ioutil.NopCloser(&b)
-		return cassette.DefaultMatcher(r, i) && (b.String() == "" || b.String() == i.Body)
+		r.Body = io.NopCloser(&b)
+		return b.String() == "" || hideDates(b.String()) == i.Body
 	})
 
 	r.AddSaveFilter(func(i *cassette.Interaction) error {
@@ -146,8 +155,8 @@ func createRecorder(testName string, recordReplay bool) (autorest.Authorizer, st
 			return strings.ReplaceAll(s, subscriptionID, uuid.Nil.String())
 		}
 
-		i.Request.Body = hideSubID(i.Request.Body)
-		i.Response.Body = hideSubID(i.Response.Body)
+		i.Request.Body = hideDates(hideSubID(i.Request.Body))
+		i.Response.Body = hideDates(hideSubID(i.Response.Body))
 		i.Request.URL = hideSubID(i.Request.URL)
 
 		for _, values := range i.Request.Headers {
@@ -172,18 +181,24 @@ func createRecorder(testName string, recordReplay bool) (autorest.Authorizer, st
 		delete(i.Response.Headers, "X-Ms-Request-Id")
 		delete(i.Response.Headers, "X-Ms-Routing-Request-Id")
 
-		return nil
-	})
+		// don't need these headers and they add to diff churn
+		delete(i.Request.Headers, "User-Agent")
+		delete(i.Response.Headers, "Date")
 
-	// request must match URI & METHOD & our custom header
-	r.SetMatcher(func(request *http.Request, i cassette.Request) bool {
-		return cassette.DefaultMatcher(request, i) &&
-			request.Header.Get(COUNT_HEADER) == i.Headers.Get(COUNT_HEADER)
+		return nil
 	})
 
 	return authorizer, subscriptionID, r, nil
 }
 
+var dateMatcher *regexp.Regexp = regexp.MustCompile(`\d{4}-\d{2}-\d{2}T\d{2}:\d{2}:\d{2}(.\d+)?Z`)
+
+// hideDates replaces all ISO8601 datetimes with a fixed value
+// this lets us match requests that may contain time-sensitive information (timestamps, etc)
+func hideDates(s string) string {
+	return dateMatcher.ReplaceAllLiteralString(s, "2001-02-03T04:05:06Z") // this should be recognizable/parseable as a fake date
+}
+
 func (tc PerTestContext) NewTestResourceGroup() *resources.ResourceGroup {
 	return &resources.ResourceGroup{
 		ObjectMeta: metav1.ObjectMeta{