Patch Subscription status when CSV is unreferenced

In some situations when actions are happening quickly, OLM can lose the
connection between the Subscription and the ClusterServiceVersion, which
leads to a "constraints not satisfiable" condition on the Subscription.
It can be hard to reproduce the exact situation we've seen rarely in our
tests, but manually deleting and immediately recreating the subscription
causes a similar situation.

In this change, in those situations, the controller will intervene after
30 seconds by updating the Subscription status directly. The
implementation allows for a 10 second window for the intervention,
during which the controller may update the status multiple times, to
address a case where OLM immediately overwrote the update. If the window
is missed, the controller may schedule another time. This is intended to
give time to OLM to potentially resolve the situation on its own.

Refs:
 - https://issues.redhat.com/browse/ACM-11453

Signed-off-by: Justin Kulikauskas <jkulikau@redhat.com>

api/v1beta1/operatorpolicy_types.go

@@ -5,6 +5,7 @@ package v1beta1
 
 import (
 	"strings"
+	"time"
 
 	metav1 "k8s.io/apimachinery/pkg/apis/meta/v1"
 	"k8s.io/apimachinery/pkg/runtime"
@@ -209,6 +210,12 @@ type OperatorPolicyStatus struct {
 	// The list of overlapping OperatorPolicies (as name.namespace) which all manage the same
 	// subscription, including this policy. When no overlapping is detected, this list will be empty.
 	OverlappingPolicies []string `json:"overlappingPolicies,omitempty"`
+
+	// Timestamp for a possible intervention to help a Subscription stuck with a
+	// ConstraintsNotSatisfiable condition. Can be in the future, indicating the
+	// policy is waiting for OLM to resolve the situation. If in the recent past,
+	// the policy may update the status of the Subscription.
+	SubscriptionInterventionTime *metav1.Time `json:"subscriptionInterventionTime,omitempty"`
 }
 
 // RelatedObjsOfKind iterates over the related objects in the status and returns a map of the index
@@ -238,6 +245,25 @@ func (status OperatorPolicyStatus) GetCondition(condType string) (int, metav1.Co
 	return -1, metav1.Condition{}
 }
 
+// Returns true if the SubscriptionInterventionTime is far enough in the past
+// to be considered expired, and therefore should be removed from the status.
+func (status OperatorPolicyStatus) SubscriptionInterventionExpired() bool {
+	if status.SubscriptionInterventionTime == nil {
+		return false
+	}
+
+	return status.SubscriptionInterventionTime.Time.Before(time.Now().Add(-10 * time.Second))
+}
+
+// Returns true if the SubscriptionInterventionTime is in the future.
+func (status OperatorPolicyStatus) SubscriptionInterventionWaiting() bool {
+	if status.SubscriptionInterventionTime == nil {
+		return false
+	}
+
+	return status.SubscriptionInterventionTime.Time.After(time.Now())
+}
+
 // OperatorPolicy is the schema for the operatorpolicies API. You can use the operator policy to
 // manage operators by providing automation for their management and reporting on the status across
 // the various operator objects.

controllers/operatorpolicy_controller.go

@@ -14,6 +14,7 @@ import (
 	"slices"
 	"strconv"
 	"strings"
+	"time"
 
 	operatorv1 "github.com/operator-framework/api/pkg/operators/v1"
 	operatorv1alpha1 "github.com/operator-framework/api/pkg/operators/v1alpha1"
@@ -46,6 +47,7 @@ import (
 const (
 	OperatorControllerName string = "operator-policy-controller"
 	CatalogSourceReady     string = "READY"
+	olmGracePeriod                = 30 * time.Second
 )
 
 var (
@@ -94,7 +96,8 @@ var (
 		Version:  "v1",
 		Resource: "packagemanifests",
 	}
-	ErrPackageManifest = errors.New("")
+	ErrPackageManifest   = errors.New("")
+	unreferencedCSVRegex = regexp.MustCompile(`clusterserviceversion (\S*) exists and is not referenced`)
 )
 
 // OperatorPolicyReconciler reconciles a OperatorPolicy object
@@ -191,6 +194,8 @@ func (r *OperatorPolicyReconciler) Reconcile(ctx context.Context, req ctrl.Reque
 		return reconcile.Result{}, err
 	}
 
+	originalStatus := *policy.Status.DeepCopy()
+
 	// Start query batch for caching and watching related objects
 	err = r.DynamicWatcher.StartQueryBatch(watcher)
 	if err != nil {
@@ -216,14 +221,16 @@ func (r *OperatorPolicyReconciler) Reconcile(ctx context.Context, req ctrl.Reque
 		errs = append(errs, err)
 	}
 
+	if conditionChanged || !reflect.DeepEqual(policy.Status, originalStatus) {
+		if err := r.Status().Update(ctx, policy); err != nil {
+			errs = append(errs, err)
+		}
+	}
+
 	if conditionChanged {
 		// Add an event for the "final" state of the policy, otherwise this only has the
 		// "early" events (and possibly has zero events).
 		conditionsToEmit = append(conditionsToEmit, calculateComplianceCondition(policy))
-
-		if err := r.Status().Update(ctx, policy); err != nil {
-			errs = append(errs, err)
-		}
 	}
 
 	for _, cond := range conditionsToEmit {
@@ -235,6 +242,14 @@ func (r *OperatorPolicyReconciler) Reconcile(ctx context.Context, req ctrl.Reque
 	result := reconcile.Result{}
 	finalErr := utilerrors.NewAggregate(errs)
 
+	if len(errs) == 0 {
+		// Schedule a requeue for the intervention.
+		// Note: this requeue will be superseded if the Subscription's status is flapping.
+		if policy.Status.SubscriptionInterventionWaiting() {
+			result.RequeueAfter = time.Until(policy.Status.SubscriptionInterventionTime.Add(time.Second))
+		}
+	}
+
 	opLog.Info("Reconciling complete", "finalErr", finalErr,
 		"conditionChanged", conditionChanged, "eventCount", len(conditionsToEmit))
 
@@ -1082,6 +1097,8 @@ func (r *OperatorPolicyReconciler) musthaveSubscription(
 	ogCorrect bool,
 ) (*operatorv1alpha1.Subscription, []metav1.Condition, bool, error) {
 	if foundSub == nil {
+		policy.Status.SubscriptionInterventionTime = nil
+
 		// Missing Subscription: report NonCompliance
 		changed := updateStatus(policy, missingWantedCond("Subscription"), missingWantedObj(desiredSub))
 
@@ -1135,12 +1152,18 @@ func (r *OperatorPolicyReconciler) musthaveSubscription(
 		subResFailed := mergedSub.Status.GetCondition(operatorv1alpha1.SubscriptionResolutionFailed)
 
 		if subResFailed.Status == corev1.ConditionTrue {
-			return r.considerResolutionFailed(ctx, policy, foundSub, mergedSub)
+			return r.considerResolutionFailed(ctx, policy, mergedSub)
+		}
+
+		if policy.Status.SubscriptionInterventionExpired() {
+			policy.Status.SubscriptionInterventionTime = nil
 		}
 
 		return mergedSub, nil, updateStatus(policy, matchesCond("Subscription"), matchedObj(foundSub)), nil
 	}
 
+	policy.Status.SubscriptionInterventionTime = nil
+
 	// Specs don't match.
 	if policy.Spec.RemediationAction.IsEnforce() && skipUpdate {
 		changed := updateStatus(policy, mismatchCondUnfixable("Subscription"), mismatchedObj(foundSub))
@@ -1179,7 +1202,6 @@ func (r *OperatorPolicyReconciler) musthaveSubscription(
 func (r *OperatorPolicyReconciler) considerResolutionFailed(
 	ctx context.Context,
 	policy *policyv1beta1.OperatorPolicy,
-	foundSub *unstructured.Unstructured,
 	mergedSub *operatorv1alpha1.Subscription,
 ) (*operatorv1alpha1.Subscription, []metav1.Condition, bool, error) {
 	opLog := ctrl.LoggerFrom(ctx)
@@ -1198,22 +1220,104 @@ func (r *OperatorPolicyReconciler) considerResolutionFailed(
 	}
 
 	if !includesSubscription {
+		if policy.Status.SubscriptionInterventionExpired() {
+			policy.Status.SubscriptionInterventionTime = nil
+		}
+
 		return mergedSub, nil, false, nil
 	}
 
 	// Handle non-ConstraintsNotSatisfiable reasons separately
 	if !strings.EqualFold(subResFailed.Reason, "ConstraintsNotSatisfiable") {
-		changed := updateStatus(policy, subResFailedCond(subResFailed), nonCompObj(foundSub, subResFailed.Reason))
+		changed := updateStatus(policy, subResFailedCond(subResFailed), nonCompObj(mergedSub, subResFailed.Reason))
+
+		if policy.Status.SubscriptionInterventionExpired() {
+			policy.Status.SubscriptionInterventionTime = nil
+		}
 
 		return mergedSub, nil, changed, nil
 	}
 
 	// A "constraints not satisfiable" message has nondeterministic clauses, and can be noisy with a list of versions.
 	// Just report a generic condition, which will prevent the OperatorPolicy status from constantly updating
 	// when the details in the Subscription status change.
-	changed := updateStatus(policy, subConstraintsNotSatisfiableCond, nonCompObj(foundSub, "ConstraintsNotSatisfiable"))
+	changed := updateStatus(policy, subConstraintsNotSatisfiableCond,
+		nonCompObj(mergedSub, "ConstraintsNotSatisfiable"))
+
+	unrefCSVMatches := unreferencedCSVRegex.FindStringSubmatch(subResFailed.Message)
+	if len(unrefCSVMatches) < 2 {
+		opLog.V(1).Info("Subscription condition does not match pattern for an unreferenced CSV",
+			"subscriptionConditionMessage", subResFailed.Message)
+
+		if policy.Status.SubscriptionInterventionExpired() {
+			policy.Status.SubscriptionInterventionTime = nil
+		}
+
+		return mergedSub, nil, changed, nil
+	}
+
+	if policy.Status.SubscriptionInterventionExpired() || policy.Status.SubscriptionInterventionTime == nil {
+		interventionTime := metav1.Time{Time: time.Now().Add(olmGracePeriod)}
+		policy.Status.SubscriptionInterventionTime = &interventionTime
+
+		opLog.V(1).Info("Detected ConstraintsNotSatisfiable, setting an intervention time",
+			"interventionTime", interventionTime, "subscription", mergedSub)
+
+		return mergedSub, nil, changed, nil
+	}
+
+	if policy.Status.SubscriptionInterventionWaiting() {
+		opLog.V(1).Info("Detected ConstraintsNotSatisfiable, giving OLM more time before possibly intervening",
+			"interventionTime", policy.Status.SubscriptionInterventionTime)
+
+		return mergedSub, nil, changed, nil
+	}
+
+	// Do the "intervention"
+
+	watcher := opPolIdentifier(policy.Namespace, policy.Name)
+
+	existingCSV, err := r.DynamicWatcher.Get(watcher, clusterServiceVersionGVK, mergedSub.Namespace, unrefCSVMatches[1])
+	if err != nil {
+		return mergedSub, nil, changed, fmt.Errorf("error getting the existing CSV in the subscription status: %w", err)
+	}
+
+	if existingCSV == nil {
+		opLog.Info("The CSV mentioned in the subscription status could not be found, not intervening",
+			"subscriptionConditionMessage", subResFailed.Message, "csvName", unrefCSVMatches[1])
+
+		return mergedSub, nil, changed, nil
+	}
+
+	// This check is based on the olm check, but does not require fully unmarshalling the csv.
+	reason, found, err := unstructured.NestedString(existingCSV.Object, "status", "reason")
+	hasReasonCopied := found && err == nil && reason == string(operatorv1alpha1.CSVReasonCopied)
 
-	return mergedSub, nil, changed, nil
+	if hasReasonCopied || operatorv1alpha1.IsCopied(existingCSV) {
+		opLog.Info("The CSV mentioned in the subscription status is a copy, not intervening",
+			"subscriptionConditionMessage", subResFailed.Message, "csvName", unrefCSVMatches[1])
+
+		return mergedSub, nil, changed, nil
+	}
+
+	if mergedSub.Status.LastUpdated.IsZero() {
+		mergedSub.Status.LastUpdated = metav1.Now()
+	}
+
+	mergedSub.Status.CurrentCSV = existingCSV.GetName()
+
+	opLog.Info("Updating Subscription status to point to CSV", "csvName", existingCSV.GetName())
+
+	if err := r.TargetClient.Status().Update(ctx, mergedSub); err != nil {
+		return mergedSub, nil, changed,
+			fmt.Errorf("error updating the Subscription status to point to the CSV: %w", err)
+	}
+
+	mergedSub.SetGroupVersionKind(subscriptionGVK) // Update might strip this information
+
+	updateStatus(policy, updatedCond("Subscription"), updatedObj(mergedSub))
+
+	return mergedSub, nil, true, nil
 }
 
 func (r *OperatorPolicyReconciler) mustnothaveSubscription(
@@ -1222,6 +1326,8 @@ func (r *OperatorPolicyReconciler) mustnothaveSubscription(
 	desiredSub *operatorv1alpha1.Subscription,
 	foundUnstructSub *unstructured.Unstructured,
 ) (*operatorv1alpha1.Subscription, []metav1.Condition, bool, error) {
+	policy.Status.SubscriptionInterventionTime = nil
+
 	if foundUnstructSub == nil {
 		// Missing Subscription: report Compliance
 		changed := updateStatus(policy, missingNotWantedCond("Subscription"), missingNotWantedObj(desiredSub))
@@ -1526,18 +1632,23 @@ func (r *OperatorPolicyReconciler) handleCSV(
 
 	var foundCSV *operatorv1alpha1.ClusterServiceVersion
 
+	relatedCSVs := make([]policyv1.RelatedObject, 0)
+
 	for _, csv := range csvList {
-		if csv.GetName() == sub.Status.InstalledCSV {
+		// If the subscription does not know about the CSV, this can report multiple CSVs as related
+		if sub.Status.InstalledCSV == "" || sub.Status.InstalledCSV == csv.GetName() {
 			matchedCSV := operatorv1alpha1.ClusterServiceVersion{}
 
 			err = runtime.DefaultUnstructuredConverter.FromUnstructured(csv.UnstructuredContent(), &matchedCSV)
 			if err != nil {
 				return nil, nil, false, err
 			}
 
-			foundCSV = &matchedCSV
+			relatedCSVs = append(relatedCSVs, existingCSVObj(&matchedCSV))
 
-			break
+			if sub.Status.InstalledCSV == csv.GetName() {
+				foundCSV = &matchedCSV
+			}
 		}
 	}
 
@@ -1549,13 +1660,14 @@ func (r *OperatorPolicyReconciler) handleCSV(
 
 	// CSV has not yet been created by OLM
 	if foundCSV == nil {
-		changed := updateStatus(policy,
-			missingWantedCond("ClusterServiceVersion"), missingCSVObj(sub.Name, sub.Namespace))
+		if len(relatedCSVs) == 0 {
+			relatedCSVs = append(relatedCSVs, missingCSVObj(sub.Name, sub.Namespace))
+		}
 
-		return foundCSV, nil, changed, nil
+		return foundCSV, nil, updateStatus(policy, missingWantedCond("ClusterServiceVersion"), relatedCSVs...), nil
 	}
 
-	return foundCSV, nil, updateStatus(policy, buildCSVCond(foundCSV), existingCSVObj(foundCSV)), nil
+	return foundCSV, nil, updateStatus(policy, buildCSVCond(foundCSV), relatedCSVs...), nil
 }
 
 func (r *OperatorPolicyReconciler) mustnothaveCSV(

deploy/crds/kustomize_operatorpolicy/policy.open-cluster-management.io_operatorpolicies.yaml

@@ -379,6 +379,14 @@ spec:
               resolvedSubscriptionLabel:
                 description: The resolved name.namespace of the subscription
                 type: string
+              subscriptionInterventionTime:
+                description: |-
+                  Timestamp for a possible intervention to help a Subscription stuck with a
+                  ConstraintsNotSatisfiable condition. Can be in the future, indicating the
+                  policy is waiting for OLM to resolve the situation. If in the recent past,
+                  the policy may update the status of the Subscription.
+                format: date-time
+                type: string
             type: object
         type: object
     served: true

deploy/crds/policy.open-cluster-management.io_operatorpolicies.yaml

@@ -369,6 +369,14 @@ spec:
               resolvedSubscriptionLabel:
                 description: The resolved name.namespace of the subscription
                 type: string
+              subscriptionInterventionTime:
+                description: |-
+                  Timestamp for a possible intervention to help a Subscription stuck with a
+                  ConstraintsNotSatisfiable condition. Can be in the future, indicating the
+                  policy is waiting for OLM to resolve the situation. If in the recent past,
+                  the policy may update the status of the Subscription.
+                format: date-time
+                type: string
             type: object
         type: object
     served: true