Set Progressing to Succeeded on ClusterExtensionRevision only after availability probes pass (#2524)

Previously, `Progressing` reason was set to `Succeeded` as soon as the rollout
transition completed, not taking into account availability probes of the last phase.
This meant setting `.spec.progressDeadlineMinutes` could not catch workloads that were
applied to the cluster but never became available, due to for example bad image reference.

Now `Progressing` stays at `RollingOut` during transition and is only set to
`Succeeded` once probes confirm availability, allowing the progress deadline
to correctly expire when a workload fails to become available in time.

Author: pedjak

internal/operator-controller/controllers/clusterextensionrevision_controller.go

@@ -8,7 +8,6 @@ import (
 	"errors"
 	"fmt"
 	"strings"
-	"sync"
 	"time"
 
 	appsv1 "k8s.io/api/apps/v1"
@@ -20,6 +19,7 @@ import (
 	"k8s.io/apimachinery/pkg/runtime/schema"
 	"k8s.io/apimachinery/pkg/types"
 	"k8s.io/apimachinery/pkg/util/sets"
+	"k8s.io/utils/clock"
 	"pkg.package-operator.run/boxcutter"
 	"pkg.package-operator.run/boxcutter/machinery"
 	machinerytypes "pkg.package-operator.run/boxcutter/machinery/types"
@@ -48,9 +48,7 @@ type ClusterExtensionRevisionReconciler struct {
 	Client                client.Client
 	RevisionEngineFactory RevisionEngineFactory
 	TrackingCache         trackingCache
-	// track if we have queued up the reconciliation that detects eventual progress deadline issues
-	// keys is revision UUID, value is boolean
-	progressDeadlineCheckInFlight sync.Map
+	Clock                 clock.Clock
 }
 
 type trackingCache interface {
@@ -86,15 +84,19 @@ func (c *ClusterExtensionRevisionReconciler) Reconcile(ctx context.Context, req
 		// check if we reached the progress deadline only if the revision is still progressing and has not succeeded yet
 		if isStillProgressing && !succeeded {
 			timeout := time.Duration(pd) * time.Minute
-			if time.Since(existingRev.CreationTimestamp.Time) > timeout {
+			if c.Clock.Since(existingRev.CreationTimestamp.Time) > timeout {
 				// progress deadline reached, reset any errors and stop reconciling this revision
-				markAsNotProgressing(reconciledRev, ocv1.ReasonProgressDeadlineExceeded, fmt.Sprintf("Revision has not rolled out for %d minutes.", pd))
+				markAsNotProgressing(reconciledRev, ocv1.ReasonProgressDeadlineExceeded, fmt.Sprintf("Revision has not rolled out for %d minute(s).", pd))
 				reconcileErr = nil
 				res = ctrl.Result{}
-			} else if _, found := c.progressDeadlineCheckInFlight.Load(existingRev.GetUID()); !found && reconcileErr == nil {
-				// if we haven't already queued up a reconcile to check for progress deadline, queue one up, but only once
-				c.progressDeadlineCheckInFlight.Store(existingRev.GetUID(), true)
-				res = ctrl.Result{RequeueAfter: timeout}
+			} else if reconcileErr == nil {
+				// We want to requeue so far in the future that the next reconciliation
+				// can detect if the revision did not progress within the given timeout.
+				// Thus, we plan the next reconcile slightly after (+2secs) the timeout is passed.
+				drift := 2 * time.Second
+				requeueAfter := existingRev.CreationTimestamp.Time.Add(timeout).Add(drift).Sub(c.Clock.Now()).Round(time.Second)
+				l.Info(fmt.Sprintf("ProgressDeadline not exceeded, requeue after ~%v to check again.", requeueAfter))
+				res = ctrl.Result{RequeueAfter: requeueAfter}
 			}
 		}
 	}
@@ -208,9 +210,7 @@ func (c *ClusterExtensionRevisionReconciler) reconcile(ctx context.Context, cer
 	}
 
 	revVersion := cer.GetAnnotations()[labels.BundleVersionKey]
-	if !rres.InTransition() {
-		markAsProgressing(cer, ocv1.ReasonSucceeded, fmt.Sprintf("Revision %s has rolled out.", revVersion))
-	} else {
+	if rres.InTransition() {
 		markAsProgressing(cer, ocv1.ReasonRollingOut, fmt.Sprintf("Revision %s is rolling out.", revVersion))
 	}
 
@@ -231,6 +231,7 @@ func (c *ClusterExtensionRevisionReconciler) reconcile(ctx context.Context, cer
 			}
 		}
 
+		markAsProgressing(cer, ocv1.ReasonSucceeded, fmt.Sprintf("Revision %s has rolled out.", revVersion))
 		markAsAvailable(cer, ocv1.ClusterExtensionRevisionReasonProbesSucceeded, "Objects are available and pass all probes.")
 
 		// We'll probably only want to remove this once we are done updating the ClusterExtension conditions
@@ -275,6 +276,9 @@ func (c *ClusterExtensionRevisionReconciler) reconcile(ctx context.Context, cer
 		} else {
 			markAsUnavailable(cer, ocv1.ReasonRollingOut, fmt.Sprintf("Revision %s is rolling out.", revVersion))
 		}
+		if meta.FindStatusCondition(cer.Status.Conditions, ocv1.ClusterExtensionRevisionTypeProgressing) == nil {
+			markAsProgressing(cer, ocv1.ReasonRollingOut, fmt.Sprintf("Revision %s is rolling out.", revVersion))
+		}
 	}
 
 	return ctrl.Result{}, nil
@@ -333,6 +337,7 @@ func (c *ClusterExtensionRevisionReconciler) SetupWithManager(mgr ctrl.Manager)
 			return true
 		},
 	}
+	c.Clock = clock.RealClock{}
 	return ctrl.NewControllerManagedBy(mgr).
 		For(
 			&ocv1.ClusterExtensionRevision{},

internal/operator-controller/controllers/clusterextensionrevision_controller_test.go

@@ -16,6 +16,8 @@ import (
 	"k8s.io/apimachinery/pkg/runtime/schema"
 	"k8s.io/apimachinery/pkg/types"
 	"k8s.io/apimachinery/pkg/util/sets"
+	"k8s.io/utils/clock"
+	clocktesting "k8s.io/utils/clock/testing"
 	"pkg.package-operator.run/boxcutter"
 	"pkg.package-operator.run/boxcutter/machinery"
 	machinerytypes "pkg.package-operator.run/boxcutter/machinery/types"
@@ -372,6 +374,7 @@ func Test_ClusterExtensionRevisionReconciler_Reconcile_RevisionReconciliation(t
 			name: "set Progressing:True:Succeeded once transition rollout is finished",
 			revisionResult: mockRevisionResult{
 				inTransition: false,
+				isComplete:   true,
 			},
 			reconcilingRevisionName: clusterExtensionRevisionName,
 			existingObjs: func() []client.Object {
@@ -380,7 +383,7 @@ func Test_ClusterExtensionRevisionReconciler_Reconcile_RevisionReconciliation(t
 				meta.SetStatusCondition(&rev1.Status.Conditions, metav1.Condition{
 					Type:               ocv1.TypeProgressing,
 					Status:             metav1.ConditionTrue,
-					Reason:             ocv1.ReasonSucceeded,
+					Reason:             ocv1.ReasonRollingOut,
 					Message:            "Revision 1.0.0 is rolling out.",
 					ObservedGeneration: 1,
 				})
@@ -945,16 +948,19 @@ func Test_ClusterExtensionRevisionReconciler_Reconcile_ProgressDeadline(t *testi
 		validate        func(*testing.T, client.Client)
 		reconcileErr    error
 		reconcileResult ctrl.Result
+		clock           clock.Clock
 	}{
 		{
 			name: "progressing set to false when progress deadline is exceeded",
 			existingObjs: func() []client.Object {
 				ext := newTestClusterExtension()
 				rev1 := newTestClusterExtensionRevision(t, clusterExtensionRevisionName, ext, testScheme)
 				rev1.Spec.ProgressDeadlineMinutes = 1
-				rev1.CreationTimestamp = metav1.NewTime(time.Now().Add(-61 * time.Second))
+				rev1.CreationTimestamp = metav1.NewTime(time.Date(2022, 1, 1, 0, 0, 0, 0, time.UTC))
 				return []client.Object{rev1, ext}
 			},
+			// 61sec elapsed since the creation of the revision
+			clock: clocktesting.NewFakeClock(time.Date(2022, 1, 1, 0, 1, 1, 0, time.UTC)),
 			revisionResult: &mockRevisionResult{
 				inTransition: true,
 			},
@@ -975,13 +981,14 @@ func Test_ClusterExtensionRevisionReconciler_Reconcile_ProgressDeadline(t *testi
 				ext := newTestClusterExtension()
 				rev1 := newTestClusterExtensionRevision(t, clusterExtensionRevisionName, ext, testScheme)
 				rev1.Spec.ProgressDeadlineMinutes = 1
-				rev1.CreationTimestamp = metav1.NewTime(time.Now())
+				rev1.CreationTimestamp = metav1.NewTime(time.Date(2021, 1, 1, 0, 0, 0, 0, time.UTC))
 				return []client.Object{rev1, ext}
 			},
+			clock: clocktesting.NewFakeClock(time.Date(2021, 1, 1, 0, 0, 0, 0, time.UTC)),
 			revisionResult: &mockRevisionResult{
 				inTransition: true,
 			},
-			reconcileResult: ctrl.Result{RequeueAfter: 1 * time.Minute},
+			reconcileResult: ctrl.Result{RequeueAfter: 62 * time.Second},
 			validate: func(t *testing.T, c client.Client) {
 				rev := &ocv1.ClusterExtensionRevision{}
 				err := c.Get(t.Context(), client.ObjectKey{
@@ -1049,6 +1056,7 @@ func Test_ClusterExtensionRevisionReconciler_Reconcile_ProgressDeadline(t *testi
 				TrackingCache: &mockTrackingCache{
 					client: testClient,
 				},
+				Clock: tc.clock,
 			}).Reconcile(t.Context(), ctrl.Request{
 				NamespacedName: types.NamespacedName{
 					Name: clusterExtensionRevisionName,

test/e2e/features/install.feature

@@ -383,6 +383,39 @@ Feature: Install ClusterExtension
       invalid ClusterExtension configuration: invalid configuration: unknown field "watchNamespace"
       """
 
+  @BoxcutterRuntime
+  @ProgressDeadline
+  Scenario: Report ClusterExtension as not progressing if the rollout does not become available within given timeout
+    Given min value for ClusterExtension .spec.progressDeadlineMinutes is set to 1
+    And min value for ClusterExtensionRevision .spec.progressDeadlineMinutes is set to 1
+    When ClusterExtension is applied
+      """
+      apiVersion: olm.operatorframework.io/v1
+      kind: ClusterExtension
+      metadata:
+        name: ${NAME}
+      spec:
+        namespace: ${TEST_NAMESPACE}
+        progressDeadlineMinutes: 1
+        serviceAccount:
+          name: olm-sa
+        source:
+          sourceType: Catalog
+          catalog:
+            packageName: test
+            # bundle refers bad image references, so that the deployment never becomes available
+            version: 1.0.2
+            selector:
+              matchLabels:
+                "olm.operatorframework.io/metadata.name": test-catalog
+      """
+    Then ClusterExtensionRevision "${NAME}-1" reports Progressing as False with Reason ProgressDeadlineExceeded
+    And ClusterExtension reports Progressing as False with Reason ProgressDeadlineExceeded and Message:
+      """
+      Revision has not rolled out for 1 minute(s).
+      """
+    And ClusterExtension reports Progressing transition between 1 and 2 minutes since its creation
+
   @BoxcutterRuntime
   @ProgressDeadline
   Scenario: Report ClusterExtension as not progressing if the rollout does not complete within given timeout
@@ -411,7 +444,7 @@ Feature: Install ClusterExtension
     Then ClusterExtensionRevision "${NAME}-1" reports Progressing as False with Reason ProgressDeadlineExceeded
     And ClusterExtension reports Progressing as False with Reason ProgressDeadlineExceeded and Message:
       """
-      Revision has not rolled out for 1 minutes.
+      Revision has not rolled out for 1 minute(s).
       """
     And ClusterExtension reports Progressing transition between 1 and 2 minutes since its creation
 

test/e2e/features/update.feature

@@ -240,6 +240,6 @@ Feature: Update ClusterExtension
     And ClusterExtension is available
     When ClusterExtension is updated to version "1.0.2"
     Then ClusterExtension reports "${NAME}-1, ${NAME}-2" as active revisions
-    And ClusterExtensionRevision "${NAME}-2" reports Progressing as True with Reason Succeeded
+    And ClusterExtensionRevision "${NAME}-2" reports Progressing as True with Reason RollingOut
     And ClusterExtensionRevision "${NAME}-2" reports Available as False with Reason ProbeFailure