From 90631f0d21be55c57b6dc45e52e7306b5938b011 Mon Sep 17 00:00:00 2001 From: Matthew Christopher Date: Mon, 21 Jun 2021 08:43:00 -0700 Subject: [PATCH] Improve recorded test logging (#1571) * Test logs * Disable -v mode on ci tests - It makes the output more readable if it's off * Ignore Taskfile changes as trigger for long test pass --- Taskfile.yml | 4 +- .../azure_deployment_reconciler.go | 4 +- .../error_translating_roundtripper.go | 10 +- .../testcommon/kube_test_context_envtest.go | 35 ++--- hack/generated/pkg/testcommon/test_context.go | 13 +- hack/generated/pkg/testcommon/test_logger.go | 140 ++++++++++++++++++ scripts/check-changes.sh | 2 +- 7 files changed, 178 insertions(+), 30 deletions(-) create mode 100644 hack/generated/pkg/testcommon/test_logger.go diff --git a/Taskfile.yml b/Taskfile.yml index b23d79740b0..c9192c88327 100644 --- a/Taskfile.yml +++ b/Taskfile.yml @@ -188,7 +188,7 @@ tasks: deps: [controller:generate-crds] cmds: # -race fails at the moment in controller-runtime - - go test -v -run '{{default ".*" .TEST_FILTER}}' ./... + - go test -run '{{default ".*" .TEST_FILTER}}' ./... controller:test-integration-envtest-cover: desc: Run integration tests with envtest using record/replay and output coverage. @@ -196,7 +196,7 @@ tasks: deps: [controller:generate-crds] cmds: # -race fails at the moment in controller-runtime - - go test -covermode atomic -coverprofile=coverage-integration-envtest.out -coverpkg="./..." -v -run '{{default ".*" .TEST_FILTER}}' ./... + - go test -covermode atomic -coverprofile=coverage-integration-envtest.out -coverpkg="./..." -run '{{default ".*" .TEST_FILTER}}' ./... controller:test-integration-envtest-live: desc: Run integration tests with envtest against live data and output coverage. diff --git a/hack/generated/pkg/reconcilers/azure_deployment_reconciler.go b/hack/generated/pkg/reconcilers/azure_deployment_reconciler.go index 9423cab1f61..2ead35f6ea3 100644 --- a/hack/generated/pkg/reconcilers/azure_deployment_reconciler.go +++ b/hack/generated/pkg/reconcilers/azure_deployment_reconciler.go @@ -415,7 +415,7 @@ func (r *AzureDeploymentReconciler) StartDeleteOfResource(ctx context.Context) ( func (r *AzureDeploymentReconciler) MonitorDelete(ctx context.Context) (ctrl.Result, error) { msg := "Continue monitoring deletion" - r.log.Info(msg) + r.log.V(1).Info(msg) r.recorder.Event(r.obj, v1.EventTypeNormal, string(DeleteActionMonitorDelete), msg) resource, err := r.constructArmResource(ctx) @@ -435,7 +435,7 @@ func (r *AzureDeploymentReconciler) MonitorDelete(ctx context.Context) (ctrl.Res } if found { - r.log.V(0).Info("Found resource: continuing to wait for deletion...") + r.log.V(1).Info("Found resource: continuing to wait for deletion...") return ctrl.Result{Requeue: true}, nil } diff --git a/hack/generated/pkg/testcommon/error_translating_roundtripper.go b/hack/generated/pkg/testcommon/error_translating_roundtripper.go index 09652d19b0d..05d5a550677 100644 --- a/hack/generated/pkg/testcommon/error_translating_roundtripper.go +++ b/hack/generated/pkg/testcommon/error_translating_roundtripper.go @@ -10,6 +10,7 @@ import ( "io" "net/http" "strings" + "testing" "github.com/dnaeon/go-vcr/cassette" "github.com/dnaeon/go-vcr/recorder" @@ -28,8 +29,8 @@ import ( // - 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} +func translateErrors(r *recorder.Recorder, cassetteName string, t *testing.T) http.RoundTripper { + return errorTranslation{r, cassetteName, nil, t} } type errorTranslation struct { @@ -37,6 +38,7 @@ type errorTranslation struct { cassetteName string cassette *cassette.Cassette + t *testing.T } func (w errorTranslation) ensureCassette() *cassette.Cassette { @@ -74,7 +76,7 @@ func (w errorTranslation) RoundTrip(req *http.Request) (*http.Response, error) { 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)) + w.t.Logf("\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 } @@ -87,7 +89,7 @@ func (w errorTranslation) RoundTrip(req *http.Request) (*http.Response, error) { } } - 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) + w.t.Logf("\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 } diff --git a/hack/generated/pkg/testcommon/kube_test_context_envtest.go b/hack/generated/pkg/testcommon/kube_test_context_envtest.go index b2fe07c89f6..431c3f8e2c3 100644 --- a/hack/generated/pkg/testcommon/kube_test_context_envtest.go +++ b/hack/generated/pkg/testcommon/kube_test_context_envtest.go @@ -7,16 +7,16 @@ package testcommon import ( "fmt" - "log" "net" + "os" "strconv" + "testing" "time" "github.com/dnaeon/go-vcr/recorder" "github.com/google/uuid" "github.com/pkg/errors" metav1 "k8s.io/apimachinery/pkg/apis/meta/v1" - "k8s.io/klog/v2/klogr" ctrl "sigs.k8s.io/controller-runtime" "sigs.k8s.io/controller-runtime/pkg/envtest" @@ -24,7 +24,7 @@ import ( ) func createEnvtestContext(perTestContext PerTestContext) (*KubeBaseTestContext, error) { - log.Printf("Creating envtest for test %s", perTestContext.TestName) + perTestContext.T.Logf("Creating envtest test: %s", perTestContext.TestName) environment := envtest.Environment{ ErrorIfCRDPathMissing: true, @@ -38,21 +38,21 @@ func createEnvtestContext(perTestContext PerTestContext) (*KubeBaseTestContext, }, } - log.Print("Starting envtest") + perTestContext.T.Log("Starting envtest") config, err := environment.Start() if err != nil { return nil, errors.Wrapf(err, "starting envtest environment") } perTestContext.T.Cleanup(func() { - log.Print("Stopping envtest") + perTestContext.T.Log("Stopping envtest") stopErr := environment.Stop() if stopErr != nil { - log.Printf("unable to stop envtest environment: %s", stopErr.Error()) + perTestContext.T.Logf("unable to stop envtest environment: %s", stopErr.Error()) } }) - log.Print("Creating & starting controller-runtime manager") + perTestContext.T.Log("Creating & starting controller-runtime manager") mgr, err := ctrl.NewManager(config, ctrl.Options{ Scheme: controllers.CreateScheme(), CertDir: environment.WebhookInstallOptions.LocalServingCertDir, @@ -66,17 +66,16 @@ func createEnvtestContext(perTestContext PerTestContext) (*KubeBaseTestContext, var requeueDelay time.Duration // defaults to 5s when zero is passed if perTestContext.AzureClientRecorder.Mode() == recorder.ModeReplaying { - log.Print("Minimizing requeue delay") + perTestContext.T.Log("Minimizing requeue delay") // skip requeue delays when replaying requeueDelay = 100 * time.Millisecond } - log.Print("Registering custom controllers") err = controllers.RegisterAll( mgr, perTestContext.AzureClient, controllers.GetKnownStorageTypes(), - klogr.New(), + perTestContext.logger, controllers.Options{ CreateDeploymentName: func(obj metav1.Object) (string, error) { // create deployment name based on test name and kubernetes name @@ -99,19 +98,21 @@ func createEnvtestContext(perTestContext PerTestContext) (*KubeBaseTestContext, // this blocks until the input chan is closed err := mgr.Start(stopManager) if err != nil { - log.Fatal(errors.Wrapf(err, "running controller-runtime manager")) + perTestContext.T.Errorf("error running controller-runtime manager: %s", err.Error()) + os.Exit(1) } }() perTestContext.T.Cleanup(func() { - log.Print("Stopping controller-runtime manager") + + perTestContext.T.Log("Stopping controller-runtime manager") close(stopManager) }) - waitForWebhooks(environment) + waitForWebhooks(perTestContext.T, environment) webhookServer := mgr.GetWebhookServer() - log.Printf("Webhook server running at: %s:%d", webhookServer.Host, webhookServer.Port) + perTestContext.T.Logf("Webhook server running at: %s:%d", webhookServer.Host, webhookServer.Port) return &KubeBaseTestContext{ PerTestContext: perTestContext, @@ -119,11 +120,11 @@ func createEnvtestContext(perTestContext PerTestContext) (*KubeBaseTestContext, }, nil } -func waitForWebhooks(env envtest.Environment) { +func waitForWebhooks(t *testing.T, env envtest.Environment) { port := env.WebhookInstallOptions.LocalServingPort address := net.JoinHostPort("127.0.0.1", strconv.Itoa(port)) - log.Printf("Checking for webhooks at: %s", address) + t.Logf("Checking for webhooks at: %s", address) timeout := 1 * time.Second for { conn, err := net.DialTimeout("tcp", address, timeout) @@ -132,7 +133,7 @@ func waitForWebhooks(env envtest.Environment) { continue } _ = conn.Close() - log.Printf("Webhooks available at: %s", address) + t.Logf("Webhooks available at: %s", address) return } } diff --git a/hack/generated/pkg/testcommon/test_context.go b/hack/generated/pkg/testcommon/test_context.go index 61312b92a69..86677127dbe 100644 --- a/hack/generated/pkg/testcommon/test_context.go +++ b/hack/generated/pkg/testcommon/test_context.go @@ -9,7 +9,6 @@ import ( "bytes" "fmt" "io" - "log" "net/http" "regexp" "strings" @@ -18,6 +17,7 @@ import ( "github.com/Azure/go-autorest/autorest" "github.com/dnaeon/go-vcr/cassette" "github.com/dnaeon/go-vcr/recorder" + "github.com/go-logr/logr" "github.com/google/uuid" "github.com/pkg/errors" metav1 "k8s.io/apimachinery/pkg/apis/meta/v1" @@ -39,6 +39,7 @@ type TestContext struct { type PerTestContext struct { TestContext T *testing.T + logger logr.Logger AzureClientRecorder *recorder.Recorder AzureClient armclient.Applier AzureSubscription string @@ -59,6 +60,8 @@ func NewTestContext(region string, recordReplay bool) TestContext { } func (tc TestContext) ForTest(t *testing.T) (PerTestContext, error) { + logger := NewTestLogger(t) + cassetteName := "recordings/" + t.Name() authorizer, subscriptionID, recorder, err := createRecorder(cassetteName, tc.RecordReplay) if err != nil { @@ -72,15 +75,16 @@ 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 = addCountHeader(translateErrors(recorder, cassetteName)) + httpClient.Transport = addCountHeader(translateErrors(recorder, cassetteName, t)) t.Cleanup(func() { if !t.Failed() { - log.Printf("saving ARM client recorder") + logger.Info("saving ARM client recorder") err := recorder.Stop() if err != nil { // cleanup function should not error-out - log.Printf("unable to stop ARM client recorder: %s", err.Error()) + logger.Error(err, "unable to stop ARM client recorder") + t.Fail() } } }) @@ -88,6 +92,7 @@ func (tc TestContext) ForTest(t *testing.T) (PerTestContext, error) { return PerTestContext{ TestContext: tc, T: t, + logger: logger, Namer: tc.NameConfig.NewResourceNamer(t.Name()), AzureClient: armClient, AzureSubscription: subscriptionID, diff --git a/hack/generated/pkg/testcommon/test_logger.go b/hack/generated/pkg/testcommon/test_logger.go new file mode 100644 index 00000000000..a46fc77d852 --- /dev/null +++ b/hack/generated/pkg/testcommon/test_logger.go @@ -0,0 +1,140 @@ +/* +Copyright (c) Microsoft Corporation. +Licensed under the MIT license. +*/ + +package testcommon + +import ( + "bytes" + "fmt" + "testing" + "time" + + "github.com/go-logr/logr" +) + +// TODO: I'm not sure the best way to configure this so for now I'm just going to set it to 5 +var LogLevel = 5 + +var _ logr.Logger = &TestLogger{} + +func NewTestLogger(t *testing.T) logr.Logger { + return &TestLogger{ + t: t, + values: nil, + enabled: true, + name: "", + } +} + +// TestLogger is a logr.Logger wrapper around t.Log, so that we can use it in the controller +type TestLogger struct { + t *testing.T + values []interface{} + + enabled bool + name string +} + +// kvListFormat was adapted from the klog method of the same name and formats a keysAndValues list into +// a sequence of "key"="value" pairs. +func kvListFormat(b *bytes.Buffer, keysAndValues ...interface{}) { + for i := 0; i < len(keysAndValues); i += 2 { + var v interface{} + k := keysAndValues[i] + if i+1 < len(keysAndValues) { + v = keysAndValues[i+1] + } else { + v = "(MISSING)" + } + b.WriteByte(' ') + if _, ok := v.(fmt.Stringer); ok { + b.WriteString(fmt.Sprintf("%s=%q", k, v)) + } else { + b.WriteString(fmt.Sprintf("%s=%#v", k, v)) + } + } +} + +func (t *TestLogger) clone() *TestLogger { + var clonedValues []interface{} + clonedValues = append(clonedValues, t.values...) + + result := &TestLogger{ + t: t.t, + enabled: t.enabled, + values: clonedValues, + name: t.name, + } + return result +} + +// makeHeader makes a header that looks a lot (but not quite exactly) like the klog header +// The idea is that looking at test logs and looking at actual container logs should be basically +// the same. +func (t *TestLogger) makeHeader() string { + now := time.Now() + timeStr := now.Format(time.RFC3339) + + nameString := "" + if t.name != "" { + nameString = fmt.Sprintf(" %s", t.name) + } + + severity := "I" // TODO: Technically there are multiple severities? + + return fmt.Sprintf("%s%s]%s", severity, timeStr, nameString) +} + +func (t *TestLogger) Info(msg string, keysAndValues ...interface{}) { + if t.Enabled() { + t.t.Helper() + + b := &bytes.Buffer{} + + header := t.makeHeader() + kvListFormat(b, t.values...) + kvListFormat(b, keysAndValues...) + + t.t.Log(fmt.Sprintf("%s \"msg\"=\"%s\"%s", header, msg, b)) + } +} + +func (t *TestLogger) Enabled() bool { + return t.enabled +} + +func (t *TestLogger) Error(err error, msg string, keysAndValues ...interface{}) { + if t.Enabled() { + b := &bytes.Buffer{} + header := t.makeHeader() + kvListFormat(b, t.values...) + kvListFormat(b, keysAndValues...) + + t.t.Log(fmt.Sprintf("%s \"msg\"=\"%s\" \"err\"=\"%s\"%s", header, msg, err, b)) + } +} + +func (t *TestLogger) V(level int) logr.InfoLogger { + result := t.clone() + if level <= LogLevel { + return result + } + + result.enabled = false + return result +} + +func (t *TestLogger) WithValues(keysAndValues ...interface{}) logr.Logger { + result := t.clone() + result.values = append(result.values, keysAndValues...) + + return result +} + +func (t *TestLogger) WithName(name string) logr.Logger { + result := t.clone() + result.name = name + return result +} diff --git a/scripts/check-changes.sh b/scripts/check-changes.sh index 9e1d7e790f2..2fe82a0700b 100755 --- a/scripts/check-changes.sh +++ b/scripts/check-changes.sh @@ -1,7 +1,7 @@ #!/bin/bash set -e -IGNORE_FILTERS=("docs/" "README.md" "hack/") +IGNORE_FILTERS=("docs/" "README.md" "hack/" "Taskfile.yml" "scripts/check-changes.sh") CHANGED_FILES=$(git diff HEAD HEAD~ --name-only) IGNORED_COUNT=0 NON_IGNORED_COUNT=0