e2e Subscription "with starting CSV" error

[akihikokuroda]

Bug Report

e2e Subscription "with starting CSV" error
https://github.com/operator-framework/operator-lifecycle-manager/runs/4628064669?check_suite_focus=true#step:4:3404

Subscription 
  with starting CSV
  /home/runner/work/operator-lifecycle-manager/operator-lifecycle-manager/test/e2e/subscription_e2e_test.go:358

[BeforeEach] Subscription
  /home/runner/work/operator-lifecycle-manager/operator-lifecycle-manager/test/e2e/subscription_e2e_test.go:57
created the subscription-e2e-mjc8n testing namespace
[It] with starting CSV
  /home/runner/work/operator-lifecycle-manager/operator-lifecycle-manager/test/e2e/subscription_e2e_test.go:358
Creating catalog source mock-nginx-vf7pc in namespace subscription-e2e-mjc8n...
Catalog source mock-nginx-vf7pc created
waiting for catalog pod mock-nginx-vf7pc to be available (for sync) - NO_CONNECTION
waiting for catalog pod mock-nginx-vf7pc to be available (for sync) - CONNECTING
waiting for catalog pod mock-nginx-vf7pc to be available (for sync) - TRANSIENT_FAILURE
waiting for catalog pod mock-nginx-vf7pc to be available (for sync) - TRANSIENT_FAILURE
catalog mock-nginx-vf7pc pod with address mock-nginx-vf7pc.subscription-e2e-mjc8n.svc:50051
17:26:19.8094:  (): nil
waiting for sub-nginx-22dj9 to have installplan ref
17:26:20.8107:  (): nil
waiting for sub-nginx-22dj9 to have installplan ref
17:26:21.8102:  (): nil
waiting for sub-nginx-22dj9 to have installplan ref
17:26:22.8103: UpgradePending (nginx-a): &ObjectReference{Kind:InstallPlan,Namespace:subscription-e2e-mjc8n,Name:install-728hg,UID:5994cb0c-655d-465d-89b2-b4835a66bf1d,APIVersion:operators.coreos.com/v1alpha1,ResourceVersion:10338,FieldPath:,}
waiting for sub-nginx-22dj9 to have installplan ref
installplan install-728hg is in phase RequiresApproval
Deleting config map mock-nginx-vf7pc-configmap...
Deleting catalog source mock-nginx-vf7pc...
[AfterEach] Subscription
  /home/runner/work/operator-lifecycle-manager/operator-lifecycle-manager/test/e2e/subscription_e2e_test.go:61
collecting the subscription-e2e-mjc8n namespace artifacts as the 'with starting CSV' test case failed
collecting logs in the ./artifacts/ artifacts directory
Storing the test artifact output in the artifacts/subscription-e2e-mjc8n directory
Collecting get catalogsources -o yaml output...
Collecting get subscriptions -o yaml output...
Collecting get operatorgroups -o yaml output...
Collecting get clusterserviceversions -o yaml output...
Collecting get installplans -o yaml output...
Collecting get pods -o wide output...
Collecting get events --sort-by .lastTimestamp output...
tearing down the subscription-e2e-mjc8n namespace


• Failure [58.732 seconds]
Subscription
/home/runner/work/operator-lifecycle-manager/operator-lifecycle-manager/test/e2e/subscription_e2e_test.go:52
  with starting CSV [It]
  /home/runner/work/operator-lifecycle-manager/operator-lifecycle-manager/test/e2e/subscription_e2e_test.go:358

  
  	Error Trace:	subscription_e2e_test.go:439
  	            				runner.go:113
  	            				runner.go:64
  	            				it_node.go:26
  	            				spec.go:215
  	            				spec.go:138
  	            				spec_runner.go:200
  	            				spec_runner.go:170
  	            				spec_runner.go:66
  	            				suite.go:79
  	            				ginkgo_dsl.go:238
  	            				ginkgo_dsl.go:221
  	            				e2e_test.go:59
  	Error:      	"[{{InstallPlan operators.coreos.com/v1alpha1} {install-6l24h install- subscription-e2e-mjc8n  02bd3ccb-e1e8-498a-8ba5-a3729cd849dc 10347 %!s(int64=1) 2021-12-24 17:26:22 +0000 UTC <nil> %!s(*int64=<nil>) map[] map[] [{operators.coreos.com/v1alpha1 Subscription sub-nginx-22dj9 e35588d9-8d0e-4222-a85a-1a6d5fd2e432 %!s(*bool=0xc001cec74a) %!s(*bool=0xc001cec749)}] []  [{catalog Update operators.coreos.com/v1alpha1 2021-12-24 17:26:22 +0000 UTC FieldsV1 {"f:metadata":{"f:generateName":{},"f:ownerReferences":{".":{},"k:{\"uid\":\"e35588d9-8d0e-4222-a85a-1a6d5fd2e432\"}":{".":{},"f:apiVersion":{},"f:blockOwnerDeletion":{},"f:controller":{},"f:kind":{},"f:name":{},"f:uid":{}}}},"f:spec":{".":{},"f:approval":{},"f:approved":{},"f:clusterServiceVersionNames":{},"f:generation":{}},"f:status":{".":{},"f:catalogSources":{},"f:phase":{},"f:plan":{}}} }]} {  [nginx-a] Manual %!s(bool=false) %!s(int=2)} {RequiresApproval [] [mock-nginx-vf7pc] [nginx-a: nginx-a[operators.coreos.com/v1alpha1/ClusterServiceVersion (mock-nginx-vf7pc/subscription-e2e-mjc8n)] (Unknown) nginx-a: insblh9j.cluster.com[apiextensions.k8s.io/v1/CustomResourceDefinition (mock-nginx-vf7pc/subscription-e2e-mjc8n)] (Unknown)] [] nil <nil> }} {{InstallPlan operators.coreos.com/v1alpha1} {install-728hg install- subscription-e2e-mjc8n  5994cb0c-655d-465d-89b2-b4835a66bf1d 10344 %!s(int64=1) 2021-12-24 17:26:21 +0000 UTC <nil> %!s(*int64=<nil>) map[operators.coreos.com/nginx-mjn2k.subscription-e2e-mjc8n:] map[] [{operators.coreos.com/v1alpha1 Subscription sub-nginx-22dj9 e35588d9-8d0e-4222-a85a-1a6d5fd2e432 %!s(*bool=0xc001ceca1a) %!s(*bool=0xc001ceca19)}] []  [{catalog Update operators.coreos.com/v1alpha1 2021-12-24 17:26:21 +0000 UTC FieldsV1 {"f:metadata":{"f:generateName":{},"f:ownerReferences":{".":{},"k:{\"uid\":\"e35588d9-8d0e-4222-a85a-1a6d5fd2e432\"}":{".":{},"f:apiVersion":{},"f:blockOwnerDeletion":{},"f:controller":{},"f:kind":{},"f:name":{},"f:uid":{}}}},"f:spec":{".":{},"f:approval":{},"f:approved":{},"f:clusterServiceVersionNames":{},"f:generation":{}},"f:status":{".":{},"f:catalogSources":{},"f:phase":{},"f:plan":{}}} } {olm Update operators.coreos.com/v1alpha1 2021-12-24 17:26:22 +0000 UTC FieldsV1 {"f:metadata":{"f:labels":{".":{},"f:operators.coreos.com/nginx-mjn2k.subscription-e2e-mjc8n":{}}}} }]} {  [nginx-a] Manual %!s(bool=false) %!s(int=1)} {RequiresApproval [] [mock-nginx-vf7pc] [nginx-a: nginx-a[operators.coreos.com/v1alpha1/ClusterServiceVersion (mock-nginx-vf7pc/subscription-e2e-mjc8n)] (Unknown) nginx-a: insblh9j.cluster.com[apiextensions.k8s.io/v1/CustomResourceDefinition (mock-nginx-vf7pc/subscription-e2e-mjc8n)] (Unknown)] [] nil <nil> }}]" should have 1 item(s), but has 2
  	Test:       	Subscription with starting CSV
  
  /home/runner/work/operator-lifecycle-manager/operator-lifecycle-manager/vendor/github.com/stretchr/testify/require/require.go:1033

  Full Stack Trace
  github.com/stretchr/testify/require.Len(0x7fe2dc6b3aa0, 0xc00103ec40, 0x2f58a20, 0xc001abcdf8, 0x1, 0x0, 0x0, 0x0)
  	/home/runner/work/operator-lifecycle-manager/operator-lifecycle-manager/vendor/github.com/stretchr/testify/require/require.go:1033 +0xdb
  github.com/operator-framework/operator-lifecycle-manager/test/e2e.glob..func20.8()
  	/home/runner/work/operator-lifecycle-manager/operator-lifecycle-manager/test/e2e/subscription_e2e_test.go:439 +0x1208
  github.com/operator-framework/operator-lifecycle-manager/test/e2e.TestEndToEnd(0xc000794780)
  	/home/runner/work/operator-lifecycle-manager/operator-lifecycle-manager/test/e2e/e2e_test.go:59 +0x2d6
  testing.tRunner(0xc000794780, 0x357d988)
  	/opt/hostedtoolcache/go/1.16.12/x64/src/testing/testing.go:1193 +0xef
  created by testing.(*T).Run
  	/opt/hostedtoolcache/go/1.16.12/x64/src/testing/testing.go:1238 +0x2b3

What did you do?
CI e2e test failed in a pull request

What did you expect to see?
No error

What did you see instead? Under which circumstances?
Error above

Environment

• operator-lifecycle-manager version:

• Kubernetes version information:

• Kubernetes cluster kind:

Possible Solution

Additional context
Add any other context about the problem here.

[akihikokuroda]

The test failed where it checks only one installplan is created. There were 2 installplans there. Here is the log snippet of the catalog operator in the CI e2e log. There are 2 worker for the namespace queue. Both workers found no InstallPlan so both create the Installplan.

### syncResolvingNamespace entry (First  id=9Swva)
2021-12-24T17:26:18.792978125Z stderr F time="2021-12-24T17:26:18Z" level=debug msg="resolving sources" id=9Swva namespace=subscription-e2e-mjc8n
2021-12-24T17:26:18.792982725Z stderr F time="2021-12-24T17:26:18Z" level=debug msg="checking if subscriptions need update" id=9Swva namespace=subscription-e2e-mjc8n
2021-12-24T17:26:18.807117851Z stderr F time="2021-12-24T17:26:18Z" level=info msg=syncing event=update reconciling="*v1alpha1.Subscription" selflink=
2021-12-24T17:26:18.991947773Z stderr F time="2021-12-24T17:26:18Z" level=debug msg="all subscriptions up to date" id=mgrnk namespace=operators
2021-12-24T17:26:19.192074408Z stderr F time="2021-12-24T17:26:19Z" level=debug msg="checking for existing installplan" channel=stable id=9Swva namespace=subscription-e2e-mjc8n pkg=nginx-mjn2k source=mock-nginx-vf7pc sub=sub-nginx-22dj9
2021-12-24T17:26:19.192113107Z stderr F time="2021-12-24T17:26:19Z" level=debug msg="resolving subscriptions in namespace" id=9Swva namespace=subscription-e2e-mjc8n
2021-12-24T17:26:19.393743223Z stderr F time="2021-12-24T17:26:19Z" level=warning msg="an error was encountered during reconciliation" error="Operation cannot be fulfilled on subscriptions.operators.coreos.com \"sub-nginx-22dj9\": the object has been modified; please app\
ly your changes to the latest version and try again" event=update reconciling="*v1alpha1.Subscription" selflink=
2021-12-24T17:26:19.393832722Z stderr F E1224 17:26:19.393710       1 queueinformer_operator.go:290] sync {"update" "subscription-e2e-mjc8n/sub-nginx-22dj9"} failed: Operation cannot be fulfilled on subscriptions.operators.coreos.com "sub-nginx-22dj9": the object has been modified; please apply your changes to the latest version and try again
2021-12-24T17:26:19.39401262Z stderr F time="2021-12-24T17:26:19Z" level=info msg=syncing event=update reconciling="*v1alpha1.Subscription" selflink=
2021-12-24T17:26:19.598978794Z stderr F time="2021-12-24T17:26:19Z" level=debug msg="resolution caused subscription changes, creating installplan" id=9Swva namespace=subscription-e2e-mjc8n
2021-12-24T17:26:19.796441261Z stderr F time="2021-12-24T17:26:19Z" level=debug msg="reconciliation successful" event=update reconciling="*v1alpha1.Subscription" selflink= state="*subscription.catalogHealthyState"
2021-12-24T17:26:19.796464761Z stderr F time="2021-12-24T17:26:19Z" level=info msg=syncing event=update reconciling="*v1alpha1.Subscription" selflink=
### syncResolvingNamespace entry (Second  id=0zRlP)
2021-12-24T17:26:19.796469161Z stderr F time="2021-12-24T17:26:19Z" level=debug msg="resolving sources" id=0zRlP namespace=subscription-e2e-mjc8n. 
2021-12-24T17:26:19.796472961Z stderr F time="2021-12-24T17:26:19Z" level=debug msg="checking if subscriptions need update" id=0zRlP namespace=subscription-e2e-mjc8n
2021-12-24T17:26:20.195521644Z stderr F time="2021-12-24T17:26:20Z" level=warning msg="an error was encountered during reconciliation" error="Operation cannot be fulfilled on subscriptions.operators.coreos.com \"sub-nginx-22dj9\": the object has been modified; please app\
ly your changes to the latest version and try again" event=update reconciling="*v1alpha1.Subscription" selflink=
2021-12-24T17:26:20.195552444Z stderr F E1224 17:26:20.195131       1 queueinformer_operator.go:290] sync {"update" "subscription-e2e-mjc8n/sub-nginx-22dj9"} failed: Operation cannot be fulfilled on subscriptions.operators.coreos.com "sub-nginx-22dj9": the object has been modified; please apply your changes to the latest version and try again
2021-12-24T17:26:20.195557143Z stderr F time="2021-12-24T17:26:20Z" level=info msg=syncing event=update reconciling="*v1alpha1.Subscription" selflink=
2021-12-24T17:26:20.395052685Z stderr F time="2021-12-24T17:26:20Z" level=debug msg="checking for existing installplan" channel=stable id=0zRlP namespace=subscription-e2e-mjc8n pkg=nginx-mjn2k source=mock-nginx-vf7pc sub=sub-nginx-22dj9
2021-12-24T17:26:20.395244283Z stderr F time="2021-12-24T17:26:20Z" level=debug msg="resolving subscriptions in namespace" id=0zRlP namespace=subscription-e2e-mjc8n
### Installplan creation (First)
2021-12-24T17:26:20.59274305Z stderr F time="2021-12-24T17:26:20Z" level=warning msg="no installplan found with matching generation, creating new one" id=9Swva namespace=subscription-e2e-mjc8n
2021-12-24T17:26:20.796957033Z stderr F time="2021-12-24T17:26:20Z" level=debug msg="reconciliation successful" event=update reconciling="*v1alpha1.Subscription" selflink= state="*subscription.catalogHealthyState"
2021-12-24T17:26:20.79720573Z stderr F time="2021-12-24T17:26:20Z" level=info msg=syncing event=update reconciling="*v1alpha1.Subscription" selflink=
2021-12-24T17:26:20.798105719Z stderr F time="2021-12-24T17:26:20Z" level=debug msg="reconciliation successful" event=update reconciling="*v1alpha1.Subscription" selflink= state="*subscription.catalogHealthyState"
2021-12-24T17:26:20.99365121Z stderr F time="2021-12-24T17:26:20Z" level=debug msg="resolution caused subscription changes, creating installplan" id=0zRlP namespace=subscription-e2e-mjc8n
2021-12-24T17:26:21.195801419Z stderr F time="2021-12-24T17:26:21Z" level=info msg=syncing event=update reconciling="*v1alpha1.Subscription" selflink=
2021-12-24T17:26:21.196677808Z stderr F time="2021-12-24T17:26:21Z" level=debug msg="reconciliation successful" event=update reconciling="*v1alpha1.Subscription" selflink= state="*subscription.catalogHealthyState"
2021-12-24T17:26:21.196712708Z stderr F time="2021-12-24T17:26:21Z" level=info msg=syncing id=BbNi2 ip=install-728hg namespace=subscription-e2e-mjc8n phase=
2021-12-24T17:26:21.196802507Z stderr F time="2021-12-24T17:26:21Z" level=info msg="skip processing installplan without status - subscription sync responsible for initial status" id=BbNi2 ip=install-728hg namespace=subscription-e2e-mjc8n phase=
2021-12-24T17:26:21.597691367Z stderr F time="2021-12-24T17:26:21Z" level=info msg=syncing event=update reconciling="*v1alpha1.Subscription" selflink=
2021-12-24T17:26:21.598186861Z stderr F time="2021-12-24T17:26:21Z" level=debug msg="reconciliation successful" event=update reconciling="*v1alpha1.Subscription" selflink= state="*subscription.catalogHealthyState"
2021-12-24T17:26:21.598354859Z stderr F time="2021-12-24T17:26:21Z" level=info msg=syncing id=14Vpt ip=install-728hg namespace=subscription-e2e-mjc8n phase=RequiresApproval
2021-12-24T17:26:21.601464421Z stderr F time="2021-12-24T17:26:21Z" level=debug msg="not approved, skipping sync"
### InstallPlan creation (Second)
2021-12-24T17:26:21.793121359Z stderr F time="2021-12-24T17:26:21Z" level=warning msg="no installplan found with matching generation, creating new one" id=0zRlP namespace=subscription-e2e-mjc8n