Investigate why forwarder could restart too long

[denis-tingaikin]

Steps to reproduce

Repeat steps from https://drive.google.com/file/d/1Pwd7T6iYPItXEqjx_Yd5NfPE-T0zgUy5

[glazychev-art]

Most likely, this behavior can be explained and there are actually no outliers here.
As I understand, we are concerned about the page 11 of the document - "Upgrade from NSM v1.2.0 to v1.4.0" - forwarder-vpp-6t7x7

The forwarder will be in a ready state only when it can serve GRPC-clients. We have the forwarder readinessProbe:
command: ["/bin/grpc-health-probe", "-spiffe", "-addr=unix:///listen.on.sock"]
But before that, it needs to get certificates from the spire-agent - usually it takes about 3-5 sec.

On page 11 we can see that the upgrade of the NSM is happening gradually including spire-agents.
But what if the forwarder upgrade happened before the spire-agent? Let's take a look:

spire-agent-gqgr2 and the forwarder-vpp-6t7x7 may be on the same node.
I think the difference between the readiness of pods (about 3 seconds) is understandable (besides, we use periodSeconds: 1)

[szvincze]

Coming back to this topic after long time again...

Since the presentation there were several changes in our configuration that made the upgrade faster. But the question is still valid about the forwarder startup time or mainly the traffic outage period.

In the worker node reboot and forwarder-vpp pod restart scenarios we observe quite big differences regarding the period of time while the traffic does not work.
As I checked the startup time of the forwarder-vpp pods after worker node reboot and forwarder-vpp pod restart. The forwarder's startup phases completed within 4-5 seconds which seems to be normal.
In a small and simple configuration it takes additional few seconds to handle traffic again. But it sometimes takes just 10 seconds from the pod restart, sometimes it takes ~20 seconds and sometimes even more than 30 seconds.

We also measured it in a bigger environment where we got various figures between 60 and 120 seconds or even more.

Is there a theory that could explain these huge differences?

[szvincze]

I managed to reproduce the issue when we restart a forwarder then the traffic cannot be recovered just a few minutes later. After some investigation it turned out when the forwarder restarted, only one of the NSM interfaces was re-created in the NSC pod, therefore the traffic failed for the affected network service.

The setup is based on NSM v1.11.1 basic kernel to ethernet to kernel example. I used a kind cluster with 4 worker nodes.
I deployed 4 NSCs, one for each node and 2 NSEs (one for IPv4 and one for IPv6), their location does not matter.
I added a container with ctraffic tool included into NSC and NSE pods, for this purpose I used registry.nordix.org/cloud-native/nsm/rvm-tester:ctraffic image.

Then I started two ctraffic servers in the NSC pods.
For example nsc-kernel-5f485bf7c-8gz6c:

ctraffic -server -address 172.16.1.1:5003&
ctraffic -server -address [100:100::1]:5003&

On the NSEs I ran ctraffic as clients for the matching servers on the NSCs, like below:

kubectl exec pods/nse-kernel4-5dd67f7f46-pjrn8 -n ns-kernel2ethernet2kernel -c ctraffic -- ctraffic -address 172.16.1.1:5003 -monitor -nconn 100 -rate 50 -timeout 600s

These clients send traffic to the addressed server via 100 connections with rate of 50 KB/s for 10 minutes. (It can happen that sometimes the ctraffic client reaches the reconnect limit [1000] and needs to be restarted.)

When all the instances are running and connected properly, and the traffic is steady (no failing or connecting state, and no drops), the tool shows similar output:

Conn act/fail/connecting: 100/0/0, Packets send/rec/dropped: 25519/24819/0
Conn act/fail/connecting: 100/0/0, Packets send/rec/dropped: 25567/24867/0
Conn act/fail/connecting: 100/0/0, Packets send/rec/dropped: 25619/24919/0
Conn act/fail/connecting: 100/0/0, Packets send/rec/dropped: 25667/24967/0
Conn act/fail/connecting: 100/0/0, Packets send/rec/dropped: 25719/25019/0
Conn act/fail/connecting: 100/0/0, Packets send/rec/dropped: 25767/25067/0
Conn act/fail/connecting: 100/0/0, Packets send/rec/dropped: 25819/25119/0
Conn act/fail/connecting: 100/0/0, Packets send/rec/dropped: 25867/25167/0

Then I started deleting the forwarder pods one by one in a cycle. I always wait until the traffic is steady again after the new forwarder started up then delete the next one and check if the traffic recovered, like below:

Conn act/fail/connecting: 59/541/41, Packets send/rec/dropped: 8405/7806/0
Conn act/fail/connecting: 1/599/99, Packets send/rec/dropped: 8406/7806/0
Conn act/fail/connecting: 0/600/100, Packets send/rec/dropped: 8406/7806/0
Conn act/fail/connecting: 0/600/100, Packets send/rec/dropped: 8406/7806/0
Conn act/fail/connecting: 0/600/100, Packets send/rec/dropped: 8406/7806/0
Conn act/fail/connecting: 0/600/100, Packets send/rec/dropped: 8406/7806/0
Conn act/fail/connecting: 0/600/100, Packets send/rec/dropped: 8406/7806/0
Conn act/fail/connecting: 0/600/100, Packets send/rec/dropped: 8406/7806/0
Conn act/fail/connecting: 0/600/100, Packets send/rec/dropped: 8406/7806/0
Conn act/fail/connecting: 100/600/0, Packets send/rec/dropped: 8426/7826/0
Conn act/fail/connecting: 100/600/0, Packets send/rec/dropped: 8472/7872/0
Conn act/fail/connecting: 100/600/0, Packets send/rec/dropped: 8526/7926/0
Conn act/fail/connecting: 100/600/0, Packets send/rec/dropped: 8572/7972/0

After some iterations the traffic to one of the NSCs did not get connected just after few minutes.
As I checked the NSM interfaces in the NSC I realized that the one for IPv6 traffic was missing. In another successful reproduction attempt the same happened but with the one for IPv4 service. And after few minutes the interface was recreated and the traffic connected again.

I tried to reproduce it with less nodes, less NSEs, also with ping instead of ctraffic without success, however most probably there are more ways to catch the same issue.

I collected some logs but unfortunately the others were already rotated.

@denis-tingaikin: Can you please check if there could be a fault in the healing mechanism that causes this behavior?

[glazychev-art]

@szvincze
I looked at the logs.
Question: is NSM_LIVENESSCHECK enabled for NSC?