Kube-router: Orphaned tunnel interfaces in multi-subnet setup

[recombinationgroup]

What happened?
We observed traffic being lost between pods on certain nodes in our cluster and certain target IPs (EC2, RDS) within the same VPC. Only pods on a certain set of nodes were affected, while pods on other nodes could reach the target IPs without issue. The lost traffic manifested itself as total packet loss.

Traffic emerging from the host VMs themselves was not affected, i.e. the issue only occurred in traffic from kubernetes pods.

The k8s nodes are spread over three subnets, which may also contain other VMs or RDS instances. The traffic loss occurred on some nodes from one of the three subnets, while the target VM was assigned an IP from one of the remaining two subnets.

There are no Security Group or iptables rules (that I know of) impeding traffic between the affected pods/VMs.

The unifying cause seems to be the existence of tunnel interfaces on the hosts. We had six pods each trying to access a TCP port on IP 10.190.49.147. Three of these pods had no trouble getting through, while three pods experienced total packet loss. On all nodes with pods experiencing packet loss, there was an IPIP interface tun-1019049147, tunneling to 10.190.49.147. Example:

19: tun-1019049147@ens5: <POINTOPOINT,NOARP,UP,LOWER_UP> mtu 8961 qdisc noqueue state UNKNOWN group default qlen 1000
    link/ipip 10.190.54.142 peer 10.190.49.147
    inet6 fe80::5efe:abe:368e/64 scope link 
       valid_lft forever preferred_lft forever

This kind of interface did _not_ exist on nodes with pods without packet loss. I am not an expert in IP routing, but it seems that the pod traffic got lost in these orphaned tunnel interfaces. routel on an affected host shows the following entry:

         target            gateway          source    proto    scope    dev tbl
         [...]
  10.190.49.147                                                 linktun-1019049147 77

while ip route shows no mention of the tun-1019049147 or linktun-... devices or the IP 10.190.49.147.

The kube-router log seems to indicate that 10.190.49.147 had at one point in time been assigned to a k8s node, which has since gone down. This IP was subsequently assigned to a new VM (which became the TCP target of our pods). It seems to me that kube-router did not remove the tunnel interface when it detected that the k8s node 10.190.49.147 went down. This seems to have led to an orphaned tunnel interface (and hence broken routing), when the IP was assigned to a new VM. Grepping the corresponding kube-router log for the target IP (entire log since the initial node provisioning) shows only the following entries:

time="2020-08-12T08:30:49Z" level=warning msg="received notification" Code=6 Communicated-Reason= Data="[]" Key=10.190.49.147 Subcode=2 Topic=Peer
time="2020-08-12T08:30:49Z" level=info msg="Peer Down" Key=10.190.49.147 Reason="notification-received code 6(cease) subcode 2(administrative shutdown)" State=BGP_FSM_ESTABLISHED Topic=Peer
I0812 08:30:49.979695       1 network_routes_controller.go:472] Tunnel interface: tun-1019049147 for the node 10.190.49.147 already exists.
I0812 08:31:46.263744       1 bgp_peers.go:341] Received node 10.190.49.147 removed update from watch API, so remove node from peer
time="2020-08-12T08:31:46Z" level=warning msg="failed to unset md5: setsockopt: no such file or directory" Key=10.190.49.147 Topic=Peer
time="2020-08-12T08:31:46Z" level=info msg="Delete a peer configuration for:10.190.49.147" Topic=Peer

The newly provisioned VM was assigned the IP 10.190.49.147 on 2020-08-19, so well after the k8s node being unregistered.

Please let me know if I can provide any more relevant logs or information.

What did you expect to happen?
I expected the traffic to reach the target IP from any pod within the cluster.

I expected no tunnel interface to 10.190.49.147 to be present on any k8s host.

How can we reproduce the behavior you experienced?
Unfortunately, I do not know how to reproduce the behavior at this point.

System Information:

• Kube-Router Version: 0.4.0
• Kubernetes Version: 1.15.12
• Cloud Type: AWS
• Kubernetes Deployment Type: kops
• Kube-Router Deployment Type: DaemonSet
• Cluster Size: 40 nodes (master+worker)
• k8s host OS: Debian 10
• k8s host docker version: 18.06.3-ce, build d7080c1

Further information:
kube-router daemonset configuration: https://gist.github.com/recombinationgroup/b94394c7ce336efc4e8d49a02caaf947
kube-router-cfg config map: https://gist.github.com/recombinationgroup/6a7699304013fa2df634fae841cf72cc
Output of various routing/ip commands on one of the affected hosts: https://gist.github.com/recombinationgroup/1561b52ecdce5df3efd6099b93572aba
Entire log of kube-router on the same affected host: https://gist.github.com/recombinationgroup/2fda27badd1cc04a6136681fc9e3216d

[aauren]

Thanks for the detailed report!

0.4.0 is a pretty old release and we've resolved a significant amount of bugs in the 1.0.X line of releases, some of them having to do with routing issues. Can you try upgrading to that version of kube-router and letting us know if you are able to reproduce the issue?

Also, any additional context between the log lines here that you can share would probably also help:

I0812 08:30:49.979695       1 network_routes_controller.go:472] Tunnel interface: tun-1019049147 for the node 10.190.49.147 already exists.
... <- any relevant logs in this section would be helpful
I0812 08:31:46.263744       1 bgp_peers.go:341] Received node 10.190.49.147 removed update from watch API, so remove node from peer

kube-router lets BGP dictate which tunnels to add and then add routes to them. This is handled by the injectRoute() method of the network_routes_controller. Before receiving the node delete message which is the second log line above, theoretically, kube-router should have been signaled to stop, at which it would withdraw all of it's BGP advertisements and injectRoute() would have been run, and the route and the tunnel should have been removed.

[recombinationgroup]

Thanks for the quick reply and your insights, @aauren :) I am aware that 0.4.0 is not that recent. We will to upgrade to the 1.0.x release, but unfortunately I cannot promise that this will be done in the next few days. Since kops only just started to support kube-router 1.0.0 in 1.19-alpha2, diverging from their supported version is always a hassle as kops will revert a manually upgraded version back to the supported version on each change.

I will see whether I can upgrade our test environment to the 1.0.x release and reproduce the issue. Given that this issue seems to arise from node churn, it might also take some time for new orphaned tunnel devices to appear.

Regarding the log file, I attached the entirety of the kube-router log on the ticket: https://gist.github.com/recombinationgroup/2fda27badd1cc04a6136681fc9e3216d
I hope this is of use to you.

I just compared the log output to a case where a peer went down and kube-router correctly removed the corresponding tunnel. In the case above, the following log line appeared:

network_routes_controller.go:472] Tunnel interface: tun-1019049147 for the node 10.190.49.147 already exists.

No such log line was present when kube-router successfully removed the tunnel/device. This is the only difference in terms of kube-router logs I could make out so far. I uploaded the entire kube-router log here: https://gist.github.com/recombinationgroup/4cae34fd69c9a99d874275b25986f2cc
The correctly removed tunnel corresponded to IP 10.190.54.142 in this case.

EDIT: I have an additional question: is it possible to manually purge orphaned tunnels to ensure a clean slate before upgrading to 1.0.x?

[char6ming]

the same case, Orphaned tunnel interfaces

deleted the node (suppose the node ip is X.Y.Z) from my k8s cluster several days, we found that any of the pod in k8s can not reach the node X.Y.Z.

then, the tun-XYZ route entry is not exists，but the tun-XYZ network interface is in up running:

# ifconfig tun-xxxxxxx
tun-101485105: flags=209<UP,POINTOPOINT,RUNNING,NOARP>  mtu 1460
        inet6 xxxx::xxxx:xxxx:xxxx prefixlen 64  scopeid 0x20<link>
        inet6 xxxx::xxxx:xxxx:xxxx  prefixlen 64  scopeid 0x20<link>
        tunnel   txqueuelen 1000  (IPIP Tunnel)
        RX packets 30522660  bytes 13900325603 (12.9 GiB)
        RX errors 0  dropped 0  overruns 0  frame 0
        TX packets 20537296  bytes 19534620956 (18.1 GiB)
        TX errors 5891  dropped 0 overruns 0  carrier 0  collisions 0

with the following system information:

• kube-route

#kube-router -V
Running kube-router version v0.3.1, built on 2019-05-12T09:22:07+0000, go1.10.8

• k8s cluster, 70+ nodes

# kubectl version
Client Version: version.Info{Major:"1", Minor:"12", GitVersion:"v1.12.4", GitCommit:"f49fa022dbe63faafd0da106ef7e05a29721d3f1", GitTreeState:"clean", BuildDate:"2018-12-14T07:10:00Z", GoVersion:"go1.10.4", Compiler:"gc", Platform:"linux/amd64"}
Server Version: version.Info{Major:"1", Minor:"12", GitVersion:"v1.12.4", GitCommit:"f49fa022dbe63faafd0da106ef7e05a29721d3f1", GitTreeState:"clean", BuildDate:"2018-12-14T06:59:37Z", GoVersion:"go1.10.4", Compiler:"gc", Platform:"linux/amd64"}

• dockerd

# docker --version
Docker version 17.06.0-ce, build 02c1d87

• linux

# cat /proc/version 
Linux version 4.18.20-1.el7.x86_64  (gcc version 4.8.5 20150623 (Red Hat 4.8.5-28) (GCC)) #1 SMP Fri Aug 16 10:58:52 CST 2019

[recombinationgroup]

I can now further specify which entities seem to be orphaned specifically. There seem to be orphaned IPIP tunnel devices (tun-xxx) corresponding to previously existing k8s nodes, and also route table entries in table 77, which seems to be managed by network_routes_controller.go. On some nodes, there are >200 entries in this table, which is more than 5 times the size of the cluster. These route table entries are of this pattern:

10.190.23.104 dev tun-1019023104 scope link 
10.190.23.131 dev tun-1019023131 scope link 
10.190.23.132 dev tun-1019023132 scope link 
10.190.23.192 dev tun-1019023192 scope link 
10.190.23.235 dev tun-1019023235 scope link 
10.190.23.242 dev tun-1019023242 scope link

I assume that these exist to make node IPs routable from within pods on the host machine? The presence of orphaned route table entries will (as far as I understand this issue) direct packages to dead tunnel interfaces. This mismatch in count between nodes and route table entries indicates to me that more than 160 orphaned route table entries exist on this particular machine. This effectively shadows 160 IPs within the VPC.

[recombinationgroup]

EDIT: The hypothesis in this comment is likely bogus. See my next comment for a more likely cause to the issue.

~@aauren I started to read into network_routes_controller.go, looking for suspicious log messages. We have log entries likes this:~

network_routes_controller.go:356] Failed to inject routes due to: no such process

~several times per day. Not being very well versed in Go, I interpret the corresponding line in watchBgpUpdates() to mean that an error was caused by either of these return statements:~

    if path.IsWithdraw {
        glog.V(2).Infof("Removing route: '%s via %s' from peer in the routing table", dst, nexthop)
        return netlink.RouteDel(route)
    }
    glog.V(2).Infof("Inject route: '%s via %s' from peer to routing table", dst, nexthop)
    return netlink.RouteReplace(route)

~Note: these lines are the same in the current master HEAD as at v0.4.0.~

~The other returns in injectRoute() return explicit errors which do not match the log line.~

~Now, since we have the issue of orphaned route entries and tunnel devices, I think that the error comes from the call to netlink.RouteDel(route). Could it be that the network route controller correctly detects that a peer is no longer active, but there is an issue when removing the route entry? If so, do you have any idea why no such process might be the cause of the underlying error?~

[recombinationgroup]

We have now investigated the issue using v1.0.1 and can still replicate the problem. It occurs both with v0.4.0 as well as v1.0.1.

The issue reproducibly occurs whenever a node from a different subnet disappears from kubernetes. I now think it is caused by missing cleanup steps.

When a node disappears, injectRoute() is called and removes a route: https://github.com/cloudnativelabs/kube-router/blob/a33089d292644c78ce262df5a7b469758a7855a2/pkg/controllers/routing/network_routes_controller.go#L494

My observation is, that this only removes the route entry in route table main, but not the tunnel interface, and more importantly not the route entry in route table 77. I can only find two locations where route table 77 (a.k.a. customRouteTableID) is referenced:

• in injectRoute() when the route table entry in 77 is initially created: https://github.com/cloudnativelabs/kube-router/blob/a33089d292644c78ce262df5a7b469758a7855a2/pkg/controllers/routing/network_routes_controller.go#L468-L474
• in pbr.go, where policyBasedRouting is disabled or enabled. My understanding is that this manages whether a rule is created, which references route table 77. https://github.com/cloudnativelabs/kube-router https://github.com/cloudnativelabs/kube-router/blob/a33089d292644c78ce262df5a7b469758a7855a2/pkg/controllers/routing/pbr.go#L25 and https://github.com/cloudnativelabs/kube-router/blob/a33089d292644c78ce262df5a7b469758a7855a2/pkg/controllers/routing/pbr.go#L47

I would suspect that there needs to be at least a call like ip route del $peer-ip table 77 in injectRoutes when a route to a peer is withdrawn. Additionally, i guess the tunnel device should be removed as well, but I have not found out where this is supposed to happen, yet. As far as I can see, this happens only if overlay networking is set to "subnet" **and** the node is in the same subnet: https://github.com/cloudnativelabs/kube-router/blob/a33089d292644c78ce262df5a7b469758a7855a2/pkg/controllers/routing/network_routes_controller.go#L429 but does not happen in case of overlay networking set to "full" (which we don't do), or if the node is within another subnet.

The reason why this issue has gone unreported until now might be that our kubernetes cluster spans over three subnets (and overlay networking is utilized) _and_ shares those subnets with non-kubernetes nodes. Orphaned tunnels and routes in table 77 are not noticeable in "pure" subnets, since new nodes within the subnets will always spawn a corresponding IPIP tunnel interface. Hence, no packets will be lost in this case. Only when IPs in the subnet are not assigned to non-kubernetes VMs, the tunnel interfaces will lead to routing issues due to the missing IPIP device on the peer.

[murali-reddy]

@recombinationgroup thanks for your investigation. let me take a look at your findings

[jaredstehler]

I can confirm same symptom as https://github.com/cloudnativelabs/kube-router/issues/973#issuecomment-681912912

I have a node 10.200.3.68 which cannot communicate with an RDS node at 10.200.4.61. This is kops 1.19, kubernetes 1.19.7, ubuntu 20, kube-router v1.1.1.

From the logs it appears that the node used to be a kubernetes IP and is now an RDS host.

time="2021-03-05T15:35:14Z" level=info msg="Add a peer configuration for:10.200.4.61" Topic=Peer
time="2021-03-05T15:35:30Z" level=info msg="skipped asn negotiation: peer-as: 64512, peer-type: internal" Key=10.200.4.61 State=BGP_FSM_OPENSENT Topic=Peer
time="2021-03-05T15:35:30Z" level=info msg="Peer Up" Key=10.200.4.61 State=BGP_FSM_OPENCONFIRM Topic=Peer
time="2021-03-05T15:45:25Z" level=info msg="peer graceful restart" Key=10.200.4.61 State=BGP_FSM_ESTABLISHED Topic=Peer
time="2021-03-05T15:45:25Z" level=info msg="Peer Down" Key=10.200.4.61 Reason=graceful-restart State=BGP_FSM_ESTABLISHED Topic=Peer
I0305 15:46:11.321943       1 bgp_peers.go:334] Received node 10.200.4.61 removed update from watch API, so remove node from peer
time="2021-03-05T15:46:11Z" level=warning msg="failed to unset md5: no such file or directory" Key=10.200.4.61 Topic=Peer
time="2021-03-05T15:46:11Z" level=info msg="Delete a peer configuration for:10.200.4.61" Topic=Peer
I0305 15:46:11.326744       1 network_routes_controller.go:592] Tunnel interface: tun-10200461 for the node 10.200.4.61 already exists.

ip link show | grep 4.61:

133: tun-10200461@ens5: <POINTOPOINT,NOARP,UP,LOWER_UP> mtu 8961 qdisc noqueue state UNKNOWN mode DEFAULT group default qlen 1000
    link/ipip 10.200.3.68 peer 10.200.4.61

[mattlqx]

This is still a problem in the latest release of kube-router, 1.2.2. Long story short, we k8s clusters on EC2 that have pods that randomly can't reach various other things in our subnets in AWS. This problem manifests itself with much greater frequency when using ASGs as IPs cycle much more frequently. A host will leave the cluster, the ipip interface will stick around and blackhole traffic to that IP, which eventually can become an ENI for RDS or an ELB and cause connection timeouts to likely critical infrastructure. IMO, this issue should be raised to a high priority.

Example:

From a pod..

[root@kong-d4bf4d9cd-bvsck /]# curl -v https://172.30.13.168
* About to connect() to 172.30.13.168 port 443 (#0)
*   Trying 172.30.13.168...
* No route to host
* Failed connect to 172.30.13.168:443; No route to host
* Closing connection 0
curl: (7) Failed connect to 172.30.13.168:443; No route to host

On the host running the pod:

18: tun-1723013168@ens5: <POINTOPOINT,NOARP,UP,LOWER_UP> mtu 8961 qdisc noqueue state UNKNOWN group default qlen 1000
    link/ipip 172.30.22.230 peer 172.30.13.168

Deleting the interface, the pod can then connect out again to the IP.

[root@kong-d4bf4d9cd-bvsck /]# curl -v https://172.30.13.168
* About to connect() to 172.30.13.168 port 443 (#0)
*   Trying 172.30.13.168...
* Connected to 172.30.13.168 (172.30.13.168) port 443 (#0)
...

[tim-mcdonald]

We discovered this same issue in our environment recently. It's obviously exacerbated in clusters that scale up and down frequently. I wrote a shell script to help identify the orphaned interfaces and discovered nodes in our clusters with 60+ bad interfaces. On one longer lived 144 day old node, we had 190 orphaned interfaces. We've seen problems with pods connecting to external EC2 instances and RDS instances in our AWS environment more than once that we could only resolve by rescheduling pods until they happened to land on a node in the same availability zone as the external instance and were able to connect. This was a difficult issue to pin down.

I would love to see this issue raised to high priority as well. It's likely affecting more users than are even aware.

[edgan]

I too and seeing this issue with Jenkins masters running in AWS with ASGs. It is bad enough I am going to switch to a different CNI if this isn't fixed soon. A few times so far I have seen it get bad enough the Jenkins worker running on a Kubernetes worker wasn't able to talk to the Jenkins Master aka the Kubernetes master for DNS via CoreDNS.

This is still an issue with 1.3.0.

ifconfig | grep tun- | grep mtu | wc -l
1309

ifconfig | grep tun- | grep mtu | wc -l
325

[aauren]

@edgan / @tim-mcdonald / @recombinationgroup / @mattlqx / @jaredstehler - I have what I believe to be a fix for this issue on: https://github.com/cloudnativelabs/kube-router/pull/1130

If any of you guys are comfortable creating your own container and testing this in a test cluster where you experience this issue I'd be much obliged. I don't have any medium to large sized clusters to fully test this in, so my only testing was in a small 2 node cluster that I stood up. This change handled cleaning up the tunnels in that small environment well. But I'm aware that I probably don't experience as many edge cases as a full legitimate cluster.

[mattlqx]

Thanks @aauren, I'll try to get it out to my dev cluster and observe it.

[aauren]

Also, turning your logging level to at least level 2 (-v=2), would be super helpful in ensuring that kube-router is doing what we would expect if you find that tunnels are still sticking around.

If it properly detects the peer is down, you should see this line in your logs at logging level 1: https://github.com/cloudnativelabs/kube-router/pull/1130/files#diff-3fbf765cf87b00da79a617317b4560be103da01106ec50b766c73dcce39a265cR534

[edgan]

@aauren I am up for testing it. I realize you probably don't want to make a new release until the fix is tested, but can you point me to a pre-existing docker image that includes this fix? Normally this would be as easy as modifying the tag in the daemonset with a new release. But I would need to figure out the build process and make a new Docker image.

[aauren]

Sure, I created an informal build here: https://hub.docker.com/layers/cloudnativelabs/kube-router-git/amd64-fix_and_refactor_injectRoute/images/sha256-10e027c1c1da7e0f6f7b7465ce867628d3443ec941701f5e8b85961d9f085954?context=repo

docker.io/cloudnativelabs/kube-router-git:amd64-fix_and_refactor_injectRoute

[aauren]

Just checking in, was anyone able to find some time to test the fix?

One thing I meant to mention before, is that this will not clean up tunnels that already existed, it only cleans up when the routes are withdrawn. So you'll want to start with a node that doesn't have a bunch of tunnels stuck on it, or purge them all before upgrading if possible.

[edgan]

@aaruen I am testing it now. I should know if it is working later today.

[edgan]

@aaruen It does seem to have fixed it. I looked last night and I looked this morning, and the number of interfaces is at 11. Where as over time it had gotten over 700 before. 11 still seems higher than I would expect given circumstance, but it does seem to be a stable number.

[edgan]

@aaruen Can we get a new official release with this fix?

[Aaruen]

@edgan Sorry to bother you, but I think you were trying to contact @aauren and not me. :)

[aauren]

@edgan - We have several important bug fixes in process. We'll definitely release one soon, but we're trying to get closure around all of the known PRs right now before we cut a new release to try to solve as many as possible.

Look for a 1.3.1 in the next week or two. In the meantime cloudnativelabs/kube-router-git:master always represents the latest changes that have been merged.

[edgan]

@aauren I am still seeing this with 1.3.1. It fixed it on my more low volume Jenkins master that just runs a few jobs every half hour. But on my more CI/CD Jenkins cluster it has gotten to the point below in three days.

ifconfig | grep mtu | wc -l
177

kubectl get pod kube-router-rdpkc -o yaml -n kube-system | grep 'image:.*kube-router.*'
    image: docker.io/cloudnativelabs/kube-router:v1.3.1
    image: cloudnativelabs/kube-router:v1.3.1

[aauren]

Can you turn up the logging to at least level two and send me the logs around the time when a node disappears from the cluster?