Traffic from pods use the wrong egress interface - sometimes #1856
Comments
|
Update: I can't send the logs as it was bigger than the maximum available size. Is there another way to share that? I don't want to make it public as it might contain sensitive information. |
|
@achevuru Thanks for the information. I updated to 1.8.0. As the issue doesn't happen instantaneously then I'll have to wait. It could take a few hours or few days. |
|
It looks this doesn't solve the issue at all. I experienced the same on a freshly started node with aws-vpc-cni:1.8.0. It looks like the egress interface selection doesn't work at all and when the pods are running fine they are using the |
|
I did some more digging. I found the case where I had two pods "behind" the same ENI, one of the was working but the other didn't. I checked the logs and I found only a few lines for the 10.31.65.52: {"level":"info","ts":"2022-02-11T12:11:11.813Z","caller":"ipamd/ipamd.go:830","msg":"Added ENI(eni-0cfc343e6d82b3909)'s IP 10.31.65.52 to datastore"}
{"level":"info","ts":"2022-02-11T12:11:11.864Z","caller":"datastore/data_store.go:360","msg":"AssignPodIPv4Address: Assign IP 10.31.65.52 to sandbox _migrated-from-cri/fd37ddee6e6e0e5c3cd0bb9548ab77c21241fe039a49d3cf315650209369f17a/unknown"}
{"level":"debug","ts":"2022-02-11T12:11:11.864Z","caller":"ipamd/ipamd.go:413","msg":"Recovered _migrated-from-cri/fd37ddee6e6e0e5c3cd0bb9548ab77c21241fe039a49d3cf315650209369f17a/unknown => eni-0cfc343e6d82b3909/10.31.65.52"}
{"level":"debug","ts":"2022-02-11T12:11:11.866Z","caller":"ipamd/ipamd.go:483","msg":"Update Rule List[[ip rule -1: from <nil> table 255 ip rule 512: from <nil> table 254 ip rule 512: from <nil> table 254 ip rule 512: from <nil> table 254 ip rule 512: from <nil> table 254 ip rule 1536: from 10.31.64.23/32 table 2 ip rule 1536: from 10.31.65.240/32 table 3 ip rule 1536: from 10.31.69.129/32 table 3 ip rule 1536: from 10.31.64.115/32 table 2 ip rule 32766: from <nil> table 254 ip rule 32767: from <nil> table 253]] for source[{10.31.65.52 ffffffff}] "But a lot more related to the 10.31.64.23: {"level":"info","ts":"2022-02-11T12:11:11.813Z","caller":"ipamd/ipamd.go:830","msg":"Added ENI(eni-0cfc343e6d82b3909)'s IP 10.31.64.23 to datastore"}
{"level":"info","ts":"2022-02-11T12:11:11.864Z","caller":"datastore/data_store.go:360","msg":"AssignPodIPv4Address: Assign IP 10.31.64.23 to sandbox _migrated-from-cri/9af8fce3cfe6bfc5a2f9a6922bc0459f8c1a1b70ad2260a14d1b7bff03525efa/unknown"}
{"level":"debug","ts":"2022-02-11T12:11:11.864Z","caller":"ipamd/ipamd.go:413","msg":"Recovered _migrated-from-cri/9af8fce3cfe6bfc5a2f9a6922bc0459f8c1a1b70ad2260a14d1b7bff03525efa/unknown => eni-0cfc343e6d82b3909/10.31.64.23"}
{"level":"debug","ts":"2022-02-11T12:11:11.865Z","caller":"ipamd/ipamd.go:483","msg":"Update Rule List[[ip rule -1: from <nil> table 255 ip rule 512: from <nil> table 254 ip rule 512: from <nil> table 254 ip rule 512: from <nil> table 254 ip rule 512: from <nil> table 254 ip rule 1536: from 10.31.64.23/32 table 2 ip rule 1536: from 10.31.65.240/32 table 3 ip rule 1536: from 10.31.69.129/32 table 3 ip rule 1536: from 10.31.64.115/32 table 2 ip rule 32766: from <nil> table 254 ip rule 32767: from <nil> table 253]] for source[{10.31.65.215 ffffffff}] "}
{"level":"debug","ts":"2022-02-11T12:11:11.865Z","caller":"ipamd/ipamd.go:483","msg":"Update Rule List[[ip rule -1: from <nil> table 255 ip rule 512: from <nil> table 254 ip rule 512: from <nil> table 254 ip rule 512: from <nil> table 254 ip rule 512: from <nil> table 254 ip rule 1536: from 10.31.64.23/32 table 2 ip rule 1536: from 10.31.65.240/32 table 3 ip rule 1536: from 10.31.69.129/32 table 3 ip rule 1536: from 10.31.64.115/32 table 2 ip rule 32766: from <nil> table 254 ip rule 32767: from <nil> table 253]] for source[{10.31.75.68 ffffffff}] "}
{"level":"debug","ts":"2022-02-11T12:11:11.865Z","caller":"ipamd/ipamd.go:483","msg":"Update Rule List[[ip rule -1: from <nil> table 255 ip rule 512: from <nil> table 254 ip rule 512: from <nil> table 254 ip rule 512: from <nil> table 254 ip rule 512: from <nil> table 254 ip rule 1536: from 10.31.64.23/32 table 2 ip rule 1536: from 10.31.65.240/32 table 3 ip rule 1536: from 10.31.69.129/32 table 3 ip rule 1536: from 10.31.64.115/32 table 2 ip rule 32766: from <nil> table 254 ip rule 32767: from <nil> table 253]] for source[{10.31.68.60 ffffffff}] "}
{"level":"debug","ts":"2022-02-11T12:11:11.865Z","caller":"ipamd/ipamd.go:483","msg":"Update Rule List[[ip rule -1: from <nil> table 255 ip rule 512: from <nil> table 254 ip rule 512: from <nil> table 254 ip rule 512: from <nil> table 254 ip rule 512: from <nil> table 254 ip rule 1536: from 10.31.64.23/32 table 2 ip rule 1536: from 10.31.65.240/32 table 3 ip rule 1536: from 10.31.69.129/32 table 3 ip rule 1536: from 10.31.64.115/32 table 2 ip rule 32766: from <nil> table 254 ip rule 32767: from <nil> table 253]] for source[{10.31.69.56 ffffffff}] "}
{"level":"debug","ts":"2022-02-11T12:11:11.865Z","caller":"ipamd/ipamd.go:483","msg":"Update Rule List[[ip rule -1: from <nil> table 255 ip rule 512: from <nil> table 254 ip rule 512: from <nil> table 254 ip rule 512: from <nil> table 254 ip rule 512: from <nil> table 254 ip rule 1536: from 10.31.64.23/32 table 2 ip rule 1536: from 10.31.65.240/32 table 3 ip rule 1536: from 10.31.69.129/32 table 3 ip rule 1536: from 10.31.64.115/32 table 2 ip rule 32766: from <nil> table 254 ip rule 32767: from <nil> table 253]] for source[{10.31.74.206 ffffffff}] "}
{"level":"debug","ts":"2022-02-11T12:11:11.865Z","caller":"ipamd/ipamd.go:483","msg":"Update Rule List[[ip rule -1: from <nil> table 255 ip rule 512: from <nil> table 254 ip rule 512: from <nil> table 254 ip rule 512: from <nil> table 254 ip rule 512: from <nil> table 254 ip rule 1536: from 10.31.64.23/32 table 2 ip rule 1536: from 10.31.65.240/32 table 3 ip rule 1536: from 10.31.69.129/32 table 3 ip rule 1536: from 10.31.64.115/32 table 2 ip rule 32766: from <nil> table 254 ip rule 32767: from <nil> table 253]] for source[{10.31.75.73 ffffffff}] "}
{"level":"debug","ts":"2022-02-11T12:11:11.866Z","caller":"ipamd/ipamd.go:483","msg":"Update Rule List[[ip rule -1: from <nil> table 255 ip rule 512: from <nil> table 254 ip rule 512: from <nil> table 254 ip rule 512: from <nil> table 254 ip rule 512: from <nil> table 254 ip rule 1536: from 10.31.64.23/32 table 2 ip rule 1536: from 10.31.65.240/32 table 3 ip rule 1536: from 10.31.69.129/32 table 3 ip rule 1536: from 10.31.64.115/32 table 2 ip rule 32766: from <nil> table 254 ip rule 32767: from <nil> table 253]] for source[{10.31.65.240 ffffffff}] "}
{"level":"debug","ts":"2022-02-11T12:11:11.866Z","caller":"ipamd/ipamd.go:483","msg":"Update Rule List[[ip rule -1: from <nil> table 255 ip rule 512: from <nil> table 254 ip rule 512: from <nil> table 254 ip rule 512: from <nil> table 254 ip rule 512: from <nil> table 254 ip rule 1536: from 10.31.64.23/32 table 2 ip rule 1536: from 10.31.65.240/32 table 3 ip rule 1536: from 10.31.69.129/32 table 3 ip rule 1536: from 10.31.64.115/32 table 2 ip rule 32766: from <nil> table 254 ip rule 32767: from <nil> table 253]] for source[{10.31.69.129 ffffffff}] "}
{"level":"debug","ts":"2022-02-11T12:11:11.866Z","caller":"ipamd/ipamd.go:483","msg":"Update Rule List[[ip rule -1: from <nil> table 255 ip rule 512: from <nil> table 254 ip rule 512: from <nil> table 254 ip rule 512: from <nil> table 254 ip rule 512: from <nil> table 254 ip rule 1536: from 10.31.64.23/32 table 2 ip rule 1536: from 10.31.65.240/32 table 3 ip rule 1536: from 10.31.69.129/32 table 3 ip rule 1536: from 10.31.64.115/32 table 2 ip rule 32766: from <nil> table 254 ip rule 32767: from <nil> table 253]] for source[{10.31.76.111 ffffffff}] "}
{"level":"debug","ts":"2022-02-11T12:11:11.866Z","caller":"ipamd/ipamd.go:483","msg":"Update Rule List[[ip rule -1: from <nil> table 255 ip rule 512: from <nil> table 254 ip rule 512: from <nil> table 254 ip rule 512: from <nil> table 254 ip rule 512: from <nil> table 254 ip rule 1536: from 10.31.64.23/32 table 2 ip rule 1536: from 10.31.65.240/32 table 3 ip rule 1536: from 10.31.69.129/32 table 3 ip rule 1536: from 10.31.64.115/32 table 2 ip rule 32766: from <nil> table 254 ip rule 32767: from <nil> table 253]] for source[{10.31.64.23 ffffffff}] "}
{"level":"info","ts":"2022-02-11T12:11:11.866Z","caller":"ipamd/ipamd.go:483","msg":"Remove current list [[ip rule 1536: from 10.31.64.23/32 table 2]]"}
{"level":"debug","ts":"2022-02-11T12:11:11.866Z","caller":"ipamd/ipamd.go:483","msg":"UpdateRuleListBySrc: Successfully removed current rule [ip rule 1536: from 10.31.64.23/32 table 2] to "}
{"level":"info","ts":"2022-02-11T12:11:11.866Z","caller":"ipamd/ipamd.go:483","msg":"UpdateRuleListBySrc: Successfully added pod rule[ip rule 1536: from 10.31.64.23/32 table 2]"}
{"level":"debug","ts":"2022-02-11T12:11:11.866Z","caller":"ipamd/ipamd.go:483","msg":"Update Rule List[[ip rule -1: from <nil> table 255 ip rule 512: from <nil> table 254 ip rule 512: from <nil> table 254 ip rule 512: from <nil> table 254 ip rule 512: from <nil> table 254 ip rule 1536: from 10.31.64.23/32 table 2 ip rule 1536: from 10.31.65.240/32 table 3 ip rule 1536: from 10.31.69.129/32 table 3 ip rule 1536: from 10.31.64.115/32 table 2 ip rule 32766: from <nil> table 254 ip rule 32767: from <nil> table 253]] for source[{10.31.65.52 ffffffff}] "}
{"level":"debug","ts":"2022-02-11T12:11:11.866Z","caller":"ipamd/ipamd.go:483","msg":"Update Rule List[[ip rule -1: from <nil> table 255 ip rule 512: from <nil> table 254 ip rule 512: from <nil> table 254 ip rule 512: from <nil> table 254 ip rule 512: from <nil> table 254 ip rule 1536: from 10.31.64.23/32 table 2 ip rule 1536: from 10.31.65.240/32 table 3 ip rule 1536: from 10.31.69.129/32 table 3 ip rule 1536: from 10.31.64.115/32 table 2 ip rule 32766: from <nil> table 254 ip rule 32767: from <nil> table 253]] for source[{10.31.64.115 ffffffff}] "}
{"level":"debug","ts":"2022-02-11T12:11:11.866Z","caller":"ipamd/ipamd.go:483","msg":"Update Rule List[[ip rule -1: from <nil> table 255 ip rule 512: from <nil> table 254 ip rule 512: from <nil> table 254 ip rule 512: from <nil> table 254 ip rule 512: from <nil> table 254 ip rule 1536: from 10.31.64.23/32 table 2 ip rule 1536: from 10.31.65.240/32 table 3 ip rule 1536: from 10.31.69.129/32 table 3 ip rule 1536: from 10.31.64.115/32 table 2 ip rule 32766: from <nil> table 254 ip rule 32767: from <nil> table 253]] for source[{10.31.71.33 ffffffff}] "}The suspicious difference that there is no I checked the routing rules: After I manually added the rules for the non-working pod it started to work - but I don't want to do that manually all the time, this is what the CNI is for, I think: I skimmed through the Changelog and didn't find an entry which can be related to this. This looks like a race condition to me. Do you think upgrading to the latest version will resolve this? Were there any changes related to this part of the code? |
|
@achevuru I continued digging as this issues blocks us quite badly. {"level":"debug","ts":"2022-02-14T09:24:18.121Z","caller":"ipamd/ipamd.go:605","msg":"Update Rule List[[ip rule -1: from <nil> table 255 ip rule 32766: from <nil> table 254 ip rule 32767: from <nil> table 253]] for source[{10.31.2.78 ffffffff}] "}
{"level":"info","ts":"2022-02-14T09:24:18.121Z","caller":"ipamd/ipamd.go:605","msg":"Remove current list [[]]"}
{"level":"debug","ts":"2022-02-14T09:24:18.121Z","caller":"ipamd/ipamd.go:605","msg":"UpdateRuleListBySrc: empty list, no need to update"}While on the working node: {"level":"debug","ts":"2022-02-14T09:25:34.989Z","caller":"ipamd/ipamd.go:605","msg":"Update Rule List[[ip rule -1: from <nil> table 255 ip rule 512: from <nil> table 254 ip rule 512: from <nil> table 254 ip rule 512: from <nil> table 254 ip rule 512: from <nil> table 254 ip rule 512: from <nil> table 254 ip rule 512: from <nil> table 254 ip rule 512: from <nil> table 254 ip rule 512: from <nil> table 254 ip rule 512: from <nil> table 254 ip rule 512: from <nil> table 254 ip rule 512: from <nil> table 254 ip rule 512: from <nil> table 254 ip rule 512: from <nil> table 254 ip rule 512: from <nil> table 254 ip rule 512: from <nil> table 254 ip rule 512: from <nil> table 254 ip rule 512: from <nil> table 254 ip rule 1536: from 10.31.70.252/32 table 2 ip rule 32766: from <nil> table 254 ip rule 32767: from <nil> table 253]] for source[{10.31.70.252 ffffffff}] "}
{"level":"info","ts":"2022-02-14T09:25:34.989Z","caller":"ipamd/ipamd.go:605","msg":"Remove current list [[ip rule 1536: from 10.31.70.252/32 table 2]]"}
{"level":"debug","ts":"2022-02-14T09:25:34.989Z","caller":"ipamd/ipamd.go:605","msg":"UpdateRuleListBySrc: Successfully removed current rule [ip rule 1536: from 10.31.70.252/32 table 2] to "}
{"level":"info","ts":"2022-02-14T09:25:34.989Z","caller":"ipamd/ipamd.go:605","msg":"UpdateRuleListBySrc: Successfully added pod rule[ip rule 1536: from 10.31.70.252/32 table 2]"}My Go knowledge is very limited - so to say - but I tried to follow the execution path for this. amazon-vpc-cni-k8s/pkg/networkutils/network.go Line 1087 in 96f2f23 In this function the code fetches the actual ip rule sh output - but through netlink - to check if is there a rule already set for the Pod's IP address as a source/from. In the non-working case the ip rule sh is basically empty so it didn't found anything. After that it tries to remove this empty rule - why?. In the next step it realizes that it's empty so leaves the function. In the working case it re-adds the same rule again.What I don't understand:
Thanks for any insights/information. If you think this is not the right place to have this discussion then we can open a Support ticket in AWS and continue there. |
|
Hello, We stumbled upon the same issue - lack of connectivity from outside to the random Pods on the Node. What I also noticed is that traffic to the "working" Pods always coming via Primary ENI, but traffic to the non working Pods is arriving via Secondary ENI. AWS CNI version is v1.7.10 |
|
@akunszt Logs you shared above are for Pods that So, if this worked prior to AMI/Kernel update for you, then some underlying issue in Kernel might be contributing to it. But, that's just a speculation and we need entire log bundle for us to debug the issue. Please feel free to open a support case and share the logs. I tried with a regular EKS AMI and I don't see any issue with pods running behind secondary ENIs. Also, can you try scheduling new pods behind secondary ENIs and see how that behaves? (Instead of reboot/update cases like above).. |
|
@PA8MM If you see correct entries for affected pods in |
|
@achevuru I opened an AWS support ticket and linked this issue. I bounced every worker and found a situation where two pods are using a secondary IP address from the same ENI which is assigned to eth1 and one is working while the other one is not. I managed to run the aws-cni-support.sh script and upload the archive - it was quite small on a new instance. |
|
@akunszt No specific knob available to force a Pod to be placed behind a Secondary ENI. You can schedule enough pods to exhaust the Primary ENI and force any subsequent pods to secondary ENIs. Are you using a custom AMI? EKS AMIs are still in 5.4.x train. |
|
@achevuru We are using the official Flatcar Linux AMIs. The 3033.2.0 - stable - is with the new kernel and 2605.22.1 - LTS - is the one with old kernel. It's the successor of the CoreOS which was practically cancelled by IBM/RedHat after they bought it. It's a minimal OS which can do only one thing, run containers, so it is ideal for Kubernetes. |
|
@achevuru Can you point me to the right direction? I just can't find where adds the CNI of the IP rules in the first place. I thought that it should be at But I didn't find anything which just remotely resembles to the |
|
@achevuru Thanks. We managed to find it out just before I read your message. It was a bit misleading that we don't use the routed-eni-cni plugin at all and it wasn't obvious that the binary will be named aws-cni and used by the aws-cni plugin. I'll let our TAM knows that the support ticket not yet reached it's destination and ask him to escalate/forward/assign to the EKS service team. |
|
@achevuru I think I found the root cause and a solution. It turned out that it wasn't the kernel, it was systemd, especially systemd-networkd. When a new interface/ENI added to the system the systemd-networkd by default cleaned up every routes and rules - it's a very stupid default setting, but hey, it's systemd... It might be worth mentioning this in the documentation as it is a very annoying, and very hard to trace issue as it happens only during runtime. If someone tests with a few pods then everything could be okay but when |
|
What happened:
We noticed that one of our pods which was running fine earlier lost access to the apiserver. After evaluating the situation we were be able to confirm that the traffic was DNAT-ed properly by kube-proxy from 10.2.0.1 to a real master node IP address. So that looked correct.
The endpoints:
Master node: eth0: 10.31.1.18/20
Worker node: eth0: 10.31.72.129/20, eth1: 10.31.75.90/20
Pod: 10.31.75.206/20
The pod's IP is a secondary IP on the eth1 interface according to the AWS console.
The outgoing traffic uses the eth0 interface - and maybe dropped by the VPC router as a spoofed traffic:
When I ping the pod's IP from the master node then it won't answer. It receives the ICMP echo-request on eth1 but sends back the echo-reply on the eth0.
I checked a newly started worker and another pod on it where it was working as expected:
I tried to switch the AWS_VPC_K8S_CNI_CONFIGURE_RPFILTER from false to true and the AWS_VPC_K8S_CNI_EXTERNALSNAT from true to false as a test but that didn't make any changes.
Attach logs
Done and will arrive shortly.
What you expected to happen:
Egress traffic uses the proper interface.
How to reproduce it (as minimally and precisely as possible):
As it doesn't happen everytime we can't reproduce it.
Anything else we need to know?:
We use this CNI version for a longer period of time but we just updated our AMIs to the latest Flatcar Stable version. That means different kernel and docker too. We didn't notice this behaviour on the old 2605 series AMIs running on kernel 5.4. This can be a race condition which is triggered by the newer kernel. Maybe, maybe not.
Environment:
kubectl version): 1.21.2cat /etc/os-release):The text was updated successfully, but these errors were encountered: