[EKS][MULTUS][CNI]: error adding container to network "ipvlan-multus"

I have followed document[1],[2] to create multus in eks.
[1]: https://aws.amazon.com/blogs/containers/amazon-eks-now-supports-multus-cni/
[2]: https://github.com/aws-samples/eks-automated-ipmgmt-multus-pods#option-2-sidecar-ip-management-solution

When I have installed it, the application pods are running fine but when the nodes are terminated and new nodes come up the following error is seen from the application logs and the busy-box pods are in container creating state. After few hours the application pods automatically move to running state.

" Warning FailedCreatePodSandBox 17m kubelet Failed to create pod sandbox: rpc error: code = Unknown desc = failed to set up sandbox container "ff692dac4ee9777cbb66e6f74cf6cbc26298c8d42663c475d5ecb4468d5f063f" network for pod "busybox-deployment-7c868c5b79-nngrp": networkPlugin cni failed to set up pod "busybox-deployment-7c868c5b79-nngrp_multus" network: [multus/busybox-deployment-7c868c5b79-nngrp:ipvlan-multus]: error adding container to network "ipvlan-multus": error at storage engine: Could not allocate IP in range: ip: 100.76.215.210 / - 100.76.215.213 / range: net.IPNet{IP:net.IP{0x64, 0x4c, 0xd7, 0xd0}, "

The issue was solved automatically after few hours and the application pods are running fine.

From the kublet logs I could see "Error adding pod to network" err="[multus/busybox-deployment-7c868c5b79-2nxrw:ipvlan-multus]: error adding container to network "ipvlan-multus": error at storage engine: Could not allocate IP in range: ip: 100.76.215.210 / - 100.76.215.213 / range: net.IPNet{IP:net.IP{0x64, 0x4c, 0xd7, 0xd0}, Mask:net.IPMask{0xff, 0xff, 0xff, 0xf0}}" pod="multus/busybox-deployment-7c868c5b79-2nxrw" podSandboxID={Type:docker ID:1d9011e1af37d97238652c377fb7b93908d7cf6f45b1d191fd7bb600728115b1} podNetnsPath="/proc/13226/ns/net" networkType="multus" networkName="multus-cni-network"

Dec 30 03:55:25 ip-100-76-214-149.ec2.internal kubelet[4885]: 2022-12-30T03:55:25Z [debug] Used defaults from parsed flat file config @ /etc/cni/net.d/whereabouts.d/whereabouts.conf
Dec 30 03:55:25 ip-100-76-214-149.ec2.internal kubelet[4885]: 2022-12-30T03:55:25Z [debug] DEL - IPAM configuration successfully read: {Name:ipvlan-multus Type:whereabouts Routes:[{Dst:{IP:0.0.0.0 Mask:00000000} GW:}] Addresses:[] IPRanges:[{OmitRanges:[] Range:100.76.215.208/28 RangeStart:100.76.215.210 RangeEnd:100.76.215.213}] OmitRanges:[] DNS:{Nameservers:[] Domain: Search:[] Options:[]} Range: RangeStart: RangeEnd: GatewayStr:100.76.215.209 LeaderLeaseDuration:1500 LeaderRenewDeadline:1000 LeaderRetryPeriod:500 LogFile:/tmp/whereabouts.log LogLevel:debug ReconcilerCronExpression:30 4 * * * OverlappingRanges:true SleepForRace:0 Gateway:100.76.215.209 Kubernetes:{KubeConfigPath:/etc/cni/net.d/whereabouts.d/whereabouts.kubeconfig K8sAPIRoot:} ConfigurationPath: PodName:busybox-deployment-7c868c5b79-2nxrw PodNamespace:multus}
Dec 30 03:55:25 ip-100-76-214-149.ec2.internal kubelet[4885]: 2022-12-30T03:55:25Z [debug] Beginning delete for ContainerID: 1d9011e1af37d97238652c377fb7b93908d7cf6f45b1d191fd7bb600728115b1
Dec 30 03:55:25 ip-100-76-214-149.ec2.internal kubelet[4885]: 2022-12-30T03:55:25Z [debug] Started leader election
Dec 30 03:55:25 ip-100-76-214-149.ec2.internal kubelet[4885]: I1230 03:55:25.431982 13411 leaderelection.go:248] attempting to acquire leader lease kube-system/whereabouts...
Dec 30 03:55:25 ip-100-76-214-149.ec2.internal kubelet[4885]: I1230 03:55:25.453393 13411 leaderelection.go:258] successfully acquired lease kube-system/whereabouts
Dec 30 03:55:25 ip-100-76-214-149.ec2.internal kubelet[4885]: 2022-12-30T03:55:25Z [debug] OnStartedLeading() called
Dec 30 03:55:25 ip-100-76-214-149.ec2.internal kubelet[4885]: 2022-12-30T03:55:25Z [debug] Elected as leader, do processing
Dec 30 03:55:25 ip-100-76-214-149.ec2.internal kubelet[4885]: 2022-12-30T03:55:25Z [debug] IPManagement -- mode: 1 / containerID: 1d9011e1af37d97238652c377fb7b93908d7cf6f45b1d191fd7bb600728115b1 / podRef: multus/busybox-deployment-7c868c5b79-2nxrw
Dec 30 03:55:25 ip-100-76-214-149.ec2.internal kubelet[4885]: 2022-12-30T03:55:25Z [error] Error deallocating IP: did not find reserved IP for container 1d9011e1af37d97238652c377fb7b93908d7cf6f45b1d191fd7bb600728115b1
Dec 30 03:55:25 ip-100-76-214-149.ec2.internal kubelet[4885]: E1230 03:55:25.463593 13411 leaderelection.go:367] Failed to update lock: Put "[https://10.100.0.1:443/apis/coordination.k8s.io/v1/namespaces/kube-system/leases/whereabouts](https://10.100.0.1/apis/coordination.k8s.io/v1/namespaces/kube-system/leases/whereabouts)": context canceled
Dec 30 03:55:25 ip-100-76-214-149.ec2.internal kubelet[4885]: I1230 03:55:25.463629 13411 leaderelection.go:283] failed to renew lease kube-system/whereabouts: timed out waiting for the condition
Dec 30 03:55:25 ip-100-76-214-149.ec2.internal kubelet[4885]: E1230 03:55:25.473011 13411 leaderelection.go:306] Failed to release lock: Operation cannot be fulfilled on leases.coordination.k8s.io "whereabouts": the object has been modified; please apply your changes to the latest version and try again
Dec 30 03:55:25 ip-100-76-214-149.ec2.internal kubelet[4885]: 2022-12-30T03:55:25Z [debug] OnStoppedLeading() called
Dec 30 03:55:25 ip-100-76-214-149.ec2.internal kubelet[4885]: 2022-12-30T03:55:25Z [debug] Finished leader election
Dec 30 03:55:25 ip-100-76-214-149.ec2.internal kubelet[4885]: 2022-12-30T03:55:25Z [debug] IPManagement: [], did not find reserved IP for container 1d9011e1af37d97238652c377fb7b93908d7cf6f45b1d191fd7bb600728115b1
Dec 30 03:55:25 ip-100-76-214-149.ec2.internal kubelet[4885]: 2022-12-30T03:55:25Z [verbose] WARNING: Problem deallocating IP: did not find reserved IP for container

In the multus logs :
2022-12-30T03:55:25Z [error] [multus/busybox-deployment-7c868c5b79-2nxrw:ipvlan-multus]: error adding container to network "ipvlan-multus": error at storage engine: Could not allocate IP in range: ip: 100.76.215.210 / - 100.76.215.213 / range: net.IPNet{IP:net.IP{0x64, 0x4c, 0xd7, 0xd0}, Mask:net.IPMask{0xff, 0xff, 0xff, 0xf0}}

Ipam-d Logs:
{"level":"info","ts":"2022-12-30T03:55:25.158Z","caller":"rpc/rpc.pb.go:713","msg":"Received AddNetwork for NS /proc/13226/ns/net, Sandbox 1d9011e1af37d97238652c377fb7b93908d7cf6f45b1d191fd7bb600728115b1, ifname eth0"}
{"level":"debug","ts":"2022-12-30T03:55:25.158Z","caller":"rpc/rpc.pb.go:713","msg":"AddNetworkRequest: K8S_POD_NAME:"busybox-deployment-7c868c5b79-2nxrw" K8S_POD_NAMESPACE:"multus" K8S_POD_INFRA_CONTAINER_ID:"1d9011e1af37d97238652c377fb7b93908d7cf6f45b1d191fd7bb600728115b1" ContainerID:"1d9011e1af37d97238652c377fb7b93908d7cf6f45b1d191fd7bb600728115b1" IfName:"eth0" NetworkName:"aws-cni" Netns:"/proc/13226/ns/net""}
{"level":"debug","ts":"2022-12-30T03:55:25.158Z","caller":"datastore/data_store.go:680","msg":"AssignIPv4Address: IP address pool stats: total: 58, assigned 3"}
{"level":"debug","ts":"2022-12-30T03:55:25.158Z","caller":"datastore/data_store.go:1338","msg":"Found a free IP not in DB - 100.76.214.49"}
{"level":"debug","ts":"2022-12-30T03:55:25.158Z","caller":"datastore/data_store.go:757","msg":"Returning Free IP 100.76.214.49"}
{"level":"debug","ts":"2022-12-30T03:55:25.158Z","caller":"datastore/data_store.go:680","msg":"New IP from CIDR pool- 100.76.214.49"}
{"level":"info","ts":"2022-12-30T03:55:25.158Z","caller":"datastore/data_store.go:784","msg":"AssignPodIPv4Address: Assign IP 100.76.214.49 to sandbox aws-cni/1d9011e1af37d97238652c377fb7b93908d7cf6f45b1d191fd7bb600728115b1/eth0"}
{"level":"debug","ts":"2022-12-30T03:55:25.159Z","caller":"rpc/rpc.pb.go:713","msg":"VPC CIDR 100.76.214.0/23"}
{"level":"debug","ts":"2022-12-30T03:55:25.159Z","caller":"rpc/rpc.pb.go:713","msg":"VPC CIDR 100.76.224.64/27"}
{"level":"info","ts":"2022-12-30T03:55:25.159Z","caller":"rpc/rpc.pb.go:713","msg":"Send AddNetworkReply: IPv4Addr 100.76.214.49, IPv6Addr: , DeviceNumber: 0, err: "}
{"level":"info","ts":"2022-12-30T03:55:25.369Z","caller":"rpc/rpc.pb.go:731","msg":"Received DelNetwork for Sandbox 1d9011e1af37d97238652c377fb7b93908d7cf6f45b1d191fd7bb600728115b1"}
{"level":"debug","ts":"2022-12-30T03:55:25.369Z","caller":"rpc/rpc.pb.go:731","msg":"DelNetworkRequest: K8S_POD_NAME:"busybox-deployment-7c868c5b79-2nxrw" K8S_POD_NAMESPACE:"multus" K8S_POD_INFRA_CONTAINER_ID:"1d9011e1af37d97238652c377fb7b93908d7cf6f45b1d191fd7bb600728115b1" Reason:"PodDeleted" ContainerID:"1d9011e1af37d97238652c377fb7b93908d7cf6f45b1d191fd7bb600728115b1" IfName:"eth0" NetworkName:"aws-cni""}
{"level":"debug","ts":"2022-12-30T03:55:25.369Z","caller":"ipamd/rpc_handler.go:220","msg":"UnassignPodIPAddress: IP address pool stats: total:58, assigned 4, sandbox aws-cni/1d9011e1af37d97238652c377fb7b93908d7cf6f45b1d191fd7bb600728115b1/eth0"}
{"level":"info","ts":"2022-12-30T03:55:25.369Z","caller":"datastore/data_store.go:1157","msg":"UnAssignPodIPAddress: Unassign IP 100.76.214.49 from sandbox aws-cni/1d9011e1af37d97238652c377fb7b93908d7cf6f45b1d191fd7bb600728115b1/eth0"}
{"level":"info","ts":"2022-12-30T03:55:25.369Z","caller":"ipamd/rpc_handler.go:220","msg":"UnassignPodIPAddress: sandbox aws-cni/1d9011e1af37d97238652c377fb7b93908d7cf6f45b1d191fd7bb600728115b1/eth0's ipAddr 100.76.214.49, DeviceNumber 0"}
{"level":"info","ts":"2022-12-30T03:55:25.369Z","caller":"rpc/rpc.pb.go:731","msg":"Send DelNetworkReply: IPv4Addr 100.76.214.49, DeviceNumber: 0, err: "}
{"level":"info","ts":"2022-12-30T03:55:25.486Z","caller":"rpc/rpc.pb.go:731","msg":"Received DelNetwork for Sandbox 1d9011e1af37d97238652c377fb7b93908d7cf6f45b1d191fd7bb600728115b1"}
{"level":"debug","ts":"2022-12-30T03:55:25.486Z","caller":"rpc/rpc.pb.go:731","msg":"DelNetworkRequest: K8S_POD_NAME:"busybox-deployment-7c868c5b79-2nxrw" K8S_POD_NAMESPACE:"multus" K8S_POD_INFRA_CONTAINER_ID:"1d9011e1af37d97238652c377fb7b93908d7cf6f45b1d191fd7bb600728115b1" Reason:"PodDeleted" ContainerID:"1d9011e1af37d97238652c377fb7b93908d7cf6f45b1d191fd7bb600728115b1" IfName:"eth0" NetworkName:"aws-cni""}
{"level":"debug","ts":"2022-12-30T03:55:25.486Z","caller":"ipamd/rpc_handler.go:220","msg":"UnassignPodIPAddress: IP address pool stats: total:58, assigned 3, sandbox aws-cni/1d9011e1af37d97238652c377fb7b93908d7cf6f45b1d191fd7bb600728115b1/eth0"}
{"level":"debug","ts":"2022-12-30T03:55:25.486Z","caller":"ipamd/rpc_handler.go:220","msg":"UnassignPodIPAddress: Failed to find IPAM entry under full key, trying CRI-migrated version"}
{"level":"warn","ts":"2022-12-30T03:55:25.486Z","caller":"ipamd/rpc_handler.go:220","msg":"UnassignPodIPAddress: Failed to find sandbox _migrated-from-cri/1d9011e1af37d97238652c377fb7b93908d7cf6f45b1d191fd7bb600728115b1/unknown"}