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

@@ -188,15 +188,15 @@ 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.
     dir: "{{.CONTROLLER_ROOT}}"
     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.

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
 	}
 

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,15 +29,16 @@ 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 {
 	recorder     *recorder.Recorder
 	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
 }
 

hack/generated/pkg/testcommon/kube_test_context_envtest.go

@@ -7,24 +7,24 @@ 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"
 
 	"github.com/Azure/azure-service-operator/hack/generated/controllers"
 )
 
 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,31 +98,33 @@ 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,
 		KubeConfig:     config,
 	}, 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
 	}
 }

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,22 +75,24 @@ 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()
 			}
 		}
 	})
 
 	return PerTestContext{
 		TestContext:         tc,
 		T:                   t,
+		logger:              logger,
 		Namer:               tc.NameConfig.NewResourceNamer(t.Name()),
 		AzureClient:         armClient,
 		AzureSubscription:   subscriptionID,