OCPBUGS-23514: Failing=Unknown upon long CO updating

When it takes too long (90m+ for machine-config and 30m+ for
others) to upgrade a cluster operator, clusterversion shows
a message with the indication that the upgrade might hit
some issue.

This will cover the case in the related OCPBUGS-23538: for some
reason, the pod under the deployment that manages the CO hit
CrashLoopBackOff. Deployment controller does not give useful
conditions in this situation [1]. Otherwise, checkDeploymentHealth [2]
would detect it.

Instead of CVO's figuring out the underlying pod's
CrashLoopBackOff which might be better to be implemented by
deployment controller, it is expected that our cluster admin
starts to dig into the cluster when such a message pops up.

In addition to the condition's message. We propagate Fail=Unknown
to make it available for other automations, such as update-status
command.

[1]. kubernetes/kubernetes#106054

[2]. https://github.com/openshift/cluster-version-operator/blob/08c0459df5096e9f16fad3af2831b62d06d415ee/lib/resourcebuilder/apps.go#L79-L136

Author: hongkailiu

Diff for: pkg/cvo/status.go

@@ -327,6 +327,14 @@ func updateClusterVersionStatus(cvStatus *configv1.ClusterVersionStatus, status
 		failingCondition.Reason = failingReason
 		failingCondition.Message = failingMessage
 	}
+	if failure != nil &&
+		skipFailure &&
+		progressReason == "ClusterOperatorUpdating" &&
+		strings.Contains(progressMessage, "longer than expected") {
+		failingCondition.Status = configv1.ConditionUnknown
+		failingCondition.Reason = "SlowClusterOperator"
+		failingCondition.Message = progressMessage
+	}
 	resourcemerge.SetOperatorStatusCondition(&cvStatus.Conditions, failingCondition)
 
 	// update progressing
@@ -555,6 +563,16 @@ func convertErrorToProgressing(now time.Time, statusFailure error) (reason strin
 	case payload.UpdateEffectReport:
 		return uErr.Reason, uErr.Error(), false
 	case payload.UpdateEffectNone:
+		m := time.Duration(30)
+		// It takes longer to upgrade MCO
+		if uErr.Name == "machine-config" {
+			m = 3 * m
+		}
+		t := payload.COUpdateStartTimesGet(uErr.Name)
+		if (!t.IsZero()) && t.Before(now.Add(-(m * time.Minute))) {
+			// returns true because it is still only a suspicion
+			return uErr.Reason, fmt.Sprintf("waiting on %s over %d minutes which is longer than expected", uErr.Name, m), true
+		}
 		return uErr.Reason, fmt.Sprintf("waiting on %s", uErr.Name), true
 	case payload.UpdateEffectFail:
 		return "", "", false

Diff for: pkg/cvo/status_test.go

@@ -5,6 +5,7 @@ import (
 	"fmt"
 	"reflect"
 	"testing"
+	"time"
 
 	"github.com/google/go-cmp/cmp"
 	"github.com/google/go-cmp/cmp/cmpopts"
@@ -358,12 +359,22 @@ func TestUpdateClusterVersionStatus_FilteringMultipleErrorsForFailingCondition(t
 	type args struct {
 		syncWorkerStatus *SyncWorkerStatus
 	}
+	payload.COUpdateStartTimesEnsure("co-not-timeout")
+	payload.COUpdateStartTimesAt("co-timeout", time.Now().Add(-60*time.Minute))
+	payload.COUpdateStartTimesAt("machine-config", time.Now().Add(-60*time.Minute))
+	defer func() {
+		payload.COUpdateStartTimesRemove("co-not-timeout")
+		payload.COUpdateStartTimesRemove("co-timeout")
+		payload.COUpdateStartTimesRemove("machine-config")
+	}()
+
 	tests := []struct {
 		name                                             string
 		args                                             args
 		shouldModifyWhenNotReconcilingAndHistoryNotEmpty bool
 		expectedConditionNotModified                     *configv1.ClusterOperatorStatusCondition
 		expectedConditionModified                        *configv1.ClusterOperatorStatusCondition
+		expectedProgressingCondition                     *configv1.ClusterOperatorStatusCondition
 	}{
 		{
 			name: "no errors are present",
@@ -394,10 +405,12 @@ func TestUpdateClusterVersionStatus_FilteringMultipleErrorsForFailingCondition(t
 			name: "single UpdateEffectNone error",
 			args: args{
 				syncWorkerStatus: &SyncWorkerStatus{
+					Actual: configv1.Release{Version: "1.2.3"},
 					Failure: &payload.UpdateError{
 						UpdateEffect: payload.UpdateEffectNone,
 						Reason:       "ClusterOperatorUpdating",
 						Message:      "Cluster operator A is updating",
+						Name:         "co-not-timeout",
 					},
 				},
 			},
@@ -412,6 +425,76 @@ func TestUpdateClusterVersionStatus_FilteringMultipleErrorsForFailingCondition(t
 				Type:   ClusterStatusFailing,
 				Status: configv1.ConditionFalse,
 			},
+			expectedProgressingCondition: &configv1.ClusterOperatorStatusCondition{
+				Type:    configv1.OperatorProgressing,
+				Status:  configv1.ConditionTrue,
+				Reason:  "ClusterOperatorUpdating",
+				Message: "Working towards 1.2.3: waiting on co-not-timeout",
+			},
+		},
+		{
+			name: "single UpdateEffectNone error and timeout",
+			args: args{
+				syncWorkerStatus: &SyncWorkerStatus{
+					Actual: configv1.Release{Version: "1.2.3"},
+					Failure: &payload.UpdateError{
+						UpdateEffect: payload.UpdateEffectNone,
+						Reason:       "ClusterOperatorUpdating",
+						Message:      "Cluster operator A is updating",
+						Name:         "co-timeout",
+					},
+				},
+			},
+			expectedConditionNotModified: &configv1.ClusterOperatorStatusCondition{
+				Type:    ClusterStatusFailing,
+				Status:  configv1.ConditionTrue,
+				Reason:  "ClusterOperatorUpdating",
+				Message: "Cluster operator A is updating",
+			},
+			shouldModifyWhenNotReconcilingAndHistoryNotEmpty: true,
+			expectedConditionModified: &configv1.ClusterOperatorStatusCondition{
+				Type:    ClusterStatusFailing,
+				Status:  configv1.ConditionUnknown,
+				Reason:  "SlowClusterOperator",
+				Message: "waiting on co-timeout over 30 minutes which is longer than expected",
+			},
+			expectedProgressingCondition: &configv1.ClusterOperatorStatusCondition{
+				Type:    configv1.OperatorProgressing,
+				Status:  configv1.ConditionTrue,
+				Reason:  "ClusterOperatorUpdating",
+				Message: "Working towards 1.2.3: waiting on co-timeout over 30 minutes which is longer than expected",
+			},
+		},
+		{
+			name: "single UpdateEffectNone error and machine-config",
+			args: args{
+				syncWorkerStatus: &SyncWorkerStatus{
+					Actual: configv1.Release{Version: "1.2.3"},
+					Failure: &payload.UpdateError{
+						UpdateEffect: payload.UpdateEffectNone,
+						Reason:       "ClusterOperatorUpdating",
+						Message:      "Cluster operator A is updating",
+						Name:         "machine-config",
+					},
+				},
+			},
+			expectedConditionNotModified: &configv1.ClusterOperatorStatusCondition{
+				Type:    ClusterStatusFailing,
+				Status:  configv1.ConditionTrue,
+				Reason:  "ClusterOperatorUpdating",
+				Message: "Cluster operator A is updating",
+			},
+			shouldModifyWhenNotReconcilingAndHistoryNotEmpty: true,
+			expectedConditionModified: &configv1.ClusterOperatorStatusCondition{
+				Type:   ClusterStatusFailing,
+				Status: configv1.ConditionFalse,
+			},
+			expectedProgressingCondition: &configv1.ClusterOperatorStatusCondition{
+				Type:    configv1.OperatorProgressing,
+				Status:  configv1.ConditionTrue,
+				Reason:  "ClusterOperatorUpdating",
+				Message: "Working towards 1.2.3: waiting on machine-config",
+			},
 		},
 		{
 			name: "single condensed UpdateEffectFail UpdateError",
@@ -621,6 +704,13 @@ func TestUpdateClusterVersionStatus_FilteringMultipleErrorsForFailingCondition(t
 				if diff := cmp.Diff(expectedCondition, condition, ignoreLastTransitionTime); diff != "" {
 					t.Errorf("unexpected condition when Reconciling == %t && isHistoryEmpty == %t\n:%s", c.isReconciling, c.isHistoryEmpty, diff)
 				}
+
+				if tc.expectedProgressingCondition != nil && !c.isReconciling && !c.isHistoryEmpty {
+					progressingCondition := resourcemerge.FindOperatorStatusCondition(cvStatus.Conditions, configv1.OperatorProgressing)
+					if diff := cmp.Diff(tc.expectedProgressingCondition, progressingCondition, ignoreLastTransitionTime); diff != "" {
+						t.Errorf("unexpected progressingCondition when Reconciling == %t && isHistoryEmpty == %t\n:%s", c.isReconciling, c.isHistoryEmpty, diff)
+					}
+				}
 			}
 		})
 	}

Diff for: pkg/payload/task.go

@@ -47,9 +47,15 @@ func InitCOUpdateStartTimes() {
 // COUpdateStartTimesEnsure adds name to clusterOperatorUpdateStartTimes map and sets to
 // current time if name does not already exist in map.
 func COUpdateStartTimesEnsure(name string) {
+	COUpdateStartTimesAt(name, time.Now())
+}
+
+// COUpdateStartTimesAt adds name to clusterOperatorUpdateStartTimes map and sets to
+// t if name does not already exist in map.
+func COUpdateStartTimesAt(name string, t time.Time) {
 	clusterOperatorUpdateStartTimes.lock.Lock()
 	if _, ok := clusterOperatorUpdateStartTimes.m[name]; !ok {
-		clusterOperatorUpdateStartTimes.m[name] = time.Now()
+		clusterOperatorUpdateStartTimes.m[name] = t
 	}
 	clusterOperatorUpdateStartTimes.lock.Unlock()
 }