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{}