Enabling DSR failing with exit status 1

[anupamdialpad]

What happened?

While enabling DSR for a service kube-router is failing with linux_networking.go:534] Failed to add route for 199.27.151.9 in custom route table for external IP's due to: exit status 1

What did you expect to happen?

DSR should get enabled successfully

How can we reproduce the behavior you experienced?

This is my service manifest

apiVersion: v1
kind: Service
metadata:
  annotations:
    kube-router.io/service.dsr: "tunnel"
  name: echo-server-lb
spec:
  externalTrafficPolicy: Cluster
  selector:
    app: echo-server
  ports:
    - protocol: TCP
      port: 8080
      targetPort: 8080
  externalIPs:
    - 199.27.151.9

After applying the service manifest I see the error in kube-router logs

System Information (please complete the following information)

• Kube-Router Version (kube-router --version): v2.2.2-dirty
• Kube-Router Parameters:

--kubeconfig=/usr/local/kube-router/kube-router.kubeconfig 
--run-router=true 
--run-firewall=true 
--run-service-proxy=true 
--v=3 
--peer-router-ips=xxx 
--peer-router-asns=65322 
--cluster-asn=65321 
--enable-ibgp=false 
--enable-overlay=false 
--bgp-graceful-restart=true 
--bgp-graceful-restart-deferral-time=30s 
--bgp-graceful-restart-time=5m 
--service-external-ip-range=199.27.151.8/30 
--runtime-endpoint=unix:///run/containerd/containerd.sock 
--enable-ipv6=true 
--advertise-external-ip=true 
--routes-sync-period=1m0s 
--iptables-sync-period=1m0s 
--ipvs-sync-period=1m0s 
--hairpin-mode=true 
--advertise-pod-cidr=true

• Kubernetes Version (kubectl version) : 1.29
• Cloud Type: on premise
• Kubernetes Deployment Type: manual installation of kubernetes
• Kube-Router Deployment Type: System Service
• Cluster Size: 2 Nodes

Logs, other output, metrics

I0421 11:22:15.086394  545684 service_endpoints_sync.go:95] Setting up DSR Services
I0421 11:22:15.086410  545684 service_endpoints_sync.go:605] Setting up policy routing required for Direct Server Return functionality.
I0421 11:22:15.086439  545684 linux_routing.go:30] Did not find iproute2's rt_tables in location /usr/lib/iproute2/rt_tables
I0421 11:22:15.086454  545684 linux_routing.go:30] Did not find iproute2's rt_tables in location /usr/share/iproute2/rt_tables
I0421 11:22:15.090968  545684 service_endpoints_sync.go:610] Custom routing table kube-router-dsr required for Direct Server Return is setup as expected.
I0421 11:22:15.091009  545684 service_endpoints_sync.go:613] Setting up custom route table required to add routes for external IP's.
I0421 11:22:15.091039  545684 linux_routing.go:30] Did not find iproute2's rt_tables in location /usr/lib/iproute2/rt_tables
I0421 11:22:15.091055  545684 linux_routing.go:30] Did not find iproute2's rt_tables in location /usr/share/iproute2/rt_tables
E0421 11:22:15.098804  545684 linux_networking.go:534] Failed to add route for 199.27.151.9 in custom route table for external IP's due to: exit status 1
I0421 11:22:15.098836  545684 service_endpoints_sync.go:621] Custom routing table required for Direct Server Return (external_ip) is setup as expected.
I0421 11:22:15.098859  545684 service_endpoints_sync.go:107] IPVS servers and services are synced to desired state
I0421 11:22:15.098872  545684 service_endpoints_sync.go:32] sync ipvs services took 1.990680596s

Additional context

1. iproute2 version is 5.10.0-4
2. kube-router is running as root and has the permission to edit /etc/iproute2/rt_tables on the host.

$ cat /etc/iproute2/rt_tables
...
77 kube-router
78 kube-router-dsr
79 external_ip

[aauren]

Hmm... Are you able to try this manually as root on the same node where kube-router is having this error?

The command that kube-router is trying to execute is:

ip route add 199.27.151.9 dev kube-bridge table 79

It would be interesting to know if you get a similar error as kube-router is getting or not.

[anupamdialpad]

Thank you @aauren for looking at this!

The command fails with RTNETLINK answers: File exists which makes me believe that the rule did get added.

root@eqx-sjc-kubenode1-staging:~ $ ip route add 199.27.151.9 dev kube-bridge table 79
RTNETLINK answers: File exists
root@eqx-sjc-kubenode1-staging:~ $ echo $?
2

root@eqx-sjc-kubenode1-staging:~ $ ip route show table 79
199.27.151.9 dev kube-bridge scope link 
199.27.151.10 dev kube-bridge scope link 

I could have ignored the error but IPVS table doesn't show any entry with the Service IP 199.27.151.9 and the advertisement doesn't happen. The two pods behind that service are with pod IPs 10.36.0.57 & 10.36.1.12.

root@eqx-sjc-kubenode1-staging:~ $ ipvsadm -L -n
IP Virtual Server version 1.2.1 (size=4096)
Prot LocalAddress:Port Scheduler Flags
  -> RemoteAddress:Port           Forward Weight ActiveConn InActConn
TCP  192.168.0.1:443 rr
  -> 34.0.4.163:6443              Masq    1      0          0         
  -> 35.199.191.22:6443           Masq    1      0          0         
TCP  192.168.55.55:8080 mh
  -> 10.36.0.57:8080              Masq    1      0          0         
  -> 10.36.1.12:8080              Masq    1      0          0   
FWM  14146 mh
  -> 10.36.0.57:8080              Tunnel  1      0          0         
  -> 10.36.1.12:8080              Tunnel  1      0          0       

root@gce-del-km-staging-anupam:~ $ kubectl get pods -o wide -l app=echo-server
NAME                READY   STATUS    RESTARTS   AGE     IP           NODE                        
echo-server-6kjn5   1/1     Running   0          6d3h    10.36.1.12   tlx-dal-kubenode1-staging
echo-server-jk6kv   1/1     Running   0          4d23h   10.36.0.57   eqx-sjc-kubenode1-staging

[aauren]

Hmm... This leads me to believe that maybe it succeeded on a subsequent attempt to add the route? Still odd that you don't see the IPVS service though. Also, note that the error code for the route existing is 2 which isn't the same as the error that kube-router got from your log where it was 1.

Do you see anything else obvious in the logs? It may have gotten lost by now, if so, maybe delete and re-create the service and see what happens in the logs?

It may also help to increase the logging verbosity using the -v option. Maybe something like -v=2 or so might show some more information?

[anupamdialpad]

This is the log with verbosity 3.

I0429 06:07:50.074478 1165426 linux_networking.go:392] Updated schedule for the service: FWMark:14146 (Flags: [hashed entry])
I0429 06:07:50.074526 1165426 linux_networking.go:406] ipvs service FWMark:14146 (Flags: [hashed entry]) already exists so returning
I0429 06:07:50.080558 1165426 network_services_controller.go:1637] looking for mangle rule with: POSTROUTING -t mangle [-s 199.27.151.9 -m tcp -p tcp --tcp-flags SYN,RST SYN -j TCPMSS --set-mss 1440]
I0429 06:07:50.082025 1165426 network_services_controller.go:1637] looking for mangle rule with: PREROUTING -t mangle [-d 199.27.151.9 -m tcp -p tcp --tcp-flags SYN,RST SYN -j TCPMSS --set-mss 1440]
W0429 06:07:50.083543 1165426 linux_networking.go:103] got an IfaceHasNoAddr error while trying to delete address 199.27.151.9 from netlink kube-dummy-if: cannot assign requested address (this is not normally bad enough to stop processing)
W0429 06:07:50.085265 1165426 linux_networking.go:118] got a No such process error while trying to remove route: exit status 2 (this is not normally bad enough to stop processing)
I0429 06:07:50.087124 1165426 linux_networking.go:447] ipvs destination 10.36.0.57:8080 (Family: IPv4, Weight: 1) already exists in the ipvs service FWMark:14146 (Flags: [hashed entry]) so not adding destination
I0429 06:07:50.089339 1165426 linux_networking.go:708] Current network namespace after netns. Set to container network namespace: NS(16: 4, 4026532790)
I0429 06:07:50.089698 1165426 linux_networking.go:767] Successfully assigned VIP: 199.27.151.9 in endpoint 10.36.0.57.
I0429 06:07:50.089896 1165426 linux_networking.go:789] Successfully disabled rp_filter in endpoint 10.36.0.57.
I0429 06:07:50.089955 1165426 linux_networking.go:799] Current network namespace after revert namespace to host network namespace: NS(16: 4, 4026532008)
I0429 06:07:50.090271 1165426 linux_networking.go:447] ipvs destination 10.36.1.12:8080 (Family: IPv4, Weight: 1) already exists in the ipvs service FWMark:14146 (Flags: [hashed entry]) so not adding destination
I0429 06:07:50.090301 1165426 service_endpoints_sync.go:362] no external IP addresses returned for service default:kubernetes skipping...
I0429 06:07:50.090319 1165426 service_endpoints_sync.go:64] Setting up NodePort Health Checks for LB services
I0429 06:07:50.090331 1165426 nodeport_healthcheck.go:38] Running UpdateServicesInfo for NodePort health check
I0429 06:07:50.090345 1165426 nodeport_healthcheck.go:70] Finished UpdateServicesInfo for NodePort health check
I0429 06:07:50.090361 1165426 service_endpoints_sync.go:71] Cleaning Up Stale VIPs from dummy interface
I0429 06:07:50.090372 1165426 service_endpoints_sync.go:628] Cleaning up if any, old service IPs on dummy interface
I0429 06:07:50.090655 1165426 service_endpoints_sync.go:649] Found an IP fe80::c831:bdff:fe9d:5982 which is no longer needed so cleaning up
I0429 06:07:50.090682 1165426 linux_networking.go:87] Ignoring link-local IP address: fe80::c831:bdff:fe9d:5982
I0429 06:07:50.090700 1165426 service_endpoints_sync.go:78] Cleaning Up Stale VIPs from IPVS
I0429 06:07:50.090802 1165426 service_endpoints_sync.go:692] Cleaning up if any, old ipvs service and servers which are no longer needed
I0429 06:07:50.090851 1165426 service_endpoints_sync.go:695] Current active service map:
{
      "13844": [
          "10.36.0.59:8099",
          "10.36.0.60:8099"
      ],
      "14146": [
          "10.36.0.57:8080",
          "10.36.1.12:8080"
      ],
      "192.168.0.1-tcp-443": [
          "35.199.191.22:6443",
          "34.0.4.163:6443"
      ],
      "192.168.120.61-tcp-80": [
          "10.36.0.59:8099",
          "10.36.0.60:8099"
      ],
      "192.168.220.83-tcp-8080": [
          "10.36.0.57:8080",
          "10.36.1.12:8080"
      ]
  }
I0429 06:07:50.091172 1165426 service_endpoints_sync.go:85] Cleaning Up Stale metrics
I0429 06:07:50.091197 1165426 service_endpoints_sync.go:88] Syncing IPVS Firewall
I0429 06:07:50.091209 1165426 network_services_controller.go:605] Attempting to attain ipset mutex lock
I0429 06:07:50.091233 1165426 network_services_controller.go:607] Attained ipset mutex lock, continuing...
I0429 06:07:50.092938 1165426 ipset.go:595] ipset (ipv6? false) restore looks like:
create TMP-PRBJ7ASFQM5DJR3Q hash:ip timeout 0
flush TMP-PRBJ7ASFQM5DJR3Q
add TMP-PRBJ7ASFQM5DJR3Q 127.0.0.1 timeout 0
add TMP-PRBJ7ASFQM5DJR3Q 192.168.0.1 timeout 0
add TMP-PRBJ7ASFQM5DJR3Q 103.35.127.34 timeout 0
create kube-router-local-ips hash:ip timeout 0
swap TMP-PRBJ7ASFQM5DJR3Q kube-router-local-ips
flush TMP-PRBJ7ASFQM5DJR3Q
add TMP-PRBJ7ASFQM5DJR3Q 192.168.220.83 timeout 0
add TMP-PRBJ7ASFQM5DJR3Q 192.168.0.1 timeout 0
add TMP-PRBJ7ASFQM5DJR3Q 192.168.120.61 timeout 0
add TMP-PRBJ7ASFQM5DJR3Q 199.27.151.9 timeout 0
add TMP-PRBJ7ASFQM5DJR3Q 199.27.151.10 timeout 0
create kube-router-svip hash:ip timeout 0
swap TMP-PRBJ7ASFQM5DJR3Q kube-router-svip
flush TMP-PRBJ7ASFQM5DJR3Q
create TMP-TF3INM4IEYGA443O hash:ip,port timeout 0
flush TMP-TF3INM4IEYGA443O
add TMP-TF3INM4IEYGA443O 192.168.220.83,tcp:8080 timeout 0
add TMP-TF3INM4IEYGA443O 192.168.0.1,tcp:443 timeout 0
add TMP-TF3INM4IEYGA443O 192.168.120.61,tcp:80 timeout 0
add TMP-TF3INM4IEYGA443O 199.27.151.9,tcp:8080 timeout 0
add TMP-TF3INM4IEYGA443O 199.27.151.10,tcp:80 timeout 0
create kube-router-svip-prt hash:ip,port timeout 0
swap TMP-TF3INM4IEYGA443O kube-router-svip-prt
flush TMP-TF3INM4IEYGA443O
destroy TMP-PRBJ7ASFQM5DJR3Q
destroy TMP-TF3INM4IEYGA443O
I0429 06:07:50.146399 1165426 ipset.go:595] ipset (ipv6? true) restore looks like:
create TMP-3TF2IQ5MKRP6NAJL hash:ip timeout 0 family inet6
flush TMP-3TF2IQ5MKRP6NAJL
add TMP-3TF2IQ5MKRP6NAJL fe80::1618:77ff:fe59:e19 timeout 0
add TMP-3TF2IQ5MKRP6NAJL fe80::88c7:18ff:fe16:a351 timeout 0
add TMP-3TF2IQ5MKRP6NAJL fe80::ec1a:dff:fe1b:d86 timeout 0
add TMP-3TF2IQ5MKRP6NAJL fe80::4432:7eff:fedc:d3d7 timeout 0
add TMP-3TF2IQ5MKRP6NAJL fe80::40a0:fdff:fe7f:c136 timeout 0
add TMP-3TF2IQ5MKRP6NAJL ::1 timeout 0
add TMP-3TF2IQ5MKRP6NAJL 2a05:e580:ff00:0:1618:77ff:fe59:e19 timeout 0
create inet6:kube-router-local-ips hash:ip timeout 0 family inet6
swap TMP-3TF2IQ5MKRP6NAJL inet6:kube-router-local-ips
flush TMP-3TF2IQ5MKRP6NAJL
create inet6:kube-router-svip hash:ip timeout 0 family inet6
swap TMP-3TF2IQ5MKRP6NAJL inet6:kube-router-svip
flush TMP-3TF2IQ5MKRP6NAJL
create TMP-54ALMNP65S4KA7CE hash:ip,port timeout 0 family inet6
flush TMP-54ALMNP65S4KA7CE
create inet6:kube-router-svip-prt hash:ip,port timeout 0 family inet6
swap TMP-54ALMNP65S4KA7CE inet6:kube-router-svip-prt
flush TMP-54ALMNP65S4KA7CE
destroy TMP-3TF2IQ5MKRP6NAJL
destroy TMP-54ALMNP65S4KA7CE
I0429 06:07:50.238449 1165426 network_services_controller.go:610] Returned ipset mutex lock
I0429 06:07:50.238500 1165426 service_endpoints_sync.go:95] Setting up DSR Services
I0429 06:07:50.238514 1165426 service_endpoints_sync.go:605] Setting up policy routing required for Direct Server Return functionality.
I0429 06:07:50.238547 1165426 linux_routing.go:30] Did not find iproute2's rt_tables in location /usr/lib/iproute2/rt_tables
I0429 06:07:50.238563 1165426 linux_routing.go:30] Did not find iproute2's rt_tables in location /usr/share/iproute2/rt_tables
I0429 06:07:50.241492 1165426 service_endpoints_sync.go:610] Custom routing table kube-router-dsr required for Direct Server Return is setup as expected.
I0429 06:07:50.241522 1165426 service_endpoints_sync.go:613] Setting up custom route table required to add routes for external IP's.
I0429 06:07:50.241552 1165426 linux_routing.go:30] Did not find iproute2's rt_tables in location /usr/lib/iproute2/rt_tables
I0429 06:07:50.241571 1165426 linux_routing.go:30] Did not find iproute2's rt_tables in location /usr/share/iproute2/rt_tables
E0429 06:07:50.247830 1165426 linux_networking.go:534] Failed to add route for 199.27.151.10 in custom route table for external IP's due to: exit status 1
E0429 06:07:50.248855 1165426 linux_networking.go:534] Failed to add route for 199.27.151.9 in custom route table for external IP's due to: exit status 1
I0429 06:07:50.248895 1165426 service_endpoints_sync.go:621] Custom routing table required for Direct Server Return (external_ip) is setup as expected.
I0429 06:07:50.248920 1165426 service_endpoints_sync.go:107] IPVS servers and services are synced to desired state
I0429 06:07:50.248933 1165426 service_endpoints_sync.go:32] sync ipvs services took 6.145008117s
I0429 06:07:50.248966 1165426 network_services_controller.go:343] Performing periodic graceful destination cleanup
I0429 06:07:50.248985 1165426 health_controller.go:91] Received heartbeat from NSC