[4.11] Node adding issue in OVN

[yaroslavkasatikov]

Hi team,
During to try find a hack until #1310 is resolved, we decided to add new spot nodes.
Some time it works, but now we faced in to new issue :(

Step to reproduce:

1. Delete stuck machine or delete spot instance
2. machine operator provisioned machine and switch them into "Running" state:

openshift-machine-api   worker-cron-7cwtg                                Running   c5.2xlarge   eu-central-1   eu-central-1c   11m     ip-10-0-218-219.eu-central-1.compute.internal   aws:///eu-central-1c/i-047a68eaabacb8fc5   running

3. Nodes started as not ready and stuck:

ip-10-0-218-219.eu-central-1.compute.internal   NotReady   cron,dev,spot,worker          8m11s   v1.24.0+9546431

4. I found in openshift-ovn-kubernetes that ovn-node started but ReadNess probe doesn't OK:

[cur@yaroslav-new ~]$ oc get pod -o wide -n openshift-ovn-kubernetes|grep  ip-10-0-218-219.eu-central-1.compute.internal
ovnkube-node-ndw6x     4/5     Running   1 (3m12s ago)    8m53s   10.0.218.219   ip-10-0-218-219.eu-central-1.compute.internal   <none>           <none>
[cur@yaroslav-new ~]$ oc logs ovnkube-node-ndw6x
error: a container name must be specified for pod ovnkube-node-ndw6x, choose one of: [ovn-controller ovn-acl-logging kube-rbac-proxy kube-rbac-proxy-ovn-metrics ovnkube-node]
[cur@yaroslav-new ~]$ oc logs ovnkube-node-ndw6x -c ovnkube-node --tail=10
I0815 05:42:53.007558    5475 node.go:375] Waiting for node ip-10-0-218-219.eu-central-1.compute.internal to start, no annotation found on node for subnet: node "ip-10-0-218-219.eu-central-1.compute.internal" has no "k8s.ovn.org/node-subnets" annotation
I0815 05:42:53.501820    5475 node.go:375] Waiting for node ip-10-0-218-219.eu-central-1.compute.internal to start, no annotation found on node for subnet: node "ip-10-0-218-219.eu-central-1.compute.internal" has no "k8s.ovn.org/node-subnets" annotation
I0815 05:42:54.001937    5475 node.go:375] Waiting for node ip-10-0-218-219.eu-central-1.compute.internal to start, no annotation found on node for subnet: node "ip-10-0-218-219.eu-central-1.compute.internal" has no "k8s.ovn.org/node-subnets" annotation
I0815 05:42:54.525571    5475 node.go:375] Waiting for node ip-10-0-218-219.eu-central-1.compute.internal to start, no annotation found on node for subnet: node "ip-10-0-218-219.eu-central-1.compute.internal" has no "k8s.ovn.org/node-subnets" annotation
I0815 05:42:55.001926    5475 node.go:375] Waiting for node ip-10-0-218-219.eu-central-1.compute.internal to start, no annotation found on node for subnet: node "ip-10-0-218-219.eu-central-1.compute.internal" has no "k8s.ovn.org/node-subnets" annotation
I0815 05:42:55.502110    5475 node.go:375] Waiting for node ip-10-0-218-219.eu-central-1.compute.internal to start, no annotation found on node for subnet: node "ip-10-0-218-219.eu-central-1.compute.internal" has no "k8s.ovn.org/node-subnets" annotation
I0815 05:42:56.001959    5475 node.go:375] Waiting for node ip-10-0-218-219.eu-central-1.compute.internal to start, no annotation found on node for subnet: node "ip-10-0-218-219.eu-central-1.compute.internal" has no "k8s.ovn.org/node-subnets" annotation
I0815 05:42:56.504082    5475 node.go:375] Waiting for node ip-10-0-218-219.eu-central-1.compute.internal to start, no annotation found on node for subnet: node "ip-10-0-218-219.eu-central-1.compute.internal" has no "k8s.ovn.org/node-subnets" annotation
I0815 05:42:57.011275    5475 node.go:375] Waiting for node ip-10-0-218-219.eu-central-1.compute.internal to start, no annotation found on node for subnet: node "ip-10-0-218-219.eu-central-1.compute.internal" has no "k8s.ovn.org/node-subnets" annotation
I0815 05:42:57.502013    5475 node.go:375] Waiting for node ip-10-0-218-219.eu-central-1.compute.internal to start, no annotation found on node for subnet: node "ip-10-0-218-219.eu-central-1.compute.internal" has no "k8s.ovn.org/node-subnets" annotation

5. on ovn master I can see this in log:

I0815 05:34:16.478814       1 egressqos.go:893] Processing sync for EgressQoS node ip-10-0-218-219.eu-central-1.compute.internal
I0815 05:34:16.478933       1 egressqos.go:896] Finished syncing EgressQoS node ip-10-0-218-219.eu-central-1.compute.internal : 142.479µs
E0815 05:34:16.478950       1 egressqos.go:876] ip-10-0-218-219.eu-central-1.compute.internal failed with : object not found
I0815 05:34:39.035910       1 obj_retry.go:1135] *v1.Pod retry create failed for openshift-network-diagnostics/network-check-target-7xf6h, will try again later: addLogicalPort failed for openshift-network-diagnostics/network-check-target-7xf6h: timed out waiting for logical switch in logical switch cache "ip-10-0-218-219.eu-central-1.compute.internal" subnet: error getting logical switch for node ip-10-0-218-219.eu-central-1.compute.internal: switch not in logical switch cache
I0815 05:34:39.036000       1 obj_retry.go:1135] *v1.Pod retry create failed for openshift-multus/network-metrics-daemon-qbgmg, will try again later: addLogicalPort failed for openshift-multus/network-metrics-daemon-qbgmg: timed out waiting for logical switch in logical switch cache "ip-10-0-218-219.eu-central-1.compute.internal" subnet: error getting logical switch for node ip-10-0-218-219.eu-central-1.compute.internal: switch not in logical switch cache

6. Checking multus:

cur@yaroslav-new ~]$ oc get pod -n  openshift-multus -o wide|grep ip-10-0-218-219.eu-central-1.compute.internal
multus-additional-cni-plugins-2m94l   1/1     Running             0               13m     10.0.218.219   ip-10-0-218-219.eu-central-1.compute.internal   <none>           <none>
multus-sk2p8                          1/1     Running             1 (2m32s ago)   13m     10.0.218.219   ip-10-0-218-219.eu-central-1.compute.internal   <none>           <none>
network-metrics-daemon-qbgmg          0/2     ContainerCreating   0               13m     <none>         ip-10-0-218-219.eu-central-1.compute.internal   <none>           <none>

[cur@yaroslav-new ~]$ oc logs multus-sk2p8 -n openshift-multus
2022-08-15T05:44:23+00:00 [cnibincopy] Successfully copied files in /usr/src/multus-cni/rhel8/bin/ to /host/opt/cni/bin/upgrade_6e80fa28-5e16-4fc7-8f12-0ce9602f3c60
2022-08-15T05:44:23+00:00 [cnibincopy] Successfully moved files in /host/opt/cni/bin/upgrade_6e80fa28-5e16-4fc7-8f12-0ce9602f3c60 to /host/opt/cni/bin/
2022-08-15T05:44:23+00:00 WARN: {unknown parameter "-"}
2022-08-15T05:44:23+00:00 Entrypoint skipped copying Multus binary.
2022-08-15T05:44:23+00:00 Generating Multus configuration file using files in /host/var/run/multus/cni/net.d...
2022-08-15T05:44:23+00:00 Attempting to find master plugin configuration, attempt 0
2022-08-15T05:44:28+00:00 Attempting to find master plugin configuration, attempt 5
2022-08-15T05:44:33+00:00 Attempting to find master plugin configuration, attempt 10
2022-08-15T05:44:38+00:00 Attempting to find master plugin configuration, attempt 15
2022-08-15T05:44:43+00:00 Attempting to find master plugin configuration, attempt 20
.....
2022-08-15T05:44:48+00:00 Attempting to find master plugin configuration, attempt 190

oc describe pod network-metrics-daemon-qbgmg -n openshift-multus
....
Events:
  Type     Reason                  Age                    From               Message
  ----     ------                  ----                   ----               -------
  Normal   Scheduled               14m                    default-scheduler  Successfully assigned openshift-multus/network-metrics-daemon-qbgmg to ip-10-0-218-219.eu-central-1.compute.internal by ip-10-0-133-210
  Warning  ErrorAddingLogicalPort  14m (x2 over 14m)      controlplane       addLogicalPort failed for openshift-multus/network-metrics-daemon-qbgmg: timed out waiting for logical switch in logical switch cache "ip-10-0-218-219.eu-central-1.compute.internal" subnet: error getting logical switch for node ip-10-0-218-219.eu-central-1.compute.internal: switch not in logical switch cache
  Warning  FailedMount             13m (x7 over 14m)      kubelet            MountVolume.SetUp failed for volume "metrics-certs" : object "openshift-multus"/"metrics-daemon-secret" not registered
  Warning  NetworkNotReady         4m13s (x301 over 14m)  kubelet            network is not ready: container runtime network not ready: NetworkReady=false reason:NetworkPluginNotReady message:Network plugin returns error: No CNI configuration file in /etc/kubernetes/cni/net.d/. Has your network provider started?

[cur@yaroslav-new ~]$ oc logs multus-additional-cni-plugins-2m94l -n openshift-multus
[cur@yaroslav-new ~]$

7. Fortunately the issue solving by deleting ovn-master pod. When pod restated, ovn-node check finished and all containers started.

I0815 05:50:22.161276   10750 node.go:375] Waiting for node ip-10-0-218-219.eu-central-1.compute.internal to start, no annotation found on node for subnet: node "ip-10-0-218-219.eu-central-1.compute.internal" has no "k8s.ovn.org/node-subnets" annotation
I0815 05:50:22.663878   10750 node.go:375] Waiting for node ip-10-0-218-219.eu-central-1.compute.internal to start, no annotation found on node for subnet: node "ip-10-0-218-219.eu-central-1.compute.internal" has no "k8s.ovn.org/node-subnets" annotation
I0815 05:50:23.160688   10750 node.go:375] Waiting for node ip-10-0-218-219.eu-central-1.compute.internal to start, no annotation found on node for subnet: node "ip-10-0-218-219.eu-central-1.compute.internal" has no "k8s.ovn.org/node-subnets" annotation
I0815 05:50:23.661682   10750 node.go:375] Waiting for node ip-10-0-218-219.eu-central-1.compute.internal to start, no annotation found on node for subnet: node "ip-10-0-218-219.eu-central-1.compute.internal" has no "k8s.ovn.org/node-subnets" annotation
I0815 05:50:24.161117   10750 node.go:375] Waiting for node ip-10-0-218-219.eu-central-1.compute.internal to start, no annotation found on node for subnet: node "ip-10-0-218-219.eu-central-1.compute.internal" has no "k8s.ovn.org/node-subnets" annotation
I0815 05:50:24.663690   10750 node.go:375] Waiting for node ip-10-0-218-219.eu-central-1.compute.internal to start, no annotation found on node for subnet: node "ip-10-0-218-219.eu-central-1.compute.internal" has no "k8s.ovn.org/node-subnets" annotation
I0815 05:50:25.168201   10750 node.go:383] Node ip-10-0-218-219.eu-central-1.compute.internal ready for ovn initialization with subnet 10.132.4.0/23
I0815 05:50:25.168225   10750 ovs.go:200] Exec(3): /usr/bin/ovn-sbctl --private-key=/ovn-cert/tls.key --certificate=/ovn-cert/tls.crt --bootstrap-ca-cert=/ovn-ca/ca-bundle.crt --db=ssl:10.0.133.210:9642,s
sl:10.0.171.146:9642,ssl:10.0.201.118:9642 --timeout=15 --no-leader-only --columns=up list Port_Binding

Both issues (this and #1310) make my cluster absolutely unpredictable :(

[vrutkovs]

Please attach (or upload to the public file sharing service) must-gather archive

[yaroslavkasatikov]

Sorry, forgot to do it.
https://dropmefiles.com/qD2Mt

The must-gather collected at the moment when one nodes stuck in NotReady

[yaroslavkasatikov]

Unfortunately, the issue is still ongoing :( Master nodes restarts didn't help

[yaroslavkasatikov]

@vrutkovs Is there any chance to rollback cluster?

[vrutkovs]

This should be possible, but I'd rather recommend restoring from etcd snapshot

[yaroslavkasatikov]

found master in NotReady.

[yaroslavkasatikov]

Hi team,
The issue is ongoing. I haven't updated cluster yet to the latest version or rollback. But network can't be initiated on just-added nodes before ovn master pod restarting. All details are the same to described above