Kube-router: kube router generates incorrect ipsets

[phin1x]

What happened?
after upgrading from kube router 1.1.1 to 1.2.2 the network communication on some nodes of our cluster suddenly stops after some time. we found out that the ipset for the local ips got messed up, all entries are gone. we checked the ipsets on the working nodes and there the ipset kube-router-local-ips has three or four members (depending on the node type).

What did you expect to happen?
kube router should not discard the members in the ipset kube-router-local-ips

How can we reproduce the behavior you experienced?
We cannot say how this problem can be reproduced, since from our point of view it appears out of nowhere.

* Screenshots / Architecture Diagrams / Network Topologies *

* System Information (please complete the following information):*

• Kube-Router Version 1.2.2
• Kube-Router Parameters: --run-router=true --run-firewall=true --run-service-proxy=true --kubeconfig=/var/lib/kube-router/kubeconfig --metrics-port=9912
• Kubernetes Version (kubectl version) : 1.20.5
• Cloud Type: on premise
• Kubernetes Deployment Type: custom setup
• Kube-Router Deployment Type: DaemonSet
• Cluster Size: 4

* Logs, other output, metrics *
No logs were recorded at the time the error occurred

Additional context

[aauren]

@phin1x Thanks for reporting. Unfortunately, if we can't reproduce it there may not be much to do here. I can maybe give you more information in case you have a node that is currently in this state, or if it happens again.

The kube-router-local-ips ipset is populated by this method: getAllLocalIPs

This method essentially lists all of your Linux network interfaces (i.e. ip link) on the node kube-router is running on and if their name doesn't contain dummy, kube, or docker it will add all of their IPv4 addresses to this ipset.

If there is an error while it is attempting to get the IP addresses you should see a message like the following in your kube-router logs: Error syncing ipvs svc iptables rules to permit traffic to service VIP's: failed to get local IPs: .... It is emitted at the error level, so it should be present no matter what.

This method is run each time the services controller is invoked (i.e. any time a relevant service changes, or on the interval --ipvs-sync-period is configured for). Therefore, the only reason why this would be missing would be if your local linux interfaces changed or it encountered an error. Additionally, nothing about this logic has changed much in more than 3 years so I would doubt that its related to the upgrade from 1.1.1 to 1.2.2.

If you encounter this error again, please give the full output of ip addr as well as the full kube-router log during the time around the error. Without this information, we'll likely have no choice but to close as not reproducable.

[phin1x]

thanks for the reply.
we already rolled back to version v1.1.1 and the problem no longer occurred (we hit the error multiple times a day). we are using kube-router since version v0.2.5 and we never had issues like that. we also don't saw any errors related to the getAllLocalIPs method.
in v1.2 the ipsets now are updated via ipset load and ipset save, mabye we are hitting a edge case there.
we will try to debug the problem, but since it only happen on 2 of our 5 clusters, it will be not easy to reproduce the error.

[aauren]

@phin1x Have you had any chance to try it out again on another cluster? I'm thinking that this may be a race condition between NetworkPolicyController and NetworkServiceController's usage of ipset, but I haven't been able to reproduce it anywhere. Furthermore, I can't explain why the ipset would be blank. I could see it maybe being old, but I can't see a race condition right now that would produce a blank set.

I'm hoping maybe you've had more luck reproducing it.

[grimurd]

I'm having what I believe is the same problem, nodes will randomly lose all network connectivity. From inside the machine I can only ping localhost, not the external IP of the machine.

This can happen to multiple machines at the same time or it can happen to a single node repeatedly over the course of an hour.

The only way to fix it is by rebooting the node.

I can see nothing in any logs on the machine, nothing relevant in the kube-router logs either. I'm completely stumped. But this sounds like the same issue I'm having.

I'll have to check the ipset the next time this happens.

EDIT

ipset --list returns a ton of ipsets so it must be a different issue

[phin1x]

@grimurd you have to check the ipset with the name kube-router-local-ips. it should contain the ips of your worker. in our case the ipset is empty and this causes the outging packages beeing dropped by a iptables rule.

ipset --list returns all ipsets which are configured.

[aauren]

To help troubleshoot this issue, it would be helpful if when this happens we could get someone to upload the full output of the following commands while the node itself is showing as offline/unreachable:

ipset list
route -n
ip addr

[grimurd]

The kube-router-local-ips ipset is empty for me

@aauren Is there an email I can send the output to?

[phin1x]

i deployed a version with more debug output. at the moment, we could not reproduced the error but i have a guess. the temporary ipsets are not unique. for example the temporary ipset for kube-router-service-ips, kube-router-node-ips and kube-router-local-ips is the same (in our case TMP-MOR3H7HU5JDLK6FI). Also, the temporary name remains the same for each ipset restore call. so there could be a race condition if the restore function is called from two different go routines, one flushed the the temporary ipset and the other want to swap it.

[phin1x]

@aauren what is the ipset with the name "kube-router-local-ips-" (note the dash at the end)?

as we lookup into the logs, kube-router sometimes generate a rule like this:

2021-05-28T02:17:56.507495342+02:00 stdout F create TMP-MOR3H7HU5JDLK6FI hash:ip family inet hashsize 1024 maxelem 65536 timeout 0
2021-05-28T02:17:56.507495342+02:00 stdout F flush TMP-MOR3H7HU5JDLK6FI
2021-05-28T02:17:56.507495342+02:00 stdout F add TMP-MOR3H7HU5JDLK6FI xxx timeout 0
2021-05-28T02:17:56.507495342+02:00 stdout F add TMP-MOR3H7HU5JDLK6FI xxx timeout 0
2021-05-28T02:17:56.507495342+02:00 stdout F add TMP-MOR3H7HU5JDLK6FI xxx timeout 0
2021-05-28T02:17:56.507495342+02:00 stdout F add TMP-MOR3H7HU5JDLK6FI 127.0.0.1 timeout 0
2021-05-28T02:17:56.507495342+02:00 stdout F create kube-router-local-ips hash:ip family inet hashsize 1024 maxelem 65536 timeout 0
2021-05-28T02:17:56.507495342+02:00 stdout F swap TMP-MOR3H7HU5JDLK6FI kube-router-local-ips
2021-05-28T02:17:56.507495342+02:00 stdout F flush TMP-MOR3H7HU5JDLK6FI
2021-05-28T02:17:56.507495342+02:00 stdout F create kube-router-local-ips- hash:ip family inet hashsize 1024 maxelem 65536 timeout 0
2021-05-28T02:17:56.507495342+02:00 stdout F swap TMP-MOR3H7HU5JDLK6FI kube-router-local-ips-
2021-05-28T02:17:56.507495342+02:00 stdout F flush TMP-MOR3H7HU5JDLK6FI

one of our node died a minute after kube-router created the ipset above and we want to better understand, what kube-router is doning here.

[aauren]

@phin1x Thanks for continuing to update here.

What you are seeing with the above is the result of two different methods of updating ipsets. NetworkPolicyController's (NPC) go routine which does a lot of work with ipsets does batch updates utilizing the TMP prefix which is seen here: https://github.com/cloudnativelabs/kube-router/blob/master/pkg/utils/ipset.go#L408

Using a batch update system was one of the changes that we made between kube-router-1.1 -> kube-router-1.2. On our clusters we saw that the time it took to run a full sync was reduced from 45 seconds to less than a second. The reason for this, is that it greatly reduces the context switches that kube-router makes when it exec's out to operate on ipsets.

However, NetworkServicesController (NSC) and NetworkRoutesController (NRC) only operate on 2 or 3 ipsets. Those ones use the old method of making a set of calls for each refresh as seen here: https://github.com/cloudnativelabs/kube-router/blob/master/pkg/utils/ipset.go#L544 which utilizes a trailing hyphen in order to accomplish the ipset swap (that is what the kube-router-local-ips- set is that you mentioned.

At this point, I think that it is very clear that this issue is being caused by ipset resource contention. We're now testing out #1088 in our production and its been very successful. If you're open to it, it would be awesome if you could test that patch out in the environment where you are experiencing problems and give feedback, but at this point I'm 99% sure that this will resolve all of the problems that we've seen so far with the 1.2 release.

If our numbers hold good through the weekend, we will likely merge those changes and back-port them to the 1.2 branch and cut an official 1.2.3 release sometime next week. After that, we'll do some more refactoring in 1.3 to make that fix a bit cleaner.

[phin1x]

thanks for the explanation. we will try the patch.

[aauren]

After 5+ days of testing in multiple clusters and these ipset symptoms not resurfacing I have merged #1088 and cut a kube-router bugfix release that contains this and several other fixes.

For anyone experiencing this issue, please try kube-router-1.2.3:

• https://hub.docker.com/layers/cloudnativelabs/kube-router/v1.2.3/images/sha256-609a899b4f0d953b4f83361aa8df0053c1eb3dad7bdaf21c5a46aa1c4c5bb883?context=explore&tab=layers
• https://github.com/cloudnativelabs/kube-router/releases/tag/v1.2.3

[phin1x]

on our cluster the patch runs fine for almost 2 days now. i will try 1.2.3 tomorrow.

[aauren]

How has this been working out for everyone so far? Any feedback on the 1.2.3 release and this issue?

[grimurd]

I haven't had any network issues since the update but I've been having some other issues that I'm not sure are related but I'll include them in case.

The kube-router pods have had problems with iptables. However after updating the daemon set to increase the log level they haven't had the same issues so it might be nothing.

I've also had kube-router pods crashing. That also improved after the daemon set was updated but a couple have still crashed since.

Centos 8 Stream 4.18.0-301.1.el8.x86_64
CRI-O 1.20.2
Kubernetes v1.20.6

Link to latest crash log

Here are logs of the iptables problems before I changed the log level

E0602 12:51:49.146281       1 service_endpoints_sync.go:293] Failed to run iptables-save: %!s(MISSING)signal: segmentation fault (core dumped) ()
E0602 12:56:49.037165       1 service_endpoints_sync.go:293] Failed to run iptables-save: %!s(MISSING)signal: segmentation fault (core dumped) ()
E0602 13:11:49.047527       1 service_endpoints_sync.go:293] Failed to run iptables-save: %!s(MISSING)signal: segmentation fault (core dumped) ()
E0602 13:41:49.125767       1 service_endpoints_sync.go:293] Failed to run iptables-save: %!s(MISSING)signal: segmentation fault (core dumped) ()
E0602 13:51:48.756115       1 service_endpoints_sync.go:69] Error syncing ipvs svc iptables rules to permit traffic to service VIP's: failed to sync ipset: ipset v7.6: Kernel error received: Resource busy
E0602 14:11:49.020428       1 network_services_controller.go:449] Error syncing hairpin iptables rules: Error deleting hairpin rules: Failed to list iptables chains: running [/sbin/iptables -t nat -S --wait]: exit status -1:

E0602 16:54:00.728588       1 service_endpoints_sync.go:293] Failed to run iptables-save: %!s(MISSING)signal: segmentation fault (core dumped) ()
E0602 17:24:00.513664       1 network_services_controller.go:449] Error syncing hairpin iptables rules: Error deleting hairpin rules: Failed to list iptables chains: running [/sbin/iptables -t nat -S --wait]: exit status -1:
E0602 17:29:00.527075       1 network_services_controller.go:449] Error syncing hairpin iptables rules: Error deleting hairpin rules: Failed to list iptables chains: running [/sbin/iptables -t nat -S --wait]: exit status -1:
E0602 17:59:00.542655       1 network_services_controller.go:449] Error syncing hairpin iptables rules: Error deleting hairpin rules: Failed to list iptables chains: running [/sbin/iptables -t nat -S --wait]: exit status -1:
E0602 18:09:00.553545       1 network_services_controller.go:449] Error syncing hairpin iptables rules: Error deleting hairpin rules: Failed to list iptables chains: running [/sbin/iptables -t nat -S --wait]: exit status -1:
E0602 18:39:00.555456       1 network_services_controller.go:449] Error syncing hairpin iptables rules: Error deleting hairpin rules: Failed to list iptables chains: running [/sbin/iptables -t nat -S --wait]: exit status -1:
E0602 18:59:00.578334       1 network_services_controller.go:449] Error syncing hairpin iptables rules: Error deleting hairpin rules: Failed to list iptables chains: running [/sbin/iptables -t nat -S --wait]: exit status -1:
E0602 19:04:00.545517       1 network_services_controller.go:449] Error syncing hairpin iptables rules: Error deleting hairpin rules: Failed to list iptables chains: running [/sbin/iptables -t nat -S --wait]: exit status -1:
E0602 19:09:00.525876       1 network_services_controller.go:449] Error syncing hairpin iptables rules: Error deleting hairpin rules: Failed to list iptables chains: running [/sbin/iptables -t nat -S --wait]: exit status -1:
E0602 19:14:00.550719       1 network_services_controller.go:449] Error syncing hairpin iptables rules: Error deleting hairpin rules: Failed to list iptables chains: running [/sbin/iptables -t nat -S --wait]: exit status -1:
E0602 19:19:00.790344       1 service_endpoints_sync.go:293] Failed to run iptables-save: %!s(MISSING)signal: segmentation fault (core dumped) ()
E0602 19:39:00.522142       1 network_services_controller.go:449] Error syncing hairpin iptables rules: Error deleting hairpin rules: Failed to list iptables chains: running [/sbin/iptables -t nat -S --wait]: exit status -1:
E0602 19:49:00.619182       1 network_routes_controller.go:301] Failed to enable IP forwarding of traffic from pods: Failed to run iptables command: running [/sbin/iptables -t filter -C FORWARD -m comment --comment allow outbound node port traffic on node interface with which node ip is associated -o eth0 -j ACCEPT --wait]: exit status -1:
E0602 19:54:00.573342       1 network_services_controller.go:449] Error syncing hairpin iptables rules: Error deleting hairpin rules: Failed to list iptables chains: running [/sbin/iptables -t nat -S --wait]: exit status -1:
E0602 20:14:00.574543       1 network_services_controller.go:449] Error syncing hairpin iptables rules: Error deleting hairpin rules: Failed to list iptables chains: running [/sbin/iptables -t nat -S --wait]: exit status -1:
E0602 20:19:00.777919       1 service_endpoints_sync.go:293] Failed to run iptables-save: %!s(MISSING)signal: segmentation fault (core dumped) ()
E0602 20:24:00.568431       1 network_services_controller.go:449] Error syncing hairpin iptables rules: Error deleting hairpin rules: Failed to list iptables chains: running [/sbin/iptables -t nat -S --wait]: exit status -1:

[murali-reddy]

How has this been working out for everyone so far? Any feedback on the 1.2.3 release and this issue?

1.2.3 seems to have fixed kops CI failures a well https://github.com/kubernetes/kops/pull/11124#issuecomment-855540852

[murali-reddy]

I haven't had any network issues since the update but I've been having some other issues that I'm not sure are related but I'll include them in case.

The kube-router pods have had problems with iptables. However after updating the daemon set to increase the log level they haven't had the same issues so it might be nothing.

I've also had kube-router pods crashing. That also improved after the daemon set was updated but a couple have still crashed since.

@grimurd thanks for feedback. I will look at the crash dump. If the issue is happening consistently across multiple nodes, please open separate issue with all relevant details.

[aauren]

Given the crickets on this issue since the fix from #1088, I'm going to call this issue done.

@grimurd feel free to open a separate issue if you would like to follow up on the iptables issue.