diff --git a/pkg/cvo/status.go b/pkg/cvo/status.go index d81358c672..8167d4ce47 100644 --- a/pkg/cvo/status.go +++ b/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 diff --git a/pkg/cvo/sync_worker.go b/pkg/cvo/sync_worker.go index 036682d211..c3c6862712 100644 --- a/pkg/cvo/sync_worker.go +++ b/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 := "" + 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 © } +// 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 := "" + if w.Failure != nil { + failure = w.Failure.Error() + } + loadFailure := "" + 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) } } } diff --git a/pkg/cvo/sync_worker_status_string_test.go b/pkg/cvo/sync_worker_status_string_test.go new file mode 100644 index 0000000000..7baad3998d --- /dev/null +++ b/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=""`) { + t.Fatalf("expected nil Failure as : %s", got) + } + if !strings.Contains(got, `loadPayloadFailure=""`) { + t.Fatalf("expected nil loadPayload Failure as : %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=""`) { + t.Fatalf("expected apply Failure :\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=""` { + t.Fatalf("unexpected zero value: %s", (LoadPayloadStatus{}).String()) + } +}