Generic healing should work with ovs forwarder

[ljkiraly]

Expected Behavior

NSM should restore after forwarder death.

Current Behavior

Basic setup of NSM was used, containing forwarder-ovs . The connection between NSC and NSE is using local 'kernel' mechanism. After forwarder restart (local or remote) the connection does not restored (checked more then 10 minutes after forwarder restart)

Failure Information

No data path healing is expected, but the generic healing should work.

Steps to Reproduce

1. Start a basic NSM setup with ovs-forwarder

kubectl apply -k https://github.com/networkservicemesh/deployments-k8s/examples/ovs?ref=2ea1a26c7ddebd212224560e2706d9f1b03f140b

2. Start the NSE and NSC based on the case 'Test local forwarder death'

kubectl apply -k https://github.com/networkservicemesh/deployments-k8s/examples/heal/local-forwarder-death?ref=2ea1a26c7ddebd212224560e2706d9f1b03f140b
 
# Wait for applications ready:
kubectl wait --for=condition=ready --timeout=1m pod -l app=alpine -n ns-local-forwarder-death
kubectl wait --for=condition=ready --timeout=1m pod -l app=nse-kernel -n ns-local-forwarder-death

 # Ping from NSC to NSE:
kubectl exec pods/alpine -n ns-local-forwarder-death -- ping -c 4 172.16.1.100

 # Ping from NSE to NSC:
kubectl exec deployments/nse-kernel -n ns-local-forwarder-death -- ping -c 4 172.16.1.101

3. Delete the local forwarder

# Find nsc node:
NSC_NODE=$(kubectl get pods -l app=alpine -n ns-local-forwarder-death --template '{{range .items}}{{.spec.nodeName}}{{"\n"}}{{end}}')

 # Find local Forwarder:
FORWARDER=$(kubectl get pods -l 'app in (forwarder-vpp,forwarder-ovs)' --field-selector spec.nodeName==${NSC_NODE} -n nsm-system --template '{{range .items}}{{.metadata.name}}{{"\n"}}{{end}}')

# Remove local Forwarder and wait for a new one to start:
kubectl delete pod -n nsm-system ${FORWARDER}

kubectl wait --for=condition=ready --timeout=1m pod -l 'app in (forwarder-vpp,forwarder-ovs)' --field-selector spec.nodeName==${NSC_NODE} -n nsm-system

6. Wait some time and check if the connection restores

 # Ping from NSC to NSE:
kubectl exec pods/alpine -n ns-local-forwarder-death -- ping -c 4 172.16.1.100


 # Ping from NSE to NSC:
kubectl exec deployments/nse-kernel -n ns-local-forwarder-death -- ping -c 4 172.16.1.101

Failure Logs

local-forwarder-death.zip

[ljkiraly]

Seems that NSM_MAX_TOKEN_LIFETIME default setting is 24h instead of 10 minutes lifetime used in vpp forwarder.
I am to repeat the test with the NSM_MAX_TOKEN_LIFETIME=10min setting.

[ljkiraly]

Same result with NSM_MAX_TOKEN_LIFETIME=10min setting.

[denis-tingaikin]

@ljkiraly Could you also attach logs from the NSC? It could help with investigation.

[ljkiraly]

@denis-tingaikin Just realized that I missed to add the logs to the zip file. I updated the attachment and I adding the nsc logs here as well.
BTW seems to me that the forwarder set the interfaces as expected. NSC detects data path failure and reset the connection.

{forwarder log}
Sep 12 16:53:02.609�[37m [TRAC] [id:81d3be5c-cad4-4811-a6ef-5c4da4306c30] [type:networkService] �[0m(57.1)                                                           request-response={"id":"81d3be5c-cad4-4811-a6ef-5c4da4306c30","network_service":"local-forwarder-death","mechanism":{"cls":"LOCAL","type":"KERNEL","parameters":{"inodeURL":"inode://4/4026534093","name":"local-forw-f280","supportsVlan":"true"}},"context":{"ip_context":{"src_ip_addrs":["172.16.1.1/32"],"dst_ip_addrs":["172.16.1.0/32"],"src_routes":[{"prefix":"172.16.1.0/32"}],"dst_routes":[{"prefix":"172.16.1.1/32"}],"excluded_prefixes":["10.96.0.0/16","10.244.0.0/16"]},"dns_context":{}},"labels":{"nodeName":"kind-worker","podName":"alpine"},"path":{"index":2,"path_segments":[{"name":"alpine-b626de3e-acbb-4b4e-9c31-a81a43ca7f2b","id":"alpine-b626de3e-acbb-4b4e-9c31-a81a43ca7f2b-0","token":"eyJhbGciOiJFUzI1NiIsInR5cCI6IkpXVCJ9.eyJzdWIiOiJzcGlmZmU6Ly9rOHMubnNtL25zL25zLWxvY2FsLWZvcndhcmRlci1kZWF0aC9wb2QvYWxwaW5lIiwiYXVkIjpbInNwaWZmZTovL2s4cy5uc20vbnMvbnNtLXN5c3RlbS9wb2QvbnNtZ3ItZjR2NGgiXSwiZXhwIjoxNjk0NTM4MTgyfQ.oYJibfRxCXQIcNEyvF_lWY-fMjzuBaktrGXvDcNnznI6X4z44MNRCtVd-NHJOGPtaAoxDUghUDYeE_6WcpFtxQ","expires":{"seconds":1694538182,"nanos":388924276}},{"name":"nsmgr-f4v4h","id":"b4b84141-cc9e-4e7b-be7f-cc3b89816e4a","token":"eyJhbGciOiJFUzI1NiIsInR5cCI6IkpXVCJ9.eyJzdWIiOiJzcGlmZmU6Ly9rOHMubnNtL25zL25zbS1zeXN0ZW0vcG9kL25zbWdyLWY0djRoIiwiYXVkIjpbInNwaWZmZTovL2s4cy5uc20vbnMvbnNtLXN5c3RlbS9wb2QvZm9yd2FyZGVyLW92cy1iOTcybiJdLCJleHAiOjE2OTQ1MzgxODJ9.l5ssrZ5w4uhRW30WnjD3XAvti8S7TvszBtkw6ogCyltUwNZgX8TgRXQaqgEuBv9Zrv31Kl-8dhLWcnncrvMGfw","expires":{"seconds":1694538182,"nanos":407122067}},{"name":"forwarder-ovs-b972n","id":"81d3be5c-cad4-4811-a6ef-5c4da4306c30","token":"eyJhbGciOiJFUzI1NiIsInR5cCI6IkpXVCJ9.eyJzdWIiOiJzcGlmZmU6Ly9rOHMubnNtL25zL25zbS1zeXN0ZW0vcG9kL2ZvcndhcmRlci1vdnMtYjk3Mm4iLCJhdWQiOlsic3BpZmZlOi8vazhzLm5zbS9ucy9ucy1sb2NhbC1mb3J3YXJkZXItZGVhdGgvcG9kL25zZS1rZXJuZWwtNmQ2NDc3ODc1Zi1ndGdkNyJdLCJleHAiOjE2OTQ1MzgxODJ9.ghEOIYMc0eYbRBxo269dicBL-_40o5vPxIwGQecEAQ5roOqR1FQHvWKQ3SKU3wrGNf_ylkbykrM7nVvR2VRS1g","expires":{"seconds":1694538182,"nanos":482070996}},{"name":"nse-kernel-6d6477875f-gtgd7","id":"f2807884-5a41-4d88-9a42-58347aada4c1","token":"eyJhbGciOiJFUzI1NiIsInR5cCI6IkpXVCJ9.eyJzdWIiOiJzcGlmZmU6Ly9rOHMubnNtL25zL25zLWxvY2FsLWZvcndhcmRlci1kZWF0aC9wb2QvbnNlLWtlcm5lbC02ZDY0Nzc4NzVmLWd0Z2Q3IiwiYXVkIjpbInNwaWZmZTovL2s4cy5uc20vbnMvbnNtLXN5c3RlbS9wb2QvZm9yd2FyZGVyLW92cy1iOTcybiJdLCJleHAiOjE2OTQ1MzgxODJ9.V7oLhExCJrFkTwZYIG-LASq5vMT4HpMW-szmg2S5HVMJ8Qyww8cRK0_sTtX7bBQz9_uRnWnJw5Pb8TViuRW4jw","expires":{"seconds":1694538182,"nanos":485355075}}]},"network_service_endpoint_name":"nse-kernel-6d6477875f-gtgd7","payload":"ETHERNET"}
Sep 12 16:53:02.611�[37m [TRAC] [id:81d3be5c-cad4-4811-a6ef-5c4da4306c30] [type:networkService] �[0m(53.1)                                                       request-response-diff={"mechanism":{"parameters":{"inodeURL":"file:///proc/799735/fd/16"}}}
Sep 12 16:53:02.649�[36m [INFO] [id:81d3be5c-cad4-4811-a6ef-5c4da4306c30] [type:networkService] �[0m(42.1)                                            /proc/sys/net/ipv4/ping_group_range was set to 0 2147483647
Sep 12 16:53:02.653�[37m [DEBU] [id:81d3be5c-cad4-4811-a6ef-5c4da4306c30] [Dst:172.16.1.1/32] [Flags:0] [Gw:<nil>] [Scope:link] [duration:531.547µs] [link.Name:local-forw-f280] [netlink:RouteReplace] [type:networkService] �[0m(38.1)                                        completed
Sep 12 16:53:02.654�[37m [DEBU] [id:81d3be5c-cad4-4811-a6ef-5c4da4306c30] [Dst:172.16.1.1/32] [Flags:0] [Gw:<nil>] [Scope:universe] [duration:145.383µs] [link.Name:local-forw-f280] [netlink:RouteReplace] [type:networkService] �[0m(38.2)                                        completed
Sep 12 16:53:02.798�[37m [TRAC] [id:81d3be5c-cad4-4811-a6ef-5c4da4306c30] [type:networkService] �[0m(33.2)                                   request-response-diff={"mechanism":{"parameters":{"-supportsVlan":"true","inodeURL":"file:///proc/799735/fd/13","name":"nsm-1"}}}
Sep 12 16:53:02.801�[37m [TRAC] [id:81d3be5c-cad4-4811-a6ef-5c4da4306c30] [type:networkService] �[0m(24.1)                          request-diff={"connection":{"mechanism":{"cls":"LOCAL","parameters":{"+inodeURL":"file:///proc/799735/fd/13","+name":"nsm-1"},"type":"KERNEL"},"path":{"path_segments":{"2":{"expires":{"nanos":482070996},"token":"eyJhbGciOiJFUzI1NiIsInR5cCI6IkpXVCJ9.eyJzdWIiOiJzcGlmZmU6Ly9rOHMubnNtL25zL25zbS1zeXN0ZW0vcG9kL2ZvcndhcmRlci1vdnMtYjk3Mm4iLCJhdWQiOlsic3BpZmZlOi8vazhzLm5zbS9ucy9ucy1sb2NhbC1mb3J3YXJkZXItZGVhdGgvcG9kL25zZS1rZXJuZWwtNmQ2NDc3ODc1Zi1ndGdkNyJdLCJleHAiOjE2OTQ1MzgxODJ9.ghEOIYMc0eYbRBxo269dicBL-_40o5vPxIwGQecEAQ5roOqR1FQHvWKQ3SKU3wrGNf_ylkbykrM7nVvR2VRS1g"},"3":{"expires":{"nanos":485355075,"seconds":1694538182},"token":"eyJhbGciOiJFUzI1NiIsInR5cCI6IkpXVCJ9.eyJzdWIiOiJzcGlmZmU6Ly9rOHMubnNtL25zL25zLWxvY2FsLWZvcndhcmRlci1kZWF0aC9wb2QvbnNlLWtlcm5lbC02ZDY0Nzc4NzVmLWd0Z2Q3IiwiYXVkIjpbInNwaWZmZTovL2s4cy5uc20vbnMvbnNtLXN5c3RlbS9wb2QvZm9yd2FyZGVyLW92cy1iOTcybiJdLCJleHAiOjE2OTQ1MzgxODJ9.V7oLhExCJrFkTwZYIG-LASq5vMT4HpMW-szmg2S5HVMJ8Qyww8cRK0_sTtX7bBQz9_uRnWnJw5Pb8TViuRW4jw"}}},"state":0},"mechanism_preferences":{"0":{"parameters":{"+inodeURL":"file:///proc/799735/fd/13","+name":"nsm-1","-supportsVlan":"true"}}}}
Sep 12 16:53:02.802�[36m [INFO] [id:81d3be5c-cad4-4811-a6ef-5c4da4306c30] [type:networkService] �[0m(23.1)                         /proc/sys/net/ipv4/ping_group_range was set to 0 2147483647
Sep 12 16:53:03.819�[37m [DEBU] [id:81d3be5c-cad4-4811-a6ef-5c4da4306c30] [Dst:172.16.1.0/32] [Flags:0] [Gw:<nil>] [Scope:link] [duration:127.581µs] [link.Name:nsm-1] [netlink:RouteReplace] [type:networkService] �[0m(21.1)                       completed
Sep 12 16:53:03.819�[37m [DEBU] [id:81d3be5c-cad4-4811-a6ef-5c4da4306c30] [Dst:172.16.1.0/32] [Flags:0] [Gw:<nil>] [Scope:universe] [duration:85.979µs] [link.Name:nsm-1] [netlink:RouteReplace] [type:networkService] �[0m(21.2)                       completed
Sep 12 16:53:03.824�[37m [TRAC] [id:81d3be5c-cad4-4811-a6ef-5c4da4306c30] [type:networkService] �[0m(11.1)             request-response-diff={"mechanism":{"parameters":{"inodeURL":"inode://4/4026532527"}}}

Sep 12 16:51:38.061�[31m [ERRO] [id:alpine-b626de3e-acbb-4b4e-9c31-a81a43ca7f2b-0] [dstIP:172.16.1.0] [srcIP:172.16.1.1] [type:networkService] �[0m(7.1)         No packets received
Sep 12 16:51:38.061�[33m [WARN] [id:alpine-b626de3e-acbb-4b4e-9c31-a81a43ca7f2b-0] [heal:eventLoop] [type:networkService] �[0m(7.2)         Data plane is down
Sep 12 16:51:38.061�[37m [DEBU] [id:alpine-b626de3e-acbb-4b4e-9c31-a81a43ca7f2b-0] [heal:eventLoop] [type:networkService] �[0m(7.3)         Reconnect with reselect
Sep 12 16:51:38.061�[37m [DEBU] [id:alpine-b626de3e-acbb-4b4e-9c31-a81a43ca7f2b-0] [heal:eventLoop] [type:networkService] �[0m(7.4)         received eventIn: <nil>, err: rpc error: code = Canceled desc = context canceled

alpine-cmd-nsc.txt

[NikitaSkrynnik]

@ljkiraly Hello, it looks like there is a problem with closing a connection. I tested it the next way:

I modified NSC to do:

• first request
• 1m sleep
• close a connection from the first request
• 15s sleep
• second request with the same request.ID

resp, err := nsmClient.Request(ctx, request)
if err != nil {
	logger.Fatalf("failed connect to NSMgr: %v", err.Error())
}
logger.Infof("successfully connected to %v. Response: %v", u.NetworkService(), resp)

time.Sleep(time.Minute)
_, err = nsmClient.Close(ctx, resp)
if err != nil {
	logger.Infof("Error while closing a connection to %v. %s", u.NetworkService(), err.Error())
}

time.Sleep(time.Second * 15)
resp, err = nsmClient.Request(ctx, request)
if err != nil {
	logger.Fatalf("failed connect to NSMgr: %v", err.Error())
}

NSC fails to do the second request because there is an error in cmd-forwarder-ovs:

failed to find link local-forw-de4f: Link not found

---

If on the second request I use a new request, it passes without any errors on cmd-forwarder-ovs:

newID := "id-1"
request1 := &networkservice.NetworkServiceRequest{
	Connection: &networkservice.Connection{
		Id:             newID,
		NetworkService: u.NetworkService(),
		Labels:         u.Labels(),
	},
	MechanismPreferences: []*networkservice.Mechanism{
		u.Mechanism(),
	},
}

resp1, err := nsmClient.Request(ctx, request1)
if err != nil {
	logger.Fatalf("failed connect to NSMgr: %v", err.Error())
}

---

Could you please check all Closes in cmd-forwarder-ovs chain? It looks like cmd-forwarder-ovs doesn't delete something on Close.