WIP: OCPBUGS-35210: prevent KCM from deleting SA-token secrets created before their SA

cmd/catalog/start.go

@@ -49,6 +49,16 @@ func newRootCmd() *cobra.Command {
 			if o.debug {
 				logger.SetLevel(logrus.DebugLevel)
 			}
+			// OCPBUGS-35210: use millisecond timestamps so OLM and audit log
+			// entries can be correlated at sub-second precision.
+			// Set on both the local logger AND the global package logger so that
+			// code using logrus.WithFields() directly also emits milliseconds.
+			msFormatter := &logrus.TextFormatter{
+				TimestampFormat: "2006-01-02T15:04:05.000Z07:00",
+				FullTimestamp:   true,
+			}
+			logger.SetFormatter(msFormatter)
+			logrus.SetFormatter(msFormatter)
 			logger.Infof("log level %s", logger.Level)
 
 			ctx, cancel := context.WithCancel(signals.Context())

pkg/controller/operators/catalog/operator.go

@@ -2100,13 +2100,33 @@ func (o *Operator) syncInstallPlans(obj interface{}) (syncError error) {
 
 	logger.Info("syncing")
 
+	// OCPBUGS-35210: log the step statuses this reconcile sees at start.
+	// Proves whether this loop received a stale cached plan (NotPresent) or
+	// the post-UpdateStatus version (Created) for the BundleSecret step.
+	if len(plan.Status.Plan) > 0 {
+		for i, step := range plan.Status.Plan {
+			if step.Resource.Kind == "BundleSecret" || step.Resource.Kind == "ServiceAccount" {
+				logger.WithFields(logrus.Fields{
+					"resourceVersion": plan.ResourceVersion,
+					"stepIndex":       i,
+					"kind":            step.Resource.Kind,
+					"name":            step.Resource.Name,
+					"status":          step.Status,
+				}).Debug("installplan step status at reconcile start")
+			}
+		}
+	}
+
 	if len(plan.Status.Plan) == 0 && len(plan.Status.BundleLookups) == 0 {
 		logger.Info("skip processing installplan without status - subscription sync responsible for initial status")
 		return
 	}
 
 	// Complete and Failed are terminal phases
 	if plan.Status.Phase == v1alpha1.InstallPlanPhaseFailed || plan.Status.Phase == v1alpha1.InstallPlanPhaseComplete {
+		// OCPBUGS-35210: log so we can confirm terminal-phase early exit in the timeline.
+		// Loops that see phase=Complete exit here without executing any steps.
+		logger.WithField("phase", plan.Status.Phase).Debug("phase is terminal, skipping execution")
 		return
 	}
 
@@ -2169,8 +2189,29 @@ func (o *Operator) syncInstallPlans(obj interface{}) (syncError error) {
 
 	defer o.requeueSubscriptionForInstallPlan(plan, logger)
 
+	// OCPBUGS-35210: log what step statuses are being persisted and the
+	// resourceVersion. A concurrent reconcile that reads before this write
+	// will have an older resourceVersion and see different step statuses.
+	{
+		fields := logrus.Fields{
+			"resourceVersion": outInstallPlan.ResourceVersion,
+			"phase":           outInstallPlan.Status.Phase,
+		}
+		if syncError != nil {
+			fields["syncError"] = syncError.Error()
+		}
+		for i, step := range outInstallPlan.Status.Plan {
+			if step.Resource.Kind == "BundleSecret" || step.Resource.Kind == "ServiceAccount" {
+				fields[fmt.Sprintf("step[%d].%s", i, step.Resource.Kind)] = string(step.Status)
+			}
+		}
+		logger.WithFields(fields).Debug("calling UpdateStatus")
+	}
+
 	// Update InstallPlan with status of transition. Log errors if we can't write them to the status.
-	if _, err := o.client.OperatorsV1alpha1().InstallPlans(plan.GetNamespace()).UpdateStatus(context.TODO(), outInstallPlan, metav1.UpdateOptions{}); err != nil {
+	if updatedPlan, err := o.client.OperatorsV1alpha1().InstallPlans(plan.GetNamespace()).UpdateStatus(context.TODO(), outInstallPlan, metav1.UpdateOptions{}); err != nil {
+		// OCPBUGS-35210: a 409 here means step statuses were NOT persisted.
+		// A concurrent reconcile that already read NotPresent will re-execute the BundleSecret step.
 		logger = logger.WithField("updateError", err.Error())
 		updateErr := errors.New("error updating InstallPlan status: " + err.Error())
 		if syncError == nil {
@@ -2179,6 +2220,13 @@ func (o *Operator) syncInstallPlans(obj interface{}) (syncError error) {
 		}
 		logger.Info("error transitioning InstallPlan")
 		syncError = fmt.Errorf("error transitioning InstallPlan: %s and error updating InstallPlan status: %s", syncError, updateErr)
+	} else {
+		// OCPBUGS-35210: log the new resourceVersion after a successful write.
+		// Any reconcile loop that read a lower resourceVersion saw stale data.
+		logger.WithFields(logrus.Fields{
+			"newResourceVersion": updatedPlan.ResourceVersion,
+			"phase":              updatedPlan.Status.Phase,
+		}).Debug("UpdateStatus succeeded")
 	}
 
 	return
@@ -2474,9 +2522,10 @@ func (o *Operator) ExecutePlan(plan *v1alpha1.InstallPlan) error {
 		o.logger.Errorf("failed to get a client for plan execution- %v", err)
 		return err
 	}
-	b := newBuilder(plan, o.lister.OperatorsV1alpha1().ClusterServiceVersionLister(), builderKubeClient, builderDynamicClient, r, o.logger, o.recorder)
+	b := newBuilder(plan, o.lister.OperatorsV1alpha1().ClusterServiceVersionLister(), builderKubeClient, kubeclient, crclient, builderDynamicClient, r, o.logger, o.recorder)
 
 	for i, step := range plan.Status.Plan {
+		beforeStatus := plan.Status.Plan[i].Status
 		if err := func(i int, step *v1alpha1.Step) error {
 			wr.PopWarnings()
 			defer func() {
@@ -2521,14 +2570,25 @@ func (o *Operator) ExecutePlan(plan *v1alpha1.InstallPlan) error {
 			}
 
 			switch step.Status {
-			case v1alpha1.StepStatusPresent, v1alpha1.StepStatusCreated, v1alpha1.StepStatusWaitingForAPI:
+			case v1alpha1.StepStatusPresent, v1alpha1.StepStatusCreated:
+				// OCPBUGS-35210: log skipped steps so we can confirm which reconcile
+				// loop sees Created (and skips) vs NotPresent (and re-executes).
+				if step.Resource.Kind == "BundleSecret" || step.Resource.Kind == "ServiceAccount" {
+					o.logger.WithFields(logrus.Fields{
+						"kind":   step.Resource.Kind,
+						"name":   step.Resource.Name,
+						"status": step.Status,
+					}).Debug("skipping step — already Created/Present")
+				}
+				return nil
+			case v1alpha1.StepStatusWaitingForAPI:
 				return nil
 			case v1alpha1.StepStatusUnknown, v1alpha1.StepStatusNotPresent:
 				manifest, err := r.ManifestForStep(step)
 				if err != nil {
 					return err
 				}
-				o.logger.WithFields(logrus.Fields{"kind": step.Resource.Kind, "name": step.Resource.Name}).Debug("execute resource")
+				o.logger.WithFields(logrus.Fields{"kind": step.Resource.Kind, "name": step.Resource.Name, "stepIndex": i}).Debug("execute resource")
 				switch step.Resource.Kind {
 				case v1alpha1.ClusterServiceVersionKind:
 					// Marshal the manifest into a CSV instance.
@@ -2596,40 +2656,6 @@ func (o *Operator) ExecutePlan(plan *v1alpha1.InstallPlan) error {
 
 					plan.Status.Plan[i].Status = status
 
-				case resolver.BundleSecretKind:
-					var s corev1.Secret
-					err := json.Unmarshal([]byte(manifest), &s)
-					if err != nil {
-						return errorwrap.Wrapf(err, "error parsing step manifest: %s", step.Resource.Name)
-					}
-
-					// add ownerrefs on the secret that point to the CSV in the bundle
-					if step.Resolving != "" {
-						owner := &v1alpha1.ClusterServiceVersion{}
-						owner.SetNamespace(plan.GetNamespace())
-						owner.SetName(step.Resolving)
-						ownerutil.AddNonBlockingOwner(&s, owner)
-					}
-
-					// Update UIDs on all CSV OwnerReferences
-					updated, err := o.getUpdatedOwnerReferences(s.OwnerReferences, plan.Namespace)
-					if err != nil {
-						return errorwrap.Wrapf(err, "error generating ownerrefs for secret %s", s.GetName())
-					}
-					s.SetOwnerReferences(updated)
-					s.SetNamespace(namespace)
-					if s.Labels == nil {
-						s.Labels = map[string]string{}
-					}
-					s.Labels[install.OLMManagedLabelKey] = install.OLMManagedLabelValue
-
-					status, err := ensurer.EnsureBundleSecret(plan.Namespace, &s)
-					if err != nil {
-						return err
-					}
-
-					plan.Status.Plan[i].Status = status
-
 				case secretKind:
 					status, err := ensurer.EnsureSecret(o.namespace, plan.GetNamespace(), step.Resource.Name)
 					if err != nil {
@@ -2915,8 +2941,40 @@ func (o *Operator) ExecutePlan(plan *v1alpha1.InstallPlan) error {
 					return notFoundErr
 				}
 			}
+			// OCPBUGS-35210: log the step that caused ExecutePlan to fail.
+			// This error becomes syncError in syncInstallPlans and appears in the
+			// UpdateStatus WRITE log — it is NOT a UpdateStatus error itself.
+			o.logger.WithFields(logrus.Fields{
+				"kind":      step.Resource.Kind,
+				"name":      step.Resource.Name,
+				"stepIndex": i,
+				"error":     err.Error(),
+			}).Debug("step execution failed — ExecutePlan returning error")
 			return err
 		}
+		// OCPBUGS-35210: log each step's outcome. Distinguish between steps that
+		// were actually executed (status changed) and steps that were skipped
+		// because they were already in a terminal state (status unchanged).
+		afterStatus := plan.Status.Plan[i].Status
+		if afterStatus == beforeStatus {
+			msg := "step execution made no progress"
+			if afterStatus == v1alpha1.StepStatusCreated || afterStatus == v1alpha1.StepStatusPresent {
+				msg = "step skipped — already in terminal state"
+			}
+			o.logger.WithFields(logrus.Fields{
+				"kind":      step.Resource.Kind,
+				"name":      step.Resource.Name,
+				"stepIndex": i,
+				"status":    afterStatus,
+			}).Debug(msg)
+		} else {
+			o.logger.WithFields(logrus.Fields{
+				"kind":      step.Resource.Kind,
+				"name":      step.Resource.Name,
+				"stepIndex": i,
+				"result":    afterStatus,
+			}).Debug("step execution result")
+		}
 	}
 
 	// Loop over one final time to check and see if everything is good.

pkg/controller/operators/catalog/step.go

@@ -2,9 +2,11 @@ package catalog
 
 import (
 	"context"
+	"encoding/json"
 	"fmt"
 
 	"github.com/operator-framework/operator-lifecycle-manager/pkg/controller/install"
+	"github.com/operator-framework/operator-lifecycle-manager/pkg/controller/registry/resolver"
 	"github.com/pkg/errors"
 	"github.com/sirupsen/logrus"
 	corev1 "k8s.io/api/core/v1"
@@ -19,10 +21,12 @@ import (
 	"k8s.io/client-go/util/retry"
 
 	"github.com/operator-framework/api/pkg/operators/v1alpha1"
+	"github.com/operator-framework/operator-lifecycle-manager/pkg/api/client/clientset/versioned"
 	listersv1alpha1 "github.com/operator-framework/operator-lifecycle-manager/pkg/api/client/listers/operators/v1alpha1"
 	"github.com/operator-framework/operator-lifecycle-manager/pkg/controller/operators/internal/alongside"
 	crdlib "github.com/operator-framework/operator-lifecycle-manager/pkg/lib/crd"
 	"github.com/operator-framework/operator-lifecycle-manager/pkg/lib/operatorclient"
+	"github.com/operator-framework/operator-lifecycle-manager/pkg/lib/ownerutil"
 )
 
 // Stepper manages cluster interactions based on the step.
@@ -43,6 +47,8 @@ type builder struct {
 	plan             *v1alpha1.InstallPlan
 	csvLister        listersv1alpha1.ClusterServiceVersionLister
 	opclient         operatorclient.ClientInterface
+	attenuatedClient operatorclient.ClientInterface
+	olmClient        versioned.Interface
 	dynamicClient    dynamic.Interface
 	manifestResolver ManifestResolver
 	logger           logrus.FieldLogger
@@ -51,11 +57,13 @@ type builder struct {
 	annotator alongside.Annotator
 }
 
-func newBuilder(plan *v1alpha1.InstallPlan, csvLister listersv1alpha1.ClusterServiceVersionLister, opclient operatorclient.ClientInterface, dynamicClient dynamic.Interface, manifestResolver ManifestResolver, logger logrus.FieldLogger, er record.EventRecorder) *builder {
+func newBuilder(plan *v1alpha1.InstallPlan, csvLister listersv1alpha1.ClusterServiceVersionLister, opclient operatorclient.ClientInterface, attenuatedClient operatorclient.ClientInterface, olmClient versioned.Interface, dynamicClient dynamic.Interface, manifestResolver ManifestResolver, logger logrus.FieldLogger, er record.EventRecorder) *builder {
 	return &builder{
 		plan:             plan,
 		csvLister:        csvLister,
 		opclient:         opclient,
+		attenuatedClient: attenuatedClient,
+		olmClient:        olmClient,
 		dynamicClient:    dynamicClient,
 		manifestResolver: manifestResolver,
 		logger:           logger,
@@ -91,6 +99,8 @@ func (b *builder) create(step v1alpha1.Step) (Stepper, error) {
 		case crdlib.V1Beta1Version:
 			return b.NewCRDV1Beta1Step(b.opclient.ApiextensionsInterface().ApiextensionsV1beta1(), &step, manifest), nil
 		}
+	case resolver.BundleSecretKind:
+		return b.NewBundleSecretStep(&step, manifest), nil
 	}
 	return nil, notSupportedStepperErr{fmt.Sprintf("stepper interface does not support %s", step.Resource.Kind)}
 }
@@ -318,3 +328,95 @@ func setInstalledAlongsideAnnotation(a alongside.Annotator, dst metav1.Object, n
 
 	a.ToObject(dst, nns)
 }
+
+// NewBundleSecretStep returns a StepperFunc for BundleSecret steps (OCPBUGS-35210 Fix 2).
+//
+// SA-token Secrets must not be created before their owning ServiceAccount exists — the
+// Kubernetes token controller (KCM) immediately deletes orphaned token secrets, and
+// EnsureBundleSecret would mark the step Created permanently, preventing any retry.
+//
+// This StepperFunc returns WaitingForAPI when the SA is absent so that NeedsRequeue()
+// keeps phase=Installing and OLM retries after 5 s. On the retry the SA has been
+// created (it appears later in the plan), and the secret is created successfully.
+// WaitingForAPI in the StepperFunc path is handled here directly — it never reaches
+// the main ExecutePlan switch that would otherwise skip the step.
+func (b *builder) NewBundleSecretStep(step *v1alpha1.Step, manifest string) StepperFunc {
+	return func() (v1alpha1.StepStatus, error) {
+		switch step.Status {
+		case v1alpha1.StepStatusPresent, v1alpha1.StepStatusCreated:
+			return step.Status, nil
+		}
+
+		namespace := b.plan.GetNamespace()
+
+		var s corev1.Secret
+		if err := json.Unmarshal([]byte(manifest), &s); err != nil {
+			return v1alpha1.StepStatusUnknown, err
+		}
+
+		saName := s.Annotations[corev1.ServiceAccountNameKey]
+		if s.Type == corev1.SecretTypeServiceAccountToken && saName != "" {
+			_, saErr := b.attenuatedClient.KubernetesInterface().CoreV1().
+				ServiceAccounts(namespace).Get(context.TODO(), saName, metav1.GetOptions{})
+			if apierrors.IsNotFound(saErr) {
+				logrus.WithFields(logrus.Fields{
+					"secret": s.Name,
+					"sa":     saName,
+				}).Info("BundleSecretStep: SA not yet created — returning WaitingForAPI (OCPBUGS-35210)")
+				return v1alpha1.StepStatusWaitingForAPI, nil
+			}
+			// Forbidden means the scoped client lacks get on serviceaccounts; proceed
+			// and attempt secret creation — KCM will gate on SA existence regardless.
+			if saErr != nil && !apierrors.IsForbidden(saErr) {
+				return v1alpha1.StepStatusUnknown, saErr
+			}
+		}
+
+		s.SetNamespace(namespace)
+		if s.Labels == nil {
+			s.Labels = map[string]string{}
+		}
+		s.Labels[install.OLMManagedLabelKey] = install.OLMManagedLabelValue
+
+		// Add the resolving CSV as a non-blocking owner so the secret is GC'd on
+		// uninstall. Use the lister (catalog-operator credentials, avoids extra API
+		// call) — UID is stable once set so a briefly-stale lister entry is safe.
+		if step.Resolving != "" {
+			csv, err := b.csvLister.ClusterServiceVersions(namespace).Get(step.Resolving)
+			if err != nil {
+				return v1alpha1.StepStatusUnknown, fmt.Errorf("error getting csv %s for secret owner ref: %w", step.Resolving, err)
+			}
+			ownerutil.AddNonBlockingOwner(&s, csv)
+		}
+
+		// Refresh UIDs on any pre-existing CSV owner refs shipped in the bundle
+		// manifest so Kubernetes GC can match them on uninstall.
+		updated, err := refreshCSVOwnerRefUIDs(s.OwnerReferences, b.olmClient, namespace)
+		if err != nil {
+			return v1alpha1.StepStatusUnknown, fmt.Errorf("error refreshing owner references for secret %s: %w", s.GetName(), err)
+		}
+		s.SetOwnerReferences(updated)
+
+		return createOrUpdateSecret(b.attenuatedClient, namespace, &s)
+	}
+}
+
+// refreshCSVOwnerRefUIDs populates the UID field on any CSV-kind owner references
+// using a live API call, matching the behaviour of getUpdatedOwnerReferences used
+// by the old BundleSecret handler. A live call (not the lister) is used so that
+// freshly-created CSVs whose UIDs have not yet synced to the informer cache are
+// handled correctly.
+func refreshCSVOwnerRefUIDs(refs []metav1.OwnerReference, olmClient versioned.Interface, namespace string) ([]metav1.OwnerReference, error) {
+	updated := append([]metav1.OwnerReference(nil), refs...)
+	for i, owner := range refs {
+		if owner.Kind == v1alpha1.ClusterServiceVersionKind {
+			csv, err := olmClient.OperatorsV1alpha1().ClusterServiceVersions(namespace).Get(context.TODO(), owner.Name, metav1.GetOptions{})
+			if err != nil {
+				return nil, err
+			}
+			owner.UID = csv.GetUID()
+			updated[i] = owner
+		}
+	}
+	return updated, nil
+}