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

staging/operator-lifecycle-manager/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.000000Z07:00",
+				FullTimestamp:   true,
+			}
+			logger.SetFormatter(msFormatter)
+			logrus.SetFormatter(msFormatter)
 			logger.Infof("log level %s", logger.Level)
 
 			ctx, cancel := context.WithCancel(signals.Context())

staging/operator-lifecycle-manager/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,26 @@ 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,
+		}
+		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 +2217,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,7 +2519,7 @@ 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, o.client, builderDynamicClient, r, o.logger, o.recorder)
 
 	for i, step := range plan.Status.Plan {
 		if err := func(i int, step *v1alpha1.Step) error {
@@ -2521,14 +2566,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.
@@ -2623,6 +2679,17 @@ func (o *Operator) ExecutePlan(plan *v1alpha1.InstallPlan) error {
 					}
 					s.Labels[install.OLMManagedLabelKey] = install.OLMManagedLabelValue
 
+					// OCPBUGS-35210: log the plan resourceVersion at the moment of creation.
+					// This ties the secret creation to a specific plan version, letting us
+					// confirm whether a concurrent reconcile held a stale or current view.
+					o.logger.WithFields(logrus.Fields{
+						"secret":          s.Name,
+						"sa":              s.Annotations[corev1.ServiceAccountNameKey],
+						"planRV":          plan.ResourceVersion,
+						"stepIndex":       i,
+						"stepStatus":      step.Status,
+					}).Debug("ExecutePlan: creating BundleSecret (OCPBUGS-35210)")
+
 					status, err := ensurer.EnsureBundleSecret(plan.Namespace, &s)
 					if err != nil {
 						return err
@@ -2915,8 +2982,25 @@ 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 the result of each step so we can see exactly
+		// which steps ran and what status they reached in this reconcile loop.
+		o.logger.WithFields(logrus.Fields{
+			"kind":      step.Resource.Kind,
+			"name":      step.Resource.Name,
+			"stepIndex": i,
+			"result":    plan.Status.Plan[i].Status,
+		}).Debug("step execution result")
 	}
 
 	// Loop over one final time to check and see if everything is good.

staging/operator-lifecycle-manager/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,7 @@ type builder struct {
 	plan             *v1alpha1.InstallPlan
 	csvLister        listersv1alpha1.ClusterServiceVersionLister
 	opclient         operatorclient.ClientInterface
+	olmClient        versioned.Interface
 	dynamicClient    dynamic.Interface
 	manifestResolver ManifestResolver
 	logger           logrus.FieldLogger
@@ -51,11 +56,12 @@ 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, olmClient versioned.Interface, dynamicClient dynamic.Interface, manifestResolver ManifestResolver, logger logrus.FieldLogger, er record.EventRecorder) *builder {
 	return &builder{
 		plan:             plan,
 		csvLister:        csvLister,
 		opclient:         opclient,
+		olmClient:        olmClient,
 		dynamicClient:    dynamicClient,
 		manifestResolver: manifestResolver,
 		logger:           logger,
@@ -91,6 +97,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 +326,92 @@ 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.opclient.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
+			}
+			if saErr != nil {
+				return v1alpha1.StepStatusUnknown, saErr
+			}
+		}
+
+		s.SetNamespace(namespace)
+		if s.Labels == nil {
+			s.Labels = map[string]string{}
+		}
+		s.Labels[install.OLMManagedLabelKey] = install.OLMManagedLabelValue
+
+		// Mirror the original owner-ref logic from operator.go: add CSV owner ref
+		// with live API UID lookup (same as getUpdatedOwnerReferences) so the secret
+		// is GC'd when the operator is uninstalled.
+		if step.Resolving != "" {
+			owner := &v1alpha1.ClusterServiceVersion{}
+			owner.SetNamespace(namespace)
+			owner.SetName(step.Resolving)
+			ownerutil.AddNonBlockingOwner(&s, owner)
+			// Update the empty UID with the current CSV UID via live API call.
+			if csv, err := b.olmClient.OperatorsV1alpha1().
+				ClusterServiceVersions(namespace).Get(context.TODO(), step.Resolving, metav1.GetOptions{}); err == nil {
+				refs := s.GetOwnerReferences()
+				for i := range refs {
+					if refs[i].Kind == v1alpha1.ClusterServiceVersionKind && refs[i].Name == step.Resolving {
+						refs[i].UID = csv.GetUID()
+					}
+				}
+				s.SetOwnerReferences(refs)
+			} else if !apierrors.IsNotFound(err) {
+				return v1alpha1.StepStatusUnknown, err
+			} else {
+				// CSV not found — clear the empty-UID owner ref to avoid API rejection.
+				s.SetOwnerReferences(nil)
+			}
+		}
+
+		_, createErr := b.opclient.KubernetesInterface().CoreV1().
+			Secrets(namespace).Create(context.TODO(), &s, metav1.CreateOptions{})
+		if createErr == nil {
+			return v1alpha1.StepStatusCreated, nil
+		}
+		if apierrors.IsAlreadyExists(createErr) {
+			s.SetNamespace(namespace)
+			if _, updateErr := b.opclient.UpdateSecret(&s); updateErr != nil {
+				return v1alpha1.StepStatusUnknown, updateErr
+			}
+			return v1alpha1.StepStatusPresent, nil
+		}
+		return v1alpha1.StepStatusUnknown, createErr
+	}
+}

staging/operator-lifecycle-manager/pkg/controller/registry/resolver/steps.go

@@ -148,6 +148,8 @@ func NewStepResourceFromBundle(bundle *api.Bundle, namespace, replaces, catalogS
 	}
 	steps := []v1alpha1.StepResource{step}
 
+	// Original ordering: bundle objects first, then synthesized SA/RBAC last.
+	// This is the UNFIXED ordering that causes OCPBUGS-35210.
 	for _, object := range bundle.Object {
 		dec := yaml.NewYAMLOrJSONDecoder(strings.NewReader(object), 10)
 		unst := &unstructured.Unstructured{}