NSE vl3 returns error when DNS is not ready

[d-uzlov]

Description

Forwarder can get an error from NSE if DNS server on the NSE side is not ready.

We should try to avoid this error and update DNS address later, when DNS is ready.

Logs

Fragment from NSE logs

Jun 21 08:57:06.460�[37m [TRAC] [id:197bac63-f60a-4745-9bf2-f3d1b9444034] [type:networkService] �[0m(1) ⎆ sdk/pkg/networkservice/common/updatepath/updatePathServer.Request()
Jun 21 08:57:06.460�[37m [TRAC] [id:197bac63-f60a-4745-9bf2-f3d1b9444034] [type:networkService] �[0m(1.1)   request={"connection":{"id":"197bac63-f60a-4745-9bf2-f3d1b9444034","network_service":"vl3-nscs-death","context":{"ip_context":{"excluded_prefixes":["10.96.0.0/16","10.244.0.0/16"]},"MTU":9000},"labels":{"nodeName":"kind-1-worker2","podName":"alpine-6b5dcf957b-scrhn"},"path":{"index":2,"path_segments":[{"name":"alpine-6b5dcf957b-scrhn","id":"alpine-6b5dcf957b-scrhn-0","token":"eyJhbGciOiJFUzI1NiIsInR5cCI6IkpXVCJ9.eyJzdWIiOiJzcGlmZmU6Ly9rOHMubnNtL25zL25zLXZsMy1uc2NzLWRlYXRoL3BvZC9hbHBpbmUtNmI1ZGNmOTU3Yi1zY3JobiIsImF1ZCI6WyJzcGlmZmU6Ly9rOHMubnNtL25zL25zbS1zeXN0ZW0vcG9kL25zbWdyLXdmMmRjIl0sImV4cCI6MTY4NzMzODQyNn0.s-Rn3RiT2bh8YjeEbe09yeVq8N2O-TOZeiICH0za0yDLOZIu_69cNdvc57LMfNyw8wxik0LzkO-LzyBVnbzOaQ","expires":{"seconds":1687338426,"nanos":181968993}},{"name":"nsmgr-wf2dc","id":"db559118-0517-4b2e-b8a8-d71e924e89d2","token":"eyJhbGciOiJFUzI1NiIsInR5cCI6IkpXVCJ9.eyJzdWIiOiJzcGlmZmU6Ly9rOHMubnNtL25zL25zbS1zeXN0ZW0vcG9kL25zbWdyLXdmMmRjIiwiYXVkIjpbInNwaWZmZTovL2s4cy5uc20vbnMvbnNtLXN5c3RlbS9wb2QvZm9yd2FyZGVyLXZwcC12eHFodyJdLCJleHAiOjE2ODczMzg0MjZ9.Tk2gWTFoHWcKglU3VgJgdLarxBeZsRO3SFIff7fGrfLVBRoeVjGSEXoD44Jpnx-21ui2gTSj2zoJ4L403EfC3g","expires":{"seconds":1687338426,"nanos":198369384}},{"name":"forwarder-vpp-vxqhw","id":"197bac63-f60a-4745-9bf2-f3d1b9444034","token":"eyJhbGciOiJFUzI1NiIsInR5cCI6IkpXVCJ9.eyJzdWIiOiJzcGlmZmU6Ly9rOHMubnNtL25zL25zbS1zeXN0ZW0vcG9kL2ZvcndhcmRlci12cHAtdnhxaHciLCJhdWQiOlsic3BpZmZlOi8vazhzLm5zbS9ucy9uc20tc3lzdGVtL3BvZC9uc21nci13ZjJkYyJdLCJleHAiOjE2ODczMzg0MjZ9.JAeWlpBg9K2xnnyOc2CEFKGjNuRGhKwtBjFv_tZvVbDFZTA9uJsJ9WAZlj-ELC8WwL_0vFWZ4NJ7OK4CiQ6YNg","expires":{"seconds":1687338426,"nanos":198955615}}]},"network_service_endpoint_name":"nse-vl3-vpp-6fcbdd789-gxfrz","payload":"IP"},"mechanism_preferences":[{"cls":"LOCAL","type":"MEMIF","parameters":{"inodeURL":""}},{"cls":"LOCAL","type":"KERNEL"}]}
Jun 21 08:57:06.460�[37m [TRAC] [id:197bac63-f60a-4745-9bf2-f3d1b9444034] [type:networkService] �[0m(1.2)   request-diff={"connection":{"id":"b8f23836-73d7-4740-8ec3-7bdbeba22cf6","path":{"index":3,"path_segments":{"+3":{"name":"nse-vl3-vpp-6fcbdd789-gxfrz","id":"b8f23836-73d7-4740-8ec3-7bdbeba22cf6"}}}}}
Jun 21 08:57:06.460�[37m [TRAC] [id:b8f23836-73d7-4740-8ec3-7bdbeba22cf6] [type:networkService] �[0m(2)  ⎆ sdk/pkg/networkservice/common/begin/beginServer.Request()
Jun 21 08:57:06.460�[37m [TRAC] [id:b8f23836-73d7-4740-8ec3-7bdbeba22cf6] [type:networkService] �[0m(3)   ⎆ sdk/pkg/networkservice/common/updatetoken/updateTokenServer.Request()
Jun 21 08:57:06.460�[37m [TRAC] [id:b8f23836-73d7-4740-8ec3-7bdbeba22cf6] [type:networkService] �[0m(3.1)     request-diff={"connection":{"path":{"path_segments":{"2":{"expires":{"nanos":459508256},"token":"eyJhbGciOiJFUzI1NiIsInR5cCI6IkpXVCJ9.eyJzdWIiOiJzcGlmZmU6Ly9rOHMubnNtL25zL25zbS1zeXN0ZW0vcG9kL2ZvcndhcmRlci12cHAtdnhxaHciLCJhdWQiOlsic3BpZmZlOi8vazhzLm5zbS9ucy9ucy12bDMtbnNjcy1kZWF0aC9wb2QvbnNlLXZsMy12cHAtNmZjYmRkNzg5LWd4ZnJ6Il0sImV4cCI6MTY4NzMzODQyNn0.Vu0vz-N3VwnLPpV-DpZd1q9Ds9W8JvqNcpdQxf5GafJqaeLQryChi9qrbmWvna66bZ_dW-v6WLdsSLgjVHSrsw"},"3":{"expires":{"nanos":460351932,"seconds":1687338426},"token":"eyJhbGciOiJFUzI1NiIsInR5cCI6IkpXVCJ9.eyJzdWIiOiJzcGlmZmU6Ly9rOHMubnNtL25zL25zLXZsMy1uc2NzLWRlYXRoL3BvZC9uc2UtdmwzLXZwcC02ZmNiZGQ3ODktZ3hmcnoiLCJhdWQiOlsic3BpZmZlOi8vazhzLm5zbS9ucy9uc20tc3lzdGVtL3BvZC9mb3J3YXJkZXItdnBwLXZ4cWh3Il0sImV4cCI6MTY4NzMzODQyNn0.updMfw8FnZVkrlcCBskqdPElEM3zlCeOC7wjqlgCRF5uh0HsDkC79Ac6MrRJQC-Vxgv1Q4IFpmhTfpjXT3Bq9Q"}}}}}
Jun 21 08:57:06.460�[37m [TRAC] [id:b8f23836-73d7-4740-8ec3-7bdbeba22cf6] [type:networkService] �[0m(4)    ⎆ sdk/pkg/networkservice/common/authorize/authorizeServer.Request()
Jun 21 08:57:06.461�[37m [TRAC] [id:b8f23836-73d7-4740-8ec3-7bdbeba22cf6] [type:networkService] �[0m(5)     ⎆ sdk/pkg/networkservice/utils/metadata/metadataServer.Request()
Jun 21 08:57:06.461�[37m [TRAC] [id:b8f23836-73d7-4740-8ec3-7bdbeba22cf6] [type:networkService] �[0m(6)      ⎆ sdk/pkg/networkservice/common/timeout/timeoutServer.Request()
Jun 21 08:57:06.461�[37m [TRAC] [id:b8f23836-73d7-4740-8ec3-7bdbeba22cf6] [type:networkService] �[0m(7)       ⎆ sdk/pkg/networkservice/common/monitor/monitorServer.Request()
Jun 21 08:57:06.461�[37m [TRAC] [id:b8f23836-73d7-4740-8ec3-7bdbeba22cf6] [type:networkService] �[0m(8)        ⎆ sdk/pkg/networkservice/common/trimpath/trimpathServer.Request()
Jun 21 08:57:06.461�[37m [TRAC] [id:b8f23836-73d7-4740-8ec3-7bdbeba22cf6] [type:networkService] �[0m(9)         ⎆ sdk/pkg/networkservice/common/null/nullServer.Request()
Jun 21 08:57:06.462�[37m [TRAC] [id:b8f23836-73d7-4740-8ec3-7bdbeba22cf6] [type:networkService] �[0m(10)          ⎆ sdk/pkg/networkservice/connectioncontext/dnscontext/vl3dns/vl3DNSServer.Request()
Jun 21 08:57:06.462�[31m [ERRO] [id:b8f23836-73d7-4740-8ec3-7bdbeba22cf6] [type:networkService] �[0m(10.1)            DNS address is initializing
Jun 21 08:57:06.462�[37m [TRAC] [id:b8f23836-73d7-4740-8ec3-7bdbeba22cf6] [type:networkService] �[0m(9.1)           request-response=null
Jun 21 08:57:06.462�[31m [ERRO] [id:b8f23836-73d7-4740-8ec3-7bdbeba22cf6] [type:networkService] �[0m(9.2)           DNS address is initializing
Jun 21 08:57:06.462�[31m [ERRO] [id:b8f23836-73d7-4740-8ec3-7bdbeba22cf6] [type:networkService] �[0m(8.1)          DNS address is initializing
Jun 21 08:57:06.462�[31m [ERRO] [id:b8f23836-73d7-4740-8ec3-7bdbeba22cf6] [type:networkService] �[0m(7.1)         DNS address is initializing
Jun 21 08:57:06.462�[31m [ERRO] [id:b8f23836-73d7-4740-8ec3-7bdbeba22cf6] [type:networkService] �[0m(6.1)        DNS address is initializing
Jun 21 08:57:06.462�[37m [DEBU] [id:b8f23836-73d7-4740-8ec3-7bdbeba22cf6] [connID:b8f23836-73d7-4740-8ec3-7bdbeba22cf6] [metadata:server] [type:networkService] �[0m(5.1)       metadata deleted
Jun 21 08:57:06.462�[31m [ERRO] [id:b8f23836-73d7-4740-8ec3-7bdbeba22cf6] [type:networkService] �[0m(5.2)       DNS address is initializing
Jun 21 08:57:06.462�[31m [ERRO] [id:b8f23836-73d7-4740-8ec3-7bdbeba22cf6] [type:networkService] �[0m(4.1)      DNS address is initializing
Jun 21 08:57:06.462�[31m [ERRO] [id:b8f23836-73d7-4740-8ec3-7bdbeba22cf6] [type:networkService] �[0m(3.2)     DNS address is initializing
Jun 21 08:57:06.462�[31m [ERRO] [id:b8f23836-73d7-4740-8ec3-7bdbeba22cf6] [type:networkService] �[0m(2.1)    DNS address is initializing
Jun 21 08:57:06.462�[31m [ERRO] [id:197bac63-f60a-4745-9bf2-f3d1b9444034] [type:networkService] �[0m(1.3)   DNS address is initializing

The fragment above is from TestRunHealSuite/TestVl3_nscs_death test but the error "DNS address is initializing" seems to happen quite often, in different tests.

TestRunHealSuite.zip

References

https://github.com/networkservicemesh/sdk/blob/a8c394e69c4e1a10acc3a61acb5eb88d57901a67/pkg/networkservice/connectioncontext/dnscontext/vl3dns/server.go#L202

[glazychev-art]

The most appropriate solution is not to return an error, but to send REFRESH_REQUESTED when the DNS is ready.

But in this case, the question is: what if this refresh fails? We should be able to do a retry. This brings us back to the idea that retry should be placed after the begin element chain. (see Solution 2 - networkservicemesh/sdk#1457 (comment))