Adding wait after olm install in olm test setup

[fjglira]

Fixes #344

[istio-testing]

Skipping CI for Draft Pull Request.
If you want CI signal for your change, please convert it to an actual PR.
You can still manually trigger a test run with /test all

[fjglira]

/test e2e-kind-olm

[fjglira]

/test e2e-kind-olm

[fjglira]

/test e2e-kind-olm

[fjglira]

/test e2e-kind-olm

[luksa]

Why is this needed? I see you've increased the wait timeout, so maybe this isn't needed anymore? If it is, please explain why in the comment.

[MaxBab]

If there is a need to wait for some specific resource to become available, better to explore the option to check that specific resource for readiness.

[fjglira]

Hey, just was a test. In the previous steps, I wait for all the labeled resources with olm.manage=true for 5 minutes. The issue here is that for some reason the catalog source resource does not start properly ramdonly, is not happening all the time:

packageserver                                   olm          ClusterServiceVersion       Installed
operatorhubio-catalog                           olm          CatalogSource               Installed
timed out waiting for the condition on pods/operatorhubio-catalog-jbsjx
timed out waiting for the condition on pods/operatorhubio-catalog-sbxmx
+ cleanup_kind_cluster operator-integration-tests

[fjglira]

In the log, we can see that even the pods are being recreated. But this is not happening always, I'm trying to find a fix for this flaky result

[MaxBab]

What is the status of the CatalogSource?
Also. what is the log output of the pod, whoch connects to the CatalogSource image?

[fjglira]

The catalogSource shows errors also:

  Conditions:
    Message:               failed to populate resolver cache from source operatorhubio-catalog/olm: failed to list bundles: rpc error: code = Unavailable desc = connection error: desc = "transport: Error while dialing: dial tcp 10.229.209.161:50051: i/o timeout"
    Reason:                ErrorPreventedResolution
    Status:                True
    Type:                  ResolutionFailed
    Last Transition Time:  2024-09-18T15:34:49Z
    Message:               all available catalogsources are healthy
    Reason:                AllCatalogSourcesHealthy
    Status:                False
    Type:                  CatalogSourcesUnhealthy
  Last Updated:            2024-09-18T15:34:49Z

The log you can see it here in the artifacts. Do you have some experience working with olm?

[luksa]

I don't think you should be waiting for the pod to be ready. What if the pod doesn't exist when the kubectl wait command is executed? You should check the status of the CatalogSource instead.

IIRC the catalogsource is just a server that serves the catalog. The fact that the server (the pod) is ready, doesn't mean that the catalog has actually been imported into OLM yet. , it doesn't mean that OLM has already imported the operators from the CatalogSource. But, I think you can check the CatalogSource status to see whether the catalog has actually been imported. See CatalogSource.status.lastConnect and .lastObservedState.

[MaxBab]

Every CatalogSource is represented by a pod that is running in the same namespace, where the CatalogSource has been created.
Worth to check the output of that pod as it may provide more information regarding the failure.

[fjglira]

In the catalog operator I see this:

2024-09-23T12:26:02.360225026Z stderr F time="2024-09-23T12:26:02Z" level=error msg="UpdateStatus - error while setting CatalogSource status" catalogsource.name=operatorhubio-catalog catalogsource.namespace=olm error="Operation cannot be fulfilled on catalogsources.operators.coreos.com \"operatorhubio-catalog\": the object has been modified; please apply your changes to the latest version and try again" id=3EZgR
2024-09-23T12:26:02.360238232Z stderr F E0923 12:26:02.360153       1 queueinformer_operator.go:319] sync {"update" "olm/operatorhubio-catalog"} failed: Operation cannot be fulfilled on catalogsources.operators.coreos.com "operatorhubio-catalog": the object has been modified; please apply your changes to the latest version and try again

Then later I see, the pod starting got an error:

2024-09-23T12:26:03.355417169Z stderr F time="2024-09-23T12:26:03Z" level=info msg="state.Key.Namespace=olm state.Key.Name=operatorhubio-catalog state.State=CONNECTING"
2024-09-23T12:26:03.356602099Z stderr F time="2024-09-23T12:26:03Z" level=info msg="state.Key.Namespace=olm state.Key.Name=operatorhubio-catalog state.State=TRANSIENT_FAILURE"

But at some point, I see this:

correctImages=true current-pod.name=operatorhubio-catalog-sbxmx current-pod.namespace=olm id=3IoXW
2024-09-23T12:26:13.17973617Z stderr F time="2024-09-23T12:26:13Z" level=info msg="of 1 pods matching label selector, 1 have the correct images and matching hash" catalogsource.name=operatorhubio-catalog catalogsource.namespace=olm correctHash=true correctImages=true current-pod.name=operatorhubio-catalog-sbxmx current-pod.namespace=olm id=3IoXW
2024-09-23T12:26:13.179835848Z stderr F time="2024-09-23T12:26:13Z" level=info msg="ensured registry server" catalogsource.name=operatorhubio-catalog catalogsource.namespace=olm id=3IoXW
2024-09-23T12:26:13.179840661Z stderr F time="2024-09-23T12:26:13Z" level=info msg="requeuing registry server sync based on polling interval 1h0m0s" catalogsource.name=operatorhubio-catalog catalogsource.namespace=olm id=3IoXW

This is the complete log trace

[MaxBab]

All this log output relates to the CatalogSource status.
The state.Key.Name=operatorhubio-catalog state.State=TRANSIENT_FAILURE" status relates to the CatalogSource itself.
But it will not show you the reason of the failure.

That's why getting the describe of the CatalogSource pod in case it was not started or logs output in case it was started, will give much more information of the failure.

[fjglira]

/test e2e-kind-olm

[fjglira]

/test e2e-kind-olm

[fjglira]

/test e2e-kind-olm

[luksa]

@fjglira You need to change this. You should wait for the CatalogSource, not the underlying pod(s).

Waiting for the pods is the wrong thing to do and won't work. The reason this is failing is because at the exact time when you run this wait command, there are two pods (one is terminating, the other is starting up). The wait command will now wait for both of these pods to become ready. But of course, the one that's terminating will never become ready and thus the wait command will fail.

[luksa]

Basically, when you use a label selector in the kubectl wait command, you're not telling kubectl to wait for at least one pod matching the selector to become ready. You're telling it to find all the pods that match the selector and then wait for all of them to become ready.

[fjglira]

Changed, now using:

timeout --foreground -v -s SIGHUP -k ${TIMEOUT} ${TIMEOUT} bash --verbose -c \
      "until ${COMMAND} get CatalogSource operatorhubio-catalog -n olm -o jsonpath='{.status.connectionState.lastObservedState}' | grep -q READY; do sleep 5; done && echo 'The CatalogSource is Ready.'"

To check directly that CatalogSource is Ready

[luksa]

/test e2e-kind-olm

[fjglira]

/test e2e-kind-olm

[fjglira]

/test e2e-kind-olm

[luksa]

This can be replaced with something like:

k wait catalogsource operatorhubio-catalog --for 'jsonpath={.status.connectionState.lastObservedState}=READY'

[fjglira]

Done

[fjglira]

/test e2e-kind-olm