e2e - "should create a Subscription for the latest entry providing the required GVK" failure #2600

akihikokuroda · 2022-01-26T23:46:43Z

Bug Report

e2e - "should create a Subscription for the latest entry providing the required GVK" failed.
https://github.com/operator-framework/operator-lifecycle-manager/runs/4957261384?check_suite_focus=true#step:4:154

Subscription when an entry in the middle of a channel does not provide a required GVK 
  should create a Subscription for the latest entry providing the required GVK
  /home/runner/work/operator-lifecycle-manager/operator-lifecycle-manager/test/e2e/subscription_e2e_test.go:106

[BeforeEach] Subscription
  /home/runner/work/operator-lifecycle-manager/operator-lifecycle-manager/test/e2e/subscription_e2e_test.go:57
created the subscription-e2e-f9m6s testing namespace
[BeforeEach] when an entry in the middle of a channel does not provide a required GVK
  /home/runner/work/operator-lifecycle-manager/operator-lifecycle-manager/test/e2e/subscription_e2e_test.go:70
Creating catalog source test-catalog in namespace subscription-e2e-f9m6s...
Catalog source test-catalog created
[It] should create a Subscription for the latest entry providing the required GVK
  /home/runner/work/operator-lifecycle-manager/operator-lifecycle-manager/test/e2e/subscription_e2e_test.go:106
[AfterEach] when an entry in the middle of a channel does not provide a required GVK
  /home/runner/work/operator-lifecycle-manager/operator-lifecycle-manager/test/e2e/subscription_e2e_test.go:102
Deleting config map test-catalog-configmap...
Deleting catalog source test-catalog...
waiting for the catalog source test-catalog-8f667 pod to be deleted...
waiting for the catalog source test-catalog-8f667 pod to be deleted...
waiting for the catalog source test-catalog-8f667 pod to be deleted...
waiting for the catalog source test-catalog-8f667 pod to be deleted...
waiting for the catalog source test-catalog-8f667 pod to be deleted...
waiting for the catalog source test-catalog-8f667 pod to be deleted...
waiting for the catalog source test-catalog-8f667 pod to be deleted...
waiting for the catalog source test-catalog-8f667 pod to be deleted...
waiting for the catalog source test-catalog-8f667 pod to be deleted...
waiting for the catalog source test-catalog-8f667 pod to be deleted...
[AfterEach] Subscription
  /home/runner/work/operator-lifecycle-manager/operator-lifecycle-manager/test/e2e/subscription_e2e_test.go:61
collecting the subscription-e2e-f9m6s namespace artifacts as the 'should create a Subscription for the latest entry providing the required GVK' test case failed
collecting logs in the ./artifacts/ artifacts directory
Storing the test artifact output in the artifacts/subscription-e2e-f9m6s 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...
No resources found in subscription-e2e-f9m6s namespace.
Collecting get events --sort-by .lastTimestamp output...
tearing down the subscription-e2e-f9m6s namespace


• Failure [71.676 seconds]
Subscription
/home/runner/work/operator-lifecycle-manager/operator-lifecycle-manager/test/e2e/subscription_e2e_test.go:52
  when an entry in the middle of a channel does not provide a required GVK
  /home/runner/work/operator-lifecycle-manager/operator-lifecycle-manager/test/e2e/subscription_e2e_test.go:65
    should create a Subscription for the latest entry providing the required GVK [It]
    /home/runner/work/operator-lifecycle-manager/operator-lifecycle-manager/test/e2e/subscription_e2e_test.go:106

    Timed out after 60.003s.
    Expected
        <[]v1alpha1.Subscription | len:1, cap:1>: [
            {
                TypeMeta: {
                    Kind: "Subscription",
                    APIVersion: "operators.coreos.com/v1alpha1",
                },
                ObjectMeta: {
                    Name: "test-subscription",
                    GenerateName: "",
                    Namespace: "subscription-e2e-f9m6s",
                    SelfLink: "",
                    UID: "943d1207-434a-4bc2-9651-813ec1d6d49b",
                    ResourceVersion: "1166",
                    Generation: 1,
                    CreationTimestamp: {
                        Time: 2022-01-26T20:26:50Z,
                    },
                    DeletionTimestamp: nil,
                    DeletionGracePeriodSeconds: nil,
                    Labels: {
                        "operators.coreos.com/root.subscription-e2e-f9m6s": "",
                    },
                    Annotations: nil,
                    OwnerReferences: nil,
                    Finalizers: nil,
                    ClusterName: "",
                    ManagedFields: [
                        {
                            Manager: "catalog",
                            Operation: "Update",
                            APIVersion: "operators.coreos.com/v1alpha1",
                            Time: {
                                Time: 2022-01-26T20:26:50Z,
                            },
                            FieldsType: "FieldsV1",
                            FieldsV1: {
                                Raw: "{\"f:status\":{\".\":{},\"f:catalogHealth\":{},\"f:conditions\":{},\"f:lastUpdated\":{}}}",
                            },
                            Subresource: "",
                        },
                        {
                            Manager: "e2e-local.test",
                            Operation: "Update",
                            APIVersion: "operators.coreos.com/v1alpha1",
                            Time: {
                                Time: 2022-01-26T20:26:50Z,
                            },
                            FieldsType: "FieldsV1",
                            FieldsV1: {
                                Raw: "{\"f:spec\":{\".\":{},\"f:channel\":{},\"f:installPlanApproval\":{},\"f:name\":{},\"f:source\":{},\"f:sourceNamespace\":{}}}",
                            },
                            Subresource: "",
                        },
                        {
                            Manager: "olm",
                            Operation: "Update",
                            APIVersion: "operators.coreos.com/v1alpha1",
                            Time: {
                                Time: 2022-01-26T20:26:51Z,
                            },
                            FieldsType: "FieldsV1",
                            FieldsV1: {
                                Raw: "{\"f:metadata\":{\"f:labels\":{\".\":{},\"f:operators.coreos.com/root.subscription-e2e-f9m6s\":{}}}}",
                            },
                            Subresource: "",
                        },
                    ],
                },
                Spec: {
                    CatalogSource: "test-catalog",
                    CatalogSourceNamespace: "subscription-e2e-f9m6s",
                    Package: "root",
                    Channel: "channel-root",
                    StartingCSV: "",
                    InstallPlanApproval: "Automatic",
                    Config: nil,
                },
                Status: {
                    CurrentCSV: "",
                    InstalledCSV: "",
                    Install: nil,
                    State: "",
                    Reason: "",
                    InstallPlanGeneration: 0,
                    InstallPlanRef: nil,
                    CatalogHealth: [
                        {
                            CatalogSourceRef: {
                                Kind: "CatalogSource",
                                Namespace: "operator-lifecycle-manager",
                                Name: "operatorhubio-catalog",
                                UID: "f9a493d1-b183-4ede-9027-7cd63902b03c",
                                APIVersion: "operators.coreos.com/v1alpha1",
                                ResourceVersion: "956",
                                FieldPath: "",
                            },
                            LastUpdated: {
        ...
    
    Gomega truncated this representation as it exceeds 'format.MaxLength'.
    Consider having the object provide a custom 'GomegaStringer' representation
    or adjust the parameters in Gomega's 'format' package.
    
    Learn more here: https://onsi.github.io/gomega/#adjusting-output
    
    to contain element matching
        <*matchers.WithTransformMatcher | 0xc0027e9340>: {
            Transform: <func(v1alpha1.Subscription) v1alpha1.SubscriptionSpec>0x2939ba0,
            Matcher: <*matchers.EqualMatcher | 0xc00285da40>{
                Expected: <v1alpha1.SubscriptionSpec>{
                    CatalogSource: "test-catalog",
                    CatalogSourceNamespace: "subscription-e2e-f9m6s",
                    Package: "dependency",
                    Channel: "channel-dependency",
                    StartingCSV: "csv-dependency-3",
                    InstallPlanApproval: "",
                    Config: nil,
                },
            },
            transformArgType: <*reflect.rtype | 0x2d46f60>{size: 0x1c0, ptrdata: 0x1c0, hash: 2418679958, tflag: 7, align: 8, fieldAlign: 8, kind: 25, equal: nil, gcdata: 85, str: 316800, ptrToThis: 5620032},
            transformedValue: <v1alpha1.SubscriptionSpec>{
                CatalogSource: "test-catalog",
                CatalogSourceNamespace: "subscription-e2e-f9m6s",
                Package: "root",
                Channel: "channel-root",
                StartingCSV: "",
                InstallPlanApproval: "",
                Config: nil,
            },
        }

    /home/runner/work/operator-lifecycle-manager/operator-lifecycle-manager/test/e2e/subscription_e2e_test.go:113

    Full Stack Trace
    github.com/operator-framework/operator-lifecycle-manager/test/e2e.glob..func22.3.3()
    	/home/runner/work/operator-lifecycle-manager/operator-lifecycle-manager/test/e2e/subscription_e2e_test.go:113 +0x175
    github.com/operator-framework/operator-lifecycle-manager/test/e2e.TestEndToEnd(0xf908f9)
    	/home/runner/work/operator-lifecycle-manager/operator-lifecycle-manager/test/e2e/e2e_test.go:59 +0x268
    testing.tRunner(0xc0001e1a00, 0x3004318)
    	/opt/hostedtoolcache/go/1.17.6/x64/src/testing/testing.go:1259 +0x102
    created by testing.(*T).Run
    	/opt/hostedtoolcache/go/1.17.6/x64/src/testing/testing.go:1306 +0x35a

What did you do?
Check CI e2e test failure

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.

The text was updated successfully, but these errors were encountered:

akihikokuroda · 2022-01-27T02:57:40Z

I looked at this farther. I saw the same error in the catalog-operator log but I couldn't reproduce this error locally. The resolve finished successfully after many reconciliations.

In the CI catalog-operator log, I saw the error of the operatorhubio-catalog in addition to the test-catalog.

2022-01-19T20:00:28.956949443Z stderr F I0119 20:00:28.956796       1 event.go:282] Event(v1.ObjectReference{Kind:"Namespace", Namespace:"", Name:"subscription-e2e-gcqhv", UID:"dfe83254-ba15-438f-badf-dd3b79c12036", APIVersion:"v1", ResourceVersion:"815", FieldPath:""}): type: 'Warning' reason: 'ResolutionFailed' [error using catalog test-catalog (in namespace subscription-e2e-gcqhv): failed to list bundles: rpc error: code = Unavailable desc = connection error: desc = "transport: Error while dialing dial tcp 10.96.185.140:50051: connect: connection refused", error using catalog operatorhubio-catalog (in namespace operator-lifecycle-manager): failed to list bundles: rpc error: code = Unavailable desc = connection error: desc = "transport: Error while dialing dial tcp 10.96.27.145:50051: connect: connection refused"]

In the log of local test has this:

I0127 01:58:47.892624       1 event.go:282] Event(v1.ObjectReference{Kind:"Namespace", Namespace:"", Name:"subscription-e2e-zjncd", UID:"1ab14d82-6325-4407-a80d-4182a3c270ca", APIVersion:"v1", ResourceVersion:"847496", FieldPath:""}): type: 'Warning' reason: 'ResolutionFailed' error using catalog test-catalog (in namespace subscription-e2e-zjncd): failed to list bundles: rpc error: code = Unavailable desc = connection error: desc = "transport: Error while dialing dial tcp 10.111.8.154:50051: i/o timeout"

It says 'i/o timeout'

akihikokuroda · 2022-01-27T03:20:40Z

The first test (this test) started at 20:00:17.685407819Z

2022-01-19T20:00:17.685407819Z stderr F time="2022-01-19T20:00:17Z" level=debug msg="resolving sources" id=5Nfe+ namespace=subscription-e2e-gcqhv

and finished at 20:01:34.043344211Z

2022-01-19T20:01:34.043344211Z stderr F time="2022-01-19T20:01:34Z" level=debug msg="handling object deletion" name=default namespace=subscription-e2e-gcqhv

I see the operatorhubio-catalog became READY at 20:01:31.819045073Z

2022-01-19T20:01:31.819045073Z stderr F time="2022-01-19T20:01:31Z" level=info msg="state.Key.Namespace=operator-lifecycle-manager state.Key.Name=operatorhubio-catalog state.State=READY"

So most of time during the first test, the operatorhubio-catalog was not in the READY state. It probably affected the test.
We probably have to make sure that the operatorhubio-catalog is READY state before the first test starts.
@timflannagan WDYT?

akihikokuroda · 2022-01-27T14:52:26Z

This failure has the same cause. https://github.com/operator-framework/operator-lifecycle-manager/runs/4961201219?check_suite_focus=true#step:4:206

The catalog-operator log has this:

2022-01-27T03:37:36.543595434Z stderr F E0127 03:37:36.540481       1 queueinformer_operator.go:290] sync "subscription-e2e-bdhmq" failed: [error using catalog operatorhubio-catalog (in namespace operator-lifecycle-manager): failed to list bundles: rpc error: code = Unavailable desc = connection error: desc = "transport: Error while dialing dial tcp 10.96.217.63:50051: connect: connection refused", error using catalog test-catalog (in namespace subscription-e2e-bdhmq): failed to list bundles: rpc error: code = Unavailable desc = connection error: desc = "transport: Error while dialing dial tcp 10.96.19.106:50051: connect: connection refused"]

timflannagan · 2022-01-27T15:00:00Z

I haven't read all the comments in this issue, but generally speaking, I think it's fine if we want to make it a testing requirement that we wait until the CatalogSource testing fixture is reporting a Ready state before we run any test cases. The only caveats would be any tests where we want to test the non-happy paths.

akihikokuroda added the kind/bug Categorizes issue or PR as related to a bug. label Jan 26, 2022

akihikokuroda mentioned this issue Jan 26, 2022

wait for catalogsource status ready before creating subscription #2601

Merged

5 tasks

openshift-merge-robot closed this as completed in #2601 Jan 27, 2022

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

e2e - "should create a Subscription for the latest entry providing the required GVK" failure #2600

e2e - "should create a Subscription for the latest entry providing the required GVK" failure #2600

akihikokuroda commented Jan 26, 2022

akihikokuroda commented Jan 27, 2022

akihikokuroda commented Jan 27, 2022 •

edited

Loading

akihikokuroda commented Jan 27, 2022

timflannagan commented Jan 27, 2022

e2e - "should create a Subscription for the latest entry providing the required GVK" failure #2600

e2e - "should create a Subscription for the latest entry providing the required GVK" failure #2600

Comments

akihikokuroda commented Jan 26, 2022

Bug Report

akihikokuroda commented Jan 27, 2022

akihikokuroda commented Jan 27, 2022 • edited Loading

akihikokuroda commented Jan 27, 2022

timflannagan commented Jan 27, 2022

akihikokuroda commented Jan 27, 2022 •

edited

Loading