amazon-vpc-cni-k8s
amazon-vpc-cni-k8s copied to clipboard
Published
20 hours ago •
aws
aws
K3S with AWS VPC CNI breaks Pod communication #9716
trafficstars
What happened:
I've attempted to integrate the AWS VPC CNI plugin into my k3s cluster. I have successfully deployed the CNI plugin, but one issue remains - pods cannot establish a connection with anything outside of their own scope (only pinging their own IP address works). The connection to the Kubernetes API and pinging 8.8.8.8 is fine when done from the EC2 instance itself but its not possible when I exec into a pod and try from there. I don’t use pod security groups.
My server node init script:
curl -sfL https://get.k3s.io | INSTALL_K3S_EXEC="server \
--cluster-cidr '172.19.0.0/16' \
--service-cidr '172.20.0.0/16' \
--cluster-dns '172.20.0.10' \
--disable traefik \
--disable servicelb \
--disable-network-policy \
--flannel-backend none \
--disable-cloud-controller \
--kubelet-arg cloud-provider=external \
--egress-selector-mode disabled \
--node-taint node-role.kubernetes.io/control-plane=:NoSchedule \
--node-name '$(hostname -f)' \
--write-kubeconfig-mode 644" sh -s -
root@ip-10-0-1-205:/home/ubuntu# kubectl get nodes -o wide
NAME STATUS ROLES AGE VERSION INTERNAL-IP EXTERNAL-IP OS-IMAGE KERNEL-VERSION CONTAINER-RUNTIME
ip-10-0-3-97.eu-central-1.compute.internal Ready <none> 37m v1.28.7+k3s1 10.0.3.97 <redacted> Ubuntu 22.04.3 LTS 6.2.0-1018-aws containerd://1.7.11-k3s2
ip-10-0-1-205.eu-central-1.compute.internal Ready control-plane,master 39m v1.28.7+k3s1 10.0.1.205 <redacted> Ubuntu 22.04.3 LTS 6.2.0-1018-aws containerd://1.7.11-k3s2
CoreDNS, the Metrics Server, the Local Path Provisioner and every pod I spawn are affected.
I changed the default service and cluster CIDRs so I'm sure of preventing conflicts with the VPC CIDR (10.0.0.0/16). I use public subnets without any NATs and all of my Security Groups, Routing Tables and Network ACLs are allowing all inbound and outgoing traffic on every port (for testing purposes ofc 😄 ). I've read somewhere that the primary ENIs together with the ones the VPC CNI spawns, should have Source/dest. check turned off so I did that - didn't help. IAM roles should also be fine (I'm using node IAM roles, not using IRSA)
Logs from the CNI located at /var/log/aws-routed-eni/plugin.log:
{"level":"info","ts":"2024-03-10T17:25:08.321Z","caller":"routed-eni-cni-plugin/cni.go:116","msg":"Constructed new logger instance"}
{"level":"info","ts":"2024-03-10T17:25:08.321Z","caller":"routed-eni-cni-plugin/cni.go:125","msg":"Received CNI add request: ContainerID(083d9e63a97995d778c7f11e715eecb3f2be1de8fde9d86cf51668c6c083d15e) Netns(/var/run/netns/cni-34f0d7b3-fd96-7e63-c16f-b90864b73421) IfName(eth0) Args(K8S_POD_UID=57575e79-7811-4131-8295-eeac64375140;IgnoreUnknown=1;K8S_POD_NAMESPACE=kube-system;K8S_POD_NAME=metrics-server-67c658944b-7rh6d;K8S_POD_INFRA_CONTAINER_ID=083d9e63a97995d778c7f11e715eecb3f2be1de8fde9d86cf51668c6c083d15e) Path(/opt/cni/bin) argsStdinData({\"cniVersion\":\"0.4.0\",\"mtu\":\"9001\",\"name\":\"aws-cni\",\"pluginLogFile\":\"/var/log/aws-routed-eni/plugin.log\",\"pluginLogLevel\":\"DEBUG\",\"podSGEnforcingMode\":\"strict\",\"type\":\"aws-cni\",\"vethPrefix\":\"eni\"})"}
{"level":"debug","ts":"2024-03-10T17:25:08.321Z","caller":"routed-eni-cni-plugin/cni.go:125","msg":"Prev Result: <nil>\n"}
{"level":"debug","ts":"2024-03-10T17:25:08.321Z","caller":"routed-eni-cni-plugin/cni.go:125","msg":"MTU value set is 9001:"}
{"level":"info","ts":"2024-03-10T17:25:08.350Z","caller":"routed-eni-cni-plugin/cni.go:125","msg":"Received add network response from ipamd for container 083d9e63a97995d778c7f11e715eecb3f2be1de8fde9d86cf51668c6c083d15e interface eth0: Success:true IPv4Addr:\"10.0.1.238\" VPCv4CIDRs:\"10.0.0.0/16\""}
{"level":"debug","ts":"2024-03-10T17:25:08.350Z","caller":"routed-eni-cni-plugin/cni.go:226","msg":"SetupPodNetwork: hostVethName=enic348b3ae002, contVethName=eth0, netnsPath=/var/run/netns/cni-34f0d7b3-fd96-7e63-c16f-b90864b73421, v4Addr=10.0.1.238/32, v6Addr=<nil>, deviceNumber=0, mtu=9001"}
{"level":"debug","ts":"2024-03-10T17:25:08.391Z","caller":"driver/driver.go:237","msg":"Successfully set IPv6 sysctls on hostVeth enic348b3ae002"}
{"level":"debug","ts":"2024-03-10T17:25:08.402Z","caller":"driver/driver.go:253","msg":"Successfully setup container route, containerAddr=10.0.1.238/32, hostVeth=enic348b3ae002, rtTable=main"}
{"level":"debug","ts":"2024-03-10T17:25:08.402Z","caller":"driver/driver.go:253","msg":"Successfully setup toContainer rule, containerAddr=10.0.1.238/32, rtTable=main"}
{"level":"debug","ts":"2024-03-10T17:25:08.402Z","caller":"routed-eni-cni-plugin/cni.go:125","msg":"Using dummy interface: {Name:dummyc348b3ae002 Mac:0 Sandbox:0}"}
{"level":"info","ts":"2024-03-10T17:25:08.476Z","caller":"routed-eni-cni-plugin/cni.go:116","msg":"Constructed new logger instance"}
{"level":"info","ts":"2024-03-10T17:25:08.487Z","caller":"routed-eni-cni-plugin/cni.go:125","msg":"Received CNI add request: ContainerID(6397e269c6b847d56d8d99b0a423bb50444f861fe68fff9a6773f70467dc1cdc) Netns(/var/run/netns/cni-eaf6f3e4-8a0a-71dc-38e2-5d56fa02e019) IfName(eth0) Args(IgnoreUnknown=1;K8S_POD_NAMESPACE=kube-system;K8S_POD_NAME=coredns-6799fbcd5-ss7tc;K8S_POD_INFRA_CONTAINER_ID=6397e269c6b847d56d8d99b0a423bb50444f861fe68fff9a6773f70467dc1cdc;K8S_POD_UID=085e52e2-8e99-4fd6-a20f-78cb8d01c4dc) Path(/opt/cni/bin) argsStdinData({\"cniVersion\":\"0.4.0\",\"mtu\":\"9001\",\"name\":\"aws-cni\",\"pluginLogFile\":\"/var/log/aws-routed-eni/plugin.log\",\"pluginLogLevel\":\"DEBUG\",\"podSGEnforcingMode\":\"strict\",\"type\":\"aws-cni\",\"vethPrefix\":\"eni\"})"}
{"level":"debug","ts":"2024-03-10T17:25:08.487Z","caller":"routed-eni-cni-plugin/cni.go:125","msg":"Prev Result: <nil>\n"}
{"level":"debug","ts":"2024-03-10T17:25:08.487Z","caller":"routed-eni-cni-plugin/cni.go:125","msg":"MTU value set is 9001:"}
{"level":"info","ts":"2024-03-10T17:25:08.499Z","caller":"routed-eni-cni-plugin/cni.go:125","msg":"Received add network response from ipamd for container 6397e269c6b847d56d8d99b0a423bb50444f861fe68fff9a6773f70467dc1cdc interface eth0: Success:true IPv4Addr:\"10.0.1.186\" VPCv4CIDRs:\"10.0.0.0/16\""}
{"level":"debug","ts":"2024-03-10T17:25:08.499Z","caller":"routed-eni-cni-plugin/cni.go:226","msg":"SetupPodNetwork: hostVethName=eni8f803867f00, contVethName=eth0, netnsPath=/var/run/netns/cni-eaf6f3e4-8a0a-71dc-38e2-5d56fa02e019, v4Addr=10.0.1.186/32, v6Addr=<nil>, deviceNumber=0, mtu=9001"}
{"level":"info","ts":"2024-03-10T17:25:08.502Z","caller":"routed-eni-cni-plugin/cni.go:116","msg":"Constructed new logger instance"}
{"level":"info","ts":"2024-03-10T17:25:08.502Z","caller":"routed-eni-cni-plugin/cni.go:125","msg":"Received CNI add request: ContainerID(e3f40107f4b0967121c00ca153ff508302e14b55db35fccc549920b18c1b51dc) Netns(/var/run/netns/cni-de247033-97cb-a1ef-30d2-461be090ff10) IfName(eth0) Args(K8S_POD_INFRA_CONTAINER_ID=e3f40107f4b0967121c00ca153ff508302e14b55db35fccc549920b18c1b51dc;K8S_POD_UID=06986617-d435-4b27-9966-7365184c24dc;IgnoreUnknown=1;K8S_POD_NAMESPACE=kube-system;K8S_POD_NAME=local-path-provisioner-6c86858495-v2q25) Path(/opt/cni/bin) argsStdinData({\"cniVersion\":\"0.4.0\",\"mtu\":\"9001\",\"name\":\"aws-cni\",\"pluginLogFile\":\"/var/log/aws-routed-eni/plugin.log\",\"pluginLogLevel\":\"DEBUG\",\"podSGEnforcingMode\":\"strict\",\"type\":\"aws-cni\",\"vethPrefix\":\"eni\"})"}
{"level":"debug","ts":"2024-03-10T17:25:08.509Z","caller":"routed-eni-cni-plugin/cni.go:125","msg":"Prev Result: <nil>\n"}
{"level":"debug","ts":"2024-03-10T17:25:08.509Z","caller":"routed-eni-cni-plugin/cni.go:125","msg":"MTU value set is 9001:"}
{"level":"info","ts":"2024-03-10T17:25:08.514Z","caller":"routed-eni-cni-plugin/cni.go:125","msg":"Received add network response from ipamd for container e3f40107f4b0967121c00ca153ff508302e14b55db35fccc549920b18c1b51dc interface eth0: Success:true IPv4Addr:\"10.0.1.91\" VPCv4CIDRs:\"10.0.0.0/16\""}
{"level":"debug","ts":"2024-03-10T17:25:08.514Z","caller":"routed-eni-cni-plugin/cni.go:226","msg":"SetupPodNetwork: hostVethName=eni59d6eac6d80, contVethName=eth0, netnsPath=/var/run/netns/cni-de247033-97cb-a1ef-30d2-461be090ff10, v4Addr=10.0.1.91/32, v6Addr=<nil>, deviceNumber=0, mtu=9001"}
{"level":"debug","ts":"2024-03-10T17:25:08.525Z","caller":"driver/driver.go:237","msg":"Successfully set IPv6 sysctls on hostVeth eni8f803867f00"}
{"level":"debug","ts":"2024-03-10T17:25:08.525Z","caller":"driver/driver.go:253","msg":"Successfully setup container route, containerAddr=10.0.1.186/32, hostVeth=eni8f803867f00, rtTable=main"}
{"level":"debug","ts":"2024-03-10T17:25:08.526Z","caller":"driver/driver.go:253","msg":"Successfully setup toContainer rule, containerAddr=10.0.1.186/32, rtTable=main"}
{"level":"debug","ts":"2024-03-10T17:25:08.526Z","caller":"routed-eni-cni-plugin/cni.go:125","msg":"Using dummy interface: {Name:dummy8f803867f00 Mac:0 Sandbox:0}"}
{"level":"debug","ts":"2024-03-10T17:25:08.567Z","caller":"driver/driver.go:237","msg":"Successfully set IPv6 sysctls on hostVeth eni59d6eac6d80"}
{"level":"debug","ts":"2024-03-10T17:25:08.567Z","caller":"driver/driver.go:253","msg":"Successfully setup container route, containerAddr=10.0.1.91/32, hostVeth=eni59d6eac6d80, rtTable=main"}
{"level":"debug","ts":"2024-03-10T17:25:08.568Z","caller":"driver/driver.go:253","msg":"Successfully setup toContainer rule, containerAddr=10.0.1.91/32, rtTable=main"}
{"level":"debug","ts":"2024-03-10T17:25:08.568Z","caller":"routed-eni-cni-plugin/cni.go:125","msg":"Using dummy interface: {Name:dummy59d6eac6d80 Mac:0 Sandbox:0}"}
{"level":"info","ts":"2024-03-10T17:28:54.727Z","caller":"routed-eni-cni-plugin/cni.go:116","msg":"Constructed new logger instance"}
{"level":"debug","ts":"2024-03-10T17:28:54.729Z","caller":"routed-eni-cni-plugin/cni.go:283","msg":"Prev Result: &{0.4.0 [{Name:eni8f803867f00 Mac: Sandbox:} {Name:eth0 Mac: Sandbox:/var/run/netns/cni-eaf6f3e4-8a0a-71dc-38e2-5d56fa02e019} {Name:dummy8f803867f00 Mac:0 Sandbox:0}] [{Version:4 Interface:0xc000012320 Address:{IP:10.0.1.186 Mask:ffffffff} Gateway:<nil>}] [] {[] [] []}}\n"}
{"level":"info","ts":"2024-03-10T17:28:54.729Z","caller":"routed-eni-cni-plugin/cni.go:283","msg":"Received CNI del request: ContainerID(6397e269c6b847d56d8d99b0a423bb50444f861fe68fff9a6773f70467dc1cdc) Netns(/var/run/netns/cni-eaf6f3e4-8a0a-71dc-38e2-5d56fa02e019) IfName(eth0) Args(K8S_POD_NAME=coredns-6799fbcd5-ss7tc;K8S_POD_INFRA_CONTAINER_ID=6397e269c6b847d56d8d99b0a423bb50444f861fe68fff9a6773f70467dc1cdc;K8S_POD_UID=085e52e2-8e99-4fd6-a20f-78cb8d01c4dc;IgnoreUnknown=1;K8S_POD_NAMESPACE=kube-system) Path(/opt/cni/bin) argsStdinData({\"cniVersion\":\"0.4.0\",\"mtu\":\"9001\",\"name\":\"aws-cni\",\"pluginLogFile\":\"/var/log/aws-routed-eni/plugin.log\",\"pluginLogLevel\":\"DEBUG\",\"podSGEnforcingMode\":\"strict\",\"prevResult\":{\"cniVersion\":\"0.4.0\",\"interfaces\":[{\"name\":\"eni8f803867f00\"},{\"name\":\"eth0\",\"sandbox\":\"/var/run/netns/cni-eaf6f3e4-8a0a-71dc-38e2-5d56fa02e019\"},{\"name\":\"dummy8f803867f00\",\"mac\":\"0\",\"sandbox\":\"0\"}],\"ips\":[{\"version\":\"4\",\"interface\":1,\"address\":\"10.0.1.186/32\"}],\"dns\":{}},\"type\":\"aws-cni\",\"vethPrefix\":\"eni\"})"}
{"level":"info","ts":"2024-03-10T17:28:54.736Z","caller":"routed-eni-cni-plugin/cni.go:283","msg":"Received del network response from ipamd for pod coredns-6799fbcd5-ss7tc namespace kube-system sandbox 6397e269c6b847d56d8d99b0a423bb50444f861fe68fff9a6773f70467dc1cdc: Success:true IPv4Addr:\"10.0.1.186\""}
{"level":"debug","ts":"2024-03-10T17:28:54.736Z","caller":"routed-eni-cni-plugin/cni.go:405","msg":"TeardownPodNetwork: containerAddr=10.0.1.186/32, deviceNumber=0"}
{"level":"debug","ts":"2024-03-10T17:28:54.736Z","caller":"driver/driver.go:267","msg":"Successfully deleted toContainer rule, containerAddr=10.0.1.186/32, rtTable=main"}
{"level":"debug","ts":"2024-03-10T17:28:54.736Z","caller":"driver/driver.go:267","msg":"Successfully deleted container route, containerAddr=10.0.1.186/32, rtTable=main"}
{"level":"info","ts":"2024-03-10T17:29:16.343Z","caller":"routed-eni-cni-plugin/cni.go:116","msg":"Constructed new logger instance"}
{"level":"debug","ts":"2024-03-10T17:29:16.344Z","caller":"routed-eni-cni-plugin/cni.go:283","msg":"Prev Result: <nil>\n"}
{"level":"info","ts":"2024-03-10T17:29:16.344Z","caller":"routed-eni-cni-plugin/cni.go:283","msg":"Received CNI del request: ContainerID(6397e269c6b847d56d8d99b0a423bb50444f861fe68fff9a6773f70467dc1cdc) Netns() IfName(eth0) Args(K8S_POD_INFRA_CONTAINER_ID=6397e269c6b847d56d8d99b0a423bb50444f861fe68fff9a6773f70467dc1cdc;K8S_POD_UID=085e52e2-8e99-4fd6-a20f-78cb8d01c4dc;IgnoreUnknown=1;K8S_POD_NAMESPACE=kube-system;K8S_POD_NAME=coredns-6799fbcd5-ss7tc) Path(/opt/cni/bin) argsStdinData({\"cniVersion\":\"0.4.0\",\"mtu\":\"9001\",\"name\":\"aws-cni\",\"pluginLogFile\":\"/var/log/aws-routed-eni/plugin.log\",\"pluginLogLevel\":\"DEBUG\",\"podSGEnforcingMode\":\"strict\",\"type\":\"aws-cni\",\"vethPrefix\":\"eni\"})"}
{"level":"info","ts":"2024-03-10T17:29:16.349Z","caller":"routed-eni-cni-plugin/cni.go:283","msg":"Container 6397e269c6b847d56d8d99b0a423bb50444f861fe68fff9a6773f70467dc1cdc not found"}
{"level":"info","ts":"2024-03-10T17:29:16.386Z","caller":"routed-eni-cni-plugin/cni.go:116","msg":"Constructed new logger instance"}
{"level":"debug","ts":"2024-03-10T17:29:16.386Z","caller":"routed-eni-cni-plugin/cni.go:283","msg":"Prev Result: <nil>\n"}
{"level":"info","ts":"2024-03-10T17:29:16.386Z","caller":"routed-eni-cni-plugin/cni.go:283","msg":"Received CNI del request: ContainerID(6397e269c6b847d56d8d99b0a423bb50444f861fe68fff9a6773f70467dc1cdc) Netns() IfName(eth0) Args(IgnoreUnknown=1;K8S_POD_NAMESPACE=kube-system;K8S_POD_NAME=coredns-6799fbcd5-ss7tc;K8S_POD_INFRA_CONTAINER_ID=6397e269c6b847d56d8d99b0a423bb50444f861fe68fff9a6773f70467dc1cdc;K8S_POD_UID=085e52e2-8e99-4fd6-a20f-78cb8d01c4dc) Path(/opt/cni/bin) argsStdinData({\"cniVersion\":\"0.4.0\",\"mtu\":\"9001\",\"name\":\"aws-cni\",\"pluginLogFile\":\"/var/log/aws-routed-eni/plugin.log\",\"pluginLogLevel\":\"DEBUG\",\"podSGEnforcingMode\":\"strict\",\"type\":\"aws-cni\",\"vethPrefix\":\"eni\"})"}
{"level":"info","ts":"2024-03-10T17:29:16.393Z","caller":"routed-eni-cni-plugin/cni.go:283","msg":"Container 6397e269c6b847d56d8d99b0a423bb50444f861fe68fff9a6773f70467dc1cdc not found"}
Logs from the CNI aws-node pods:
Defaulted container "aws-node" out of: aws-node, aws-eks-nodeagent, aws-vpc-cni-init (init)
Installed /host/opt/cni/bin/aws-cni
Installed /host/opt/cni/bin/egress-cni
time="2024-03-10T17:24:57Z" level=info msg="Starting IPAM daemon... "
time="2024-03-10T17:24:57Z" level=info msg="Checking for IPAM connectivity... "
time="2024-03-10T17:24:59Z" level=info msg="Copying config file... "
time="2024-03-10T17:24:59Z" level=info msg="Successfully copied CNI plugin binary and config file."
E0310 17:34:08.943889 9 reflector.go:147] pkg/mod/k8s.io/[email protected]/tools/cache/reflector.go:229: Failed to watch *v1.Node: the server is currently unable to handle the request (get nodes) - error from a previous attempt: read tcp 10.0.1.205:46480->172.20.0.1:443: read: connection reset by peer
E0310 17:34:08.945055 9 reflector.go:147] pkg/mod/k8s.io/[email protected]/tools/cache/reflector.go:229: Failed to watch *v1.Pod: the server is currently unable to handle the request (get pods) - error from a previous attempt: read tcp 10.0.1.205:46466->172.20.0.1:443: read: connection reset by peer
Generally, the logs from the pods stop at "Successfully copied CNI plugin binary and config file.", I've tried many times to check them but believe it or not, for the first time I see these reflector errors.
Log from the ipamd, again located at /var/log/aws-routed-eni/ipamd.log:
{"level":"info","ts":"2024-03-10T17:24:57.074Z","caller":"logger/logger.go:52","msg":"Constructed new logger instance"}
{"level":"info","ts":"2024-03-10T17:24:57.074Z","caller":"networkutils/network.go:143","msg":"Initialized new logger as an existing instance was not found"}
{"level":"info","ts":"2024-03-10T17:24:57.093Z","caller":"aws-k8s-agent/main.go:42","msg":"Starting L-IPAMD ..."}
{"level":"info","ts":"2024-03-10T17:24:57.094Z","caller":"aws-k8s-agent/main.go:53","msg":"Testing communication with server"}
{"level":"info","ts":"2024-03-10T17:24:57.099Z","caller":"wait/loop.go:53","msg":"Successful communication with the Cluster! Cluster Version is: v1.28. git version: v1.28.7+k3s1. git tree state: clean. commit: 051b14b248655896fdfd7ba6c93db6182cde7431. platform: linux/amd64"}
{"level":"debug","ts":"2024-03-10T17:24:57.214Z","caller":"eventrecorder/eventrecorder.go:68","msg":"Node found aws-node-q2h6l - labels - 5"}
{"level":"warn","ts":"2024-03-10T17:24:57.214Z","caller":"awssession/session.go:66","msg":"HTTP_TIMEOUT env is not set or set to less than 10 seconds, defaulting to httpTimeout to 10sec"}
{"level":"debug","ts":"2024-03-10T17:24:57.216Z","caller":"ipamd/ipamd.go:335","msg":"Discovered region: eu-central-1"}
{"level":"info","ts":"2024-03-10T17:24:57.217Z","caller":"ipamd/ipamd.go:335","msg":"Custom networking enabled false"}
{"level":"debug","ts":"2024-03-10T17:24:57.217Z","caller":"awsutils/awsutils.go:377","msg":"Found availability zone: eu-central-1a "}
{"level":"debug","ts":"2024-03-10T17:24:57.218Z","caller":"awsutils/awsutils.go:377","msg":"Discovered the instance primary IPv4 address: 10.0.1.205"}
{"level":"debug","ts":"2024-03-10T17:24:57.219Z","caller":"awsutils/awsutils.go:377","msg":"Found instance-id: i-0eab21cd49fe2d8fb "}
{"level":"debug","ts":"2024-03-10T17:24:57.219Z","caller":"awsutils/awsutils.go:377","msg":"Found instance-type: t3a.small "}
{"level":"debug","ts":"2024-03-10T17:24:57.220Z","caller":"awsutils/awsutils.go:377","msg":"Found primary interface's MAC address: 02:3c:57:d5:54:8b"}
{"level":"debug","ts":"2024-03-10T17:24:57.221Z","caller":"awsutils/awsutils.go:377","msg":"eni-0a80ddc608579a6ff is the primary ENI of this instance"}
{"level":"debug","ts":"2024-03-10T17:24:57.222Z","caller":"awsutils/awsutils.go:377","msg":"Found subnet-id: subnet-03aa442dddccaf297 "}
{"level":"debug","ts":"2024-03-10T17:24:57.222Z","caller":"ipamd/ipamd.go:344","msg":"Using WARM_ENI_TARGET 1"}
{"level":"debug","ts":"2024-03-10T17:24:57.222Z","caller":"ipamd/ipamd.go:345","msg":"Using WARM_IP_TARGET 2"}
{"level":"debug","ts":"2024-03-10T17:24:57.222Z","caller":"ipamd/ipamd.go:346","msg":"Using MINIMUM_IP_TARGET 10"}
{"level":"debug","ts":"2024-03-10T17:24:57.222Z","caller":"ipamd/ipamd.go:347","msg":"Using WARM_PREFIX_TARGET 1"}
{"level":"info","ts":"2024-03-10T17:24:57.222Z","caller":"ipamd/ipamd.go:364","msg":"Prefix Delegation enabled false"}
{"level":"debug","ts":"2024-03-10T17:24:57.222Z","caller":"ipamd/ipamd.go:369","msg":"Start node init"}
{"level":"debug","ts":"2024-03-10T17:24:57.222Z","caller":"ipamd/ipamd.go:384","msg":"Max ip per ENI 3 and max prefixes per ENI 0"}
{"level":"info","ts":"2024-03-10T17:24:57.222Z","caller":"awsutils/awsutils.go:1706","msg":"Will attempt to clean up AWS CNI leaked ENIs after waiting 3m43s."}
{"level":"info","ts":"2024-03-10T17:24:57.223Z","caller":"ipamd/ipamd.go:398","msg":"Setting up host network... "}
{"level":"debug","ts":"2024-03-10T17:24:57.223Z","caller":"networkutils/network.go:294","msg":"Found the Link that uses mac address 02:3c:57:d5:54:8b and its index is 2 (attempt 1/5)"}
{"level":"debug","ts":"2024-03-10T17:24:57.223Z","caller":"networkutils/network.go:425","msg":"Trying to find primary interface that has mac : 02:3c:57:d5:54:8b"}
{"level":"debug","ts":"2024-03-10T17:24:57.223Z","caller":"networkutils/network.go:425","msg":"Discovered interface: lo, mac: "}
{"level":"debug","ts":"2024-03-10T17:24:57.224Z","caller":"networkutils/network.go:425","msg":"Discovered interface: ens5, mac: 02:3c:57:d5:54:8b"}
{"level":"info","ts":"2024-03-10T17:24:57.224Z","caller":"networkutils/network.go:425","msg":"Discovered primary interface: ens5"}
{"level":"debug","ts":"2024-03-10T17:24:57.237Z","caller":"networkutils/network.go:445","msg":"Adding 10.0.0.0/16 CIDR to NAT chain"}
{"level":"debug","ts":"2024-03-10T17:24:57.237Z","caller":"networkutils/network.go:445","msg":"Total CIDRs to program - 1"}
{"level":"debug","ts":"2024-03-10T17:24:57.237Z","caller":"networkutils/network.go:445","msg":"Setup Host Network: iptables -N AWS-SNAT-CHAIN-0 -t nat"}
{"level":"debug","ts":"2024-03-10T17:24:57.240Z","caller":"networkutils/network.go:445","msg":"Setup Host Network: iptables -A POSTROUTING -m comment --comment \"AWS SNAT CHAIN\" -j AWS-SNAT-CHAIN-0"}
{"level":"debug","ts":"2024-03-10T17:24:57.240Z","caller":"networkutils/network.go:445","msg":"Setup Host Network: iptables -A AWS-SNAT-CHAIN-0 -d {10.0.0.0/16 %!s(bool=false)} -t nat -j RETURN"}
{"level":"debug","ts":"2024-03-10T17:24:57.240Z","caller":"networkutils/network.go:767","msg":"Setup Host Network: loading existing iptables nat rules with chain prefix AWS-SNAT-CHAIN"}
{"level":"debug","ts":"2024-03-10T17:24:57.251Z","caller":"networkutils/network.go:767","msg":"host network setup: found potentially stale rule for chain AWS-SNAT-CHAIN-0: [-N AWS-SNAT-CHAIN-0]"}
{"level":"debug","ts":"2024-03-10T17:24:57.251Z","caller":"networkutils/network.go:537","msg":"Setup Host Network: computing stale iptables rules for nat table with chain prefix AWS-SNAT-CHAIN"}
{"level":"debug","ts":"2024-03-10T17:24:57.251Z","caller":"networkutils/network.go:537","msg":"Setup Host Network: active chain found: AWS-SNAT-CHAIN-0"}
{"level":"debug","ts":"2024-03-10T17:24:57.251Z","caller":"networkutils/network.go:445","msg":"iptableRules: [nat/POSTROUTING rule first SNAT rules for non-VPC outbound traffic shouldExist true rule [-m comment --comment AWS SNAT CHAIN -j AWS-SNAT-CHAIN-0] nat/AWS-SNAT-CHAIN-0 rule AWS-SNAT-CHAIN-0 shouldExist true rule [-d 10.0.0.0/16 -m comment --comment AWS SNAT CHAIN -j RETURN] nat/AWS-SNAT-CHAIN-0 rule last SNAT rule for non-VPC outbound traffic shouldExist true rule [! -o vlan+ -m comment --comment AWS, SNAT -m addrtype ! --dst-type LOCAL -j SNAT --to-source 10.0.1.205 --random-fully] mangle/PREROUTING rule connmark for primary ENI shouldExist true rule [-m comment --comment AWS, primary ENI -i ens5 -m addrtype --dst-type LOCAL --limit-iface-in -j CONNMARK --set-mark 0x80/0x80] mangle/PREROUTING rule connmark restore for primary ENI shouldExist true rule [-m comment --comment AWS, primary ENI -i eni+ -j CONNMARK --restore-mark --mask 0x80] mangle/PREROUTING rule connmark restore for primary ENI from vlan shouldExist true rule [-m comment --comment AWS, primary ENI -i vlan+ -j CONNMARK --restore-mark --mask 0x80]]"}
{"level":"debug","ts":"2024-03-10T17:24:57.251Z","caller":"networkutils/network.go:449","msg":"execute iptable rule : first SNAT rules for non-VPC outbound traffic"}
{"level":"debug","ts":"2024-03-10T17:24:57.254Z","caller":"networkutils/network.go:449","msg":"rule nat/POSTROUTING rule first SNAT rules for non-VPC outbound traffic shouldExist true rule [-m comment --comment AWS SNAT CHAIN -j AWS-SNAT-CHAIN-0] exists false, err <nil>"}
{"level":"debug","ts":"2024-03-10T17:24:57.257Z","caller":"networkutils/network.go:449","msg":"execute iptable rule : AWS-SNAT-CHAIN-0"}
{"level":"debug","ts":"2024-03-10T17:24:57.260Z","caller":"networkutils/network.go:449","msg":"rule nat/AWS-SNAT-CHAIN-0 rule AWS-SNAT-CHAIN-0 shouldExist true rule [-d 10.0.0.0/16 -m comment --comment AWS SNAT CHAIN -j RETURN] exists false, err <nil>"}
{"level":"debug","ts":"2024-03-10T17:24:57.264Z","caller":"networkutils/network.go:449","msg":"execute iptable rule : last SNAT rule for non-VPC outbound traffic"}
{"level":"debug","ts":"2024-03-10T17:24:57.268Z","caller":"networkutils/network.go:449","msg":"rule nat/AWS-SNAT-CHAIN-0 rule last SNAT rule for non-VPC outbound traffic shouldExist true rule [! -o vlan+ -m comment --comment AWS, SNAT -m addrtype ! --dst-type LOCAL -j SNAT --to-source 10.0.1.205 --random-fully] exists false, err <nil>"}
{"level":"debug","ts":"2024-03-10T17:24:57.273Z","caller":"networkutils/network.go:449","msg":"execute iptable rule : connmark for primary ENI"}
{"level":"debug","ts":"2024-03-10T17:24:57.290Z","caller":"networkutils/network.go:449","msg":"rule mangle/PREROUTING rule connmark for primary ENI shouldExist true rule [-m comment --comment AWS, primary ENI -i ens5 -m addrtype --dst-type LOCAL --limit-iface-in -j CONNMARK --set-mark 0x80/0x80] exists false, err <nil>"}
{"level":"debug","ts":"2024-03-10T17:24:57.294Z","caller":"networkutils/network.go:449","msg":"execute iptable rule : connmark restore for primary ENI"}
{"level":"debug","ts":"2024-03-10T17:24:57.297Z","caller":"networkutils/network.go:449","msg":"rule mangle/PREROUTING rule connmark restore for primary ENI shouldExist true rule [-m comment --comment AWS, primary ENI -i eni+ -j CONNMARK --restore-mark --mask 0x80] exists false, err <nil>"}
{"level":"debug","ts":"2024-03-10T17:24:57.302Z","caller":"networkutils/network.go:449","msg":"execute iptable rule : connmark restore for primary ENI from vlan"}
{"level":"debug","ts":"2024-03-10T17:24:57.305Z","caller":"networkutils/network.go:449","msg":"rule mangle/PREROUTING rule connmark restore for primary ENI from vlan shouldExist true rule [-m comment --comment AWS, primary ENI -i vlan+ -j CONNMARK --restore-mark --mask 0x80] exists false, err <nil>"}
{"level":"debug","ts":"2024-03-10T17:24:57.308Z","caller":"networkutils/network.go:453","msg":"Total CIDRs to exempt from connmark rules - 1"}
{"level":"debug","ts":"2024-03-10T17:24:57.308Z","caller":"networkutils/network.go:453","msg":"Setup Host Network: iptables -N AWS-CONNMARK-CHAIN-0 -t nat"}
{"level":"debug","ts":"2024-03-10T17:24:57.311Z","caller":"networkutils/network.go:453","msg":"Setup Host Network: iptables -t nat -A PREROUTING -i eni+ -m comment --comment \"AWS, outbound connections\" -j AWS-CONNMARK-CHAIN-0"}
{"level":"debug","ts":"2024-03-10T17:24:57.311Z","caller":"networkutils/network.go:453","msg":"Setup Host Network: iptables -A AWS-CONNMARK-CHAIN-0 -d 10.0.0.0/16 -t nat -j RETURN"}
{"level":"debug","ts":"2024-03-10T17:24:57.311Z","caller":"networkutils/network.go:767","msg":"Setup Host Network: loading existing iptables nat rules with chain prefix AWS-CONNMARK-CHAIN"}
{"level":"debug","ts":"2024-03-10T17:24:57.319Z","caller":"networkutils/network.go:767","msg":"host network setup: found potentially stale rule for chain AWS-CONNMARK-CHAIN-0: [-N AWS-CONNMARK-CHAIN-0]"}
{"level":"debug","ts":"2024-03-10T17:24:57.319Z","caller":"networkutils/network.go:673","msg":"Setup Host Network: computing stale iptables rules for nat table with chain prefix AWS-CONNMARK-CHAIN"}
{"level":"debug","ts":"2024-03-10T17:24:57.319Z","caller":"networkutils/network.go:673","msg":"Setup Host Network: active chain found: AWS-CONNMARK-CHAIN-0"}
{"level":"debug","ts":"2024-03-10T17:24:57.319Z","caller":"networkutils/network.go:453","msg":"iptableRules: [nat/PREROUTING rule connmark rule for non-VPC outbound traffic shouldExist false rule [-i eni+ -m comment --comment AWS, outbound connections -m state --state NEW -j AWS-CONNMARK-CHAIN-0] nat/PREROUTING rule connmark rule for non-VPC outbound traffic shouldExist true rule [-i eni+ -m comment --comment AWS, outbound connections -j AWS-CONNMARK-CHAIN-0] nat/AWS-CONNMARK-CHAIN-0 rule AWS-CONNMARK-CHAIN-0 shouldExist true rule [-d 10.0.0.0/16 -m comment --comment AWS CONNMARK CHAIN, VPC CIDR -j RETURN] nat/PREROUTING rule connmark to fwmark copy shouldExist false rule [-m comment --comment AWS, CONNMARK -j CONNMARK --restore-mark --mask 0x80] nat/PREROUTING rule connmark to fwmark copy shouldExist true rule [-m comment --comment AWS, CONNMARK -j CONNMARK --restore-mark --mask 0x80] nat/AWS-CONNMARK-CHAIN-0 rule connmark rule for external outbound traffic shouldExist true rule [-m comment --comment AWS, CONNMARK -j CONNMARK --set-xmark 0x80/0x80]]"}
{"level":"debug","ts":"2024-03-10T17:24:57.319Z","caller":"networkutils/network.go:457","msg":"execute iptable rule : connmark rule for non-VPC outbound traffic"}
{"level":"debug","ts":"2024-03-10T17:24:57.330Z","caller":"networkutils/network.go:457","msg":"rule nat/PREROUTING rule connmark rule for non-VPC outbound traffic shouldExist false rule [-i eni+ -m comment --comment AWS, outbound connections -m state --state NEW -j AWS-CONNMARK-CHAIN-0] exists false, err <nil>"}
{"level":"debug","ts":"2024-03-10T17:24:57.331Z","caller":"networkutils/network.go:457","msg":"execute iptable rule : connmark rule for non-VPC outbound traffic"}
{"level":"debug","ts":"2024-03-10T17:24:57.334Z","caller":"networkutils/network.go:457","msg":"rule nat/PREROUTING rule connmark rule for non-VPC outbound traffic shouldExist true rule [-i eni+ -m comment --comment AWS, outbound connections -j AWS-CONNMARK-CHAIN-0] exists false, err <nil>"}
{"level":"debug","ts":"2024-03-10T17:24:57.337Z","caller":"networkutils/network.go:457","msg":"execute iptable rule : AWS-CONNMARK-CHAIN-0"}
{"level":"debug","ts":"2024-03-10T17:24:57.341Z","caller":"networkutils/network.go:457","msg":"rule nat/AWS-CONNMARK-CHAIN-0 rule AWS-CONNMARK-CHAIN-0 shouldExist true rule [-d 10.0.0.0/16 -m comment --comment AWS CONNMARK CHAIN, VPC CIDR -j RETURN] exists false, err <nil>"}
{"level":"debug","ts":"2024-03-10T17:24:57.345Z","caller":"networkutils/network.go:457","msg":"execute iptable rule : connmark to fwmark copy"}
{"level":"debug","ts":"2024-03-10T17:24:57.348Z","caller":"networkutils/network.go:457","msg":"rule nat/PREROUTING rule connmark to fwmark copy shouldExist false rule [-m comment --comment AWS, CONNMARK -j CONNMARK --restore-mark --mask 0x80] exists false, err <nil>"}
{"level":"debug","ts":"2024-03-10T17:24:57.348Z","caller":"networkutils/network.go:457","msg":"execute iptable rule : connmark to fwmark copy"}
{"level":"debug","ts":"2024-03-10T17:24:57.351Z","caller":"networkutils/network.go:457","msg":"rule nat/PREROUTING rule connmark to fwmark copy shouldExist true rule [-m comment --comment AWS, CONNMARK -j CONNMARK --restore-mark --mask 0x80] exists false, err <nil>"}
{"level":"debug","ts":"2024-03-10T17:24:57.354Z","caller":"networkutils/network.go:457","msg":"execute iptable rule : connmark rule for external outbound traffic"}
{"level":"debug","ts":"2024-03-10T17:24:57.357Z","caller":"networkutils/network.go:457","msg":"rule nat/AWS-CONNMARK-CHAIN-0 rule connmark rule for external outbound traffic shouldExist true rule [-m comment --comment AWS, CONNMARK -j CONNMARK --set-xmark 0x80/0x80] exists false, err <nil>"}
{"level":"debug","ts":"2024-03-10T17:24:57.368Z","caller":"awsutils/awsutils.go:1165","msg":"Total number of interfaces found: 1 "}
{"level":"debug","ts":"2024-03-10T17:24:57.368Z","caller":"awsutils/awsutils.go:553","msg":"Found ENI MAC address: 02:3c:57:d5:54:8b"}
{"level":"debug","ts":"2024-03-10T17:24:57.370Z","caller":"awsutils/awsutils.go:553","msg":"Found ENI: eni-0a80ddc608579a6ff, MAC 02:3c:57:d5:54:8b, device 0"}
{"level":"info","ts":"2024-03-10T17:24:57.543Z","caller":"ipamd/ipamd.go:408","msg":"Got network card index 0 for ENI eni-0a80ddc608579a6ff"}
{"level":"info","ts":"2024-03-10T17:24:57.543Z","caller":"ipamd/ipamd.go:408","msg":"eni-0a80ddc608579a6ff is of type: interface"}
{"level":"debug","ts":"2024-03-10T17:24:57.543Z","caller":"ipamd/ipamd.go:369","msg":"DescribeAllENIs success: ENIs: 1, tagged: 1"}
{"level":"debug","ts":"2024-03-10T17:24:57.543Z","caller":"ipamd/ipamd.go:369","msg":"Discovered ENI eni-0a80ddc608579a6ff, trying to set it up"}
{"level":"debug","ts":"2024-03-10T17:24:57.544Z","caller":"ipamd/ipamd.go:423","msg":"Tagging ENI eni-0a80ddc608579a6ff with missing tags: map[node.k8s.amazonaws.com/instance_id:i-0eab21cd49fe2d8fb]"}
{"level":"debug","ts":"2024-03-10T17:24:57.726Z","caller":"retry/retry.go:70","msg":"Successfully tagged ENI: eni-0a80ddc608579a6ff"}
{"level":"debug","ts":"2024-03-10T17:24:57.726Z","caller":"ipamd/ipamd.go:1039","msg":"DataStore add an ENI eni-0a80ddc608579a6ff"}
{"level":"info","ts":"2024-03-10T17:24:57.726Z","caller":"ipamd/ipamd.go:432","msg":"Found ENIs having 1 secondary IPs and 0 Prefixes"}
{"level":"debug","ts":"2024-03-10T17:24:57.726Z","caller":"ipamd/ipamd.go:1102","msg":"IP pool stats: Total IPs/Prefixes = 0/0, AssignedIPs/CooldownIPs: 0/0, c.maxIPsPerENI = 3"}
{"level":"debug","ts":"2024-03-10T17:24:57.726Z","caller":"ipamd/ipamd.go:1123","msg":"IP pool stats: Total IPs/Prefixes = 0/0, AssignedIPs/CooldownIPs: 0/0, c.maxIPsPerENI = 3"}
{"level":"info","ts":"2024-03-10T17:24:57.726Z","caller":"ipamd/ipamd.go:369","msg":"ENI eni-0a80ddc608579a6ff set up."}
{"level":"info","ts":"2024-03-10T17:24:57.726Z","caller":"ipamd/ipamd.go:454","msg":"Begin ipam state recovery from backing store"}
{"level":"debug","ts":"2024-03-10T17:24:57.726Z","caller":"ipamd/ipamd.go:454","msg":"backing store doesn't exists, assuming bootstrap on a new node"}
{"level":"debug","ts":"2024-03-10T17:24:57.726Z","caller":"ipamd/ipamd.go:480","msg":"tryUnassignPrefixesFromENIs"}
{"level":"debug","ts":"2024-03-10T17:24:57.727Z","caller":"ipamd/ipamd.go:591","msg":"Update Rule List with set []"}
{"level":"info","ts":"2024-03-10T17:24:57.728Z","caller":"ipamd/ipamd.go:495","msg":"Found sg-0b0a77d0329b19fcc, added to ipamd cache"}
{"level":"debug","ts":"2024-03-10T17:24:57.729Z","caller":"awsutils/awsutils.go:490","msg":"Total number of interfaces found: 1 "}
{"level":"debug","ts":"2024-03-10T17:24:57.729Z","caller":"awsutils/awsutils.go:553","msg":"Found ENI MAC address: 02:3c:57:d5:54:8b"}
{"level":"debug","ts":"2024-03-10T17:24:57.731Z","caller":"awsutils/awsutils.go:553","msg":"Found ENI: eni-0a80ddc608579a6ff, MAC 02:3c:57:d5:54:8b, device 0"}
{"level":"debug","ts":"2024-03-10T17:24:57.733Z","caller":"ipamd/ipamd.go:495","msg":"Update ENI eni-0a80ddc608579a6ff"}
{"level":"info","ts":"2024-03-10T17:24:58.057Z","caller":"ipamd/ipamd.go:507","msg":"Get Node Info for: ip-10-0-1-205.eu-central-1.compute.internal"}
{"level":"debug","ts":"2024-03-10T17:24:58.157Z","caller":"ipamd/ipamd.go:551","msg":"Starting to increase pool size"}
{"level":"debug","ts":"2024-03-10T17:24:58.158Z","caller":"ipamd/ipamd.go:783","msg":"Node found \"ip-10-0-1-205.eu-central-1.compute.internal\" - no of taints - 3"}
{"level":"debug","ts":"2024-03-10T17:24:58.158Z","caller":"ipamd/ipamd.go:908","msg":"Found ENI eni-0a80ddc608579a6ff that has less than the maximum number of IP/Prefixes addresses allocated: cur=0, max=3"}
{"level":"info","ts":"2024-03-10T17:24:58.158Z","caller":"ipamd/ipamd.go:913","msg":"Trying to allocate 3 IP addresses on ENI eni-0a80ddc608579a6ff"}
{"level":"debug","ts":"2024-03-10T17:24:58.158Z","caller":"ipamd/ipamd.go:913","msg":"PD enabled - false"}
{"level":"info","ts":"2024-03-10T17:24:58.573Z","caller":"ipamd/ipamd.go:913","msg":"Allocated 3 private IP addresses"}
{"level":"info","ts":"2024-03-10T17:24:58.573Z","caller":"ipamd/ipamd.go:1095","msg":"Adding 10.0.1.186/32 to DS for eni-0a80ddc608579a6ff"}
{"level":"info","ts":"2024-03-10T17:24:58.573Z","caller":"ipamd/ipamd.go:1095","msg":"Added ENI(eni-0a80ddc608579a6ff)'s IP/Prefix 10.0.1.186/32 to datastore"}
{"level":"info","ts":"2024-03-10T17:24:58.573Z","caller":"ipamd/ipamd.go:1095","msg":"Adding 10.0.1.91/32 to DS for eni-0a80ddc608579a6ff"}
{"level":"info","ts":"2024-03-10T17:24:58.573Z","caller":"ipamd/ipamd.go:1095","msg":"Added ENI(eni-0a80ddc608579a6ff)'s IP/Prefix 10.0.1.91/32 to datastore"}
{"level":"info","ts":"2024-03-10T17:24:58.573Z","caller":"ipamd/ipamd.go:1095","msg":"Adding 10.0.1.238/32 to DS for eni-0a80ddc608579a6ff"}
{"level":"info","ts":"2024-03-10T17:24:58.573Z","caller":"ipamd/ipamd.go:1095","msg":"Added ENI(eni-0a80ddc608579a6ff)'s IP/Prefix 10.0.1.238/32 to datastore"}
{"level":"debug","ts":"2024-03-10T17:24:58.573Z","caller":"ipamd/ipamd.go:1102","msg":"IP pool stats: Total IPs/Prefixes = 3/0, AssignedIPs/CooldownIPs: 0/0, c.maxIPsPerENI = 3"}
{"level":"debug","ts":"2024-03-10T17:24:58.573Z","caller":"ipamd/ipamd.go:825","msg":"IP pool stats: Total IPs/Prefixes = 3/0, AssignedIPs/CooldownIPs: 0/0, c.maxIPsPerENI = 3"}
{"level":"debug","ts":"2024-03-10T17:24:58.573Z","caller":"ipamd/ipamd.go:369","msg":"node init completed successfully"}
{"level":"info","ts":"2024-03-10T17:24:58.573Z","caller":"aws-k8s-agent/main.go:91","msg":"Serving RPC Handler version on 127.0.0.1:50051"}
{"level":"info","ts":"2024-03-10T17:24:58.573Z","caller":"runtime/asm_amd64.s:1650","msg":"IP pool manager - max pods: 110, warm IP target: 2, warm prefix target: 1, warm ENI target: 1, minimum IP target: 10"}
{"level":"info","ts":"2024-03-10T17:24:58.573Z","caller":"runtime/asm_amd64.s:1650","msg":"Serving metrics on port 61678"}
{"level":"info","ts":"2024-03-10T17:24:58.574Z","caller":"runtime/asm_amd64.s:1650","msg":"Setting up shutdown hook."}
{"level":"info","ts":"2024-03-10T17:24:58.574Z","caller":"ipamd/introspect.go:54","msg":"Serving introspection endpoints on 127.0.0.1:61679"}
{"level":"debug","ts":"2024-03-10T17:25:01.074Z","caller":"ipamd/ipamd.go:645","msg":"IP stats - total IPs: 3, assigned IPs: 0, cooldown IPs: 0"}
{"level":"debug","ts":"2024-03-10T17:25:01.074Z","caller":"ipamd/ipamd.go:663","msg":"Starting to increase pool size"}
{"level":"debug","ts":"2024-03-10T17:25:01.074Z","caller":"ipamd/ipamd.go:783","msg":"Node found \"ip-10-0-1-205.eu-central-1.compute.internal\" - no of taints - 2"}
{"level":"info","ts":"2024-03-10T17:25:01.074Z","caller":"awsutils/awsutils.go:734","msg":"Trying to allocate 3 IP addresses on new ENI"}
{"level":"debug","ts":"2024-03-10T17:25:01.075Z","caller":"awsutils/awsutils.go:734","msg":"PD enabled - false"}
{"level":"info","ts":"2024-03-10T17:25:01.075Z","caller":"awsutils/awsutils.go:734","msg":"Using same config as the primary interface for the new ENI"}
{"level":"info","ts":"2024-03-10T17:25:01.075Z","caller":"awsutils/awsutils.go:734","msg":"Creating ENI with security groups: [sg-0b0a77d0329b19fcc] in subnet: subnet-03aa442dddccaf297"}
{"level":"info","ts":"2024-03-10T17:25:01.562Z","caller":"awsutils/awsutils.go:734","msg":"Created a new ENI: eni-030816e696d19e38d"}
{"level":"debug","ts":"2024-03-10T17:25:01.733Z","caller":"awsutils/awsutils.go:780","msg":"Discovered device number is used: 0"}
{"level":"debug","ts":"2024-03-10T17:25:01.733Z","caller":"awsutils/awsutils.go:780","msg":"Found a free device number: 1"}
{"level":"info","ts":"2024-03-10T17:25:02.911Z","caller":"ipamd/ipamd.go:849","msg":"Successfully created and attached a new ENI eni-030816e696d19e38d to instance"}
{"level":"debug","ts":"2024-03-10T17:25:02.912Z","caller":"awsutils/awsutils.go:1589","msg":"Total number of interfaces found: 1 "}
{"level":"debug","ts":"2024-03-10T17:25:02.912Z","caller":"awsutils/awsutils.go:553","msg":"Found ENI MAC address: 02:3c:57:d5:54:8b"}
{"level":"debug","ts":"2024-03-10T17:25:02.915Z","caller":"awsutils/awsutils.go:553","msg":"Found ENI: eni-0a80ddc608579a6ff, MAC 02:3c:57:d5:54:8b, device 0"}
Also the ipamd log is huge and mainly this piece of log is repeated over and over:
{"level":"debug","ts":"2024-03-10T17:26:48.747Z","caller":"ipamd/ipamd.go:663","msg":"Skipping ENI allocation as the max ENI limit is already reached"}
{"level":"debug","ts":"2024-03-10T17:26:48.747Z","caller":"ipamd/ipamd.go:701","msg":"Node found \"ip-10-0-1-205.eu-central-1.compute.internal\" - no of taints - 1"}
{"level":"debug","ts":"2024-03-10T17:26:48.747Z","caller":"datastore/data_store.go:1001","msg":"ENI eni-0a80ddc608579a6ff cannot be deleted because it is primary"}
{"level":"debug","ts":"2024-03-10T17:26:48.747Z","caller":"datastore/data_store.go:1001","msg":"ENI eni-030816e696d19e38d cannot be deleted because it is required for WARM_IP_TARGET: 2"}
{"level":"debug","ts":"2024-03-10T17:26:53.749Z","caller":"ipamd/ipamd.go:645","msg":"IP stats - total IPs: 6, assigned IPs: 3, cooldown IPs: 0"}
{"level":"debug","ts":"2024-03-10T17:26:53.749Z","caller":"ipamd/ipamd.go:663","msg":"Starting to increase pool size"}
I also use the AWS Cloud Provider. Some logs from it:
I0310 17:36:35.275716 1 serving.go:348] Generated self-signed cert in-memory
I0310 17:36:35.634390 1 serving.go:348] Generated self-signed cert in-memory
W0310 17:36:35.635344 1 client_config.go:618] Neither --kubeconfig nor --master was specified. Using the inClusterConfig. This might not work.
I0310 17:36:36.324906 1 requestheader_controller.go:244] Loaded a new request header values for RequestHeaderAuthRequestController
I0310 17:36:36.327076 1 aws.go:681] Loading region from metadata service
I0310 17:36:36.328986 1 aws.go:1341] Building AWS cloudprovider
I0310 17:36:36.329073 1 aws.go:681] Loading region from metadata service
I0310 17:36:36.511666 1 tags.go:77] AWS cloud filtering on ClusterID: avatars-prod
I0310 17:36:36.511704 1 aws.go:1431] The following IP families will be added to nodes: [ipv4]
I0310 17:36:36.511775 1 controllermanager.go:167] Version: v1.27.1
I0310 17:36:36.519120 1 requestheader_controller.go:169] Starting RequestHeaderAuthRequestController
I0310 17:36:36.519283 1 shared_informer.go:311] Waiting for caches to sync for RequestHeaderAuthRequestController
I0310 17:36:36.519462 1 configmap_cafile_content.go:202] "Starting controller" name="client-ca::kube-system::extension-apiserver-authentication::client-ca-file"
I0310 17:36:36.519500 1 shared_informer.go:311] Waiting for caches to sync for client-ca::kube-system::extension-apiserver-authentication::client-ca-file
I0310 17:36:36.519567 1 configmap_cafile_content.go:202] "Starting controller" name="client-ca::kube-system::extension-apiserver-authentication::requestheader-client-ca-file"
I0310 17:36:36.519587 1 shared_informer.go:311] Waiting for caches to sync for client-ca::kube-system::extension-apiserver-authentication::requestheader-client-ca-file
I0310 17:36:36.520261 1 tlsconfig.go:200] "Loaded serving cert" certName="Generated self signed cert" certDetail="\"localhost@1710092195\" [serving] validServingFor=[127.0.0.1,localhost,localhost] issuer=\"localhost-ca@1710092194\" (2024-03-10 16:36:34 +0000 UTC to 2025-03-10 16:36:34 +0000 UTC (now=2024-03-10 17:36:36.52019894 +0000 UTC))"
I0310 17:36:36.521293 1 named_certificates.go:53] "Loaded SNI cert" index=0 certName="self-signed loopback" certDetail="\"apiserver-loopback-client@1710092196\" [serving] validServingFor=[apiserver-loopback-client] issuer=\"apiserver-loopback-client-ca@1710092195\" (2024-03-10 16:36:35 +0000 UTC to 2025-03-10 16:36:35 +0000 UTC (now=2024-03-10 17:36:36.521243645 +0000 UTC))"
I0310 17:36:36.522295 1 secure_serving.go:210] Serving securely on [::]:10258
I0310 17:36:36.523933 1 leaderelection.go:245] attempting to acquire leader lease kube-system/cloud-controller-manager...
I0310 17:36:36.524207 1 tlsconfig.go:240] "Starting DynamicServingCertificateController"
I0310 17:36:36.623055 1 shared_informer.go:318] Caches are synced for RequestHeaderAuthRequestController
I0310 17:36:36.623264 1 shared_informer.go:318] Caches are synced for client-ca::kube-system::extension-apiserver-authentication::client-ca-file
I0310 17:36:36.622980 1 shared_informer.go:318] Caches are synced for client-ca::kube-system::extension-apiserver-authentication::requestheader-client-ca-file
I0310 17:36:36.623853 1 tlsconfig.go:178] "Loaded client CA" index=0 certName="client-ca::kube-system::extension-apiserver-authentication::client-ca-file,client-ca::kube-system::extension-apiserver-authentication::requestheader-client-ca-file" certDetail="\"k3s-client-ca@1710091447\" [] issuer=\"<self>\" (2024-03-10 17:24:07 +0000 UTC to 2034-03-08 17:24:07 +0000 UTC (now=2024-03-10 17:36:36.623782164 +0000 UTC))"
I0310 17:36:36.623926 1 tlsconfig.go:178] "Loaded client CA" index=1 certName="client-ca::kube-system::extension-apiserver-authentication::client-ca-file,client-ca::kube-system::extension-apiserver-authentication::requestheader-client-ca-file" certDetail="\"k3s-request-header-ca@1710091447\" [] issuer=\"<self>\" (2024-03-10 17:24:07 +0000 UTC to 2034-03-08 17:24:07 +0000 UTC (now=2024-03-10 17:36:36.623869256 +0000 UTC))"
I0310 17:36:36.625170 1 tlsconfig.go:200] "Loaded serving cert" certName="Generated self signed cert" certDetail="\"localhost@1710092195\" [serving] validServingFor=[127.0.0.1,localhost,localhost] issuer=\"localhost-ca@1710092194\" (2024-03-10 16:36:34 +0000 UTC to 2025-03-10 16:36:34 +0000 UTC (now=2024-03-10 17:36:36.625128186 +0000 UTC))"
I0310 17:36:36.626832 1 named_certificates.go:53] "Loaded SNI cert" index=0 certName="self-signed loopback" certDetail="\"apiserver-loopback-client@1710092196\" [serving] validServingFor=[apiserver-loopback-client] issuer=\"apiserver-loopback-client-ca@1710092195\" (2024-03-10 16:36:35 +0000 UTC to 2025-03-10 16:36:35 +0000 UTC (now=2024-03-10 17:36:36.626788895 +0000 UTC))"
I0310 17:36:53.582157 1 leaderelection.go:255] successfully acquired lease kube-system/cloud-controller-manager
I0310 17:36:53.582424 1 event.go:307] "Event occurred" object="kube-system/cloud-controller-manager" fieldPath="" kind="Lease" apiVersion="coordination.k8s.io/v1" type="Normal" reason="LeaderElection" message="ip-10-0-1-205_1ee31878-460b-4cca-b592-65245d8dbad7 became leader"
E0310 17:36:53.603081 1 controllermanager.go:523] unable to get all supported resources from server: unable to retrieve the complete list of server APIs: metrics.k8s.io/v1beta1: stale GroupVersion discovery: metrics.k8s.io/v1beta1
I0310 17:36:53.603548 1 aws.go:861] Setting up informers for Cloud
I0310 17:36:53.603612 1 controllermanager.go:317] Starting "cloud-node-lifecycle"
I0310 17:36:53.603849 1 controllermanager.go:336] Started "cloud-node-lifecycle"
I0310 17:36:53.603878 1 controllermanager.go:317] Starting "service"
I0310 17:36:53.604249 1 controllermanager.go:336] Started "service"
I0310 17:36:53.604279 1 controllermanager.go:317] Starting "route"
I0310 17:36:53.604287 1 core.go:104] Will not configure cloud provider routes, --configure-cloud-routes: false
W0310 17:36:53.604298 1 controllermanager.go:324] Skipping "route"
W0310 17:36:53.604305 1 controllermanager.go:313] "tagging" is disabled
I0310 17:36:53.604313 1 controllermanager.go:317] Starting "cloud-node"
I0310 17:36:53.604558 1 controllermanager.go:336] Started "cloud-node"
I0310 17:36:53.605337 1 controller.go:229] Starting service controller
I0310 17:36:53.605369 1 shared_informer.go:311] Waiting for caches to sync for service
I0310 17:36:53.605422 1 node_controller.go:161] Sending events to api server.
I0310 17:36:53.605470 1 node_controller.go:170] Waiting for informer caches to sync
I0310 17:36:53.605781 1 node_lifecycle_controller.go:113] Sending events to api server
I0310 17:36:53.706013 1 shared_informer.go:318] Caches are synced for service
I0310 17:36:53.706106 1 controller.go:695] Syncing backends for all LB services.
I0310 17:36:53.706122 1 controller.go:699] Successfully updated 0 out of 0 load balancers to direct traffic to the updated set of nodes
I0310 17:36:53.706140 1 controller.go:695] Syncing backends for all LB services.
I0310 17:36:53.706148 1 controller.go:699] Successfully updated 0 out of 0 load balancers to direct traffic to the updated set of nodes
I0310 17:36:53.861710 1 node_controller.go:263] Update 2 nodes status took 155.713325ms.
I0310 17:41:54.125980 1 node_controller.go:263] Update 2 nodes status took 263.853156ms.
I0310 17:46:54.388569 1 node_controller.go:263] Update 2 nodes status took 261.571023ms.
I0310 17:51:54.638539 1 node_controller.go:263] Update 2 nodes status took 249.106726ms.
I0310 17:56:54.898585 1 node_controller.go:263] Update 2 nodes status took 259.40673ms.
I0310 18:01:55.175429 1 node_controller.go:263] Update 2 nodes status took 276.230037ms.
I0310 18:06:55.420354 1 node_controller.go:263] Update 2 nodes status took 244.130273ms.
I0310 18:11:55.679277 1 node_controller.go:263] Update 2 nodes status took 258.715474ms.
I0310 18:16:55.933493 1 node_controller.go:263] Update 2 nodes status took 253.175861ms.
I0310 18:21:56.175402 1 node_controller.go:263] Update 2 nodes status took 241.365186ms.
I0310 18:26:56.429710 1 node_controller.go:263] Update 2 nodes status took 253.703817ms.
I0310 18:31:56.687088 1 node_controller.go:263] Update 2 nodes status took 256.310866ms.
I0310 18:36:56.980733 1 node_controller.go:263] Update 2 nodes status took 293.216163ms.
I0310 18:41:57.259135 1 node_controller.go:263] Update 2 nodes status took 278.282528ms.
I0310 18:46:57.508262 1 node_controller.go:263] Update 2 nodes status took 248.196734ms.
I0310 18:51:57.757563 1 node_controller.go:263] Update 2 nodes status took 248.515382ms.
Logs from CoreDNS:
[INFO] plugin/kubernetes: waiting for Kubernetes API before starting server
[INFO] plugin/kubernetes: waiting for Kubernetes API before starting server
[INFO] plugin/kubernetes: waiting for Kubernetes API before starting server
[INFO] plugin/kubernetes: waiting for Kubernetes API before starting server
[INFO] plugin/kubernetes: waiting for Kubernetes API before starting server
[INFO] plugin/kubernetes: waiting for Kubernetes API before starting server
[INFO] plugin/kubernetes: waiting for Kubernetes API before starting server
[INFO] plugin/kubernetes: waiting for Kubernetes API before starting server
[INFO] plugin/kubernetes: waiting for Kubernetes API before starting server
[WARNING] plugin/kubernetes: starting server with unsynced Kubernetes API
.:53
[WARNING] No files matching import glob pattern: /etc/coredns/custom/*.override
[WARNING] No files matching import glob pattern: /etc/coredns/custom/*.server
[INFO] plugin/reload: Running configuration SHA512 = b941b080e5322f6519009bb49349462c7ddb6317425b0f6a83e5451175b720703949e3f3b454a24e77f3ffe57fd5e9c6130e528a5a1dd00d9000e4afd6c1108d
CoreDNS-1.10.1
linux/amd64, go1.20, 055b2c3
[ERROR] plugin/errors: 2 6543219994913675665.4441469366046872804. HINFO: read udp 10.0.3.96:47362->10.0.0.2:53: i/o timeout
[ERROR] plugin/errors: 2 6543219994913675665.4441469366046872804. HINFO: read udp 10.0.3.96:35611->10.0.0.2:53: i/o timeout
[ERROR] plugin/errors: 2 6543219994913675665.4441469366046872804. HINFO: read udp 10.0.3.96:36800->10.0.0.2:53: i/o timeout
[ERROR] plugin/errors: 2 6543219994913675665.4441469366046872804. HINFO: read udp 10.0.3.96:56372->10.0.0.2:53: i/o timeout
[ERROR] plugin/errors: 2 6543219994913675665.4441469366046872804. HINFO: read udp 10.0.3.96:53501->10.0.0.2:53: i/o timeout
[ERROR] plugin/errors: 2 6543219994913675665.4441469366046872804. HINFO: read udp 10.0.3.96:35763->10.0.0.2:53: i/o timeout
[ERROR] plugin/errors: 2 6543219994913675665.4441469366046872804. HINFO: read udp 10.0.3.96:35057->10.0.0.2:53: i/o timeout
[ERROR] plugin/errors: 2 6543219994913675665.4441469366046872804. HINFO: read udp 10.0.3.96:41373->10.0.0.2:53: i/o timeout
[WARNING] plugin/kubernetes: Kubernetes API connection failure: Get "https://172.20.0.1:443/version": dial tcp 172.20.0.1:443: i/o timeout
[ERROR] plugin/errors: 2 6543219994913675665.4441469366046872804. HINFO: read udp 10.0.3.96:35344->10.0.0.2:53: i/o timeout
[ERROR] plugin/errors: 2 6543219994913675665.4441469366046872804. HINFO: read udp 10.0.3.96:56989->10.0.0.2:53: i/o timeout
[WARNING] No files matching import glob pattern: /etc/coredns/custom/*.override
[WARNING] No files matching import glob pattern: /etc/coredns/custom/*.server
The local path provisioner also complains about not being able to connect to the Kubernetes API.
I asked the same question in the k3s project, but we were not able to figure it out there. Any help would be greatly appreciated!
Side note: when using Flannel, which comes with k3s by default, the problem does not occur
Environment:
- Kubernetes version (use
kubectl version): 1.28.7+k3s1 (1.28.7) - CNI Version: 1.16.4
- OS (e.g:
cat /etc/os-release): Ubuntu 22.04.3 LTS - Kernel (e.g.
uname -a): 6.2.0-1018-aws
