From aa78e6ff29fe708170b210059d706736a7f4565c Mon Sep 17 00:00:00 2001 From: Raimund Sacherer Date: Wed, 12 Aug 2026 16:17:00 +0200 Subject: [PATCH] OCPBUGS-35210: prevent KCM from deleting SA-token secrets created before their SA MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit SA-token Secrets included in an operator bundle are placed earlier in the InstallPlan step list than the synthesized ServiceAccount step. OLM creates the Secret before the SA exists; the Kubernetes token controller (KCM) immediately deletes any token secret whose referenced ServiceAccount is absent, and OLM then marks the step as Created permanently — preventing any future retry and leaving the operator without its token secret. The issue is not always reproduceable (see test document) because a rescheduled loop run is able to get the stale RV, which still does not see the Secret as created, but the prior loop created the SA so this time the Secret will not be deleted. Fix: add a StepperFunc for BundleSecretKind (mirroring the existing CRD StepperFunc pattern). The new NewBundleSecretStep checks whether the SA referenced by the secret already exists before attempting creation: - SA absent → return WaitingForAPI; NeedsRequeue() returns true, keeping phase=Installing and triggering a 5-second requeue. - SA present → create the secret with correct owner refs (live API UID lookup, matching getUpdatedOwnerReferences behaviour) and return Created/Present. Because the StepperFunc handles WaitingForAPI internally it never reaches the main ExecutePlan switch case that would otherwise skip the step, so no changes to the switch statement or to NeedsRequeue() are required. Also adds structured debug logging to syncInstallPlans (plan resourceVersion, per-step BS/SA status at reconcile start, UpdateStatus call/result) to make the race observable in OLM pod logs during investigation. Most likely the additional logging will be removed via further commits. Tested: 30-iteration statistical reproducer against OCP 4.17 — 0/30 bug fires with the fix (without the fix we are looking at roughly 60% failure/40% Success). This PR is still a draft and work in progress. --- .../cmd/catalog/start.go | 10 ++ .../controller/operators/catalog/operator.go | 92 ++++++++++++++++- .../pkg/controller/operators/catalog/step.go | 99 ++++++++++++++++++- .../pkg/controller/registry/resolver/steps.go | 2 + .../cmd/catalog/start.go | 10 ++ .../controller/operators/catalog/operator.go | 92 ++++++++++++++++- .../pkg/controller/operators/catalog/step.go | 99 ++++++++++++++++++- .../pkg/controller/registry/resolver/steps.go | 2 + 8 files changed, 396 insertions(+), 10 deletions(-) diff --git a/staging/operator-lifecycle-manager/cmd/catalog/start.go b/staging/operator-lifecycle-manager/cmd/catalog/start.go index 7161131880..bef8144093 100644 --- a/staging/operator-lifecycle-manager/cmd/catalog/start.go +++ b/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()) diff --git a/staging/operator-lifecycle-manager/pkg/controller/operators/catalog/operator.go b/staging/operator-lifecycle-manager/pkg/controller/operators/catalog/operator.go index a8e3677446..d2c4b56848 100644 --- a/staging/operator-lifecycle-manager/pkg/controller/operators/catalog/operator.go +++ b/staging/operator-lifecycle-manager/pkg/controller/operators/catalog/operator.go @@ -2100,6 +2100,23 @@ 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 @@ -2107,6 +2124,9 @@ func (o *Operator) syncInstallPlans(obj interface{}) (syncError error) { // 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. diff --git a/staging/operator-lifecycle-manager/pkg/controller/operators/catalog/step.go b/staging/operator-lifecycle-manager/pkg/controller/operators/catalog/step.go index e2afbde78c..728a242196 100644 --- a/staging/operator-lifecycle-manager/pkg/controller/operators/catalog/step.go +++ b/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 + } +} diff --git a/staging/operator-lifecycle-manager/pkg/controller/registry/resolver/steps.go b/staging/operator-lifecycle-manager/pkg/controller/registry/resolver/steps.go index dbe3be8534..9d2f0acd43 100644 --- a/staging/operator-lifecycle-manager/pkg/controller/registry/resolver/steps.go +++ b/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{} diff --git a/vendor/github.com/operator-framework/operator-lifecycle-manager/cmd/catalog/start.go b/vendor/github.com/operator-framework/operator-lifecycle-manager/cmd/catalog/start.go index 7161131880..bef8144093 100644 --- a/vendor/github.com/operator-framework/operator-lifecycle-manager/cmd/catalog/start.go +++ b/vendor/github.com/operator-framework/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()) diff --git a/vendor/github.com/operator-framework/operator-lifecycle-manager/pkg/controller/operators/catalog/operator.go b/vendor/github.com/operator-framework/operator-lifecycle-manager/pkg/controller/operators/catalog/operator.go index a8e3677446..d2c4b56848 100644 --- a/vendor/github.com/operator-framework/operator-lifecycle-manager/pkg/controller/operators/catalog/operator.go +++ b/vendor/github.com/operator-framework/operator-lifecycle-manager/pkg/controller/operators/catalog/operator.go @@ -2100,6 +2100,23 @@ 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 @@ -2107,6 +2124,9 @@ func (o *Operator) syncInstallPlans(obj interface{}) (syncError error) { // 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. diff --git a/vendor/github.com/operator-framework/operator-lifecycle-manager/pkg/controller/operators/catalog/step.go b/vendor/github.com/operator-framework/operator-lifecycle-manager/pkg/controller/operators/catalog/step.go index e2afbde78c..728a242196 100644 --- a/vendor/github.com/operator-framework/operator-lifecycle-manager/pkg/controller/operators/catalog/step.go +++ b/vendor/github.com/operator-framework/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 + } +} diff --git a/vendor/github.com/operator-framework/operator-lifecycle-manager/pkg/controller/registry/resolver/steps.go b/vendor/github.com/operator-framework/operator-lifecycle-manager/pkg/controller/registry/resolver/steps.go index dbe3be8534..9d2f0acd43 100644 --- a/vendor/github.com/operator-framework/operator-lifecycle-manager/pkg/controller/registry/resolver/steps.go +++ b/vendor/github.com/operator-framework/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{}