aws-cni Failed to create pod sandbox error

[nikhlagrwl]

What happened:
We have an EKS cluster in AWS with self managed Linux node groups, instance type - c5a.2xlarge. We have configured warm pool (stopped state) in the Auto Scaling Group and whenever any pods are coming up which is scaling up instances from warm pool to normal pool, we are getting the below logs in the cluster events and the overall pod start time is increasing.

Warning FailedCreatePodSandBox 118s kubelet Failed to create pod sandbox: rpc error: code = Unknown desc = failed to setup network for sandbox "719d35bdbfe36a98c614414306a9596bd9fa1c8a1c5db554b2ed19a44cb54b04": plugin type="aws-cni" name="aws-cni" failed (add): add cmd: Error received from AddNetwork gRPC call: rpc error: code = Unavailable desc = connection error: desc = "transport: Error while dialing: dial tcp 127.0.0.1:50051: connect: connection refused"

Attach logs
Warning FailedCreatePodSandBox 118s kubelet Failed to create pod sandbox: rpc error: code = Unknown desc = failed to setup network for sandbox "719d35bdbfe36a98c614414306a9596bd9fa1c8a1c5db554b2ed19a44cb54b04": plugin type="aws-cni" name="aws-cni" failed (add): add cmd: Error received from AddNetwork gRPC call: rpc error: code = Unavailable desc = connection error: desc = "transport: Error while dialing: dial tcp 127.0.0.1:50051: connect: connection refused"

What you expected to happen:

How to reproduce it (as minimally and precisely as possible):

Anything else we need to know?:

Environment:

• Kubernetes version (use kubectl version):
• CNI Version: v1.19.2-eksbuild.5
• OS (e.g: cat /etc/os-release):
• Kernel (e.g. uname -a):

[jaydeokar]

Have you checked the errors in the ipamd log why the GRPC server was down ? you can find the logs in /var/log/aws-routed-eni/ipamd.log

Does it recover eventually or a consistent failure ? If the node is starting from a stopped state, it does take few seconds to go through the node init, discover the ENIs and IPs before starting the GRPC server.

[nikhlagrwl]

Does it recover eventually or a consistent failure ?

It does recover after some time and the recovery time varies from few secs to few mins.

Posting the logs from the file /var/log/aws-routed-eni/ipamd.log

{"level":"info","ts":"2025-08-20T09:42:59.766Z","caller":"logger/logger.go:52","msg":"Constructed new logger instance"}
{"level":"info","ts":"2025-08-20T09:42:59.771Z","caller":"networkutils/network.go:149","msg":"Initialized new logger as an existing instance was not found"}
{"level":"info","ts":"2025-08-20T09:42:59.884Z","caller":"aws-k8s-agent/main.go:51","msg":"Starting L-IPAMD   ..."}
{"level":"info","ts":"2025-08-20T09:42:59.885Z","caller":"aws-k8s-agent/main.go:51","msg":"Waiting to connect API server for upto 30s..."}
{"level":"info","ts":"2025-08-20T09:42:59.917Z","caller":"aws-k8s-agent/main.go:122","msg":"Testing communication with server ..."}
{"level":"info","ts":"2025-08-20T09:42:59.939Z","caller":"wait/loop.go:53","msg":"Successful communication with the Cluster! Cluster Version is: v1.31.10-eks-931bdca"}
{"level":"info","ts":"2025-08-20T09:42:59.939Z","caller":"aws-k8s-agent/main.go:51","msg":"API server connectivity established."}
{"level":"info","ts":"2025-08-20T09:42:59.951Z","caller":"aws-k8s-agent/main.go:131","msg":"Cache-based Kubernetes client successfully created."}
{"level":"info","ts":"2025-08-20T09:42:59.951Z","caller":"aws-k8s-agent/main.go:131","msg":"k8sClient created successfully"}
{"level":"debug","ts":"2025-08-20T09:43:00.053Z","caller":"eventrecorder/eventrecorder.go:68","msg":"Pod found aws-node-4hgj6 - labels - 5"}
{"level":"warn","ts":"2025-08-20T09:43:00.053Z","caller":"awssession/session.go:68","msg":"HTTP_TIMEOUT env is not set or set to less than 10 seconds, defaulting to httpTimeout to 10sec"}
{"level":"debug","ts":"2025-08-20T09:43:00.061Z","caller":"ipamd/ipamd.go:412","msg":"Discovered region: eu-central-1"}
{"level":"info","ts":"2025-08-20T09:43:00.061Z","caller":"ipamd/ipamd.go:412","msg":"Custom networking enabled false"}
{"level":"info","ts":"2025-08-20T09:43:00.061Z","caller":"ipamd/ipamd.go:412","msg":"Subnet discovery enabled true"}
{"level":"debug","ts":"2025-08-20T09:43:00.062Z","caller":"awsutils/awsutils.go:423","msg":"Found availability zone: eu-central-1c "}
{"level":"debug","ts":"2025-08-20T09:43:00.063Z","caller":"awsutils/awsutils.go:423","msg":"Discovered the instance primary IPv4 address: 192.173.128.237"}
{"level":"debug","ts":"2025-08-20T09:43:00.064Z","caller":"awsutils/awsutils.go:423","msg":"Found instance-id: i-0397fcdfd0634c585 "}
{"level":"debug","ts":"2025-08-20T09:43:00.064Z","caller":"awsutils/awsutils.go:423","msg":"Found instance-type: c5a.2xlarge "}
{"level":"debug","ts":"2025-08-20T09:43:00.065Z","caller":"awsutils/awsutils.go:423","msg":"Found primary interface's MAC address: 0a:36:65:b9:6a:ad"}
{"level":"debug","ts":"2025-08-20T09:43:00.065Z","caller":"awsutils/awsutils.go:423","msg":"eni-0c348ad0630d58229 is the primary ENI of this instance"}
{"level":"debug","ts":"2025-08-20T09:43:00.066Z","caller":"awsutils/awsutils.go:423","msg":"Found subnet-id: subnet-05e8a66251f0c700d "}
{"level":"debug","ts":"2025-08-20T09:43:00.067Z","caller":"awsutils/awsutils.go:423","msg":"Found vpc-id: vpc-09c1993831df1b1d3 "}
{"level":"debug","ts":"2025-08-20T09:43:00.067Z","caller":"ipamd/ipamd.go:421","msg":"Using WARM_ENI_TARGET 1"}
{"level":"debug","ts":"2025-08-20T09:43:00.067Z","caller":"ipamd/ipamd.go:424","msg":"Using WARM_PREFIX_TARGET 1"}
{"level":"info","ts":"2025-08-20T09:43:00.067Z","caller":"ipamd/ipamd.go:448","msg":"Prefix Delegation enabled false"}
{"level":"debug","ts":"2025-08-20T09:43:00.067Z","caller":"ipamd/ipamd.go:452","msg":"Start node init"}
{"level":"debug","ts":"2025-08-20T09:43:00.067Z","caller":"ipamd/ipamd.go:464","msg":"Max ip per ENI 14 and max prefixes per ENI 0"}
{"level":"info","ts":"2025-08-20T09:43:00.067Z","caller":"awsutils/awsutils.go:1971","msg":"Will attempt to clean up AWS CNI leaked ENIs after waiting 3m20s."}
{"level":"info","ts":"2025-08-20T09:43:00.067Z","caller":"ipamd/ipamd.go:476","msg":"Setting up host network... "}
{"level":"debug","ts":"2025-08-20T09:43:00.069Z","caller":"networkutils/network.go:300","msg":"Found the Link that uses mac address 0a:36:65:b9:6a:ad and its index is 2 (attempt 1/5)"}
{"level":"debug","ts":"2025-08-20T09:43:00.069Z","caller":"networkutils/network.go:431","msg":"Trying to find primary interface that has mac : 0a:36:65:b9:6a:ad"}
{"level":"debug","ts":"2025-08-20T09:43:00.069Z","caller":"networkutils/network.go:431","msg":"Discovered interface: lo, mac: "}
{"level":"debug","ts":"2025-08-20T09:43:00.069Z","caller":"networkutils/network.go:431","msg":"Discovered interface: eth0, mac: 0a:36:65:b9:6a:ad"}
{"level":"info","ts":"2025-08-20T09:43:00.069Z","caller":"networkutils/network.go:431","msg":"Discovered primary interface: eth0"}
{"level":"debug","ts":"2025-08-20T09:43:00.141Z","caller":"networkutils/network.go:448","msg":"Adding 192.173.0.0/16 CIDR to NAT chain"}
{"level":"debug","ts":"2025-08-20T09:43:00.141Z","caller":"networkutils/network.go:448","msg":"Total CIDRs to program - 1"}
{"level":"debug","ts":"2025-08-20T09:43:00.141Z","caller":"networkutils/network.go:448","msg":"Setup Host Network: iptables -N AWS-SNAT-CHAIN-0 -t nat"}
{"level":"debug","ts":"2025-08-20T09:43:00.143Z","caller":"networkutils/network.go:448","msg":"Setup Host Network: iptables -A POSTROUTING -m comment --comment \"AWS SNAT CHAIN\" -j AWS-SNAT-CHAIN-0"}
{"level":"debug","ts":"2025-08-20T09:43:00.143Z","caller":"networkutils/network.go:448","msg":"Setup Host Network: iptables -A AWS-SNAT-CHAIN-0 -d 192.173.0.0/16 -m comment --comment AWS SNAT CHAIN -t nat -j RETURN"}
{"level":"debug","ts":"2025-08-20T09:43:00.143Z","caller":"networkutils/network.go:772","msg":"Setup Host Network: loading existing iptables nat rules with chain prefix AWS-SNAT-CHAIN"}
{"level":"debug","ts":"2025-08-20T09:43:00.148Z","caller":"networkutils/network.go:772","msg":"host network setup: found potentially stale rule for chain AWS-SNAT-CHAIN-0: [-N AWS-SNAT-CHAIN-0]"}
{"level":"debug","ts":"2025-08-20T09:43:00.148Z","caller":"networkutils/network.go:542","msg":"Setup Host Network: computing stale iptables rules for nat table with chain prefix AWS-SNAT-CHAIN"}
{"level":"debug","ts":"2025-08-20T09:43:00.148Z","caller":"networkutils/network.go:542","msg":"Setup Host Network: active chain found: AWS-SNAT-CHAIN-0"}
{"level":"debug","ts":"2025-08-20T09:43:00.148Z","caller":"networkutils/network.go:448","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 192.173.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 192.173.128.237 --random-fully] mangle/PREROUTING rule connmark for primary ENI shouldExist true rule [-m comment --comment AWS, primary ENI -i eth0 -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":"2025-08-20T09:43:00.148Z","caller":"networkutils/network.go:452","msg":"execute iptable rule : first SNAT rules for non-VPC outbound traffic"}
{"level":"debug","ts":"2025-08-20T09:43:00.150Z","caller":"networkutils/network.go:452","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":"2025-08-20T09:43:00.152Z","caller":"networkutils/network.go:452","msg":"execute iptable rule : AWS-SNAT-CHAIN-0"}
{"level":"debug","ts":"2025-08-20T09:43:00.153Z","caller":"networkutils/network.go:452","msg":"rule nat/AWS-SNAT-CHAIN-0 rule AWS-SNAT-CHAIN-0 shouldExist true rule [-d 192.173.0.0/16 -m comment --comment AWS SNAT CHAIN -j RETURN] exists false, err <nil>"}
{"level":"debug","ts":"2025-08-20T09:43:00.155Z","caller":"networkutils/network.go:452","msg":"execute iptable rule : last SNAT rule for non-VPC outbound traffic"}
{"level":"debug","ts":"2025-08-20T09:43:00.157Z","caller":"networkutils/network.go:452","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 192.173.128.237 --random-fully] exists false, err <nil>"}
{"level":"debug","ts":"2025-08-20T09:43:00.159Z","caller":"networkutils/network.go:452","msg":"execute iptable rule : connmark for primary ENI"}
{"level":"debug","ts":"2025-08-20T09:43:00.164Z","caller":"networkutils/network.go:452","msg":"rule mangle/PREROUTING rule connmark for primary ENI shouldExist true rule [-m comment --comment AWS, primary ENI -i eth0 -m addrtype --dst-type LOCAL --limit-iface-in -j CONNMARK --set-mark 0x80/0x80] exists false, err <nil>"}
{"level":"debug","ts":"2025-08-20T09:43:00.166Z","caller":"networkutils/network.go:452","msg":"execute iptable rule : connmark restore for primary ENI"}
{"level":"debug","ts":"2025-08-20T09:43:00.167Z","caller":"networkutils/network.go:452","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":"2025-08-20T09:43:00.169Z","caller":"networkutils/network.go:452","msg":"execute iptable rule : connmark restore for primary ENI from vlan"}
{"level":"debug","ts":"2025-08-20T09:43:00.170Z","caller":"networkutils/network.go:452","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":"2025-08-20T09:43:00.172Z","caller":"networkutils/network.go:456","msg":"Total CIDRs to exempt from connmark rules - 1"}
{"level":"debug","ts":"2025-08-20T09:43:00.172Z","caller":"networkutils/network.go:456","msg":"Setup Host Network: iptables -N AWS-CONNMARK-CHAIN-0 -t nat"}
{"level":"debug","ts":"2025-08-20T09:43:00.173Z","caller":"networkutils/network.go:456","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":"2025-08-20T09:43:00.173Z","caller":"networkutils/network.go:456","msg":"Setup Host Network: iptables -A AWS-CONNMARK-CHAIN-0 -d 192.173.0.0/16 -t nat -j RETURN"}
{"level":"debug","ts":"2025-08-20T09:43:00.173Z","caller":"networkutils/network.go:772","msg":"Setup Host Network: loading existing iptables nat rules with chain prefix AWS-CONNMARK-CHAIN"}
{"level":"debug","ts":"2025-08-20T09:43:00.179Z","caller":"networkutils/network.go:772","msg":"host network setup: found potentially stale rule for chain AWS-CONNMARK-CHAIN-0: [-N AWS-CONNMARK-CHAIN-0]"}
{"level":"debug","ts":"2025-08-20T09:43:00.179Z","caller":"networkutils/network.go:678","msg":"Setup Host Network: computing stale iptables rules for nat table with chain prefix AWS-CONNMARK-CHAIN"}
{"level":"debug","ts":"2025-08-20T09:43:00.179Z","caller":"networkutils/network.go:678","msg":"Setup Host Network: active chain found: AWS-CONNMARK-CHAIN-0"}
{"level":"debug","ts":"2025-08-20T09:43:00.179Z","caller":"networkutils/network.go:456","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 192.173.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":"2025-08-20T09:43:00.179Z","caller":"networkutils/network.go:460","msg":"execute iptable rule : connmark rule for non-VPC outbound traffic"}
{"level":"debug","ts":"2025-08-20T09:43:00.183Z","caller":"networkutils/network.go:460","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":"2025-08-20T09:43:00.183Z","caller":"networkutils/network.go:460","msg":"execute iptable rule : connmark rule for non-VPC outbound traffic"}
{"level":"debug","ts":"2025-08-20T09:43:00.184Z","caller":"networkutils/network.go:460","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":"2025-08-20T09:43:00.186Z","caller":"networkutils/network.go:460","msg":"execute iptable rule : AWS-CONNMARK-CHAIN-0"}
{"level":"debug","ts":"2025-08-20T09:43:00.187Z","caller":"networkutils/network.go:460","msg":"rule nat/AWS-CONNMARK-CHAIN-0 rule AWS-CONNMARK-CHAIN-0 shouldExist true rule [-d 192.173.0.0/16 -m comment --comment AWS CONNMARK CHAIN, VPC CIDR -j RETURN] exists false, err <nil>"}
{"level":"debug","ts":"2025-08-20T09:43:00.189Z","caller":"networkutils/network.go:460","msg":"execute iptable rule : connmark to fwmark copy"}
{"level":"debug","ts":"2025-08-20T09:43:00.191Z","caller":"networkutils/network.go:460","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":"2025-08-20T09:43:00.191Z","caller":"networkutils/network.go:460","msg":"execute iptable rule : connmark to fwmark copy"}
{"level":"debug","ts":"2025-08-20T09:43:00.193Z","caller":"networkutils/network.go:460","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":"2025-08-20T09:43:00.195Z","caller":"networkutils/network.go:460","msg":"execute iptable rule : connmark rule for external outbound traffic"}
{"level":"debug","ts":"2025-08-20T09:43:00.196Z","caller":"networkutils/network.go:460","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":"2025-08-20T09:43:00.202Z","caller":"awsutils/awsutils.go:1392","msg":"Total number of interfaces found: 1 "}
{"level":"debug","ts":"2025-08-20T09:43:00.202Z","caller":"awsutils/awsutils.go:604","msg":"Found ENI MAC address: 0a:36:65:b9:6a:ad"}
{"level":"debug","ts":"2025-08-20T09:43:00.205Z","caller":"awsutils/awsutils.go:604","msg":"Found ENI: eni-0c348ad0630d58229, MAC 0a:36:65:b9:6a:ad, device 0"}
{"level":"debug","ts":"2025-08-20T09:43:00.206Z","caller":"awsutils/awsutils.go:604","msg":"Found IPv4 addresses associated with interface. This is not efa-only interface"}
{"level":"info","ts":"2025-08-20T09:43:00.417Z","caller":"ipamd/ipamd.go:489","msg":"Got network card index 0 for ENI eni-0c348ad0630d58229"}
{"level":"info","ts":"2025-08-20T09:43:00.417Z","caller":"ipamd/ipamd.go:489","msg":"eni-0c348ad0630d58229 is of type: interface"}
{"level":"debug","ts":"2025-08-20T09:43:00.417Z","caller":"ipamd/ipamd.go:452","msg":"DescribeAllENIs success: ENIs: 1, tagged: 1"}
{"level":"info","ts":"2025-08-20T09:43:00.417Z","caller":"ipamd/ipamd.go:501","msg":"initialized datastore for network cards index 0"}
{"level":"debug","ts":"2025-08-20T09:43:00.417Z","caller":"ipamd/ipamd.go:452","msg":"Discovered ENI eni-0c348ad0630d58229, trying to set it up"}
{"level":"debug","ts":"2025-08-20T09:43:00.417Z","caller":"ipamd/ipamd.go:1250","msg":"DataStore add an ENI eni-0c348ad0630d58229"}
{"level":"info","ts":"2025-08-20T09:43:00.417Z","caller":"ipamd/ipamd.go:518","msg":"Found ENIs having 15 secondary IPs and 0 Prefixes"}
{"level":"info","ts":"2025-08-20T09:43:00.417Z","caller":"ipamd/ipamd.go:1310","msg":"Adding 192.173.155.237/32 to DS for eni-0c348ad0630d58229"}
{"level":"info","ts":"2025-08-20T09:43:00.417Z","caller":"ipamd/ipamd.go:1310","msg":"Added ENI(eni-0c348ad0630d58229)'s IP/Prefix 192.173.155.237/32 to datastore"}
{"level":"info","ts":"2025-08-20T09:43:00.417Z","caller":"ipamd/ipamd.go:1310","msg":"Adding 192.173.134.40/32 to DS for eni-0c348ad0630d58229"}
{"level":"info","ts":"2025-08-20T09:43:00.417Z","caller":"ipamd/ipamd.go:1310","msg":"Added ENI(eni-0c348ad0630d58229)'s IP/Prefix 192.173.134.40/32 to datastore"}
{"level":"info","ts":"2025-08-20T09:43:00.417Z","caller":"ipamd/ipamd.go:1310","msg":"Adding 192.173.155.202/32 to DS for eni-0c348ad0630d58229"}
{"level":"info","ts":"2025-08-20T09:43:00.417Z","caller":"ipamd/ipamd.go:1310","msg":"Added ENI(eni-0c348ad0630d58229)'s IP/Prefix 192.173.155.202/32 to datastore"}
{"level":"info","ts":"2025-08-20T09:43:00.417Z","caller":"ipamd/ipamd.go:1310","msg":"Adding 192.173.142.228/32 to DS for eni-0c348ad0630d58229"}
{"level":"info","ts":"2025-08-20T09:43:00.417Z","caller":"ipamd/ipamd.go:1310","msg":"Added ENI(eni-0c348ad0630d58229)'s IP/Prefix 192.173.142.228/32 to datastore"}
{"level":"info","ts":"2025-08-20T09:43:00.417Z","caller":"ipamd/ipamd.go:1310","msg":"Adding 192.173.152.103/32 to DS for eni-0c348ad0630d58229"}
{"level":"info","ts":"2025-08-20T09:43:00.417Z","caller":"ipamd/ipamd.go:1310","msg":"Added ENI(eni-0c348ad0630d58229)'s IP/Prefix 192.173.152.103/32 to datastore"}
{"level":"info","ts":"2025-08-20T09:43:00.417Z","caller":"ipamd/ipamd.go:1310","msg":"Adding 192.173.159.161/32 to DS for eni-0c348ad0630d58229"}
{"level":"info","ts":"2025-08-20T09:43:00.417Z","caller":"ipamd/ipamd.go:1310","msg":"Added ENI(eni-0c348ad0630d58229)'s IP/Prefix 192.173.159.161/32 to datastore"}
{"level":"info","ts":"2025-08-20T09:43:00.417Z","caller":"ipamd/ipamd.go:1310","msg":"Adding 192.173.142.67/32 to DS for eni-0c348ad0630d58229"}
{"level":"info","ts":"2025-08-20T09:43:00.417Z","caller":"ipamd/ipamd.go:1310","msg":"Added ENI(eni-0c348ad0630d58229)'s IP/Prefix 192.173.142.67/32 to datastore"}
{"level":"info","ts":"2025-08-20T09:43:00.417Z","caller":"ipamd/ipamd.go:1310","msg":"Adding 192.173.143.3/32 to DS for eni-0c348ad0630d58229"}
{"level":"info","ts":"2025-08-20T09:43:00.417Z","caller":"ipamd/ipamd.go:1310","msg":"Added ENI(eni-0c348ad0630d58229)'s IP/Prefix 192.173.143.3/32 to datastore"}
{"level":"info","ts":"2025-08-20T09:43:00.418Z","caller":"ipamd/ipamd.go:1310","msg":"Adding 192.173.139.252/32 to DS for eni-0c348ad0630d58229"}
{"level":"info","ts":"2025-08-20T09:43:00.418Z","caller":"ipamd/ipamd.go:1310","msg":"Added ENI(eni-0c348ad0630d58229)'s IP/Prefix 192.173.139.252/32 to datastore"}
{"level":"info","ts":"2025-08-20T09:43:00.418Z","caller":"ipamd/ipamd.go:1310","msg":"Adding 192.173.146.92/32 to DS for eni-0c348ad0630d58229"}
{"level":"info","ts":"2025-08-20T09:43:00.418Z","caller":"ipamd/ipamd.go:1310","msg":"Added ENI(eni-0c348ad0630d58229)'s IP/Prefix 192.173.146.92/32 to datastore"}
{"level":"info","ts":"2025-08-20T09:43:00.418Z","caller":"ipamd/ipamd.go:1310","msg":"Adding 192.173.139.95/32 to DS for eni-0c348ad0630d58229"}
{"level":"info","ts":"2025-08-20T09:43:00.418Z","caller":"ipamd/ipamd.go:1310","msg":"Added ENI(eni-0c348ad0630d58229)'s IP/Prefix 192.173.139.95/32 to datastore"}
{"level":"info","ts":"2025-08-20T09:43:00.418Z","caller":"ipamd/ipamd.go:1310","msg":"Adding 192.173.139.223/32 to DS for eni-0c348ad0630d58229"}
{"level":"info","ts":"2025-08-20T09:43:00.418Z","caller":"ipamd/ipamd.go:1310","msg":"Added ENI(eni-0c348ad0630d58229)'s IP/Prefix 192.173.139.223/32 to datastore"}
{"level":"info","ts":"2025-08-20T09:43:00.418Z","caller":"ipamd/ipamd.go:1310","msg":"Adding 192.173.149.241/32 to DS for eni-0c348ad0630d58229"}
{"level":"info","ts":"2025-08-20T09:43:00.418Z","caller":"ipamd/ipamd.go:1310","msg":"Added ENI(eni-0c348ad0630d58229)'s IP/Prefix 192.173.149.241/32 to datastore"}
{"level":"info","ts":"2025-08-20T09:43:00.418Z","caller":"ipamd/ipamd.go:1310","msg":"Adding 192.173.132.113/32 to DS for eni-0c348ad0630d58229"}
{"level":"info","ts":"2025-08-20T09:43:00.418Z","caller":"ipamd/ipamd.go:1310","msg":"Added ENI(eni-0c348ad0630d58229)'s IP/Prefix 192.173.132.113/32 to datastore"}
{"level":"debug","ts":"2025-08-20T09:43:00.418Z","caller":"ipamd/ipamd.go:1317","msg":"IP pool stats for network card 0: Total IPs/Prefixes = 14/0, AssignedIPs/CooldownIPs: 0/0, c.maxIPsPerENI = 14"}
{"level":"debug","ts":"2025-08-20T09:43:00.418Z","caller":"ipamd/ipamd.go:1338","msg":"IP pool stats for network card 0: Total IPs/Prefixes = 14/0, AssignedIPs/CooldownIPs: 0/0, c.maxIPsPerENI = 14"}
{"level":"info","ts":"2025-08-20T09:43:00.418Z","caller":"ipamd/ipamd.go:452","msg":"ENI eni-0c348ad0630d58229 set up."}
{"level":"info","ts":"2025-08-20T09:43:00.418Z","caller":"datastore/data_store.go:1594","msg":"Begin ipam state recovery from backing store"}
{"level":"debug","ts":"2025-08-20T09:43:00.418Z","caller":"datastore/data_store.go:1594","msg":"backing store doesn't exists, assuming bootstrap on a new node"}
{"level":"debug","ts":"2025-08-20T09:43:00.418Z","caller":"ipamd/ipamd.go:553","msg":"tryUnassignPrefixesFromENIs"}
{"level":"debug","ts":"2025-08-20T09:43:00.418Z","caller":"ipamd/ipamd.go:702","msg":"Update Rule List with set []"}
{"level":"info","ts":"2025-08-20T09:43:00.419Z","caller":"ipamd/ipamd.go:570","msg":"Found sg-03ec51e36413a230a, added to ipamd cache"}
{"level":"info","ts":"2025-08-20T09:43:00.419Z","caller":"ipamd/ipamd.go:570","msg":"Found sg-0a0c6162dea848468, added to ipamd cache"}
{"level":"debug","ts":"2025-08-20T09:43:00.419Z","caller":"ipamd/ipamd.go:570","msg":"Update ENI eni-0c348ad0630d58229"}
{"level":"info","ts":"2025-08-20T09:43:00.877Z","caller":"ipamd/ipamd.go:584","msg":"Get Node Info for: ip-192-173-128-237.eu-central-1.compute.internal"}
{"level":"debug","ts":"2025-08-20T09:43:00.978Z","caller":"ipamd/ipamd.go:640","msg":"is datastore pool low for networkCard 0, decision false"}
{"level":"debug","ts":"2025-08-20T09:43:00.978Z","caller":"ipamd/ipamd.go:452","msg":"node init completed successfully"}
{"level":"info","ts":"2025-08-20T09:43:00.978Z","caller":"aws-k8s-agent/main.go:178","msg":"Serving RPC Handler version  on 127.0.0.1:50051"}
{"level":"info","ts":"2025-08-20T09:43:00.979Z","caller":"ipamd/introspect.go:55","msg":"Serving introspection endpoints on 127.0.0.1:61679"}
{"level":"info","ts":"2025-08-20T09:43:00.978Z","caller":"runtime/asm_amd64.s:1700","msg":"IP pool manager - max pods: 58, warm IP target: 0, warm prefix target: 1, warm ENI target: 1, minimum IP target: 0"}
{"level":"info","ts":"2025-08-20T09:43:00.978Z","caller":"runtime/asm_amd64.s:1700","msg":"Serving metrics on port 61678"}
{"level":"info","ts":"2025-08-20T09:43:00.979Z","caller":"runtime/asm_amd64.s:1700","msg":"Setting up shutdown hook."}
{"level":"debug","ts":"2025-08-20T09:43:03.480Z","caller":"ipamd/ipamd.go:766","msg":"IP stats for Network Card 0 - total IPs: 14, assigned IPs: 0, cooldown IPs: 0"}
{"level":"debug","ts":"2025-08-20T09:43:05.982Z","caller":"ipamd/ipamd.go:769","msg":"Reconciling ENI/IP pool info because time since last 2562047h47m16.854775807s > 1m0s"}
{"level":"debug","ts":"2025-08-20T09:43:05.983Z","caller":"ipamd/ipamd.go:1546","msg":"Total number of interfaces found: 1 "}
{"level":"debug","ts":"2025-08-20T09:43:05.983Z","caller":"awsutils/awsutils.go:604","msg":"Found ENI MAC address: 0a:36:65:b9:6a:ad"}
{"level":"debug","ts":"2025-08-20T09:43:05.985Z","caller":"awsutils/awsutils.go:604","msg":"Found ENI: eni-0c348ad0630d58229, MAC 0a:36:65:b9:6a:ad, device 0"}
{"level":"debug","ts":"2025-08-20T09:43:05.987Z","caller":"awsutils/awsutils.go:604","msg":"Found IPv4 addresses associated with interface. This is not efa-only interface"}
{"level":"debug","ts":"2025-08-20T09:43:05.988Z","caller":"ipamd/ipamd.go:769","msg":"Reconcile existing ENI eni-0c348ad0630d58229 IP pool"}
{"level":"info","ts":"2025-08-20T09:43:05.988Z","caller":"ipamd/ipamd.go:1692","msg":"Reconcile and skip primary IP 192.173.128.237 on ENI eni-0c348ad0630d58229"}
{"level":"info","ts":"2025-08-20T09:43:05.989Z","caller":"ipamd/ipamd.go:1692","msg":"Trying to add 192.173.155.237"}
{"level":"info","ts":"2025-08-20T09:43:05.989Z","caller":"ipamd/ipamd.go:1816","msg":"Adding 192.173.155.237/32 to DS for eni-0c348ad0630d58229"}
{"level":"info","ts":"2025-08-20T09:43:05.989Z","caller":"ipamd/ipamd.go:1816","msg":"IP already in DS"}
{"level":"info","ts":"2025-08-20T09:43:05.989Z","caller":"ipamd/ipamd.go:1692","msg":"Trying to add 192.173.134.40"}
{"level":"info","ts":"2025-08-20T09:43:05.989Z","caller":"ipamd/ipamd.go:1816","msg":"Adding 192.173.134.40/32 to DS for eni-0c348ad0630d58229"}
{"level":"info","ts":"2025-08-20T09:43:05.989Z","caller":"ipamd/ipamd.go:1816","msg":"IP already in DS"}
{"level":"info","ts":"2025-08-20T09:43:05.989Z","caller":"ipamd/ipamd.go:1692","msg":"Trying to add 192.173.155.202"}
{"level":"info","ts":"2025-08-20T09:43:05.989Z","caller":"ipamd/ipamd.go:1816","msg":"Adding 192.173.155.202/32 to DS for eni-0c348ad0630d58229"}
{"level":"info","ts":"2025-08-20T09:43:05.989Z","caller":"ipamd/ipamd.go:1816","msg":"IP already in DS"}
{"level":"info","ts":"2025-08-20T09:43:05.989Z","caller":"ipamd/ipamd.go:1692","msg":"Trying to add 192.173.142.228"}
{"level":"info","ts":"2025-08-20T09:43:05.989Z","caller":"ipamd/ipamd.go:1816","msg":"Adding 192.173.142.228/32 to DS for eni-0c348ad0630d58229"}
{"level":"info","ts":"2025-08-20T09:43:05.989Z","caller":"ipamd/ipamd.go:1816","msg":"IP already in DS"}
{"level":"info","ts":"2025-08-20T09:43:05.989Z","caller":"ipamd/ipamd.go:1692","msg":"Trying to add 192.173.152.103"}
{"level":"info","ts":"2025-08-20T09:43:05.989Z","caller":"ipamd/ipamd.go:1816","msg":"Adding 192.173.152.103/32 to DS for eni-0c348ad0630d58229"}
{"level":"info","ts":"2025-08-20T09:43:05.989Z","caller":"ipamd/ipamd.go:1816","msg":"IP already in DS"}
{"level":"info","ts":"2025-08-20T09:43:05.989Z","caller":"ipamd/ipamd.go:1692","msg":"Trying to add 192.173.159.161"}
{"level":"info","ts":"2025-08-20T09:43:05.989Z","caller":"ipamd/ipamd.go:1816","msg":"Adding 192.173.159.161/32 to DS for eni-0c348ad0630d58229"}
{"level":"info","ts":"2025-08-20T09:43:05.989Z","caller":"ipamd/ipamd.go:1816","msg":"IP already in DS"}
{"level":"info","ts":"2025-08-20T09:43:05.989Z","caller":"ipamd/ipamd.go:1692","msg":"Trying to add 192.173.142.67"}
{"level":"info","ts":"2025-08-20T09:43:05.989Z","caller":"ipamd/ipamd.go:1816","msg":"Adding 192.173.142.67/32 to DS for eni-0c348ad0630d58229"}
{"level":"info","ts":"2025-08-20T09:43:05.989Z","caller":"ipamd/ipamd.go:1816","msg":"IP already in DS"}
{"level":"info","ts":"2025-08-20T09:43:05.989Z","caller":"ipamd/ipamd.go:1692","msg":"Trying to add 192.173.143.3"}
{"level":"info","ts":"2025-08-20T09:43:05.989Z","caller":"ipamd/ipamd.go:1816","msg":"Adding 192.173.143.3/32 to DS for eni-0c348ad0630d58229"}
{"level":"info","ts":"2025-08-20T09:43:05.989Z","caller":"ipamd/ipamd.go:1816","msg":"IP already in DS"}
{"level":"info","ts":"2025-08-20T09:43:05.989Z","caller":"ipamd/ipamd.go:1692","msg":"Trying to add 192.173.139.252"}
{"level":"info","ts":"2025-08-20T09:43:05.989Z","caller":"ipamd/ipamd.go:1816","msg":"Adding 192.173.139.252/32 to DS for eni-0c348ad0630d58229"}
{"level":"info","ts":"2025-08-20T09:43:05.989Z","caller":"ipamd/ipamd.go:1816","msg":"IP already in DS"}
{"level":"info","ts":"2025-08-20T09:43:05.989Z","caller":"ipamd/ipamd.go:1692","msg":"Trying to add 192.173.146.92"}
{"level":"info","ts":"2025-08-20T09:43:05.989Z","caller":"ipamd/ipamd.go:1816","msg":"Adding 192.173.146.92/32 to DS for eni-0c348ad0630d58229"}
{"level":"info","ts":"2025-08-20T09:43:05.989Z","caller":"ipamd/ipamd.go:1816","msg":"IP already in DS"}
{"level":"info","ts":"2025-08-20T09:43:05.989Z","caller":"ipamd/ipamd.go:1692","msg":"Trying to add 192.173.139.95"}
{"level":"info","ts":"2025-08-20T09:43:05.989Z","caller":"ipamd/ipamd.go:1816","msg":"Adding 192.173.139.95/32 to DS for eni-0c348ad0630d58229"}
{"level":"info","ts":"2025-08-20T09:43:05.989Z","caller":"ipamd/ipamd.go:1816","msg":"IP already in DS"}
{"level":"info","ts":"2025-08-20T09:43:05.989Z","caller":"ipamd/ipamd.go:1692","msg":"Trying to add 192.173.139.223"}
{"level":"info","ts":"2025-08-20T09:43:05.989Z","caller":"ipamd/ipamd.go:1816","msg":"Adding 192.173.139.223/32 to DS for eni-0c348ad0630d58229"}
{"level":"info","ts":"2025-08-20T09:43:05.989Z","caller":"ipamd/ipamd.go:1816","msg":"IP already in DS"}
{"level":"info","ts":"2025-08-20T09:43:05.989Z","caller":"ipamd/ipamd.go:1692","msg":"Trying to add 192.173.149.241"}
{"level":"info","ts":"2025-08-20T09:43:05.989Z","caller":"ipamd/ipamd.go:1816","msg":"Adding 192.173.149.241/32 to DS for eni-0c348ad0630d58229"}
{"level":"info","ts":"2025-08-20T09:43:05.989Z","caller":"ipamd/ipamd.go:1816","msg":"IP already in DS"}
{"level":"info","ts":"2025-08-20T09:43:05.989Z","caller":"ipamd/ipamd.go:1692","msg":"Trying to add 192.173.132.113"}
{"level":"info","ts":"2025-08-20T09:43:05.989Z","caller":"ipamd/ipamd.go:1816","msg":"Adding 192.173.132.113/32 to DS for eni-0c348ad0630d58229"}
{"level":"info","ts":"2025-08-20T09:43:05.989Z","caller":"ipamd/ipamd.go:1816","msg":"IP already in DS"}
{"level":"debug","ts":"2025-08-20T09:43:05.989Z","caller":"ipamd/ipamd.go:769","msg":"Reconcile existing ENI eni-0c348ad0630d58229 IP prefixes"}
{"level":"debug","ts":"2025-08-20T09:43:05.989Z","caller":"ipamd/ipamd.go:1618","msg":"Found prefix pool count 0 for eni eni-0c348ad0630d58229\n"}
{"level":"debug","ts":"2025-08-20T09:43:05.989Z","caller":"ipamd/ipamd.go:769","msg":"Successfully Reconciled ENI/IP pool"}
{"level":"debug","ts":"2025-08-20T09:43:05.989Z","caller":"ipamd/ipamd.go:1663","msg":"IP pool stats for network card 0: Total IPs/Prefixes = 14/0, AssignedIPs/CooldownIPs: 0/0, c.maxIPsPerENI = 14"}
{"level":"debug","ts":"2025-08-20T09:43:05.989Z","caller":"ipamd/ipamd.go:769","msg":"Primary IP for ENI eni-0c348ad0630d58229 is 192.173.128.237"}
{"level":"info","ts":"2025-08-20T09:43:08.232Z","caller":"rpc/rpc_grpc.pb.go:117","msg":"Received AddNetwork for NS /var/run/netns/cni-0666cff9-050f-64b9-6d97-411fa9c689d9, Sandbox 10643182d77755847e83a4838abc9b44f15734ee18081a43e04187606b1e3733, ifname eth0"}
{"level":"debug","ts":"2025-08-20T09:43:08.233Z","caller":"rpc/rpc_grpc.pb.go:117","msg":"AddNetworkRequest: K8S_POD_NAME:\"chrome-41e5d6ff-739d-46c8-894b-5c46db33540d-6m2gq\"  K8S_POD_NAMESPACE:\"turboscale-managed-grid-euc1-001\"  K8S_POD_INFRA_CONTAINER_ID:\"10643182d77755847e83a4838abc9b44f15734ee18081a43e04187606b1e3733\"  ContainerID:\"10643182d77755847e83a4838abc9b44f15734ee18081a43e04187606b1e3733\"  IfName:\"eth0\"  NetworkName:\"aws-cni\"  Netns:\"/var/run/netns/cni-0666cff9-050f-64b9-6d97-411fa9c689d9\""}
{"level":"info","ts":"2025-08-20T09:43:08.233Z","caller":"rpc/rpc_grpc.pb.go:117","msg":"Required MultiNIC access false, interfaces required 1"}
{"level":"debug","ts":"2025-08-20T09:43:08.233Z","caller":"datastore/data_store.go:615","msg":"AssignPodIPv4Address: IP address pool stats: total 14, assigned 0"}
{"level":"debug","ts":"2025-08-20T09:43:08.233Z","caller":"datastore/data_store.go:1300","msg":"Found a free IP not in DB - 192.173.142.228"}
{"level":"debug","ts":"2025-08-20T09:43:08.233Z","caller":"datastore/data_store.go:695","msg":"Returning Free IP 192.173.142.228"}
{"level":"debug","ts":"2025-08-20T09:43:08.233Z","caller":"datastore/data_store.go:615","msg":"New IP from CIDR pool- 192.173.142.228"}
{"level":"info","ts":"2025-08-20T09:43:08.233Z","caller":"datastore/data_store.go:722","msg":"assignPodIPAddressUnsafe: Assign IP 192.173.142.228 to sandbox aws-cni/10643182d77755847e83a4838abc9b44f15734ee18081a43e04187606b1e3733/eth0 with metadata {K8SPodNamespace:turboscale-managed-grid-euc1-001 K8SPodName:chrome-41e5d6ff-739d-46c8-894b-5c46db33540d-6m2gq InterfacesCount:1}"}
{"level":"info","ts":"2025-08-20T09:43:08.233Z","caller":"rpc/rpc_grpc.pb.go:117","msg":"Assigned IP from network card: 0 -> IPv4: 192.173.142.228, IPv6: , device number: 0, "}
{"level":"info","ts":"2025-08-20T09:43:08.233Z","caller":"rpc/rpc_grpc.pb.go:117","msg":"Address assigned from datastores:  1"}
{"level":"debug","ts":"2025-08-20T09:43:08.234Z","caller":"rpc/rpc_grpc.pb.go:117","msg":"VPC CIDR 192.173.0.0/16"}
{"level":"info","ts":"2025-08-20T09:43:08.234Z","caller":"rpc/rpc_grpc.pb.go:117","msg":"Send AddNetworkReply: Success: true IPAddr: [IPv4Addr:\"192.173.142.228\"  RouteTableId:1], resp: Success:true  IPAllocationMetadata:{IPv4Addr:\"192.173.142.228\"  RouteTableId:1}  VPCv4CIDRs:\"192.173.0.0/16\"  NetworkPolicyMode:\"standard\", err: <nil>"}
{"level":"debug","ts":"2025-08-20T09:43:08.489Z","caller":"ipamd/ipamd.go:780","msg":"IP pool is too low for Network Card 0: available (13) < ENI target (1) * addrsPerENI (14)"}
{"level":"debug","ts":"2025-08-20T09:43:08.489Z","caller":"ipamd/ipamd.go:2524","msg":"IP pool stats for network card 0: Total IPs/Prefixes = 14/0, AssignedIPs/CooldownIPs: 1/0, c.maxIPsPerENI = 14"}
{"level":"debug","ts":"2025-08-20T09:43:08.489Z","caller":"ipamd/ipamd.go:766","msg":"IP stats for Network Card 0 - total IPs: 14, assigned IPs: 1, cooldown IPs: 0"}
{"level":"debug","ts":"2025-08-20T09:43:08.489Z","caller":"ipamd/ipamd.go:784","msg":"Starting to increase pool size for network card 0"}
{"level":"debug","ts":"2025-08-20T09:43:08.489Z","caller":"ipamd/ipamd.go:937","msg":"Node found \"ip-192-173-128-237.eu-central-1.compute.internal\" - no of taints - 1"}
{"level":"info","ts":"2025-08-20T09:43:08.489Z","caller":"awsutils/awsutils.go:849","msg":"Trying to allocate 14 IP addresses on new ENI"}
{"level":"debug","ts":"2025-08-20T09:43:08.489Z","caller":"awsutils/awsutils.go:849","msg":"PD enabled - false"}
{"level":"info","ts":"2025-08-20T09:43:08.715Z","caller":"awsutils/awsutils.go:849","msg":"Creating ENI with security groups: [sg-03ec51e36413a230a sg-0a0c6162dea848468] in subnet: subnet-05e8a66251f0c700d"}
{"level":"info","ts":"2025-08-20T09:43:09.194Z","caller":"awsutils/awsutils.go:1014","msg":"Created a new ENI: eni-056f5a156ca5435d0"}
{"level":"debug","ts":"2025-08-20T09:43:09.329Z","caller":"awsutils/awsutils.go:895","msg":"Discovered device number is used for network card 0: 0"}
{"level":"debug","ts":"2025-08-20T09:43:09.329Z","caller":"awsutils/awsutils.go:895","msg":"Found a free device number for network card 0 : 1"}
{"level":"info","ts":"2025-08-20T09:43:10.637Z","caller":"ipamd/ipamd.go:1049","msg":"Successfully created and attached a new ENI eni-056f5a156ca5435d0 to instance on network card 0"}
{"level":"debug","ts":"2025-08-20T09:43:10.638Z","caller":"awsutils/awsutils.go:1854","msg":"Total number of interfaces found: 1 "}
{"level":"debug","ts":"2025-08-20T09:43:10.638Z","caller":"awsutils/awsutils.go:604","msg":"Found ENI MAC address: 0a:36:65:b9:6a:ad"}
{"level":"debug","ts":"2025-08-20T09:43:10.640Z","caller":"awsutils/awsutils.go:604","msg":"Found ENI: eni-0c348ad0630d58229, MAC 0a:36:65:b9:6a:ad, device 0"}
{"level":"debug","ts":"2025-08-20T09:43:10.642Z","caller":"awsutils/awsutils.go:604","msg":"Found IPv4 addresses associated with interface. This is not efa-only interface"}
{"level":"debug","ts":"2025-08-20T09:43:10.644Z","caller":"retry/retry.go:70","msg":"Not able to find the right ENI yet (attempt 1/12)"}
{"level":"debug","ts":"2025-08-20T09:43:10.754Z","caller":"awsutils/awsutils.go:1854","msg":"Total number of interfaces found: 1 "}
{"level":"debug","ts":"2025-08-20T09:43:10.754Z","caller":"awsutils/awsutils.go:604","msg":"Found ENI MAC address: 0a:36:65:b9:6a:ad"}
{"level":"debug","ts":"2025-08-20T09:43:10.757Z","caller":"awsutils/awsutils.go:604","msg":"Found ENI: eni-0c348ad0630d58229, MAC 0a:36:65:b9:6a:ad, device 0"}
{"level":"debug","ts":"2025-08-20T09:43:10.759Z","caller":"awsutils/awsutils.go:604","msg":"Found IPv4 addresses associated with interface. This is not efa-only interface"}
{"level":"debug","ts":"2025-08-20T09:43:10.761Z","caller":"retry/retry.go:70","msg":"Not able to find the right ENI yet (attempt 2/12)"}
{"level":"debug","ts":"2025-08-20T09:43:10.969Z","caller":"awsutils/awsutils.go:1854","msg":"Total number of interfaces found: 1 "}
{"level":"debug","ts":"2025-08-20T09:43:10.969Z","caller":"awsutils/awsutils.go:604","msg":"Found ENI MAC address: 0a:36:65:b9:6a:ad"}
{"level":"debug","ts":"2025-08-20T09:43:10.975Z","caller":"awsutils/awsutils.go:604","msg":"Found ENI: eni-0c348ad0630d58229, MAC 0a:36:65:b9:6a:ad, device 0"}
{"level":"debug","ts":"2025-08-20T09:43:10.977Z","caller":"awsutils/awsutils.go:604","msg":"Found IPv4 addresses associated with interface. This is not efa-only interface"}
{"level":"debug","ts":"2025-08-20T09:43:10.981Z","caller":"retry/retry.go:70","msg":"Not able to find the right ENI yet (attempt 3/12)"}
{"level":"debug","ts":"2025-08-20T09:43:11.420Z","caller":"awsutils/awsutils.go:1854","msg":"Total number of interfaces found: 2 "}
{"level":"debug","ts":"2025-08-20T09:43:11.420Z","caller":"awsutils/awsutils.go:604","msg":"Found ENI MAC address: 0a:36:65:b9:6a:ad"}
{"level":"debug","ts":"2025-08-20T09:43:11.423Z","caller":"awsutils/awsutils.go:604","msg":"Found ENI: eni-0c348ad0630d58229, MAC 0a:36:65:b9:6a:ad, device 0"}
{"level":"debug","ts":"2025-08-20T09:43:11.425Z","caller":"awsutils/awsutils.go:604","msg":"Found IPv4 addresses associated with interface. This is not efa-only interface"}
{"level":"debug","ts":"2025-08-20T09:43:11.428Z","caller":"awsutils/awsutils.go:604","msg":"Found ENI MAC address: 0a:88:ea:97:ae:cf"}
{"level":"debug","ts":"2025-08-20T09:43:11.430Z","caller":"awsutils/awsutils.go:604","msg":"Found ENI: eni-056f5a156ca5435d0, MAC 0a:88:ea:97:ae:cf, device 1"}
{"level":"debug","ts":"2025-08-20T09:43:11.432Z","caller":"awsutils/awsutils.go:604","msg":"Found IPv4 addresses associated with interface. This is not efa-only interface"}
{"level":"debug","ts":"2025-08-20T09:43:11.435Z","caller":"retry/retry.go:70","msg":"ENI ID: eni-056f5a156ca5435d0 IP Addr: 15, IPv4Prefixes:- 0, IPv6Prefixes:- 0"}
{"level":"debug","ts":"2025-08-20T09:43:11.435Z","caller":"ipamd/ipamd.go:1250","msg":"DataStore add an ENI eni-056f5a156ca5435d0"}
{"level":"info","ts":"2025-08-20T09:43:11.435Z","caller":"networkutils/network.go:1024","msg":"Setting up network for an ENI with IP address 192.173.141.109, MAC address 0a:88:ea:97:ae:cf, CIDR 192.173.128.0/19, route table 2 and Network Card 0"}
{"level":"debug","ts":"2025-08-20T09:43:11.436Z","caller":"networkutils/network.go:1041","msg":"Found the Link that uses mac address 0a:88:ea:97:ae:cf and its index is 4 (attempt 1/5)"}
{"level":"debug","ts":"2025-08-20T09:43:11.446Z","caller":"networkutils/network.go:1024","msg":"Setting up ENI's primary IP 192.173.141.109"}
{"level":"debug","ts":"2025-08-20T09:43:11.446Z","caller":"networkutils/network.go:1024","msg":"Adding IP address 192.173.141.109/19"}
{"level":"debug","ts":"2025-08-20T09:43:11.446Z","caller":"networkutils/network.go:1024","msg":"Setting up ENI's default gateway 192.173.128.1, table 2, linkIndex 4"}
{"level":"debug","ts":"2025-08-20T09:43:11.447Z","caller":"retry/retry.go:70","msg":"Successfully added/replaced route to be 192.173.128.1/0"}
{"level":"debug","ts":"2025-08-20T09:43:11.447Z","caller":"retry/retry.go:70","msg":"Successfully added/replaced route to be 0.0.0.0/0"}
{"level":"info","ts":"2025-08-20T09:43:11.447Z","caller":"networkutils/network.go:1024","msg":"Adding rule for Primary IP [ip rule 32765: from 192.173.141.109/32 to all table 2 ]"}
{"level":"debug","ts":"2025-08-20T09:43:11.447Z","caller":"networkutils/network.go:1024","msg":"setupENINetwork: rule for Primary IP 192.173.141.109 added"}
{"level":"info","ts":"2025-08-20T09:43:11.447Z","caller":"ipamd/ipamd.go:1069","msg":"Found ENIs having 15 secondary IPs and 0 Prefixes"}
{"level":"info","ts":"2025-08-20T09:43:11.447Z","caller":"ipamd/ipamd.go:1310","msg":"Adding 192.173.137.108/32 to DS for eni-056f5a156ca5435d0"}
{"level":"info","ts":"2025-08-20T09:43:11.447Z","caller":"ipamd/ipamd.go:1310","msg":"Added ENI(eni-056f5a156ca5435d0)'s IP/Prefix 192.173.137.108/32 to datastore"}
{"level":"info","ts":"2025-08-20T09:43:11.447Z","caller":"ipamd/ipamd.go:1310","msg":"Adding 192.173.129.235/32 to DS for eni-056f5a156ca5435d0"}
{"level":"info","ts":"2025-08-20T09:43:11.447Z","caller":"ipamd/ipamd.go:1310","msg":"Added ENI(eni-056f5a156ca5435d0)'s IP/Prefix 192.173.129.235/32 to datastore"}
{"level":"info","ts":"2025-08-20T09:43:11.447Z","caller":"ipamd/ipamd.go:1310","msg":"Adding 192.173.146.235/32 to DS for eni-056f5a156ca5435d0"}
{"level":"info","ts":"2025-08-20T09:43:11.447Z","caller":"ipamd/ipamd.go:1310","msg":"Added ENI(eni-056f5a156ca5435d0)'s IP/Prefix 192.173.146.235/32 to datastore"}
{"level":"info","ts":"2025-08-20T09:43:11.447Z","caller":"ipamd/ipamd.go:1310","msg":"Adding 192.173.128.166/32 to DS for eni-056f5a156ca5435d0"}
{"level":"info","ts":"2025-08-20T09:43:11.447Z","caller":"ipamd/ipamd.go:1310","msg":"Added ENI(eni-056f5a156ca5435d0)'s IP/Prefix 192.173.128.166/32 to datastore"}
{"level":"info","ts":"2025-08-20T09:43:11.447Z","caller":"ipamd/ipamd.go:1310","msg":"Adding 192.173.142.160/32 to DS for eni-056f5a156ca5435d0"}
{"level":"info","ts":"2025-08-20T09:43:11.447Z","caller":"ipamd/ipamd.go:1310","msg":"Added ENI(eni-056f5a156ca5435d0)'s IP/Prefix 192.173.142.160/32 to datastore"}
{"level":"info","ts":"2025-08-20T09:43:11.447Z","caller":"ipamd/ipamd.go:1310","msg":"Adding 192.173.134.163/32 to DS for eni-056f5a156ca5435d0"}
{"level":"info","ts":"2025-08-20T09:43:11.447Z","caller":"ipamd/ipamd.go:1310","msg":"Added ENI(eni-056f5a156ca5435d0)'s IP/Prefix 192.173.134.163/32 to datastore"}
{"level":"info","ts":"2025-08-20T09:43:11.447Z","caller":"ipamd/ipamd.go:1310","msg":"Adding 192.173.157.194/32 to DS for eni-056f5a156ca5435d0"}
{"level":"info","ts":"2025-08-20T09:43:11.447Z","caller":"ipamd/ipamd.go:1310","msg":"Added ENI(eni-056f5a156ca5435d0)'s IP/Prefix 192.173.157.194/32 to datastore"}
{"level":"info","ts":"2025-08-20T09:43:11.447Z","caller":"ipamd/ipamd.go:1310","msg":"Adding 192.173.136.2/32 to DS for eni-056f5a156ca5435d0"}
{"level":"info","ts":"2025-08-20T09:43:11.447Z","caller":"ipamd/ipamd.go:1310","msg":"Added ENI(eni-056f5a156ca5435d0)'s IP/Prefix 192.173.136.2/32 to datastore"}
{"level":"info","ts":"2025-08-20T09:43:11.447Z","caller":"ipamd/ipamd.go:1310","msg":"Adding 192.173.152.157/32 to DS for eni-056f5a156ca5435d0"}
{"level":"info","ts":"2025-08-20T09:43:11.447Z","caller":"ipamd/ipamd.go:1310","msg":"Added ENI(eni-056f5a156ca5435d0)'s IP/Prefix 192.173.152.157/32 to datastore"}
{"level":"info","ts":"2025-08-20T09:43:11.447Z","caller":"ipamd/ipamd.go:1310","msg":"Adding 192.173.142.157/32 to DS for eni-056f5a156ca5435d0"}
{"level":"info","ts":"2025-08-20T09:43:11.447Z","caller":"ipamd/ipamd.go:1310","msg":"Added ENI(eni-056f5a156ca5435d0)'s IP/Prefix 192.173.142.157/32 to datastore"}
{"level":"info","ts":"2025-08-20T09:43:11.447Z","caller":"ipamd/ipamd.go:1310","msg":"Adding 192.173.138.184/32 to DS for eni-056f5a156ca5435d0"}
{"level":"info","ts":"2025-08-20T09:43:11.447Z","caller":"ipamd/ipamd.go:1310","msg":"Added ENI(eni-056f5a156ca5435d0)'s IP/Prefix 192.173.138.184/32 to datastore"}
{"level":"info","ts":"2025-08-20T09:43:11.447Z","caller":"ipamd/ipamd.go:1310","msg":"Adding 192.173.139.118/32 to DS for eni-056f5a156ca5435d0"}
{"level":"info","ts":"2025-08-20T09:43:11.447Z","caller":"ipamd/ipamd.go:1310","msg":"Added ENI(eni-056f5a156ca5435d0)'s IP/Prefix 192.173.139.118/32 to datastore"}
{"level":"info","ts":"2025-08-20T09:43:11.447Z","caller":"ipamd/ipamd.go:1310","msg":"Adding 192.173.137.112/32 to DS for eni-056f5a156ca5435d0"}
{"level":"info","ts":"2025-08-20T09:43:11.447Z","caller":"ipamd/ipamd.go:1310","msg":"Added ENI(eni-056f5a156ca5435d0)'s IP/Prefix 192.173.137.112/32 to datastore"}
{"level":"info","ts":"2025-08-20T09:43:11.447Z","caller":"ipamd/ipamd.go:1310","msg":"Adding 192.173.153.210/32 to DS for eni-056f5a156ca5435d0"}
{"level":"info","ts":"2025-08-20T09:43:11.447Z","caller":"ipamd/ipamd.go:1310","msg":"Added ENI(eni-056f5a156ca5435d0)'s IP/Prefix 192.173.153.210/32 to datastore"}
{"level":"debug","ts":"2025-08-20T09:43:11.447Z","caller":"ipamd/ipamd.go:1317","msg":"IP pool stats for network card 0: Total IPs/Prefixes = 28/0, AssignedIPs/CooldownIPs: 1/0, c.maxIPsPerENI = 14"}
{"level":"debug","ts":"2025-08-20T09:43:11.447Z","caller":"ipamd/ipamd.go:1338","msg":"IP pool stats for network card 0: Total IPs/Prefixes = 28/0, AssignedIPs/CooldownIPs: 1/0, c.maxIPsPerENI = 14"}
{"level":"debug","ts":"2025-08-20T09:43:11.447Z","caller":"ipamd/ipamd.go:1025","msg":"IP pool stats for network card 0: Total IPs/Prefixes = 28/0, AssignedIPs/CooldownIPs: 1/0, c.maxIPsPerENI = 14"}
{"level":"debug","ts":"2025-08-20T09:43:16.448Z","caller":"ipamd/ipamd.go:766","msg":"IP stats for Network Card 0 - total IPs: 28, assigned IPs: 1, cooldown IPs: 0"}
{"level":"debug","ts":"2025-08-20T09:43:21.452Z","caller":"ipamd/ipamd.go:766","msg":"IP stats for Network Card 0 - total IPs: 28, assigned IPs: 1, cooldown IPs: 0"}
{"level":"debug","ts":"2025-08-20T09:43:26.455Z","caller":"ipamd/ipamd.go:766","msg":"IP stats for Network Card 0 - total IPs: 28, assigned IPs: 1, cooldown IPs: 0"}
{"level":"debug","ts":"2025-08-20T09:43:31.457Z","caller":"ipamd/ipamd.go:766","msg":"IP stats for Network Card 0 - total IPs: 28, assigned IPs: 1, cooldown IPs: 0"}
{"level":"debug","ts":"2025-08-20T09:43:36.460Z","caller":"ipamd/ipamd.go:766","msg":"IP stats for Network Card 0 - total IPs: 28, assigned IPs: 1, cooldown IPs: 0"}
{"level":"debug","ts":"2025-08-20T09:43:41.462Z","caller":"ipamd/ipamd.go:766","msg":"IP stats for Network Card 0 - total IPs: 28, assigned IPs: 1, cooldown IPs: 0"}
{"level":"debug","ts":"2025-08-20T09:43:46.464Z","caller":"ipamd/ipamd.go:766","msg":"IP stats for Network Card 0 - total IPs: 28, assigned IPs: 1, cooldown IPs: 0"}
[root@ip-192-173-128-237 ec2-user]#

[jaydeokar]

In this case, it seems like the RPC server was ready within 1 sec. Does the pod get scheduled even before the aws-node start time ?
Are these logs from the node where you see the issue ? Because it does seem the RPC handler was active and no errors.

{"level":"info","ts":"2025-08-20T09:42:59.766Z","caller":"logger/logger.go:52","msg":"Constructed new logger instance"}
{"level":"info","ts":"2025-08-20T09:43:00.978Z","caller":"aws-k8s-agent/main.go:178","msg":"Serving RPC Handler version  on 127.0.0.1:50051"}

[nikhlagrwl]

I used the below script to collect logs from the ec2 node -
curl -O https://amazon-eks.s3.amazonaws.com/support/log-collector-script/linux/eks-log-collector.sh; sudo bash eks-log-collector.sh

Below is the observation -
The ec2 instance came up at time 2025-08-26T00:19:06.145346379Z, below are the containerd logs -

Aug 26 00:19:05 ip-192-168-149-247.ec2.internal systemd[1]: Starting containerd container runtime...
Aug 26 00:19:06 ip-192-168-149-247.ec2.internal containerd[2592]: time="2025-08-26T00:19:06.145346379Z" level=info msg="starting containerd" revision=05044ec0a9a75232cad458027ca83437aae3f4da version=1.7.27

But in the ipamd.log file the first log appears at 2025-08-26T00:20:21.629Z, below is the log line -

{"level":"info","ts":"2025-08-26T00:20:21.629Z","caller":"logger/logger.go:52","msg":"Constructed new logger instance"}
{"level":"info","ts":"2025-08-26T00:20:21.634Z","caller":"networkutils/network.go:143","msg":"Initialized new logger as an existing instance was not found"}
{"level":"info","ts":"2025-08-26T00:20:21.732Z","caller":"aws-k8s-agent/main.go:42","msg":"Starting L-IPAMD ..."}
{"level":"info","ts":"2025-08-26T00:20:21.762Z","caller":"aws-k8s-agent/main.go:53","msg":"Testing communication with server"}
{"level":"info","ts":"2025-08-26T00:20:21.777Z","caller":"wait/loop.go:53","msg":"Successful communication with the Cluster! Cluster Version is: v1.31. git version: v1.31.10-eks-931bdca. git tree state: clean. commit: a058d32065a4507f77fbdc62157574cc86c7fca7. platform: linux/amd64"}
{"level":"debug","ts":"2025-08-26T00:20:21.883Z","caller":"eventrecorder/eventrecorder.go:68","msg":"Node found aws-node-kz4mj - labels - 5"}
{"level":"warn","ts":"2025-08-26T00:20:21.883Z","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":"2025-08-26T00:20:21.886Z","caller":"ipamd/ipamd.go:346","msg":"Discovered region: us-east-1"}
{"level":"info","ts":"2025-08-26T00:20:21.886Z","caller":"ipamd/ipamd.go:346","msg":"Custom networking enabled false"}
{"level":"info","ts":"2025-08-26T00:20:21.886Z","caller":"ipamd/ipamd.go:346","msg":"Subnet discovery enabled true"}
{"level":"debug","ts":"2025-08-26T00:20:21.886Z","caller":"awsutils/awsutils.go:385","msg":"Found availability zone: us-east-1c "}
{"level":"debug","ts":"2025-08-26T00:20:21.887Z","caller":"awsutils/awsutils.go:385","msg":"Discovered the instance primary IPv4 address: 192.168.149.247"}

This is just a scenario of one machine, i have seen delays worth 3-4 mins as well.

[anikin-devops]

We are facing the same issue I guess.

Our error:
Failed to create pod sandbox: rpc error: code = Unknown desc = failed to setup network for sandbox "c78cf6b9afa316b358c5bcd06ec6df37b03743ddb97ca951b6cfd439f531d971": plugin type="aws-cni" name="aws-cni" failed (add): add cmd: failed to assign an IP address to container

I have found out that it is related some how to max-pods option.
We are facing mentioned error when using ENABLE_PREFIX_DELEGATION = "true" variable. However when its in default value (false), seems like the error vanishes.
ENABLE_PREFIX_DELEGATION suppose to provide max-pods option for kubelet. For example when you want to use custom pod limit for your worker nodes.

Kubernetes version = 1.33
vpc-cni version = v1.20.0-eksbuild.1