OCPBUGS-14392: make sync status Failure logs human-readable

pkg/cvo/status.go

@@ -162,7 +162,7 @@ func (optr *Operator) syncStatus(ctx context.Context, original, config *configv1
 	if len(validationErrs) != 0 || status.Failure != nil {
 		verbosityLevel = klog.Level(2)
 	}
-	klog.V(verbosityLevel).Infof("Synchronizing status errs=%#v status=%#v", validationErrs, status)
+	klog.V(verbosityLevel).Infof("Synchronizing status errs=%v status=%s", validationErrs, status)
 
 	cvUpdated := false
 	// update the config with the latest available updates

pkg/cvo/sync_worker.go

@@ -103,6 +103,15 @@ type LoadPayloadStatus struct {
 	LastTransitionTime time.Time
 }
 
+// String returns a curated summary suitable for logs.
+func (s LoadPayloadStatus) String() string {
+	failure := "<none>"
+	if s.Failure != nil {
+		failure = s.Failure.Error()
+	}
+	return fmt.Sprintf("step=%q message=%q failure=%q", s.Step, s.Message, failure)
+}
+
 type CapabilityStatus struct {
 	Status                configv1.ClusterVersionCapabilitiesStatus
 	ImplicitlyEnabledCaps []configv1.ClusterVersionCapability
@@ -149,6 +158,24 @@ func (w SyncWorkerStatus) DeepCopy() *SyncWorkerStatus {
 	return &copy
 }
 
+// String returns a curated summary suitable for logs. Prefer this over %#v: nested
+// Failure values (including unexported loadPayloadStatus.Failure) otherwise render as
+// pointer addresses under Go-syntax formatting.
+func (w SyncWorkerStatus) String() string {
+	failure := "<none>"
+	if w.Failure != nil {
+		failure = w.Failure.Error()
+	}
+	loadFailure := "<none>"
+	if w.loadPayloadStatus.Failure != nil {
+		loadFailure = w.loadPayloadStatus.Failure.Error()
+	}
+	return fmt.Sprintf("generation=%d done=%d/%d completed=%d reconciling=%t initial=%t version=%q image=%q failure=%q loadPayloadStep=%q loadPayloadFailure=%q",
+		w.Generation, w.Done, w.Total, w.Completed, w.Reconciling, w.Initial,
+		w.Actual.Version, w.Actual.Image, failure,
+		w.loadPayloadStatus.Step, loadFailure)
+}
+
 // SyncWorker retrieves and applies the desired image, tracking the status for the parent to
 // monitor. The worker accepts a desired state via Update() and works to keep that state in
 // sync. Once a particular image version is synced, it will be updated no more often than
@@ -712,7 +739,7 @@ func (w *SyncWorker) Start(ctx context.Context, maxWorkers int) {
 				defer cancelFn()
 
 				previousStatus := w.Status()
-				klog.V(2).Infof("Previous sync status: %#v", previousStatus)
+				klog.V(2).Infof("Previous sync status: %s", previousStatus)
 				return w.apply(ctx, work, maxWorkers, previousStatus)
 			}()
 			if err != nil {
@@ -914,13 +941,13 @@ func (w *SyncWorker) updateApplyStatus(update SyncWorkerStatus) {
 	update.CapabilitiesStatus = w.status.CapabilitiesStatus
 	update.EnabledFeatureGates = w.status.EnabledFeatureGates.Clone()
 
-	klog.V(6).Infof("Payload apply status change %#v", update)
+	klog.V(6).Infof("Payload apply status change %s", update)
 	w.status = update
 	select {
 	case w.report <- update:
 	default:
 		if klog.V(6).Enabled() {
-			klog.Infof("Status report channel was full %#v", update)
+			klog.Infof("Status report channel was full %s", update)
 		}
 	}
 }
@@ -942,13 +969,13 @@ func (w *SyncWorker) updateLoadStatus(update SyncWorkerStatus) {
 	update.VersionHash = w.status.VersionHash
 	update.LastProgress = w.status.LastProgress
 
-	klog.V(6).Infof("Payload load status change %#v", update)
+	klog.V(6).Infof("Payload load status change %s", update)
 	w.status = update
 	select {
 	case w.report <- update:
 	default:
 		if klog.V(6).Enabled() {
-			klog.Infof("Status report channel was full %#v", update)
+			klog.Infof("Status report channel was full %s", update)
 		}
 	}
 }

pkg/cvo/sync_worker_status_string_test.go

@@ -0,0 +1,107 @@
+package cvo
+
+import (
+	"fmt"
+	"regexp"
+	"strings"
+	"testing"
+
+	configv1 "github.com/openshift/api/config/v1"
+
+	"github.com/openshift/cluster-version-operator/pkg/payload"
+)
+
+func TestSyncWorkerStatus_String(t *testing.T) {
+	hexAddr := regexp.MustCompile(`0x[0-9a-fA-F]+`)
+
+	t.Run("nil failures", func(t *testing.T) {
+		got := SyncWorkerStatus{}.String()
+		if strings.Contains(got, "0x") && hexAddr.MatchString(got) {
+			t.Fatalf("zero-value String() should not dump pointer addresses: %s", got)
+		}
+		if !strings.Contains(got, `failure="<none>"`) {
+			t.Fatalf("expected nil Failure as <none>: %s", got)
+		}
+		if !strings.Contains(got, `loadPayloadFailure="<none>"`) {
+			t.Fatalf("expected nil loadPayload Failure as <none>: %s", got)
+		}
+	})
+
+	t.Run("apply sync failure", func(t *testing.T) {
+		msg := `Could not update deployment "openshift-cluster-version/cluster-version-operator" (33 of 33): timed out waiting for the condition`
+		status := SyncWorkerStatus{
+			Generation:  4,
+			Failure:     &payload.UpdateError{Reason: "UpdatePayloadResourceFailed", Message: msg},
+			Done:        3,
+			Total:       33,
+			Completed:   0,
+			Reconciling: false,
+			Initial:     true,
+			Actual: configv1.Release{
+				Version: "4.14.0-0.nightly-2023-05-28-215458",
+				Image:   "registry.ci.openshift.org/ocp/release@sha256:abc",
+			},
+			loadPayloadStatus: LoadPayloadStatus{Step: "PayloadLoaded"},
+		}
+		got := status.String()
+		if !strings.Contains(got, "Could not update deployment") || !strings.Contains(got, "timed out waiting for the condition") {
+			t.Fatalf("missing apply failure message:\n%s", got)
+		}
+		if !strings.Contains(got, `generation=4`) || !strings.Contains(got, `done=3/33`) {
+			t.Fatalf("missing scalar fields:\n%s", got)
+		}
+		if !strings.Contains(got, `loadPayloadStep="PayloadLoaded"`) {
+			t.Fatalf("missing loadPayloadStep:\n%s", got)
+		}
+		if hexAddr.MatchString(got) {
+			t.Fatalf("String() must not contain pointer addresses:\n%s", got)
+		}
+		// Contrast with %#v, which is the old buggy log format.
+		bad := fmt.Sprintf("%#v", &status)
+		if !strings.Contains(bad, "(*payload.UpdateError)") {
+			t.Fatalf("test assumption failed: %%#v should still dump UpdateError as a pointer:\n%s", bad)
+		}
+	})
+
+	t.Run("payload load failure", func(t *testing.T) {
+		loadMsg := `Retrieving payload failed version="4.14.0" image="img" failure=no such host`
+		status := SyncWorkerStatus{
+			Generation: 5,
+			Failure:    nil,
+			Actual:     configv1.Release{Version: "4.14.0", Image: "img"},
+			loadPayloadStatus: LoadPayloadStatus{
+				Step:    "RetrievePayload",
+				Message: loadMsg,
+				Failure: fmt.Errorf("%s", loadMsg),
+			},
+		}
+		got := status.String()
+		if !strings.Contains(got, `failure="<none>"`) {
+			t.Fatalf("expected apply Failure <none>:\n%s", got)
+		}
+		if !strings.Contains(got, `loadPayloadStep="RetrievePayload"`) {
+			t.Fatalf("missing loadPayloadStep:\n%s", got)
+		}
+		if !strings.Contains(got, `loadPayloadFailure="`) || !strings.Contains(got, "Retrieving payload failed") || !strings.Contains(got, "no such host") {
+			t.Fatalf("missing loadPayloadFailure text:\n%s", got)
+		}
+		if hexAddr.MatchString(got) {
+			t.Fatalf("String() must not contain pointer addresses:\n%s", got)
+		}
+	})
+}
+
+func TestLoadPayloadStatus_String(t *testing.T) {
+	got := LoadPayloadStatus{
+		Step:    "VerifyPayloadVersion",
+		Message: "verifying",
+		Failure: fmt.Errorf("version mismatch"),
+	}.String()
+	wantSub := `step="VerifyPayloadVersion" message="verifying" failure="version mismatch"`
+	if got != wantSub {
+		t.Fatalf("got %q, want %q", got, wantSub)
+	}
+	if (LoadPayloadStatus{}).String() != `step="" message="" failure="<none>"` {
+		t.Fatalf("unexpected zero value: %s", (LoadPayloadStatus{}).String())
+	}
+}