Failed to run bundle: install plan is not available for the subscription

[pohly]

Bug Report

What did you do?

• installed OLM with operator-sdk olm install
• tried to install an operator with operator-sdk run bundle

What did you expect to see?

The operator should start to run.

What did you see instead? Under which circumstances?

operator-sdk run bundle --namespace default --timeout 5m 172.17.42.1:5001/pmem-csi-bundle:v100.0.0 --skip-tls
time="2021-11-17T14:21:35+01:00" level=info msg="Successfully created registry pod: 172-17-42-1-5001-pmem-csi-bundle-v100-0-0"
time="2021-11-17T14:21:35+01:00" level=info msg="Created CatalogSource: pmem-csi-operator-catalog"
time="2021-11-17T14:21:35+01:00" level=info msg="OperatorGroup \"operator-sdk-og\" created"
time="2021-11-17T14:21:35+01:00" level=info msg="Created Subscription: pmem-csi-operator-v100-0-0-sub"
time="2021-11-17T14:26:27+01:00" level=fatal msg="Failed to run bundle: install plan is not available for the subscription pmem-csi-operator-v100-0-0-sub: timed out waiting for the condition\n"

This only happens with OLM 1.19.1. The same commands work when installing OLM 0.18.3 with operator-sdk olm install --version=v0.18.3.

Environment

• operator-lifecycle-manager version: v0.19.1
• operator-sdk: 1.13.1
• Kubernetes version information:

Client Version: version.Info{Major:"1", Minor:"20", GitVersion:"v1.20.2", GitCommit:"faecb196815e248d3ecfb03c680a4507229c2a56", GitTreeState:"clean", BuildDate:"2021-01-27T08:53:39Z", GoVersion:"go1.15.2", Compiler:"gc", Platform:"linux/amd64"}
Server Version: version.Info{Major:"1", Minor:"22", GitVersion:"v1.22.3", GitCommit:"c92036820499fedefec0f847e2054d824aea6cd1", GitTreeState:"clean", BuildDate:"2021-10-27T18:35:25Z", GoVersion:"go1.16.9", Compiler:"gc", Platform:"linux/amd64"}

• Kubernetes cluster kind: kubeadm on Fedora 34 running in VMs

Additional context

I encountered this in PMEM-CSI, tracked there as intel/pmem-csi#1050

More diagnostics:

$ kubectl describe --all-namespaces subscriptions
Name:         pmem-csi-operator-v100-0-0-sub
Namespace:    default
Labels:       operators.coreos.com/pmem-csi-operator.default=
Annotations:  <none>
API Version:  operators.coreos.com/v1alpha1
Kind:         Subscription
Metadata:
  Creation Timestamp:  2021-11-17T13:21:35Z
  Generation:          1
  Managed Fields:
    API Version:  operators.coreos.com/v1alpha1
    Fields Type:  FieldsV1
    fieldsV1:
      f:status:
        .:
        f:catalogHealth:
        f:conditions:
        f:lastUpdated:
    Manager:      catalog
    Operation:    Update
    Subresource:  status
    Time:         2021-11-17T13:21:35Z
    API Version:  operators.coreos.com/v1alpha1
    Fields Type:  FieldsV1
    fieldsV1:
      f:metadata:
        f:labels:
          .:
          f:operators.coreos.com/pmem-csi-operator.default:
    Manager:      olm
    Operation:    Update
    Time:         2021-11-17T13:21:35Z
    API Version:  operators.coreos.com/v1alpha1
    Fields Type:  FieldsV1
    fieldsV1:
      f:spec:
        .:
        f:channel:
        f:installPlanApproval:
        f:name:
        f:source:
        f:sourceNamespace:
        f:startingCSV:
    Manager:         operator-sdk
    Operation:       Update
    Time:            2021-11-17T13:21:35Z
  Resource Version:  21120
  UID:               d96c7834-6a74-4b6a-9f91-28e8841103f6
Spec:
  Channel:                alpha
  Install Plan Approval:  Manual
  Name:                   pmem-csi-operator
  Source:                 pmem-csi-operator-catalog
  Source Namespace:       default
  Starting CSV:           pmem-csi-operator.v100.0.0
Status:
  Catalog Health:
    Catalog Source Ref:
      API Version:       operators.coreos.com/v1alpha1
      Kind:              CatalogSource
      Name:              pmem-csi-operator-catalog
      Namespace:         default
      Resource Version:  21117
      UID:               f7422ba4-9ffb-43c0-b4dc-0a530a6c847f
    Healthy:             true
    Last Updated:        2021-11-17T13:21:36Z
    Catalog Source Ref:
      API Version:       operators.coreos.com/v1alpha1
      Kind:              CatalogSource
      Name:              operatorhubio-catalog
      Namespace:         olm
      Resource Version:  17519
      UID:               a8fb807c-b7b3-425f-bba6-4ef890b5c060
    Healthy:             true
    Last Updated:        2021-11-17T13:21:36Z
  Conditions:
    Last Transition Time:  2021-11-17T13:21:36Z
    Message:               all available catalogsources are healthy
    Reason:                AllCatalogSourcesHealthy
    Status:                False
    Type:                  CatalogSourcesUnhealthy
  Last Updated:            2021-11-17T13:21:36Z
Events:                    <none>

Note the odd "AllCatalogSourcesHealthy: False". This pod here might be responsible for it (not sure) and reports an error:

$ kubectl logs -n olm pods/catalog-operator-84976fd7df-x5tmr
...
E1117 13:21:35.798270       1 queueinformer_operator.go:290] sync {"update" "default/pmem-csi-operator-v100-0-0-sub"} failed: Operation cannot be fulfilled on subscriptions.operators.coreos.com "pmem-csi-operator-v100-0-0-sub": the object has been modified; please apply your changes to the latest version and try again
time="2021-11-17T13:21:35Z" level=info msg=syncing event=update reconciling="*v1alpha1.Subscription" selflink=
time="2021-11-17T13:21:35Z" level=info msg=syncing event=update reconciling="*v1alpha1.Subscription" selflink=
time="2021-11-17T13:21:36Z" level=warning msg="an error was encountered during reconciliation" error="Operation cannot be fulfilled on subscriptions.operators.coreos.com \"pmem-csi-operator-v100-0-0-sub\": the object has been modified; please apply your changes to the latest version and try again" event=update reconciling="*v1alpha1.Subscription" selflink=
...

This repeats a few times but then not anymore. Deleting that pod doesn't help, the recreated one has the same problem.

[pohly]

For comparison, here's the subscription when using OLM 0.18.1:

``` Spec: Channel: alpha Install Plan Approval: Manual Name: pmem-csi-operator Source: pmem-csi-operator-catalog Source Namespace: pmem-csi Starting CSV: pmem-csi-operator.v1.1.0 Status: Catalog Health: Catalog Source Ref: API Version: operators.coreos.com/v1alpha1 Kind: CatalogSource Name: operatorhubio-catalog Namespace: olm Resource Version: 6982 UID: 690eea06-7304-4e48-ac8e-106af540a9e5 Healthy: true Last Updated: 2021-11-19T13:08:56Z Catalog Source Ref: API Version: operators.coreos.com/v1alpha1 Kind: CatalogSource Name: pmem-csi-operator-catalog Namespace: pmem-csi Resource Version: 7093 UID: 8107f14f-accd-48eb-842f-e905a4865ba6 Healthy: true Last Updated: 2021-11-19T13:08:56Z Conditions: Last Transition Time: 2021-11-19T13:08:56Z Message: all available catalogsources are healthy Reason: AllCatalogSourcesHealthy Status: False Type: CatalogSourcesUnhealthy Last Transition Time: 2021-11-19T13:08:55Z Reason: RequiresApproval Status: True Type: InstallPlanPending Current CSV: pmem-csi-operator.v1.1.0 Install Plan Generation: 1 Install Plan Ref: API Version: operators.coreos.com/v1alpha1 Kind: InstallPlan Name: install-br4hc Namespace: pmem-csi Resource Version: 7078 UID: 4e1fa4fe-6819-43fb-89c4-3a447f5b6867 Installed CSV: pmem-csi-operator.v1.1.0 Installplan: API Version: operators.coreos.com/v1alpha1 Kind: InstallPlan Name: install-br4hc Uuid: 4e1fa4fe-6819-43fb-89c4-3a447f5b6867 Last Updated: 2021-11-19T13:08:59Z State: AtLatestKnown ```

And the log:

``` time="2021-11-19T13:08:52Z" level=warning msg="an error was encountered during reconciliation" error="Operation cannot be fulfilled on subscriptions.operators.coreos.com \"pmem-csi-operator-v1-1-0-sub\": the object has been modified; please apply your changes to the latest version and try again" event=update reconciling="*v1alpha1.Subscription" selflink= E1119 13:08:52.045924 1 queueinformer_operator.go:290] sync {"update" "pmem-csi/pmem-csi-operator-v1-1-0-sub"} failed: Operation cannot be fulfilled on subscriptions.operators.coreos.com "pmem-csi-operator-v1-1-0-sub": the object has been modified; please apply your changes to the latest version and try again time="2021-11-19T13:08:52Z" level=info msg=syncing event=update reconciling="*v1alpha1.Subscription" selflink= time="2021-11-19T13:08:52Z" level=info msg=syncing id=5NYPJ ip=install-kmp2g namespace=pmem-csi phase=RequiresApproval time="2021-11-19T13:08:52Z" level=info msg=syncing id=bTVM3 ip=install-kmp2g namespace=pmem-csi phase=RequiresApproval time="2021-11-19T13:08:52Z" level=warning msg="status not equal, updating..." id=bTVM3 ip=install-kmp2g namespace=pmem-csi phase=RequiresApproval time="2021-11-19T13:08:52Z" level=info msg=syncing event=update reconciling="*v1alpha1.Subscription" selflink= time="2021-11-19T13:08:53Z" level=warning msg="an error was encountered during reconciliation" error="Operation cannot be fulfilled on subscriptions.operators.coreos.com \"pmem-csi-operator-v1-1-0-sub\": the object has been modified; please apply your changes to the latest version and try again" event=update reconciling="*v1alpha1.Subscription" selflink= E1119 13:08:53.045650 1 queueinformer_operator.go:290] sync {"update" "pmem-csi/pmem-csi-operator-v1-1-0-sub"} failed: Operation cannot be fulfilled on subscriptions.operators.coreos.com "pmem-csi-operator-v1-1-0-sub": the object has been modified; please apply your changes to the latest version and try again time="2021-11-19T13:08:53Z" level=info msg=syncing event=update reconciling="*v1alpha1.Subscription" selflink= time="2021-11-19T13:08:53Z" level=info msg=syncing id=8yt8e ip=install-kmp2g namespace=pmem-csi phase=RequiresApproval time="2021-11-19T13:08:54Z" level=warning msg="an error was encountered during reconciliation" error="Operation cannot be fulfilled on subscriptions.operators.coreos.com \"pmem-csi-operator-v1-1-0-sub\": the object has been modified; please apply your changes to the latest version and try again" event=update reconciling="*v1alpha1.Subscription" selflink= E1119 13:08:54.044598 1 queueinformer_operator.go:290] sync {"update" "pmem-csi/pmem-csi-operator-v1-1-0-sub"} failed: Operation cannot be fulfilled on subscriptions.operators.coreos.com "pmem-csi-operator-v1-1-0-sub": the object has been modified; please apply your changes to the latest version and try again time="2021-11-19T13:08:54Z" level=info msg=syncing event=update reconciling="*v1alpha1.Subscription" selflink= time="2021-11-19T13:08:54Z" level=info msg=syncing event=update reconciling="*v1alpha1.Subscription" selflink= time="2021-11-19T13:08:54Z" level=warning msg="an error was encountered during reconciliation" error="Operation cannot be fulfilled on subscriptions.operators.coreos.com \"pmem-csi-operator-v1-1-0-sub\": the object has been modified; please apply your changes to the latest version and try again" event=update reconciling="*v1alpha1.Subscription" selflink= E1119 13:08:54.840031 1 queueinformer_operator.go:290] sync {"update" "pmem-csi/pmem-csi-operator-v1-1-0-sub"} failed: Operation cannot be fulfilled on subscriptions.operators.coreos.com "pmem-csi-operator-v1-1-0-sub": the object has been modified; please apply your changes to the latest version and try again time="2021-11-19T13:08:54Z" level=info msg=syncing event=update reconciling="*v1alpha1.Subscription" selflink= time="2021-11-19T13:08:54Z" level=info msg=syncing event=update reconciling="*v1alpha1.Subscription" selflink= time="2021-11-19T13:08:55Z" level=info msg=syncing id=GE/Dn ip=install-br4hc namespace=pmem-csi phase=RequiresApproval time="2021-11-19T13:08:55Z" level=warning msg="status not equal, updating..." id=GE/Dn ip=install-br4hc namespace=pmem-csi phase=RequiresApproval time="2021-11-19T13:08:55Z" level=info msg=syncing event=update reconciling="*v1alpha1.Subscription" selflink= time="2021-11-19T13:08:55Z" level=info msg=syncing event=update reconciling="*v1alpha1.Subscription" selflink= time="2021-11-19T13:08:55Z" level=info msg=syncing id=NP9XF ip=install-kmp2g namespace=pmem-csi phase=RequiresApproval E1119 13:08:56.245183 1 queueinformer_operator.go:290] sync {"update" "pmem-csi/install-br4hc"} failed: failed to update installplan bundle lookups: Operation cannot be fulfilled on installplans.operators.coreos.com "install-br4hc": the object has been modified; please apply your changes to the latest version and try again time="2021-11-19T13:08:56Z" level=info msg=syncing id=iVO7a ip=install-br4hc namespace=pmem-csi phase=RequiresApproval time="2021-11-19T13:08:56Z" level=info msg="added to bundle, Kind=CustomResourceDefinition" configmap=pmem-csi/11d78c0562e2cd02702a57d274e90d36ba5d472d5d861a29575c9a530690e15 key=pmem-csi.intel.com_pmemcsideployments.yaml time="2021-11-19T13:08:56Z" level=info msg="added to bundle, Kind=Service" configmap=pmem-csi/11d78c0562e2cd02702a57d274e90d36ba5d472d5d861a29575c9a530690e15 key=pmem-csi-operator-metrics_v1_service.yaml time="2021-11-19T13:08:56Z" level=info msg="added to bundle, Kind=ClusterServiceVersion" configmap=pmem-csi/11d78c0562e2cd02702a57d274e90d36ba5d472d5d861a29575c9a530690e15 key=pmem-csi-operator.clusterserviceversion.yaml time="2021-11-19T13:08:56Z" level=info msg="added to bundle, Kind=ServiceAccount" configmap=pmem-csi/11d78c0562e2cd02702a57d274e90d36ba5d472d5d861a29575c9a530690e15 key=pmem-csi-operator_v1_serviceaccount.yaml time="2021-11-19T13:08:56Z" level=warning msg="status not equal, updating..." id=iVO7a ip=install-br4hc namespace=pmem-csi phase=RequiresApproval time="2021-11-19T13:08:56Z" level=warning msg="an error was encountered during reconciliation" error="Operation cannot be fulfilled on subscriptions.operators.coreos.com \"pmem-csi-operator-v1-1-0-sub\": the object has been modified; please apply your changes to the latest version and try again" event=update reconciling="*v1alpha1.Subscription" selflink= E1119 13:08:56.653801 1 queueinformer_operator.go:290] sync {"update" "pmem-csi/pmem-csi-operator-v1-1-0-sub"} failed: Operation cannot be fulfilled on subscriptions.operators.coreos.com "pmem-csi-operator-v1-1-0-sub": the object has been modified; please apply your changes to the latest version and try again time="2021-11-19T13:08:56Z" level=info msg=syncing event=update reconciling="*v1alpha1.Subscription" selflink= time="2021-11-19T13:08:57Z" level=info msg=syncing id=/PkrD ip=install-br4hc namespace=pmem-csi phase=RequiresApproval time="2021-11-19T13:08:57Z" level=info msg="added to bundle, Kind=ServiceAccount" configmap=pmem-csi/11d78c0562e2cd02702a57d274e90d36ba5d472d5d861a29575c9a530690e15 key=pmem-csi-operator_v1_serviceaccount.yaml time="2021-11-19T13:08:57Z" level=info msg="added to bundle, Kind=CustomResourceDefinition" configmap=pmem-csi/11d78c0562e2cd02702a57d274e90d36ba5d472d5d861a29575c9a530690e15 key=pmem-csi.intel.com_pmemcsideployments.yaml time="2021-11-19T13:08:57Z" level=info msg="added to bundle, Kind=Service" configmap=pmem-csi/11d78c0562e2cd02702a57d274e90d36ba5d472d5d861a29575c9a530690e15 key=pmem-csi-operator-metrics_v1_service.yaml time="2021-11-19T13:08:57Z" level=info msg="added to bundle, Kind=ClusterServiceVersion" configmap=pmem-csi/11d78c0562e2cd02702a57d274e90d36ba5d472d5d861a29575c9a530690e15 key=pmem-csi-operator.clusterserviceversion.yaml time="2021-11-19T13:08:57Z" level=warning msg="status not equal, updating..." id=/PkrD ip=install-br4hc namespace=pmem-csi phase=RequiresApproval time="2021-11-19T13:08:57Z" level=info msg=syncing event=update reconciling="*v1alpha1.Subscription" selflink= time="2021-11-19T13:08:57Z" level=info msg=syncing id=kU63Z ip=install-kmp2g namespace=pmem-csi phase=RequiresApproval time="2021-11-19T13:08:57Z" level=info msg="added to bundle, Kind=CustomResourceDefinition" configmap=pmem-csi/11d78c0562e2cd02702a57d274e90d36ba5d472d5d861a29575c9a530690e15 key=pmem-csi.intel.com_pmemcsideployments.yaml time="2021-11-19T13:08:57Z" level=info msg="added to bundle, Kind=Service" configmap=pmem-csi/11d78c0562e2cd02702a57d274e90d36ba5d472d5d861a29575c9a530690e15 key=pmem-csi-operator-metrics_v1_service.yaml time="2021-11-19T13:08:57Z" level=info msg="added to bundle, Kind=ClusterServiceVersion" configmap=pmem-csi/11d78c0562e2cd02702a57d274e90d36ba5d472d5d861a29575c9a530690e15 key=pmem-csi-operator.clusterserviceversion.yaml time="2021-11-19T13:08:57Z" level=info msg="added to bundle, Kind=ServiceAccount" configmap=pmem-csi/11d78c0562e2cd02702a57d274e90d36ba5d472d5d861a29575c9a530690e15 key=pmem-csi-operator_v1_serviceaccount.yaml time="2021-11-19T13:08:57Z" level=warning msg="status not equal, updating..." id=kU63Z ip=install-kmp2g namespace=pmem-csi phase=RequiresApproval time="2021-11-19T13:08:57Z" level=warning msg="an error was encountered during reconciliation" error="Operation cannot be fulfilled on subscriptions.operators.coreos.com \"pmem-csi-operator-v1-1-0-sub\": the object has been modified; please apply your changes to the latest version and try again" event=update reconciling="*v1alpha1.Subscription" selflink= E1119 13:08:57.444901 1 queueinformer_operator.go:290] sync {"update" "pmem-csi/pmem-csi-operator-v1-1-0-sub"} failed: Operation cannot be fulfilled on subscriptions.operators.coreos.com "pmem-csi-operator-v1-1-0-sub": the object has been modified; please apply your changes to the latest version and try again time="2021-11-19T13:08:57Z" level=info msg=syncing event=update reconciling="*v1alpha1.Subscription" selflink= time="2021-11-19T13:08:57Z" level=info msg=syncing event=update reconciling="*v1alpha1.Subscription" selflink= E1119 13:08:57.646167 1 queueinformer_operator.go:290] sync {"update" "pmem-csi/install-br4hc"} failed: failed to update installplan bundle lookups: Operation cannot be fulfilled on installplans.operators.coreos.com "install-br4hc": the object has been modified; please apply your changes to the latest version and try again time="2021-11-19T13:08:57Z" level=info msg=syncing id=bJNHg ip=install-br4hc namespace=pmem-csi phase=RequiresApproval time="2021-11-19T13:08:58Z" level=info msg=syncing event=update reconciling="*v1alpha1.Subscription" selflink= time="2021-11-19T13:08:58Z" level=info msg=syncing id=edGDA ip=install-kmp2g namespace=pmem-csi phase=RequiresApproval time="2021-11-19T13:08:58Z" level=info msg=syncing id=8qVMP ip=install-br4hc namespace=pmem-csi phase=RequiresApproval time="2021-11-19T13:08:58Z" level=info msg=syncing event=update reconciling="*v1alpha1.Subscription" selflink= time="2021-11-19T13:08:58Z" level=info msg=syncing event=update reconciling="*v1alpha1.Subscription" selflink= time="2021-11-19T13:08:58Z" level=info msg=syncing event=update reconciling="*v1alpha1.Subscription" selflink= time="2021-11-19T13:08:58Z" level=info msg=syncing id=Y6++j ip=install-kmp2g namespace=pmem-csi phase=Installing ```

The "object has been modified" error also occurs, so that seems to be a red herring. The difference is that here the phase eventually gets to "Installing".