search

networkservicemesh / sdk

Apache License 2.0
33 stars 36 forks source link

invoke remote interpose endpoint when actual endpoint not found #1067

Open pperiyasamy opened 3 years ago

pperiyasamy commented 3 years ago

Expected Behavior

The NSC and NSE are running in different worker nodes which are connected through veth pair <-> vxlan tunnel <-> veth pairvWire connection with this example using ovs forwarder.

when kubectl delete -k . is run, all of the network resources created by ovs forwarder should be cleaned up at both sides.

Current Behavior

On the endpoint side, there are no resources cleaned up and forwarder chain element's Close handler not invoked. But the network resources are cleaned up properly on client side. This seems to be because of endpoint pod is deleted first followed by client pod.

Failure Information (for bugs)

Here is the logs at the client side forwarder.

Aug 16 07:28:37.402 [INFO] [name:forwarder-ovs-lb2lj] (1) ⎆ sdk/pkg/networkservice/common/updatepath/updatePathServer.Close() span=799e6326100fb0ea:386e8981662d4458:198046b81daaaf28:1
Aug 16 07:28:37.403 [INFO] [name:forwarder-ovs-lb2lj] (1.1)   request={"id":"751b4178-99a8-41bb-baf8-01e68f695593","network_service":"icmp-responder","mechanism":{"cls":"LOCAL","type":"KERNEL","parameters":{"inodeURL":"inode://3/4026535414","name":"nsm-1"}},"context":{"ip_context":{"src_ip_addrs":["172.16.1.101/32"],"dst_ip_addrs":["172.16.1.100/32"],"src_routes":[{"prefix":"172.16.1.100/32"}],"dst_routes":[{"prefix":"172.16.1.101/32"}]},"dns_context":{}},"labels":{"nodeName":"dl380-004"},"path":{"index":1,"path_segments":[{"name":"nsc-kernel-cb878b7cf-hqv8f","id":"nsc-kernel-cb878b7cf-hqv8f-0","token":"eyJhbGciOiJFUzI1NiIsInR5cCI6IkpXVCJ9.eyJhdWQiOiJzcGlmZmU6Ly9leGFtcGxlLm9yZy9ucy9uc20tc3lzdGVtL3NhL2RlZmF1bHQiLCJleHAiOjE2MjkwOTkyMTMsInN1YiI6InNwaWZmZTovL2V4YW1wbGUub3JnL25zL25zLWM1bG1xL3NhL2RlZmF1bHQifQ.cMZVH7HJC1wkkDgD_cnhsMHXkOtvrUsfrLalgV1KSHS1etjJauOS2wVAhb1m1H-XniD33cCLTfiFgNvFddTVzQ","expires":{"seconds":1629099213,"nanos":102726858}},{"name":"nsmgr-jfsn8","id":"751b4178-99a8-41bb-baf8-01e68f695593","token":"eyJhbGciOiJFUzI1NiIsInR5cCI6IkpXVCJ9.eyJhdWQiOiJzcGlmZmU6Ly9leGFtcGxlLm9yZy9ucy9ucy1jNWxtcS9zYS9kZWZhdWx0IiwiZXhwIjoxNjI5MDk5NTE3LCJzdWIiOiJzcGlmZmU6Ly9leGFtcGxlLm9yZy9ucy9uc20tc3lzdGVtL3NhL2RlZmF1bHQifQ.xol-3Rmg8dYeOgJqp_bUpqe8xBvWrc_54BOFupEqYRi8ojShpnnPcJpUmR-sfXxzEuoZO0Ll3A2b5nbSC5rXUQ","expires":{"seconds":1629099517,"nanos":3680363}},{"name":"forwarder-ovs-lb2lj","id":"282faf67-e439-4b08-88d4-549ecfbdfdb7","token":"eyJhbGciOiJFUzI1NiIsInR5cCI6IkpXVCJ9.eyJhdWQiOiJzcGlmZmU6Ly9leGFtcGxlLm9yZy9ucy9uc20tc3lzdGVtL3NhL2RlZmF1bHQiLCJleHAiOjE2MjkxMDEzMTcsInN1YiI6InNwaWZmZTovL2V4YW1wbGUub3JnL25zL25zbS1zeXN0ZW0vc2EvZGVmYXVsdCJ9.jJAqvbcJ3ummEGf1H280H-swrs6A5OrBguGFemgWAsxdtoydyfpmBoAqDmQNBZQJItb4AabI1W6Ndf6AXfgXCw","expires":{"seconds":1629101317}},{"name":"nsmgr-jfsn8","id":"72f5586e-f534-40e1-9fa0-33f93d651235","token":"eyJhbGciOiJFUzI1NiIsInR5cCI6IkpXVCJ9.eyJhdWQiOiJzcGlmZmU6Ly9leGFtcGxlLm9yZy9ucy9uc20tc3lzdGVtL3NhL2RlZmF1bHQiLCJleHAiOjE2MjkwOTk0NTUsInN1YiI6InNwaWZmZTovL2V4YW1wbGUub3JnL25zL25zbS1zeXN0ZW0vc2EvZGVmYXVsdCJ9.muCEAquEcqKu_JCSl3T0ZvYPUuHbCEnDMG2T3q_Pyp0MpHhsdYpwY7_xfenpBq1z2k6gIg0cHd14zIJ-lWRnPA","expires":{"seconds":1629099455,"nanos":428071588}},{"name":"nsmgr-6rnxw","id":"aeffa3f8-1088-47fc-9666-a00b0b20e21a","token":"eyJhbGciOiJFUzI1NiIsInR5cCI6IkpXVCJ9.eyJhdWQiOiJzcGlmZmU6Ly9leGFtcGxlLm9yZy9ucy9uc20tc3lzdGVtL3NhL2RlZmF1bHQiLCJleHAiOjE2MjkwOTk0NTUsInN1YiI6InNwaWZmZTovL2V4YW1wbGUub3JnL25zL25zbS1zeXN0ZW0vc2EvZGVmYXVsdCJ9.gjvUWyXp40vVE6fqeaUj3bJocMwzCgJTX9d73-SVzqBbWE41p0kcbFUMcG9EC7al3OPNhJk4QsNsLmFbLz0m3g","expires":{"seconds":1629099455,"nanos":511622540}},{"name":"forwarder-ovs-4xcwc","id":"94c26a80-1411-4dba-9cd4-1221b594a3e6","token":"eyJhbGciOiJFUzI1NiIsInR5cCI6IkpXVCJ9.eyJhdWQiOiJzcGlmZmU6Ly9leGFtcGxlLm9yZy9ucy9uc20tc3lzdGVtL3NhL2RlZmF1bHQiLCJleHAiOjE2MjkxMDE0MDAsInN1YiI6InNwaWZmZTovL2V4YW1wbGUub3JnL25zL25zbS1zeXN0ZW0vc2EvZGVmYXVsdCJ9.HKKZTwvXKDmH--j7JwWwKEuGb1ewcligsngptX_wveC11ykZiE_29taOal3ApIb4d00EB-SuZsh9IDgwrp51qA","expires":{"seconds":1629101400}},{"name":"nsmgr-6rnxw","id":"26da1d03-5eb9-416e-82f3-33bc5ce9c78c","token":"eyJhbGciOiJFUzI1NiIsInR5cCI6IkpXVCJ9.eyJhdWQiOiJzcGlmZmU6Ly9leGFtcGxlLm9yZy9ucy9ucy1jNWxtcS9zYS9kZWZhdWx0IiwiZXhwIjoxNjI5MDk5NDU1LCJzdWIiOiJzcGlmZmU6Ly9leGFtcGxlLm9yZy9ucy9uc20tc3lzdGVtL3NhL2RlZmF1bHQifQ.KurfymBbe0c8Zauq6J1wcST3oj3utzGAmE-Ok4_mSE5nmN_-_Jl38TUGeEQ6SD6-bpnvvn2Q-ttgGU1m2Fhieg","expires":{"seconds":1629099455,"nanos":607075570}},{"name":"nse-kernel-945c556db-5l5kn","id":"44f8f3e4-2aa5-4754-9794-8fe49a78a31b","token":"eyJhbGciOiJFUzI1NiIsInR5cCI6IkpXVCJ9.eyJhdWQiOiJzcGlmZmU6Ly9leGFtcGxlLm9yZy9ucy9uc20tc3lzdGVtL3NhL2RlZmF1bHQiLCJleHAiOjE2MjkwOTk0NTUsInN1YiI6InNwaWZmZTovL2V4YW1wbGUub3JnL25zL25zLWM1bG1xL3NhL2RlZmF1bHQifQ.ciu3Zs2PFb7BSG2gzjN8dkXDMr6-jQucpWsRxUllqx_t-_V_CxCHAMNQDw8V0Rm51JIb47YJCYR5SzwyzDBCvg","expires":{"seconds":1629099455,"nanos":703069874}}]},"network_service_endpoint_name":"8c906f88-002a-4732-8764-71de19c1f6d5-nse-kernel-945c556db-5l5kn","payload":"ETHERNET"} span=799e6326100fb0ea:386e8981662d4458:198046b81daaaf28:1
Aug 16 07:28:37.403 [INFO] [name:forwarder-ovs-lb2lj] (1.2)   request-diff={"id":"282faf67-e439-4b08-88d4-549ecfbdfdb7","path":{"index":2}} span=799e6326100fb0ea:386e8981662d4458:198046b81daaaf28:1
Aug 16 07:28:37.403 [INFO] [name:forwarder-ovs-lb2lj] (2)  ⎆ sdk/pkg/networkservice/common/authorize/authorizeServer.Close() span=799e6326100fb0ea:207e2a788b8d78f5:386e8981662d4458:1
Aug 16 07:28:37.403 [INFO] [name:forwarder-ovs-lb2lj] (3)   ⎆ sdk/pkg/networkservice/common/serialize/serializeServer.Close() span=799e6326100fb0ea:7fcfc3ddd1115c9e:207e2a788b8d78f5:1
Aug 16 07:28:37.403 [INFO] [name:forwarder-ovs-lb2lj] (4)    ⎆ sdk/pkg/networkservice/common/timeout/timeoutServer.Close() span=799e6326100fb0ea:0d1d030e20f6faed:7fcfc3ddd1115c9e:1
Aug 16 07:28:37.404 [INFO] [name:forwarder-ovs-lb2lj] (5)     ⎆ sdk/pkg/networkservice/utils/metadata/metadataServer.Close() span=799e6326100fb0ea:64afdb562e842790:0d1d030e20f6faed:1
Aug 16 07:28:37.404 [INFO] [name:forwarder-ovs-lb2lj] (6)      ⎆ sdk/pkg/networkservice/common/monitor/monitorServer.Close() span=799e6326100fb0ea:5c701854c16e4b7f:64afdb562e842790:1
Aug 16 07:28:37.404 [INFO] [name:forwarder-ovs-lb2lj] (7)       ⎆ sdk/pkg/networkservice/common/updatetoken/updateTokenServer.Close() span=799e6326100fb0ea:7b1336a7e51bcbc3:5c701854c16e4b7f:1
Aug 16 07:28:37.404 [INFO] [name:forwarder-ovs-lb2lj] (7.1)         request-diff={"path":{"path_segments":{"2":{"token":"eyJhbGciOiJFUzI1NiIsInR5cCI6IkpXVCJ9.eyJhdWQiOiJzcGlmZmU6Ly9leGFtcGxlLm9yZy9ucy9uc20tc3lzdGVtL3NhL2RlZmF1bHQiLCJleHAiOjE2MjkxMDEzMTcsInN1YiI6InNwaWZmZTovL2V4YW1wbGUub3JnL25zL25zbS1zeXN0ZW0vc2EvZGVmYXVsdCJ9.TdVW_i0zuss5sVPLFR2JcHVVgmWa6Wu6mRV8ds1fCDGRa6I0pjSA6fZJkbJIgl7gttCRjtkxY7tIN6U4J8QSJg"}}}} span=799e6326100fb0ea:7b1336a7e51bcbc3:5c701854c16e4b7f:1
Aug 16 07:28:37.405 [INFO] [name:forwarder-ovs-lb2lj] (8)        ⎆ sdk/pkg/networkservice/utils/metadata/metadataServer.Close() span=799e6326100fb0ea:4f37c97325457df7:7b1336a7e51bcbc3:1
Aug 16 07:28:37.405 [INFO] [name:forwarder-ovs-lb2lj] (9)         ⎆ sdk/pkg/networkservice/common/mechanisms/recvfd/recvFDServer.Close() span=799e6326100fb0ea:7cf8d9a21406be7c:4f37c97325457df7:1
Aug 16 07:28:37.405 [INFO] [name:forwarder-ovs-lb2lj] (9.1)           request-diff={"mechanism":{"parameters":{"inodeURL":"file:///proc/28785/fd/11"}}} span=799e6326100fb0ea:7cf8d9a21406be7c:4f37c97325457df7:1
Aug 16 07:28:37.405 [INFO] [name:forwarder-ovs-lb2lj] (10)          ⎆ sdk/pkg/networkservice/common/mechanisms/sendfd/sendFDServer.Close() span=799e6326100fb0ea:286e0066cfec73d2:7cf8d9a21406be7c:1
Aug 16 07:28:37.405 [INFO] [name:forwarder-ovs-lb2lj] (11)           ⎆ sdk/pkg/networkservice/common/clienturl/clientURLServer.Close() span=799e6326100fb0ea:0465362094683f0d:286e0066cfec73d2:1
Aug 16 07:28:37.405 [INFO] [name:forwarder-ovs-lb2lj] (12)            ⎆ sdk/pkg/networkservice/common/heal/healServer.Close() span=799e6326100fb0ea:612cd6651234582e:0465362094683f0d:1
Aug 16 07:28:37.406 [INFO] [name:forwarder-ovs-lb2lj] (13)             ⎆ sdk/pkg/networkservice/common/mechanisms/mechanismsServer.Close() span=799e6326100fb0ea:12a6d47f341cac18:612cd6651234582e:1
Aug 16 07:28:37.406 [INFO] [name:forwarder-ovs-lb2lj] (14)              ⎆ sdk/pkg/networkservice/core/next/nextServer.Close() span=799e6326100fb0ea:28f125ae3e11dd80:12a6d47f341cac18:1
Aug 16 07:28:37.406 [INFO] [name:forwarder-ovs-lb2lj] (15)               ⎆ sdk-ovs/pkg/networkservice/mechanisms/kernel/kernelServer.Close() span=799e6326100fb0ea:27e41553e02d740d:28f125ae3e11dd80:1
Aug 16 07:28:37.406 [INFO] [name:forwarder-ovs-lb2lj] (16)                ⎆ sdk-kernel/pkg/kernel/networkservice/inject/injectServer.Close() span=799e6326100fb0ea:721c0712b818e4cf:27e41553e02d740d:1
Aug 16 07:28:37.406 [INFO] [name:forwarder-ovs-lb2lj] (17)                 ⎆ sdk/pkg/networkservice/core/next/nextServer.Close() span=799e6326100fb0ea:0fbdb003d8e19580:721c0712b818e4cf:1
Aug 16 07:28:37.407 [INFO] [name:forwarder-ovs-lb2lj] (18)                  ⎆ sdk-kernel/pkg/kernel/networkservice/connectioncontextkernel/mtu/mtuServer.Close() span=799e6326100fb0ea:0badb3d5a50a7cd5:0fbdb003d8e19580:1
Aug 16 07:28:37.407 [INFO] [name:forwarder-ovs-lb2lj] (19)                   ⎆ sdk-kernel/pkg/kernel/networkservice/connectioncontextkernel/ipcontext/ipneighbors/ipNeighborsServer.Close() span=799e6326100fb0ea:07dc7f792742e427:0badb3d5a50a7cd5:1
Aug 16 07:28:37.407 [INFO] [name:forwarder-ovs-lb2lj] (20)                    ⎆ sdk-kernel/pkg/kernel/networkservice/connectioncontextkernel/ipcontext/routes/routesServer.Close() span=799e6326100fb0ea:32468b7b5a7857e2:07dc7f792742e427:1
Aug 16 07:28:37.407 [INFO] [name:forwarder-ovs-lb2lj] (21)                     ⎆ sdk-kernel/pkg/kernel/networkservice/connectioncontextkernel/ipcontext/ipaddress/ipaddressServer.Close() span=799e6326100fb0ea:1f526ea38dda5593:32468b7b5a7857e2:1
Aug 16 07:28:37.407 [INFO] [name:forwarder-ovs-lb2lj] (22)                      ⎆ sdk/pkg/networkservice/common/connect/connectServer.Close() span=799e6326100fb0ea:2f92133f871eab2e:1f526ea38dda5593:1
Aug 16 07:28:37.407 [INFO] [name:forwarder-ovs-lb2lj] (23)                       ⎆ sdk/pkg/networkservice/common/updatepath/updatePathClient.Close() span=799e6326100fb0ea:7d7ffb50e2bdb927:2f92133f871eab2e:1
Aug 16 07:28:37.408 [INFO] [name:forwarder-ovs-lb2lj] (24)                        ⎆ sdk/pkg/networkservice/common/serialize/serializeClient.Close() span=799e6326100fb0ea:6ac1f21963b63758:7d7ffb50e2bdb927:1
Aug 16 07:28:37.408 [INFO] [name:forwarder-ovs-lb2lj] (25)                         ⎆ sdk/pkg/networkservice/common/refresh/refreshClient.Close() span=799e6326100fb0ea:31330f4cd0db83b6:6ac1f21963b63758:1
Aug 16 07:28:37.408 [INFO] [name:forwarder-ovs-lb2lj] (26)                          ⎆ sdk/pkg/networkservice/utils/metadata/metaDataClient.Close() span=799e6326100fb0ea:7f4a03aefaf46b73:31330f4cd0db83b6:1
Aug 16 07:28:37.408 [INFO] [name:forwarder-ovs-lb2lj] (27)                           ⎆ sdk/pkg/networkservice/common/heal/healClient.Close() span=799e6326100fb0ea:4ca117248b03da0e:7f4a03aefaf46b73:1
Aug 16 07:28:37.409 [INFO] [name:forwarder-ovs-lb2lj] (28)                            ⎆ sdk/pkg/networkservice/common/mechanismtranslation/mechanismTranslationClient.Close() span=799e6326100fb0ea:02d8ddf77286b0ca:4ca117248b03da0e:1
Aug 16 07:28:37.409 [INFO] [name:forwarder-ovs-lb2lj] (28.1)                              request-diff={"mechanism":{"cls":"REMOTE","parameters":{"+dst_ip":"10.10.10.33","+dst_port":"4789","+src_ip":"10.10.10.22","+src_port":"4789","+vni":"9832580","-inodeURL":"file:///proc/28785/fd/11","-name":"nsm-1"},"type":"VXLAN"}} span=799e6326100fb0ea:02d8ddf77286b0ca:4ca117248b03da0e:1
Aug 16 07:28:37.409 [INFO] [name:forwarder-ovs-lb2lj] (29)                             ⎆ sdk-ovs/pkg/networkservice/l2ovsconnect/l2ConnectClient.Close() span=799e6326100fb0ea:03ef94773359798a:02d8ddf77286b0ca:1
Aug 16 07:28:37.409 [INFO] [name:forwarder-ovs-lb2lj] (30)                              ⎆ sdk/pkg/networkservice/core/next/nextClient.Close() span=799e6326100fb0ea:22e60bd1c0090849:03ef94773359798a:1
Aug 16 07:28:37.409 [INFO] [name:forwarder-ovs-lb2lj] (31)                               ⎆ sdk-kernel/pkg/kernel/networkservice/connectioncontextkernel/mtu/mtuClient.Close() span=799e6326100fb0ea:4cc01c6b8c2b7cb5:22e60bd1c0090849:1
Aug 16 07:28:37.409 [INFO] [name:forwarder-ovs-lb2lj] (32)                                ⎆ sdk-kernel/pkg/kernel/networkservice/connectioncontextkernel/ipcontext/ipneighbors/ipNeighborsClient.Close() span=799e6326100fb0ea:426b03b4bd2eebf1:4cc01c6b8c2b7cb5:1
Aug 16 07:28:37.410 [INFO] [name:forwarder-ovs-lb2lj] (33)                                 ⎆ sdk-kernel/pkg/kernel/networkservice/connectioncontextkernel/ipcontext/routes/routesClient.Close() span=799e6326100fb0ea:75c1d565689f5154:426b03b4bd2eebf1:1
Aug 16 07:28:37.410 [INFO] [name:forwarder-ovs-lb2lj] (34)                                  ⎆ sdk-kernel/pkg/kernel/networkservice/connectioncontextkernel/ipcontext/ipaddress/ipaddressClient.Close() span=799e6326100fb0ea:4ed80bb884582271:75c1d565689f5154:1
Aug 16 07:28:37.410 [INFO] [name:forwarder-ovs-lb2lj] (35)                                   ⎆ sdk-kernel/pkg/kernel/networkservice/inject/injectClient.Close() span=799e6326100fb0ea:1e1e3ca817664d06:4ed80bb884582271:1
Aug 16 07:28:37.410 [INFO] [name:forwarder-ovs-lb2lj] (36)                                    ⎆ sdk-ovs/pkg/networkservice/mechanisms/kernel/kernelClient.Close() span=799e6326100fb0ea:73d1691b7d5c33b0:1e1e3ca817664d06:1
Aug 16 07:28:37.411 [INFO] [name:forwarder-ovs-lb2lj] (37)                                     ⎆ sdk/pkg/networkservice/core/next/nextClient.Close() span=799e6326100fb0ea:1b5dbe2e13658bcd:73d1691b7d5c33b0:1
Aug 16 07:28:37.411 [INFO] [name:forwarder-ovs-lb2lj] (38)                                      ⎆ sdk-ovs/pkg/networkservice/mechanisms/vxlan/vxlanClient.Close() span=799e6326100fb0ea:4e45daaf3c965570:1b5dbe2e13658bcd:1
Aug 16 07:28:37.411 [INFO] [name:forwarder-ovs-lb2lj] (39)                                       ⎆ sdk/pkg/networkservice/common/mechanisms/vxlan/vni/vniClient.Close() span=799e6326100fb0ea:6824c4c0d5f92d93:4e45daaf3c965570:1
Aug 16 07:28:37.411 [INFO] [name:forwarder-ovs-lb2lj] (40)                                        ⎆ sdk/pkg/networkservice/common/mechanisms/recvfd/recvFDClient.Close() span=799e6326100fb0ea:1bf53610083033c9:6824c4c0d5f92d93:1
Aug 16 07:28:37.411 [INFO] [name:forwarder-ovs-lb2lj] (41)                                         ⎆ sdk/pkg/networkservice/common/mechanisms/sendfd/sendFDClient.Close() span=799e6326100fb0ea:1bfd489cdfd81d23:1bf53610083033c9:1
Aug 16 07:28:37.412 [INFO] [name:forwarder-ovs-lb2lj] (42)                                          ⎆ sdk/pkg/networkservice/common/null/nullClient.Close() span=799e6326100fb0ea:3e81e641114d0af8:1bfd489cdfd81d23:1
Aug 16 07:28:37.412 [INFO] [name:forwarder-ovs-lb2lj] (43)                                           ⎆ api/pkg/api/networkservice/networkServiceClient.Close() span=799e6326100fb0ea:0045f7a130308c59:3e81e641114d0af8:1
Aug 16 07:28:37.415 [ERRO] [name:forwarder-ovs-lb2lj] (43.1)                                             rpc error: code = Canceled desc = grpc: the client connection is closing
Error returned from api/pkg/api/networkservice/networkServiceClient.Close
github.com/networkservicemesh/sdk/pkg/networkservice/core/trace.(*beginTraceClient).Close
        /go/pkg/mod/github.com/networkservicemesh/sdk@v0.5.1-0.20210810055235-c3154387718f/pkg/networkservice/core/trace/client.go:85
github.com/networkservicemesh/sdk/pkg/networkservice/core/next.(*nextClient).Close
        /go/pkg/mod/github.com/networkservicemesh/sdk@v0.5.1-0.20210810055235-c3154387718f/pkg/networkservice/core/next/client.go:82
github.com/networkservicemesh/sdk/pkg/networkservice/core/next.(*nextClient).Close
        /go/pkg/mod/github.com/networkservicemesh/sdk@v0.5.1-0.20210810055235-c3154387718f/pkg/networkservice/core/next/client.go:84
github.com/networkservicemesh/sdk/pkg/networkservice/core/trace.(*endTraceClient).Close
        /go/pkg/mod/github.com/networkservicemesh/sdk@v0.5.1-0.20210810055235-c3154387718f/pkg/networkservice/core/trace/client.go:106
github.com/networkservicemesh/sdk/pkg/networkservice/core/next.(*nextClient).Close
        /go/pkg/mod/github.com/networkservicemesh/sdk@v0.5.1-0.20210810055235-c3154387718f/pkg/networkservice/core/next/client.go:84
github.com/networkservicemesh/sdk/pkg/networkservice/common/null.(*nullClient).Close
        /go/pkg/mod/github.com/networkservicemesh/sdk@v0.5.1-0.20210810055235-c3154387718f/pkg/networkservice/common/null/client.go:47
github.com/networkservicemesh/sdk/pkg/networkservice/core/trace.(*beginTraceClient).Close
        /go/pkg/mod/github.com/networkservicemesh/sdk@v0.5.1-0.20210810055235-c3154387718f/pkg/networkservice/core/trace/client.go:81
github.com/networkservicemesh/sdk/pkg/networkservice/core/next.(*nextClient).Close
        /go/pkg/mod/github.com/networkservicemesh/sdk@v0.5.1-0.20210810055235-c3154387718f/pkg/networkservice/core/next/client.go:82
github.com/networkservicemesh/sdk/pkg/networkservice/core/next.(*nextClient).Close
        /go/pkg/mod/github.com/networkservicemesh/sdk@v0.5.1-0.20210810055235-c3154387718f/pkg/networkservice/core/next/client.go:82
github.com/networkservicemesh/sdk/pkg/networkservice/core/trace.(*endTraceClient).Close
        /go/pkg/mod/github.com/networkservicemesh/sdk@v0.5.1-0.20210810055235-c3154387718f/pkg/networkservice/core/trace/client.go:106
github.com/networkservicemesh/sdk/pkg/networkservice/core/next.(*nextClient).Close
        /go/pkg/mod/github.com/networkservicemesh/sdk@v0.5.1-0.20210810055235-c3154387718f/pkg/networkservice/core/next/client.go:84
github.com/networkservicemesh/sdk/pkg/networkservice/common/mechanisms/sendfd.(*sendFDClient).Close
        /go/pkg/mod/github.com/networkservicemesh/sdk@v0.5.1-0.20210810055235-c3154387718f/pkg/networkservice/common/mechanisms/sendfd/client.go:81
github.com/networkservicemesh/sdk/pkg/networkservice/core/trace.(*beginTraceClient).Close
        /go/pkg/mod/github.com/networkservicemesh/sdk@v0.5.1-0.20210810055235-c3154387718f/pkg/networkservice/core/trace/client.go:81
github.com/networkservicemesh/sdk/pkg/networkservice/core/next.(*nextClient).Close
        /go/pkg/mod/github.com/networkservicemesh/sdk@v0.5.1-0.20210810055235-c3154387718f/pkg/networkservice/core/next/client.go:82
github.com/networkservicemesh/sdk/pkg/networkservice/core/next.(*nextClient).Close
        /go/pkg/mod/github.com/networkservicemesh/sdk@v0.5.1-0.20210810055235-c3154387718f/pkg/networkservice/core/next/client.go:82
github.com/networkservicemesh/sdk/pkg/networkservice/core/trace.(*endTraceClient).Close
        /go/pkg/mod/github.com/networkservicemesh/sdk@v0.5.1-0.20210810055235-c3154387718f/pkg/networkservice/core/trace/client.go:106
github.com/networkservicemesh/sdk/pkg/networkservice/core/next.(*nextClient).Close
        /go/pkg/mod/github.com/networkservicemesh/sdk@v0.5.1-0.20210810055235-c3154387718f/pkg/networkservice/core/next/client.go:84
github.com/networkservicemesh/sdk/pkg/networkservice/common/mechanisms/recvfd.(*recvFDClient).Close
        /go/pkg/mod/github.com/networkservicemesh/sdk@v0.5.1-0.20210810055235-c3154387718f/pkg/networkservice/common/mechanisms/recvfd/client.go:100
github.com/networkservicemesh/sdk/pkg/networkservice/core/trace.(*beginTraceClient).Close
        /go/pkg/mod/github.com/networkservicemesh/sdk@v0.5.1-0.20210810055235-c3154387718f/pkg/networkservice/core/trace/client.go:81
github.com/networkservicemesh/sdk/pkg/networkservice/core/next.(*nextClient).Close
        /go/pkg/mod/github.com/networkservicemesh/sdk@v0.5.1-0.20210810055235-c3154387718f/pkg/networkservice/core/next/client.go:82
github.com/networkservicemesh/sdk/pkg/networkservice/core/next.(*nextClient).Close
        /go/pkg/mod/github.com/networkservicemesh/sdk@v0.5.1-0.20210810055235-c3154387718f/pkg/networkservice/core/next/client.go:82
github.com/networkservicemesh/sdk/pkg/networkservice/core/trace.(*endTraceClient).Close
        /go/pkg/mod/github.com/networkservicemesh/sdk@v0.5.1-0.20210810055235-c3154387718f/pkg/networkservice/core/trace/client.go:106
github.com/networkservicemesh/sdk/pkg/networkservice/core/next.(*nextClient).Close
        /go/pkg/mod/github.com/networkservicemesh/sdk@v0.5.1-0.20210810055235-c3154387718f/pkg/networkservice/core/next/client.go:84
github.com/networkservicemesh/sdk/pkg/networkservice/core/trace.(*endTraceClient).Close
        /go/pkg/mod/github.com/networkservicemesh/sdk@v0.5.1-0.20210810055235-c3154387718f/pkg/networkservice/core/trace/client.go:106
github.com/networkservicemesh/sdk/pkg/networkservice/core/next.(*nextClient).Close
        /go/pkg/mod/github.com/networkservicemesh/sdk@v0.5.1-0.20210810055235-c3154387718f/pkg/networkservice/core/next/client.go:84
github.com/networkservicemesh/sdk/pkg/networkservice/common/mechanisms/vxlan/vni.(*vniClient).Close
        /go/pkg/mod/github.com/networkservicemesh/sdk@v0.5.1-0.20210810055235-c3154387718f/pkg/networkservice/common/mechanisms/vxlan/vni/client.go:57
github.com/networkservicemesh/sdk/pkg/networkservice/core/trace.(*beginTraceClient).Close
        /go/pkg/mod/github.com/networkservicemesh/sdk@v0.5.1-0.20210810055235-c3154387718f/pkg/networkservice/core/trace/client.go:81
github.com/networkservicemesh/sdk/pkg/networkservice/core/next.(*nextClient).Close
        /go/pkg/mod/github.com/networkservicemesh/sdk@v0.5.1-0.20210810055235-c3154387718f/pkg/networkservice/core/next/client.go:82
github.com/networkservicemesh/sdk/pkg/networkservice/core/next.(*nextClient).Close
        /go/pkg/mod/github.com/networkservicemesh/sdk@v0.5.1-0.20210810055235-c3154387718f/pkg/networkservice/core/next/client.go:84
github.com/networkservicemesh/sdk/pkg/networkservice/core/trace.(*endTraceClient).Close
        /go/pkg/mod/github.com/networkservicemesh/sdk@v0.5.1-0.20210810055235-c3154387718f/pkg/networkservice/core/trace/client.go:106
github.com/networkservicemesh/sdk/pkg/networkservice/core/next.(*nextClient).Close
        /go/pkg/mod/github.com/networkservicemesh/sdk@v0.5.1-0.20210810055235-c3154387718f/pkg/networkservice/core/next/client.go:84
github.com/networkservicemesh/sdk-ovs/pkg/networkservice/mechanisms/vxlan.(*vxlanClient).Close
        /build/local/sdk-ovs/pkg/networkservice/mechanisms/vxlan/client.go:73 span=799e6326100fb0ea:0045f7a130308c59:3e81e641114d0af8:1
2021/08/16 07:28:37 Reporting span 799e6326100fb0ea:0045f7a130308c59:3e81e641114d0af8:1
Aug 16 07:28:37.415 [INFO] [name:forwarder-ovs-lb2lj] (42.1)                                            response={"id":"282faf67-e439-4b08-88d4-549ecfbdfdb7","network_service":"icmp-responder","mechanism":{"cls":"REMOTE","type":"VXLAN","parameters":{"dst_ip":"10.10.10.33","dst_port":"4789","src_ip":"10.10.10.22","src_port":"4789","vni":"9832580"}},"context":{"ip_context":{"src_ip_addrs":["172.16.1.101/32"],"dst_ip_addrs":["172.16.1.100/32"],"src_routes":[{"prefix":"172.16.1.100/32"}],"dst_routes":[{"prefix":"172.16.1.101/32"}]},"dns_context":{}},"labels":{"nodeName":"dl380-004"},"path":{"index":2,"path_segments":[{"name":"nsc-kernel-cb878b7cf-hqv8f","id":"nsc-kernel-cb878b7cf-hqv8f-0","token":"eyJhbGciOiJFUzI1NiIsInR5cCI6IkpXVCJ9.eyJhdWQiOiJzcGlmZmU6Ly9leGFtcGxlLm9yZy9ucy9uc20tc3lzdGVtL3NhL2RlZmF1bHQiLCJleHAiOjE2MjkwOTkyMTMsInN1YiI6InNwaWZmZTovL2V4YW1wbGUub3JnL25zL25zLWM1bG1xL3NhL2RlZmF1bHQifQ.cMZVH7HJC1wkkDgD_cnhsMHXkOtvrUsfrLalgV1KSHS1etjJauOS2wVAhb1m1H-XniD33cCLTfiFgNvFddTVzQ","expires":{"seconds":1629099213,"nanos":102726858}},{"name":"nsmgr-jfsn8","id":"751b4178-99a8-41bb-baf8-01e68f695593","token":"eyJhbGciOiJFUzI1NiIsInR5cCI6IkpXVCJ9.eyJhdWQiOiJzcGlmZmU6Ly9leGFtcGxlLm9yZy9ucy9ucy1jNWxtcS9zYS9kZWZhdWx0IiwiZXhwIjoxNjI5MDk5NTE3LCJzdWIiOiJzcGlmZmU6Ly9leGFtcGxlLm9yZy9ucy9uc20tc3lzdGVtL3NhL2RlZmF1bHQifQ.xol-3Rmg8dYeOgJqp_bUpqe8xBvWrc_54BOFupEqYRi8ojShpnnPcJpUmR-sfXxzEuoZO0Ll3A2b5nbSC5rXUQ","expires":{"seconds":1629099517,"nanos":3680363}},{"name":"forwarder-ovs-lb2lj","id":"282faf67-e439-4b08-88d4-549ecfbdfdb7","token":"eyJhbGciOiJFUzI1NiIsInR5cCI6IkpXVCJ9.eyJhdWQiOiJzcGlmZmU6Ly9leGFtcGxlLm9yZy9ucy9uc20tc3lzdGVtL3NhL2RlZmF1bHQiLCJleHAiOjE2MjkxMDEzMTcsInN1YiI6InNwaWZmZTovL2V4YW1wbGUub3JnL25zL25zbS1zeXN0ZW0vc2EvZGVmYXVsdCJ9.TdVW_i0zuss5sVPLFR2JcHVVgmWa6Wu6mRV8ds1fCDGRa6I0pjSA6fZJkbJIgl7gttCRjtkxY7tIN6U4J8QSJg","expires":{"seconds":1629101317}},{"name":"nsmgr-jfsn8","id":"72f5586e-f534-40e1-9fa0-33f93d651235","token":"eyJhbGciOiJFUzI1NiIsInR5cCI6IkpXVCJ9.eyJhdWQiOiJzcGlmZmU6Ly9leGFtcGxlLm9yZy9ucy9uc20tc3lzdGVtL3NhL2RlZmF1bHQiLCJleHAiOjE2MjkwOTk0NTUsInN1YiI6InNwaWZmZTovL2V4YW1wbGUub3JnL25zL25zbS1zeXN0ZW0vc2EvZGVmYXVsdCJ9.muCEAquEcqKu_JCSl3T0ZvYPUuHbCEnDMG2T3q_Pyp0MpHhsdYpwY7_xfenpBq1z2k6gIg0cHd14zIJ-lWRnPA","expires":{"seconds":1629099455,"nanos":428071588}},{"name":"nsmgr-6rnxw","id":"aeffa3f8-1088-47fc-9666-a00b0b20e21a","token":"eyJhbGciOiJFUzI1NiIsInR5cCI6IkpXVCJ9.eyJhdWQiOiJzcGlmZmU6Ly9leGFtcGxlLm9yZy9ucy9uc20tc3lzdGVtL3NhL2RlZmF1bHQiLCJleHAiOjE2MjkwOTk0NTUsInN1YiI6InNwaWZmZTovL2V4YW1wbGUub3JnL25zL25zbS1zeXN0ZW0vc2EvZGVmYXVsdCJ9.gjvUWyXp40vVE6fqeaUj3bJocMwzCgJTX9d73-SVzqBbWE41p0kcbFUMcG9EC7al3OPNhJk4QsNsLmFbLz0m3g","expires":{"seconds":1629099455,"nanos":511622540}},{"name":"forwarder-ovs-4xcwc","id":"94c26a80-1411-4dba-9cd4-1221b594a3e6","token":"eyJhbGciOiJFUzI1NiIsInR5cCI6IkpXVCJ9.eyJhdWQiOiJzcGlmZmU6Ly9leGFtcGxlLm9yZy9ucy9uc20tc3lzdGVtL3NhL2RlZmF1bHQiLCJleHAiOjE2MjkxMDE0MDAsInN1YiI6InNwaWZmZTovL2V4YW1wbGUub3JnL25zL25zbS1zeXN0ZW0vc2EvZGVmYXVsdCJ9.HKKZTwvXKDmH--j7JwWwKEuGb1ewcligsngptX_wveC11ykZiE_29taOal3ApIb4d00EB-SuZsh9IDgwrp51qA","expires":{"seconds":1629101400}},{"name":"nsmgr-6rnxw","id":"26da1d03-5eb9-416e-82f3-33bc5ce9c78c","token":"eyJhbGciOiJFUzI1NiIsInR5cCI6IkpXVCJ9.eyJhdWQiOiJzcGlmZmU6Ly9leGFtcGxlLm9yZy9ucy9ucy1jNWxtcS9zYS9kZWZhdWx0IiwiZXhwIjoxNjI5MDk5NDU1LCJzdWIiOiJzcGlmZmU6Ly9leGFtcGxlLm9yZy9ucy9uc20tc3lzdGVtL3NhL2RlZmF1bHQifQ.KurfymBbe0c8Zauq6J1wcST3oj3utzGAmE-Ok4_mSE5nmN_-_Jl38TUGeEQ6SD6-bpnvvn2Q-ttgGU1m2Fhieg","expires":{"seconds":1629099455,"nanos":607075570}},{"name":"nse-kernel-945c556db-5l5kn","id":"44f8f3e4-2aa5-4754-9794-8fe49a78a31b","token":"eyJhbGciOiJFUzI1NiIsInR5cCI6IkpXVCJ9.eyJhdWQiOiJzcGlmZmU6Ly9leGFtcGxlLm9yZy9ucy9uc20tc3lzdGVtL3NhL2RlZmF1bHQiLCJleHAiOjE2MjkwOTk0NTUsInN1YiI6InNwaWZmZTovL2V4YW1wbGUub3JnL25zL25zLWM1bG1xL3NhL2RlZmF1bHQifQ.ciu3Zs2PFb7BSG2gzjN8dkXDMr6-jQucpWsRxUllqx_t-_V_CxCHAMNQDw8V0Rm51JIb47YJCYR5SzwyzDBCvg","expires":{"seconds":1629099455,"nanos":703069874}}]},"network_service_endpoint_name":"8c906f88-002a-4732-8764-71de19c1f6d5-nse-kernel-945c556db-5l5kn","payload":"ETHERNET"} span=799e6326100fb0ea:3e81e641114d0af8:1bfd489cdfd81d23:1
Aug 16 07:28:37.418 [ERRO] [name:forwarder-ovs-lb2lj] (42.2)                                            Error returned from api/pkg/api/networkservice/networkServiceClient.Close: rpc error: code = Canceled desc = grpc: the client connection is closing span=799e6326100fb0ea:3e81e641114d0af8:1bfd489cdfd81d23:1
2021/08/16 07:28:37 Reporting span 799e6326100fb0ea:3e81e641114d0af8:1bfd489cdfd81d23:1
Aug 16 07:28:37.420 [ERRO] [name:forwarder-ovs-lb2lj] (41.1)                                           Error returned from api/pkg/api/networkservice/networkServiceClient.Close: rpc error: code = Canceled desc = grpc: the client connection is closing span=799e6326100fb0ea:1bfd489cdfd81d23:1bf53610083033c9:1
2021/08/16 07:28:37 Reporting span 799e6326100fb0ea:1bfd489cdfd81d23:1bf53610083033c9:1
Aug 16 07:28:37.421 [ERRO] [name:forwarder-ovs-lb2lj] (40.1)                                          Error returned from api/pkg/api/networkservice/networkServiceClient.Close: rpc error: code = Canceled desc = grpc: the client connection is closing span=799e6326100fb0ea:1bf53610083033c9:6824c4c0d5f92d93:1
2021/08/16 07:28:37 Reporting span 799e6326100fb0ea:1bf53610083033c9:6824c4c0d5f92d93:1
Aug 16 07:28:37.422 [ERRO] [name:forwarder-ovs-lb2lj] (39.1)                                         Error returned from api/pkg/api/networkservice/networkServiceClient.Close: rpc error: code = Canceled desc = grpc: the client connection is closing span=799e6326100fb0ea:6824c4c0d5f92d93:4e45daaf3c965570:1
2021/08/16 07:28:37 Reporting span 799e6326100fb0ea:6824c4c0d5f92d93:4e45daaf3c965570:1
Aug 16 07:28:37.432 [ERRO] [name:forwarder-ovs-lb2lj] (38.1)                                        Error returned from api/pkg/api/networkservice/networkServiceClient.Close: rpc error: code = Canceled desc = grpc: the client connection is closing span=799e6326100fb0ea:4e45daaf3c965570:1b5dbe2e13658bcd:1
2021/08/16 07:28:37 Reporting span 799e6326100fb0ea:4e45daaf3c965570:1b5dbe2e13658bcd:1
Aug 16 07:28:37.432 [ERRO] [name:forwarder-ovs-lb2lj] (37.1)                                       Error returned from api/pkg/api/networkservice/networkServiceClient.Close: rpc error: code = Canceled desc = grpc: the client connection is closing span=799e6326100fb0ea:1b5dbe2e13658bcd:73d1691b7d5c33b0:1
2021/08/16 07:28:37 Reporting span 799e6326100fb0ea:1b5dbe2e13658bcd:73d1691b7d5c33b0:1
Aug 16 07:28:37.437 [ERRO] [kernelClient:Close] [name:forwarder-ovs-lb2lj] (36.1)                                      Failed to delete port tapdst-282faf67 from br-nsm, stdout: "", stderr: "ovs-vsctl: no port named tapdst-282faf67\n", error: exit status 1 span=799e6326100fb0ea:73d1691b7d5c33b0:1e1e3ca817664d06:1
Aug 16 07:28:37.440 [ERRO] [name:forwarder-ovs-lb2lj] (36.2)                                      Error returned from api/pkg/api/networkservice/networkServiceClient.Close: rpc error: code = Canceled desc = grpc: the client connection is closing span=799e6326100fb0ea:73d1691b7d5c33b0:1e1e3ca817664d06:1
2021/08/16 07:28:37 Reporting span 799e6326100fb0ea:73d1691b7d5c33b0:1e1e3ca817664d06:1
Aug 16 07:28:37.441 [ERRO] [name:forwarder-ovs-lb2lj] (35.1)                                     Error returned from api/pkg/api/networkservice/networkServiceClient.Close: rpc error: code = Canceled desc = grpc: the client connection is closing span=799e6326100fb0ea:1e1e3ca817664d06:4ed80bb884582271:1
2021/08/16 07:28:37 Reporting span 799e6326100fb0ea:1e1e3ca817664d06:4ed80bb884582271:1
Aug 16 07:28:37.442 [ERRO] [name:forwarder-ovs-lb2lj] (34.1)                                    Error returned from api/pkg/api/networkservice/networkServiceClient.Close: rpc error: code = Canceled desc = grpc: the client connection is closing span=799e6326100fb0ea:4ed80bb884582271:75c1d565689f5154:1
2021/08/16 07:28:37 Reporting span 799e6326100fb0ea:4ed80bb884582271:75c1d565689f5154:1
Aug 16 07:28:37.442 [ERRO] [name:forwarder-ovs-lb2lj] (33.1)                                   Error returned from api/pkg/api/networkservice/networkServiceClient.Close: rpc error: code = Canceled desc = grpc: the client connection is closing span=799e6326100fb0ea:75c1d565689f5154:426b03b4bd2eebf1:1
2021/08/16 07:28:37 Reporting span 799e6326100fb0ea:75c1d565689f5154:426b03b4bd2eebf1:1
Aug 16 07:28:37.443 [ERRO] [name:forwarder-ovs-lb2lj] (32.1)                                  Error returned from api/pkg/api/networkservice/networkServiceClient.Close: rpc error: code = Canceled desc = grpc: the client connection is closing span=799e6326100fb0ea:426b03b4bd2eebf1:4cc01c6b8c2b7cb5:1
2021/08/16 07:28:37 Reporting span 799e6326100fb0ea:426b03b4bd2eebf1:4cc01c6b8c2b7cb5:1
Aug 16 07:28:37.443 [ERRO] [name:forwarder-ovs-lb2lj] (31.1)                                 Error returned from api/pkg/api/networkservice/networkServiceClient.Close: rpc error: code = Canceled desc = grpc: the client connection is closing span=799e6326100fb0ea:4cc01c6b8c2b7cb5:22e60bd1c0090849:1
2021/08/16 07:28:37 Reporting span 799e6326100fb0ea:4cc01c6b8c2b7cb5:22e60bd1c0090849:1
Aug 16 07:28:37.444 [ERRO] [name:forwarder-ovs-lb2lj] (30.1)                                Error returned from api/pkg/api/networkservice/networkServiceClient.Close: rpc error: code = Canceled desc = grpc: the client connection is closing span=799e6326100fb0ea:22e60bd1c0090849:03ef94773359798a:1
2021/08/16 07:28:37 Reporting span 799e6326100fb0ea:22e60bd1c0090849:03ef94773359798a:1
Aug 16 07:28:37.511 [ERRO] [name:forwarder-ovs-lb2lj] (29.1)                               Error returned from api/pkg/api/networkservice/networkServiceClient.Close: rpc error: code = Canceled desc = grpc: the client connection is closing span=799e6326100fb0ea:03ef94773359798a:02d8ddf77286b0ca:1
2021/08/16 07:28:37 Reporting span 799e6326100fb0ea:03ef94773359798a:02d8ddf77286b0ca:1
Aug 16 07:28:37.511 [ERRO] [name:forwarder-ovs-lb2lj] (28.2)                              Error returned from api/pkg/api/networkservice/networkServiceClient.Close: rpc error: code = Canceled desc = grpc: the client connection is closing span=799e6326100fb0ea:02d8ddf77286b0ca:4ca117248b03da0e:1
2021/08/16 07:28:37 Reporting span 799e6326100fb0ea:02d8ddf77286b0ca:4ca117248b03da0e:1
Aug 16 07:28:37.511 [INFO] [name:forwarder-ovs-lb2lj] (27.1)                             response-diff={"mechanism":{"cls":"LOCAL","parameters":{"+inodeURL":"file:///proc/28785/fd/11","+name":"nsm-1","-dst_ip":"10.10.10.33","-dst_port":"4789","-src_ip":"10.10.10.22","-src_port":"4789","-vni":"9832580"},"type":"KERNEL"}} span=799e6326100fb0ea:4ca117248b03da0e:7f4a03aefaf46b73:1
Aug 16 07:28:37.511 [ERRO] [name:forwarder-ovs-lb2lj] (27.2)                             Error returned from api/pkg/api/networkservice/networkServiceClient.Close: rpc error: code = Canceled desc = grpc: the client connection is closing span=799e6326100fb0ea:4ca117248b03da0e:7f4a03aefaf46b73:1
2021/08/16 07:28:37 Reporting span 799e6326100fb0ea:4ca117248b03da0e:7f4a03aefaf46b73:1
Aug 16 07:28:37.512 [ERRO] [name:forwarder-ovs-lb2lj] (26.1)                            Error returned from api/pkg/api/networkservice/networkServiceClient.Close: rpc error: code = Canceled desc = grpc: the client connection is closing span=799e6326100fb0ea:7f4a03aefaf46b73:31330f4cd0db83b6:1
2021/08/16 07:28:37 Reporting span 799e6326100fb0ea:7f4a03aefaf46b73:31330f4cd0db83b6:1
Aug 16 07:28:37.512 [ERRO] [name:forwarder-ovs-lb2lj] (25.1)                           Error returned from api/pkg/api/networkservice/networkServiceClient.Close: rpc error: code = Canceled desc = grpc: the client connection is closing span=799e6326100fb0ea:31330f4cd0db83b6:6ac1f21963b63758:1
2021/08/16 07:28:37 Reporting span 799e6326100fb0ea:31330f4cd0db83b6:6ac1f21963b63758:1
Aug 16 07:28:37.513 [ERRO] [name:forwarder-ovs-lb2lj] (24.1)                          Error returned from api/pkg/api/networkservice/networkServiceClient.Close: rpc error: code = Canceled desc = grpc: the client connection is closing span=799e6326100fb0ea:6ac1f21963b63758:7d7ffb50e2bdb927:1
2021/08/16 07:28:37 Reporting span 799e6326100fb0ea:6ac1f21963b63758:7d7ffb50e2bdb927:1
Aug 16 07:28:37.514 [ERRO] [name:forwarder-ovs-lb2lj] (23.1)                         Error returned from api/pkg/api/networkservice/networkServiceClient.Close: rpc error: code = Canceled desc = grpc: the client connection is closing span=799e6326100fb0ea:7d7ffb50e2bdb927:2f92133f871eab2e:1
2021/08/16 07:28:37 Reporting span 799e6326100fb0ea:7d7ffb50e2bdb927:2f92133f871eab2e:1
Aug 16 07:28:37.514 [INFO] [name:forwarder-ovs-lb2lj] (22.1)                        request-diff={"mechanism":{"cls":"LOCAL","parameters":{"+inodeURL":"file:///proc/28785/fd/11","+name":"nsm-1","-dst_ip":"10.10.10.33","-dst_port":"4789","-src_ip":"10.10.10.22","-src_port":"4789","-vni":"9832580"},"type":"KERNEL"}} span=799e6326100fb0ea:2f92133f871eab2e:1f526ea38dda5593:1
Aug 16 07:28:37.515 [ERRO] [name:forwarder-ovs-lb2lj] (22.2)                        errors during client close: Error returned from api/pkg/api/networkservice/networkServiceClient.Close: rpc error: code = Canceled desc = grpc: the client connection is closing span=799e6326100fb0ea:2f92133f871eab2e:1f526ea38dda5593:1
2021/08/16 07:28:37 Reporting span 799e6326100fb0ea:2f92133f871eab2e:1f526ea38dda5593:1
Aug 16 07:28:37.516 [ERRO] [name:forwarder-ovs-lb2lj] (21.1)                       errors during client close: Error returned from api/pkg/api/networkservice/networkServiceClient.Close: rpc error: code = Canceled desc = grpc: the client connection is closing span=799e6326100fb0ea:1f526ea38dda5593:32468b7b5a7857e2:1
2021/08/16 07:28:37 Reporting span 799e6326100fb0ea:1f526ea38dda5593:32468b7b5a7857e2:1
Aug 16 07:28:37.517 [ERRO] [name:forwarder-ovs-lb2lj] (20.1)                      errors during client close: Error returned from api/pkg/api/networkservice/networkServiceClient.Close: rpc error: code = Canceled desc = grpc: the client connection is closing span=799e6326100fb0ea:32468b7b5a7857e2:07dc7f792742e427:1
2021/08/16 07:28:37 Reporting span 799e6326100fb0ea:32468b7b5a7857e2:07dc7f792742e427:1
Aug 16 07:28:37.518 [ERRO] [name:forwarder-ovs-lb2lj] (19.1)                     errors during client close: Error returned from api/pkg/api/networkservice/networkServiceClient.Close: rpc error: code = Canceled desc = grpc: the client connection is closing span=799e6326100fb0ea:07dc7f792742e427:0badb3d5a50a7cd5:1
2021/08/16 07:28:37 Reporting span 799e6326100fb0ea:07dc7f792742e427:0badb3d5a50a7cd5:1
Aug 16 07:28:37.519 [ERRO] [name:forwarder-ovs-lb2lj] (18.1)                    errors during client close: Error returned from api/pkg/api/networkservice/networkServiceClient.Close: rpc error: code = Canceled desc = grpc: the client connection is closing span=799e6326100fb0ea:0badb3d5a50a7cd5:0fbdb003d8e19580:1
2021/08/16 07:28:37 Reporting span 799e6326100fb0ea:0badb3d5a50a7cd5:0fbdb003d8e19580:1
Aug 16 07:28:37.521 [ERRO] [name:forwarder-ovs-lb2lj] (17.1)                   errors during client close: Error returned from api/pkg/api/networkservice/networkServiceClient.Close: rpc error: code = Canceled desc = grpc: the client connection is closing span=799e6326100fb0ea:0fbdb003d8e19580:721c0712b818e4cf:1
2021/08/16 07:28:37 Reporting span 799e6326100fb0ea:0fbdb003d8e19580:721c0712b818e4cf:1
Aug 16 07:28:37.549 [ERRO] [name:forwarder-ovs-lb2lj] (16.1)                  errors during client close: Error returned from api/pkg/api/networkservice/networkServiceClient.Close: rpc error: code = Canceled desc = grpc: the client connection is closing span=799e6326100fb0ea:721c0712b818e4cf:27e41553e02d740d:1
2021/08/16 07:28:37 Reporting span 799e6326100fb0ea:721c0712b818e4cf:27e41553e02d740d:1
Aug 16 07:28:37.630 [ERRO] [name:forwarder-ovs-lb2lj] (15.1)                 errors during client close: Error returned from api/pkg/api/networkservice/networkServiceClient.Close: rpc error: code = Canceled desc = grpc: the client connection is closing span=799e6326100fb0ea:27e41553e02d740d:28f125ae3e11dd80:1
2021/08/16 07:28:37 Reporting span 799e6326100fb0ea:27e41553e02d740d:28f125ae3e11dd80:1
Aug 16 07:28:37.632 [ERRO] [name:forwarder-ovs-lb2lj] (14.1)                errors during client close: Error returned from api/pkg/api/networkservice/networkServiceClient.Close: rpc error: code = Canceled desc = grpc: the client connection is closing span=799e6326100fb0ea:28f125ae3e11dd80:12a6d47f341cac18:1
2021/08/16 07:28:37 Reporting span 799e6326100fb0ea:28f125ae3e11dd80:12a6d47f341cac18:1
Aug 16 07:28:37.632 [ERRO] [name:forwarder-ovs-lb2lj] (13.1)               errors during client close: Error returned from api/pkg/api/networkservice/networkServiceClient.Close: rpc error: code = Canceled desc = grpc: the client connection is closing span=799e6326100fb0ea:12a6d47f341cac18:612cd6651234582e:1
2021/08/16 07:28:37 Reporting span 799e6326100fb0ea:12a6d47f341cac18:612cd6651234582e:1
Aug 16 07:28:37.633 [ERRO] [name:forwarder-ovs-lb2lj] (12.1)              errors during client close: Error returned from api/pkg/api/networkservice/networkServiceClient.Close: rpc error: code = Canceled desc = grpc: the client connection is closing span=799e6326100fb0ea:612cd6651234582e:0465362094683f0d:1
2021/08/16 07:28:37 Reporting span 799e6326100fb0ea:612cd6651234582e:0465362094683f0d:1
Aug 16 07:28:37.634 [ERRO] [name:forwarder-ovs-lb2lj] (11.2)             errors during client close: Error returned from api/pkg/api/networkservice/networkServiceClient.Close: rpc error: code = Canceled desc = grpc: the client connection is closing span=799e6326100fb0ea:0465362094683f0d:286e0066cfec73d2:1
2021/08/16 07:28:37 Reporting span 799e6326100fb0ea:0465362094683f0d:286e0066cfec73d2:1
Aug 16 07:28:37.634 [ERRO] [name:forwarder-ovs-lb2lj] (10.1)            errors during client close: Error returned from api/pkg/api/networkservice/networkServiceClient.Close: rpc error: code = Canceled desc = grpc: the client connection is closing span=799e6326100fb0ea:286e0066cfec73d2:7cf8d9a21406be7c:1
2021/08/16 07:28:37 Reporting span 799e6326100fb0ea:286e0066cfec73d2:7cf8d9a21406be7c:1
Aug 16 07:28:37.634 [ERRO] [name:forwarder-ovs-lb2lj] (9.2)           errors during client close: Error returned from api/pkg/api/networkservice/networkServiceClient.Close: rpc error: code = Canceled desc = grpc: the client connection is closing span=799e6326100fb0ea:7cf8d9a21406be7c:4f37c97325457df7:1
2021/08/16 07:28:37 Reporting span 799e6326100fb0ea:7cf8d9a21406be7c:4f37c97325457df7:1
Aug 16 07:28:37.635 [ERRO] [name:forwarder-ovs-lb2lj] (8.1)          errors during client close: Error returned from api/pkg/api/networkservice/networkServiceClient.Close: rpc error: code = Canceled desc = grpc: the client connection is closing span=799e6326100fb0ea:4f37c97325457df7:7b1336a7e51bcbc3:1
2021/08/16 07:28:37 Reporting span 799e6326100fb0ea:4f37c97325457df7:7b1336a7e51bcbc3:1
Aug 16 07:28:37.635 [ERRO] [name:forwarder-ovs-lb2lj] (7.2)         errors during client close: Error returned from api/pkg/api/networkservice/networkServiceClient.Close: rpc error: code = Canceled desc = grpc: the client connection is closing span=799e6326100fb0ea:7b1336a7e51bcbc3:5c701854c16e4b7f:1
2021/08/16 07:28:37 Reporting span 799e6326100fb0ea:7b1336a7e51bcbc3:5c701854c16e4b7f:1
Aug 16 07:28:37.636 [ERRO] [name:forwarder-ovs-lb2lj] (6.1)        errors during client close: Error returned from api/pkg/api/networkservice/networkServiceClient.Close: rpc error: code = Canceled desc = grpc: the client connection is closing span=799e6326100fb0ea:5c701854c16e4b7f:64afdb562e842790:1
2021/08/16 07:28:37 Reporting span 799e6326100fb0ea:5c701854c16e4b7f:64afdb562e842790:1
Aug 16 07:28:37.636 [ERRO] [name:forwarder-ovs-lb2lj] (5.1)       errors during client close: Error returned from api/pkg/api/networkservice/networkServiceClient.Close: rpc error: code = Canceled desc = grpc: the client connection is closing span=799e6326100fb0ea:64afdb562e842790:0d1d030e20f6faed:1
2021/08/16 07:28:37 Reporting span 799e6326100fb0ea:64afdb562e842790:0d1d030e20f6faed:1
Aug 16 07:28:37.636 [ERRO] [name:forwarder-ovs-lb2lj] (4.1)      errors during client close: Error returned from api/pkg/api/networkservice/networkServiceClient.Close: rpc error: code = Canceled desc = grpc: the client connection is closing span=799e6326100fb0ea:0d1d030e20f6faed:7fcfc3ddd1115c9e:1
2021/08/16 07:28:37 Reporting span 799e6326100fb0ea:0d1d030e20f6faed:7fcfc3ddd1115c9e:1
Aug 16 07:28:37.636 [ERRO] [name:forwarder-ovs-lb2lj] (3.1)     errors during client close: Error returned from api/pkg/api/networkservice/networkServiceClient.Close: rpc error: code = Canceled desc = grpc: the client connection is closing span=799e6326100fb0ea:7fcfc3ddd1115c9e:207e2a788b8d78f5:1
2021/08/16 07:28:37 Reporting span 799e6326100fb0ea:7fcfc3ddd1115c9e:207e2a788b8d78f5:1
Aug 16 07:28:37.637 [ERRO] [name:forwarder-ovs-lb2lj] (2.1)    errors during client close: Error returned from api/pkg/api/networkservice/networkServiceClient.Close: rpc error: code = Canceled desc = grpc: the client connection is closing span=799e6326100fb0ea:207e2a788b8d78f5:386e8981662d4458:1
2021/08/16 07:28:37 Reporting span 799e6326100fb0ea:207e2a788b8d78f5:386e8981662d4458:1
Aug 16 07:28:37.637 [ERRO] [name:forwarder-ovs-lb2lj] (1.3)   errors during client close: Error returned from api/pkg/api/networkservice/networkServiceClient.Close: rpc error: code = Canceled desc = grpc: the client connection is closing span=799e6326100fb0ea:386e8981662d4458:198046b81daaaf28:1
2021/08/16 07:28:37 Reporting span 799e6326100fb0ea:386e8981662d4458:198046b81daaaf28:1
2021/08/16 07:28:37 Reporting span 799e6326100fb0ea:198046b81daaaf28:152d6ee4f929c745:1
2021/08/16 07:28:37 Reporting span 1e47c34ad4cafdd2:06e618a491f40c40:69fb520f55dc0c29:1

Steps to Reproduce

  1. Bring up NSC and NSE on two different worker nodes.
  2. Perform kubectl delete -k . which would delete both endpoint and client together.
  3. You get the idea...

Context

Failure Logs

No relevant logs generated at this time for endpoint side forwarder.

Is this an issue at sdk side ? Please feel free to reject it when if this is not a bug.

denis-tingaikin commented 3 years ago

I feel we need to test this scenario with forwarder vpp and verify is Close called.

denis-tingaikin commented 3 years ago

@pperiyasamy Could you check this on forwarder vpp? Note: forwarder vpp is also supported veth pair

pperiyasamy commented 3 years ago

@denis-tingaikin Whenever I delete only NSC pod, then Close is always called on both local and remote forwarder, there is no problem here. but when NSC and NSE pods are deleted together, then Close at Endpoint forwarder side is not invoked. is there a chance that sdk chain element would return prematurely without invoking interpose endpoint's close when actual endpoint service (icmp-responder) not found ?

denis-tingaikin commented 3 years ago

Ah, I got it. For this kind scenario timeout chain element will close resources by tokens expiration.

pperiyasamy commented 3 years ago

@denis-tingaikin yes, upon timeout (after 5 mins) close was invoked on the forwarder, but connect server again failed with error no client found for the connection, looks it happened at here, this causes stale n/w entries forever on that client connection. any idea why connInfowasn't present when close (I'm sure this was a first close invocation) is invoked ? Looks this issue is not reproducible for every attempt. can we make NSMgr to invoke close on the endpoint side forwarder even when endpoint service is gone ?

denis-tingaikin commented 3 years ago

I think it is an issue of connect cache. Currently @Bolodya1997 working on removing cache from connect Server. So I'm mostly sure this problem will be solved in https://github.com/networkservicemesh/sdk/pull/1069

Bolodya1997 commented 3 years ago

In such scenario I expect the following behavior for the NSM:

Client -> L NSMgr -> L Forwarder -> L NSMgr -> R NSMgr -> R Forwarder -> R NSMgr -> Endpoint
  1. Endpoint dies.
  2. R NSMgr notices Endpoint death and starts closing chain in order:
    1. R NSMgr -> Endpoint = context canceled or client connection is closing error in R NSMgr logs.
    2. R Forwarder -> R NSMgr = no client found error in R Forwarder logs.
    3. R NSMgr -> R Forwarder = no client found error in R NSMgr logs.
    4. ...
    5. L NSMgr -> L Forwarder = no client found error in L NSMgr logs.
  3. Client sends Close.
  4. L NSMgr receives Close and starts closing chain in order:
    1. L NSMgr -> L Forwarder.
    2. L Forwarder -> L NSMgr.
    3. L NSMgr -> R NSMgr.
    4. ...
    5. R NSMgr -> Endpoint = client connection is closing error returned to Client.

In some place [2] meets [4] and it results in stopping both [2, 4] and most probably returning no client found error to Client.

Since Close was not successful for any part of chain, timeout will happen for all connections and will end with no client found error.

As a result, any part of the chain should be closed at least 2 times - first with heal/Close, second with timeout.

@pperiyasamy I can see that in the logs you have provided L Forwarder receives client connection is closing error. Who originates this error? Also can you please share how is it the whole case differs from the behavior that I expect.

pperiyasamy commented 3 years ago

@Bolodya1997 There were no logs at R Forwarder at the time of endpoint/client deletion, this made me to think L NSMgr -> R NSMgr -> R Forwarder call didn't happen. saw logs only at L Forwarder side which I've pasted already. upon timeout, there are logs at R Forwarder for this connection but that returned prematurely at connect server with error no client found for the connection, due to this no entries (for connecting endpoint) for that particular client connection are cleaned up as none of client chain element's close are invoked. I would attach more logs when I get into this issue again.