Note: This bug is displayed in read-only format because the product is no longer active in Red Hat Bugzilla.

Bug 2006751

Summary: network-check-target pod cannot be ready
Product: OpenShift Container Platform Reporter: zhaozhanqi <zzhao>
Component: NetworkingAssignee: Riccardo Ravaioli <rravaiol>
Networking sub component: ovn-kubernetes QA Contact: Anurag saxena <anusaxen>
Status: CLOSED DUPLICATE Docs Contact:
Severity: medium    
Priority: unspecified CC: huirwang, rravaiol
Version: 4.9Keywords: Reopened
Target Milestone: ---   
Target Release: ---   
Hardware: Unspecified   
OS: Unspecified   
Whiteboard:
Fixed In Version: Doc Type: If docs needed, set a value
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2022-01-24 17:33:15 UTC Type: Bug
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:

Description zhaozhanqi 2021-09-22 10:40:52 UTC
Description of problem:

Setup OVN cluster, found one network-check-target pod is not ready with 

Warning  ProbeError  36s (x2678 over 6h33m)  kubelet  Readiness probe error: Get "http://10.129.2.4:8080/": dial tcp 10.129.2.4:8080: connect: no route to host


$ oc get pod -n openshift-network-diagnostics -o wide
NAME                                   READY   STATUS    RESTARTS   AGE     IP            NODE                                         NOMINATED NODE   READINESS GATES
network-check-source-5f9895c67-m8kdl   1/1     Running   0          6h48m   10.131.0.16   ip-10-0-215-234.us-east-2.compute.internal   <none>           <none>
network-check-target-97x8b             0/1     Running   0          6h35m   10.129.2.4    ip-10-0-167-199.us-east-2.compute.internal   <none>           <none>
network-check-target-dqpzr             1/1     Running   0          6h48m   10.130.0.3    ip-10-0-156-72.us-east-2.compute.internal    <none>           <none>
network-check-target-krv8x             1/1     Running   0          6h48m   10.128.0.3    ip-10-0-184-210.us-east-2.compute.internal   <none>           <none>
network-check-target-q4ttp             1/1     Running   0          6h48m   10.129.0.4    ip-10-0-205-203.us-east-2.compute.internal   <none>           <none>
network-check-target-q5sfg             1/1     Running   0          6h36m   10.128.2.4    ip-10-0-144-43.us-east-2.compute.internal    <none>           <none>
network-check-target-wdwpc             1/1     Running   0          6h36m   10.131.0.3    ip-10-0-215-234.us-east-2.compute.internal   <none>           <none>

Version-Release number of selected component (if applicable):
4.9.0-0.nightly-2021-09-21-215600

How reproducible:
not always

Steps to Reproduce:
1.
2.
3.

Actual results:

met error logs:

ovnkube-master-bzpc7-ovnkube-master.log:E0922 03:41:59.329319       1 ovn.go:557] error while creating logical port openshift-network-diagnostics_network-check-target-97x8b error: Reconnecting...Transaction Failed due to an error: constraint violation details: Transaction causes multiple rows in "Logical_Switch_Port" table to have identical values (openshift-network-diagnostics_network-check-target-97x8b) for index on column "name".  First row, with UUID f19a76b8-fda7-4779-bfe9-980cf6aae3a2, was inserted by this transaction.  Second row, with UUID e80fb1d7-d74b-46ea-8a4e-bab83d52bb70, existed in the database before this transaction, which modified some of the row's columns but not any columns in this index. in committing transaction


Expected results:


Additional info:

Comment 3 Riccardo Ravaioli 2021-09-22 14:44:52 UTC

*** This bug has been marked as a duplicate of bug 1997205 ***

Comment 4 Riccardo Ravaioli 2021-09-23 13:05:28 UTC
We are indeed hitting the same chain of events as in https://bugzilla.redhat.com/show_bug.cgi?id=1997205, but in this case we're running a very recent nightly build of 4.9, which includes the fixes by Tim in https://bugzilla.redhat.com/show_bug.cgi?id=2004340 and Surya in https://bugzilla.redhat.com/show_bug.cgi?id=1998614.

These two fixes effectively solve the bug that had been reported earlier in 1997205.

We can see see it from the logs in ovnkube-master, where addLogicalPort is executed three times.

***** Run 1, most probably upon an "add pod" event, sets IP and MAC addresses (let's call them IP1,MAC1) in pod annotations and nbdb:

namespaces/openshift-ovn-kubernetes/pods/ovnkube-master-bzpc7/ovnkube-master/ovnkube-master/logs/current.log:4015:2021-09-22T03:41:59.163683297Z I0922 03:41:59.163227       1 kube.go:67] Setting annotations map[k8s.ovn.org/pod-networks:{"default":{"ip_addresses":["10.129.2.3/23"],"mac_address":"0a:58:0a:81:02:03","gateway_ips":["10.129.2.1"],"ip_address":"10.129.2.3/23","gateway_ip":"10.129.2.1"}}] on pod openshift-network-diagnostics/network-check-target-97x8b

namespaces/openshift-ovn-kubernetes/pods/ovnkube-master-bzpc7/ovnkube-master/ovnkube-master/logs/current.log:4038:2021-09-22T03:41:59.209752587Z I0922 03:41:59.209732       1 ovn.go:458] [785ca7a2-4ed3-4942-8fae-c368ff3f8e8f/openshift-network-diagnostics/network-check-target-97x8b] retry pod setup

namespaces/openshift-ovn-kubernetes/pods/ovnkube-master-bzpc7/ovnkube-master/ovnkube-master/logs/current.log:4088:2021-09-22T03:41:59.253124761Z I0922 03:41:59.253102       1 pods.go:251] [openshift-network-diagnostics/network-check-target-97x8b] addLogicalPort took 173.6539ms


***** Run 2, most probably upon an "update pod" event, fails to parse the pod annotation and goes on to allocate a new IP & MAC address, which replace the previous pod annotation. It then fails to update nbdb with the new values, due to nbdb disconnecting from the monitor connection held by ovsdb client in ovnkube-master. This disconnection is handled by Surya's patch for https://bugzilla.redhat.com/show_bug.cgi?id=1998614 (notice the "Reconnecting..." part in the error message, which did not appear when the same set of events took place in https://bugzilla.redhat.com/show_bug.cgi?id=1997205, reported prior to this fix)

namespaces/openshift-ovn-kubernetes/pods/ovnkube-master-bzpc7/ovnkube-master/ovnkube-master/logs/current.log:4089:2021-09-22T03:41:59.259648656Z I0922 03:41:59.259573       1 kube.go:67] Setting annotations map[k8s.ovn.org/pod-networks:{"default":{"ip_addresses":["10.129.2.4/23"],"mac_address":"0a:58:0a:81:02:04","gateway_ips":["10.129.2.1"],"ip_address":"10.129.2.4/23","gateway_ip":"10.129.2.1"}}] on pod openshift-network-diagnostics/network-check-target-97x8b

namespaces/openshift-ovn-kubernetes/pods/ovnkube-master-bzpc7/ovnkube-master/ovnkube-master/logs/current.log:4150:2021-09-22T03:41:59.329368608Z I0922 03:41:59.329307       1 pods.go:251] [openshift-network-diagnostics/network-check-target-97x8b] addLogicalPort took 119.554208ms

namespaces/openshift-ovn-kubernetes/pods/ovnkube-master-bzpc7/ovnkube-master/ovnkube-master/logs/current.log:4151:2021-09-22T03:41:59.329368608Z E0922 03:41:59.329319       1 ovn.go:557] error while creating logical port openshift-network-diagnostics_network-check-target-97x8b error: Reconnecting...Transaction Failed due to an error: constraint violation details: Transaction causes multiple rows in "Logical_Switch_Port" table to have identical values (openshift-network-diagnostics_network-check-target-97x8b) for index on column "name".  First row, with UUID f19a76b8-fda7-4779-bfe9-980cf6aae3a2, was inserted by this transaction.  Second row, with UUID e80fb1d7-d74b-46ea-8a4e-bab83d52bb70, existed in the database before this transaction, which modified some of the row's columns but not any columns in this index. in committing transaction

namespaces/openshift-ovn-kubernetes/pods/ovnkube-master-bzpc7/ovnkube-master/ovnkube-master/logs/current.log:4152:2021-09-22T03:41:59.329368608Z I0922 03:41:59.329343       1 ovn.go:464] [785ca7a2-4ed3-4942-8fae-c368ff3f8e8f/openshift-network-diagnostics/network-check-target-97x8b] setup retry failed; will try again later
namespaces/openshift-ovn-kubernetes/pods/ovnkube-master-bzpc7/ovnkube-master/ovnkube-master/logs/current.log:4153:2021-09-22T03:41:59.329391089Z I0922 03:41:59.329374       1 ovn.go:458] [785ca7a2-4ed3-4942-8fae-c368ff3f8e8f/openshift-network-diagnostics/network-check-target-97x8b] retry pod setup


***** Run 3, where addLogicalPort finally succeeds because the connection to nbdb was re-established. It finds the existing logical switch port in nbdb created in run 1 and updates the LSP entry successfully with MAC2,IP2:

namespaces/openshift-ovn-kubernetes/pods/ovnkube-master-bzpc7/ovnkube-master/ovnkube-master/logs/current.log:4154:2021-09-22T03:41:59.329419345Z I0922 03:41:59.329410       1 pods.go:309] LSP already exists for port: openshift-network-diagnostics_network-check-target-97x8b

namespaces/openshift-ovn-kubernetes/pods/ovnkube-master-bzpc7/ovnkube-master/ovnkube-master/logs/current.log:4483:2021-09-22T03:41:59.950624766Z I0922 03:41:59.950592       1 pods.go:251] [openshift-network-diagnostics/network-check-target-97x8b] addLogicalPort took 621.207655ms

namespaces/openshift-ovn-kubernetes/pods/ovnkube-master-bzpc7/ovnkube-master/ovnkube-master/logs/current.log:4484:2021-09-22T03:41:59.950624766Z I0922 03:41:59.950613       1 ovn.go:461] [785ca7a2-4ed3-4942-8fae-c368ff3f8e8f/openshift-network-diagnostics/network-check-target-97x8b] pod setup successful


***** Ovnkube-node, which failed to run CNI ADD in https://bugzilla.redhat.com/show_bug.cgi?id=1997205 because ovn-controller was setting annotations with the initial addresses and not the new ones, here succeeds:

namespaces/openshift-ovn-kubernetes/pods/ovnkube-node-5bd74/ovnkube-node/ovnkube-node/logs/current.log:257:2021-09-22T03:42:46.077743345Z I0922 03:42:46.077687    2975 cni.go:236] [openshift-network-diagnostics/
network-check-target-97x8b f60b4c84cc609dcb2d0196f63d0b219a07697ecf68915c3c1c73ae3d20b193fd] ADD starting CNI request [openshift-network-diagnostics/network-check-target-97x8b f60b4c84cc609dcb2d0196f63d0b219a076
97ecf68915c3c1c73ae3d20b193fd]

namespaces/openshift-ovn-kubernetes/pods/ovnkube-node-5bd74/ovnkube-node/ovnkube-node/logs/current.log:259:2021-09-22T03:42:46.217046008Z I0922 03:42:46.216562    2975 helper_linux.go:258] ConfigureOVS: namespac
e: openshift-network-diagnostics, podName: network-check-target-97x8b

namespaces/openshift-ovn-kubernetes/pods/ovnkube-node-5bd74/ovnkube-node/ovnkube-node/logs/current.log:261:2021-09-22T03:42:48.099286652Z I0922 03:42:48.099019    2975 cni.go:246] [openshift-network-diagnostics/
network-check-target-97x8b f60b4c84cc609dcb2d0196f63d0b219a07697ecf68915c3c1c73ae3d20b193fd] ADD finished CNI request [openshift-network-diagnostics/network-check-target-97x8b f60b4c84cc609dcb2d0196f63d0b219a076
97ecf68915c3c1c73ae3d20b193fd], result "{\"Result\":{\"interfaces\":[{\"name\":\"f60b4c84cc609dc\",\"mac\":\"36:ab:c4:5c:27:4d\"},{\"name\":\"eth0\",\"mac\":\"0a:58:0a:81:02:04\",\"sandbox\":\"/var/run/netns/1b3
b45bc-573e-4743-9d53-b52e8a0f1a09\"}],\"ips\":[{\"version\":\"4\",\"interface\":1,\"address\":\"10.129.2.4/23\",\"gateway\":\"10.129.2.1\"}],\"dns\":{}},\"PodIFInfo\":null,\"KubeAuth\":{\"kube-api-server\":\"htt
ps://api-int.zzhao490922.qe.devcluster.openshift.com:6443\",\"kube-api-token\"[...]\"}}", err <nil>


***** When inspecting the must-gather with the omg tool, I see indeed that the pod is in the running state and was assigned the second IP address from the run 2 of addLogicalPort:
$ omg get pods -o wide
NAME                                  READY  STATUS   RESTARTS  AGE    IP           NODE
network-check-target-97x8b            0/1    Running  0         6h53m  10.129.2.4   ip-10-0-167-199.us-east-2.compute.internal
 
 
Now, the pod setup is correct (pod status = running), but we do see that the container inside the pod is not ready. 

$ omg get events
LAST SEEN  TYPE     REASON      OBJECT                          MESSAGE
3m17s      Warning  ProbeError  pod/network-check-target-97x8b  Readiness probe error: Get "http://10.129.2.4:8080/": dial tcp 10.129.2.4:8080: connect: no route to host

Timestamps for this event are included namespaces/openshift-network-diagnostics/core/events.yaml, but there are no more details in kubelet logs.

This seems to be a problem with the container image itself rather than the podsetup, but of course if I can get access to a running cluster with this problem, I can try to figure out more.

Thanks!