amazon-vpc-cni-k8s icon indicating copy to clipboard operation
amazon-vpc-cni-k8s copied to clipboard

Published 20 hours ago • verified publisher icon aws

Non fatal but persistent warning: "Failed to create pod sandbox ... failed to assign an IP address to container."

Open taer opened this issue 1 year ago • 3 comments
trafficstars

Every pod that we startup gets this one Warning level event one time.

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

Here are all the events for that pod.

6m2s                       Normal    Scheduled                Pod/engine-content-cars-etl-cron-short-28809865-2dhw7   Successfully assigned content-api/engine-content-cars-etl-cron-short-28809865-2dhw7 to ip-172-21-171-235.ec2.internal
6m2s                       Normal    SecurityGroupRequested   Pod/engine-content-cars-etl-cron-short-28809865-2dhw7   Pod will get the following Security Groups [sg-040fe161363814f9b sg-04df5482042d9290e]
6m2s                       Warning   FailedCreatePodSandBox   Pod/engine-content-cars-etl-cron-short-28809865-2dhw7   Failed to create pod sandbox: rpc error: code = Unknown desc = failed to setup network for sandbox "8fd6567d166d83aa85a4ee6dc055876106e2abb8b4678180607ea5800dec5001": plugin type="aws-cni" name="aws-cni" failed (add): add cmd: failed to assign an IP address to container
6m2s                       Normal    SuccessfulCreate         Job/engine-content-cars-etl-cron-short-28809865         Created pod: engine-content-cars-etl-cron-short-28809865-2dhw7
6m1s                       Normal    ResourceAllocated        Pod/engine-content-cars-etl-cron-short-28809865-2dhw7   Allocated [{"eniId":"eni-0f225e0d5531c7cce","ifAddress":"0e:f1:ce:61:9c:d7","privateIp":"172.21.189.168","ipv6Addr":"","vlanId":2,"subnetCidr":"172.21.160.0/19","subnetV6Cidr":""}] to the pod
6m1s                       Normal    Pulled                   Pod/engine-content-cars-etl-cron-short-28809865-2dhw7   Container image "docker.io/istio/proxyv2:1.22.3" already present on machine
6m1s                       Normal    Created                  Pod/engine-content-cars-etl-cron-short-28809865-2dhw7   Created container istio-validation
6m1s                       Normal    Started                  Pod/engine-content-cars-etl-cron-short-28809865-2dhw7   Started container istio-validation
6m                         Normal    Created                  Pod/engine-content-cars-etl-cron-short-28809865-2dhw7   Created container istio-proxy
6m                         Normal    Started                  Pod/engine-content-cars-etl-cron-short-28809865-2dhw7   Started container istio-proxy
6m                         Normal    Pulled                   Pod/engine-content-cars-etl-cron-short-28809865-2dhw7   Container image "docker.io/istio/proxyv2:1.22.3" already present on machine
5m58s                      Normal    Pulled                   Pod/engine-content-cars-etl-cron-short-28809865-2dhw7   Container image "534287151633.dkr.ecr.us-east-1.amazonaws.com/engine-content-etl:0.2.4" already present on machine
5m58s                      Normal    Created                  Pod/engine-content-cars-etl-cron-short-28809865-2dhw7   Created container engine-content-cars-etl-cron-short
5m58s                      Normal    Started                  Pod/engine-content-cars-etl-cron-short-28809865-2dhw7   Started container engine-content-cars-etl-cron-short
5m41s                      Normal    Killing                  Pod/engine-content-cars-etl-cron-short-28809865-2dhw7   Stopping container istio-proxy

To date, this has seems just like noise. But it happens whether this is a pod on a new host or existing.

Config params for aws-cni are

{
        init = {
          env = {
            DISABLE_TCP_EARLY_DEMUX = "true"
          }
        }
        env = {
          # Reference docs https://docs.aws.amazon.com/eks/latest/userguide/cni-increase-ip-addresses.html
          ENABLE_PREFIX_DELEGATION          = "true"
          WARM_PREFIX_TARGET                = "1"
          ENABLE_POD_ENI                    = "true",
          POD_SECURITY_GROUP_ENFORCING_MODE = "standard",
          AWS_VPC_K8S_CNI_EXTERNALSNAT      = "true"
        }
      }

This is on a 1.30 EKS cluster. CNI image is: 602401143452.dkr.ecr.us-east-1.amazonaws.com/amazon-k8s-cni:v1.18.3-eksbuild.3

Again, this seems non-fatal, but I'd love to eliminate warnings from my clusters events if possible

Thanks

taer avatar Oct 10 '24 20:10 taer

It seems to only be on the pods with security groups assigned via POD_ENI. They do not have this warning when there are no sec groups assigned

taer avatar Oct 10 '24 21:10 taer

digging into the cni logs, I get this.

For this warning failed to setup network for sandbox "d78e79e2f3c65976885cf228da933b8d35471497f1bdfacbff8d246, in the logs, I see the following in plugin.log

{"level":"info","ts":"2024-10-10T21:51:34.284Z","caller":"routed-eni-cni-plugin/cni.go:119","msg":"Constructed new logger instance"}
{"level":"info","ts":"2024-10-10T21:51:34.284Z","caller":"routed-eni-cni-plugin/cni.go:128","msg":"Received CNI add request: ContainerID(d78e79e2f3c65976885cf228da933b8d35471497f1bdfacbff8d24644f175222) Netns(/var/run/netns/cni-a1e04c19-447f-a214-5ccf-76f51a955e74) IfName(eth0) Args(K8S_POD_NAMESPACE=booking-cars;K8S_POD_NAME=jobs-79c5bb8c56-l7mfw;K8S_POD_INFRA_CONTAINER_ID=d78e79e2f3c65976885cf228da933b8d35471497f1bdfacbff8d24644f175222;K8S_POD_UID=a94b7427-7856-4dc4-844c-8a426631e99d;IgnoreUnknown=1) 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\":\"standard\",\"type\":\"aws-cni\",\"vethPrefix\":\"eni\"})"}
{"level":"debug","ts":"2024-10-10T21:51:34.284Z","caller":"routed-eni-cni-plugin/cni.go:128","msg":"Prev Result: <nil>\n"}
{"level":"debug","ts":"2024-10-10T21:51:34.284Z","caller":"routed-eni-cni-plugin/cni.go:128","msg":"MTU value set is 9001:"}
{"level":"error","ts":"2024-10-10T21:51:34.301Z","caller":"routed-eni-cni-plugin/cni.go:128","msg":"Failed to assign an IP address to container d78e79e2f3c65976885cf228da933b8d35471497f1bdfacbff8d24644f175222"}
{"level":"info","ts":"2024-10-10T21:51:34.337Z","caller":"routed-eni-cni-plugin/cni.go:119","msg":"Constructed new logger instance"}
{"level":"debug","ts":"2024-10-10T21:51:34.337Z","caller":"routed-eni-cni-plugin/cni.go:314","msg":"Prev Result: <nil>\n"}
{"level":"info","ts":"2024-10-10T21:51:34.337Z","caller":"routed-eni-cni-plugin/cni.go:314","msg":"Received CNI del request: ContainerID(d78e79e2f3c65976885cf228da933b8d35471497f1bdfacbff8d24644f175222) Netns(/var/run/netns/cni-a1e04c19-447f-a214-5ccf-76f51a955e74) IfName(eth0) Args(IgnoreUnknown=1;K8S_POD_NAMESPACE=booking-cars;K8S_POD_NAME=jobs-79c5bb8c56-l7mfw;K8S_POD_INFRA_CONTAINER_ID=d78e79e2f3c65976885cf228da933b8d35471497f1bdfacbff8d24644f175222;K8S_POD_UID=a94b7427-7856-4dc4-844c-8a426631e99d) 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\":\"standard\",\"type\":\"aws-cni\",\"vethPrefix\":\"eni\"})"}
{"level":"info","ts":"2024-10-10T21:51:34.340Z","caller":"routed-eni-cni-plugin/cni.go:314","msg":"Container d78e79e2f3c65976885cf228da933b8d35471497f1bdfacbff8d24644f175222 not found"}
{"level":"info","ts":"2024-10-10T21:51:34.993Z","caller":"routed-eni-cni-plugin/cni.go:119","msg":"Constructed new logger instance"}
{"level":"info","ts":"2024-10-10T21:51:34.993Z","caller":"routed-eni-cni-plugin/cni.go:128","msg":"Received CNI add request: ContainerID(6f8cbcf57411933b3f53a986a6cf91dbe2f2e6120012c96ee7447bcc0f1c4caa) Netns(/var/run/netns/cni-cfaf09cc-342d-794e-978a-c7afa071a0e2) IfName(eth0) Args(K8S_POD_UID=a94b7427-7856-4dc4-844c-8a426631e99d;IgnoreUnknown=1;K8S_POD_NAMESPACE=booking-cars;K8S_POD_NAME=jobs-79c5bb8c56-l7mfw;K8S_POD_INFRA_CONTAINER_ID=6f8cbcf57411933b3f53a986a6cf91dbe2f2e6120012c96ee7447bcc0f1c4caa) 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\":\"standard\",\"type\":\"aws-cni\",\"vethPrefix\":\"eni\"})"}
{"level":"debug","ts":"2024-10-10T21:51:34.993Z","caller":"routed-eni-cni-plugin/cni.go:128","msg":"Prev Result: <nil>\n"}
{"level":"debug","ts":"2024-10-10T21:51:34.993Z","caller":"routed-eni-cni-plugin/cni.go:128","msg":"MTU value set is 9001:"}
{"level":"info","ts":"2024-10-10T21:51:35.002Z","caller":"routed-eni-cni-plugin/cni.go:128","msg":"Received add network response from ipamd for container 6f8cbcf57411933b3f53a986a6cf91dbe2f2e6120012c96ee7447bcc0f1c4caa interface eth0: Success:true IPv4Addr:\"172.21.149.56\" DeviceNumber:-1 UseExternalSNAT:true VPCv4CIDRs:\"172.21.0.0/16\" PodVlanId:2 PodENIMAC:\"0a:ff:c4:52:0f:4d\" PodENISubnetGW:\"172.21.128.1\" ParentIfIndex:7 NetworkPolicyMode:\"standard\""}
{"level":"debug","ts":"2024-10-10T21:51:35.002Z","caller":"routed-eni-cni-plugin/cni.go:221","msg":"SetupBranchENIPodNetwork: hostVethName=eni83f7dc8eecd, contVethName=eth0, netnsPath=/var/run/netns/cni-cfaf09cc-342d-794e-978a-c7afa071a0e2, v4Addr=172.21.149.56/32, v6Addr=<nil>, vlanID=2, eniMAC=0a:ff:c4:52:0f:4d, subnetGW=172.21.128.1, parentIfIndex=7, mtu=9001, podSGEnforcingMode=standard"}
{"level":"debug","ts":"2024-10-10T21:51:35.027Z","caller":"driver/driver.go:280","msg":"Successfully set IPv6 sysctls on hostVeth eni83f7dc8eecd"}
{"level":"debug","ts":"2024-10-10T21:51:35.031Z","caller":"driver/driver.go:319","msg":"Successfully setup container route, containerAddr=172.21.149.56/32, hostVeth=eni83f7dc8eecd, rtTable=main"}
{"level":"debug","ts":"2024-10-10T21:51:35.031Z","caller":"driver/driver.go:319","msg":"Successfully setup toContainer rule, containerAddr=172.21.149.56/32, rtTable=main"}
{"level":"debug","ts":"2024-10-10T21:51:35.031Z","caller":"driver/driver.go:319","msg":"Successfully setup fromContainer rule, containerAddr=172.21.149.56/32, rtTable=102"}
{"level":"debug","ts":"2024-10-10T21:51:35.031Z","caller":"routed-eni-cni-plugin/cni.go:128","msg":"Using dummy interface: {Name:dummy83f7dc8eecd Mac:2 Mtu:0 Sandbox: SocketPath: PciID:}"}

however, that containerID doesn't exist anymore. immediately after, we get this log that looks more successful

{"level":"info","ts":"2024-10-10T21:51:34.993Z","caller":"routed-eni-cni-plugin/cni.go:119","msg":"Constructed new logger instance"}
{"level":"info","ts":"2024-10-10T21:51:34.993Z","caller":"routed-eni-cni-plugin/cni.go:128","msg":"Received CNI add request: ContainerID(6f8cbcf57411933b3f53a986a6cf91dbe2f2e6120012c96ee7447bcc0f1c4caa) Netns(/var/run/netns/cni-cfaf09cc-342d-794e-978a-c7afa071a0e2) IfName(eth0) Args(K8S_POD_UID=a94b7427-7856-4dc4-844c-8a426631e99d;IgnoreUnknown=1;K8S_POD_NAMESPACE=booking-cars;K8S_POD_NAME=jobs-79c5bb8c56-l7mfw;K8S_POD_INFRA_CONTAINER_ID=6f8cbcf57411933b3f53a986a6cf91dbe2f2e6120012c96ee7447bcc0f1c4caa) 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\":\"standard\",\"type\":\"aws-cni\",\"vethPrefix\":\"eni\"})"}
{"level":"debug","ts":"2024-10-10T21:51:34.993Z","caller":"routed-eni-cni-plugin/cni.go:128","msg":"Prev Result: <nil>\n"}
{"level":"debug","ts":"2024-10-10T21:51:34.993Z","caller":"routed-eni-cni-plugin/cni.go:128","msg":"MTU value set is 9001:"}
{"level":"info","ts":"2024-10-10T21:51:35.002Z","caller":"routed-eni-cni-plugin/cni.go:128","msg":"Received add network response from ipamd for container 6f8cbcf57411933b3f53a986a6cf91dbe2f2e6120012c96ee7447bcc0f1c4caa interface eth0: Success:true IPv4Addr:\"172.21.149.56\" DeviceNumber:-1 UseExternalSNAT:true VPCv4CIDRs:\"172.21.0.0/16\" PodVlanId:2 PodENIMAC:\"0a:ff:c4:52:0f:4d\" PodENISubnetGW:\"172.21.128.1\" ParentIfIndex:7 NetworkPolicyMode:\"standard\""}
{"level":"debug","ts":"2024-10-10T21:51:35.002Z","caller":"routed-eni-cni-plugin/cni.go:221","msg":"SetupBranchENIPodNetwork: hostVethName=eni83f7dc8eecd, contVethName=eth0, netnsPath=/var/run/netns/cni-cfaf09cc-342d-794e-978a-c7afa071a0e2, v4Addr=172.21.149.56/32, v6Addr=<nil>, vlanID=2, eniMAC=0a:ff:c4:52:0f:4d, subnetGW=172.21.128.1, parentIfIndex=7, mtu=9001, podSGEnforcingMode=standard"}
{"level":"debug","ts":"2024-10-10T21:51:35.027Z","caller":"driver/driver.go:280","msg":"Successfully set IPv6 sysctls on hostVeth eni83f7dc8eecd"}
{"level":"debug","ts":"2024-10-10T21:51:35.031Z","caller":"driver/driver.go:319","msg":"Successfully setup container route, containerAddr=172.21.149.56/32, hostVeth=eni83f7dc8eecd, rtTable=main"}
{"level":"debug","ts":"2024-10-10T21:51:35.031Z","caller":"driver/driver.go:319","msg":"Successfully setup toContainer rule, containerAddr=172.21.149.56/32, rtTable=main"}
{"level":"debug","ts":"2024-10-10T21:51:35.031Z","caller":"driver/driver.go:319","msg":"Successfully setup fromContainer rule, containerAddr=172.21.149.56/32, rtTable=102"}
{"level":"debug","ts":"2024-10-10T21:51:35.031Z","caller":"routed-eni-cni-plugin/cni.go:128","msg":"Using dummy interface: {Name:dummy83f7dc8eecd Mac:2 Mtu:0 Sandbox: SocketPath: PciID:}"}

That is the IP that was assigned the pod. and all it's metadata. However, that containerID referenced in the logs doesn;t exist. pruned a few fields out to clean this output up

  containerStatuses:
  - containerID: containerd://ce473166e144f8bd2b4194126615184b0daa7f2458c2155171ce19950159aedc
    image: 534287151633.dkr.ecr.us-east-1.amazonaws.com/engine-booking-cars-jobs:0.0.233
    name: engine-cars-jobs
    ready: true
  
  initContainerStatuses:
  - containerID: containerd://38518dd367bf27fb92a68ce18e8e286bbe2b5d724afd0643b20aee649eddc8f3
    image: docker.io/istio/proxyv2:1.22.3
    lastState: {}
    name: istio-validation
    ready: true
    restartCount: 0
    started: false
    state:
      terminated:
        containerID: containerd://38518dd367bf27fb92a68ce18e8e286bbe2b5d724afd0643b20aee649eddc8f3
        exitCode: 0
        finishedAt: "2024-10-10T21:51:35Z"
        reason: Completed
        startedAt: "2024-10-10T21:51:35Z"
  - containerID: containerd://7902dd019a1e676f906bfade7ba62acc3757f8b91ee839c45e0a10fdb0ad517e
    image: docker.io/istio/proxyv2:1.22.3
    name: istio-proxy

in ipamd.log

{"level":"info","ts":"2024-10-10T21:51:34.288Z","caller":"rpc/rpc.pb.go:863","msg":"Received AddNetwork for NS /var/run/netns/cni-a1e04c19-447f-a214-5ccf-76f51a955e74, Sandbox d78e79e2f3c65976885cf228da933b8d35471497f1bdfacbff8d24644
f175222, ifname eth0"}
{"level":"debug","ts":"2024-10-10T21:51:34.288Z","caller":"rpc/rpc.pb.go:863","msg":"AddNetworkRequest: K8S_POD_NAME:\"jobs-79c5bb8c56-l7mfw\"  K8S_POD_NAMESPACE:\"booking-cars\"  K8S_POD_INFRA_CONTAINER_ID:\"d78e79e2f3c65976885cf228
da933b8d35471497f1bdfacbff8d24644f175222\"  ContainerID:\"d78e79e2f3c65976885cf228da933b8d35471497f1bdfacbff8d24644f175222\"  IfName:\"eth0\"  NetworkName:\"aws-cni\"  Netns:\"/var/run/netns/cni-a1e04c19-447f-a214-5ccf-76f51a955e74\"
"}
{"level":"debug","ts":"2024-10-10T21:51:34.289Z","caller":"ipamd/ipamd.go:1953","msg":"Total number of interfaces found: 2 "}
{"level":"debug","ts":"2024-10-10T21:51:34.289Z","caller":"awsutils/awsutils.go:567","msg":"Found ENI MAC address: 0a:ff:f5:68:32:a5"}
{"level":"debug","ts":"2024-10-10T21:51:34.292Z","caller":"awsutils/awsutils.go:567","msg":"Found ENI: eni-0781745ef7092319e, MAC 0a:ff:f5:68:32:a5, device 0"}
{"level":"debug","ts":"2024-10-10T21:51:34.297Z","caller":"awsutils/awsutils.go:567","msg":"Found ENI MAC address: 0a:ff:fa:e1:d4:7b"}
{"level":"debug","ts":"2024-10-10T21:51:34.299Z","caller":"awsutils/awsutils.go:567","msg":"Found ENI: eni-038ebac53d7639b13, MAC 0a:ff:fa:e1:d4:7b, device 2"}
{"level":"debug","ts":"2024-10-10T21:51:34.301Z","caller":"networkutils/network.go:969","msg":"Found the Link that uses mac address 0a:ff:fa:e1:d4:7b and its index is 7 (attempt 1/5)"}
{"level":"info","ts":"2024-10-10T21:51:34.301Z","caller":"rpc/rpc.pb.go:863","msg":"Send AddNetworkReply: failed to get Branch ENI resource"}
{"level":"info","ts":"2024-10-10T21:51:34.339Z","caller":"rpc/rpc.pb.go:881","msg":"Received DelNetwork for Sandbox d78e79e2f3c65976885cf228da933b8d35471497f1bdfacbff8d24644f175222"}
{"level":"debug","ts":"2024-10-10T21:51:34.339Z","caller":"rpc/rpc.pb.go:881","msg":"DelNetworkRequest: K8S_POD_NAME:\"jobs-79c5bb8c56-l7mfw\"  K8S_POD_NAMESPACE:\"booking-cars\"  K8S_POD_INFRA_CONTAINER_ID:\"d78e79e2f3c65976885cf228da933b8d35471497f1bdfacbff8d24644f175222\"  Reason:\"PodDeleted\"  ContainerID:\"d78e79e2f3c65976885cf228da933b8d35471497f1bdfacbff8d24644f175222\"  IfName:\"eth0\"  NetworkName:\"aws-cni\""}{"level":"debug","ts":"2024-10-10T21:51:34.339Z","caller":"ipamd/rpc_handler.go:261","msg":"UnassignPodIPAddress: IP address pool stats: total 32, assigned 5, sandbox aws-cni/d78e79e2f3c65976885cf228da933b8d35471497f1bdfacbff8d24644f175222/eth0"}{"level":"debug","ts":"2024-10-10T21:51:34.339Z","caller":"ipamd/rpc_handler.go:261","msg":"UnassignPodIPAddress: Failed to find IPAM entry under full key, trying CRI-migrated version"}
{"level":"warn","ts":"2024-10-10T21:51:34.339Z","caller":"ipamd/rpc_handler.go:261","msg":"UnassignPodIPAddress: Failed to find sandbox _migrated-from-cri/d78e79e2f3c65976885cf228da933b8d35471497f1bdfacbff8d24644f175222/unknown"}
{"level":"info","ts":"2024-10-10T21:51:34.339Z","caller":"rpc/rpc.pb.go:881","msg":"Send DelNetworkReply: IPv4Addr: , IPv6Addr: , DeviceNumber: 0, err: datastore: unknown pod"}{"level":"info","ts":"2024-10-10T21:51:34.995Z","caller":"rpc/rpc.pb.go:863","msg":"Received AddNetwork for NS /var/run/netns/cni-cfaf09cc-342d-794e-978a-c7afa071a0e2, Sandbox 6f8cbcf57411933b3f53a986a6cf91dbe2f2e6120012c96ee7447bcc0f1c4caa, ifname eth0"}
{"level":"debug","ts":"2024-10-10T21:51:34.995Z","caller":"rpc/rpc.pb.go:863","msg":"AddNetworkRequest: K8S_POD_NAME:\"jobs-79c5bb8c56-l7mfw\"  K8S_POD_NAMESPACE:\"booking-cars\"  K8S_POD_INFRA_CONTAINER_ID:\"6f8cbcf57411933b3f53a986a6cf91dbe2f2e6120012c96ee7447bcc0f1c4caa\"  ContainerID:\"6f8cbcf57411933b3f53a986a6cf91dbe2f2e6120012c96ee7447bcc0f1c4caa\"  IfName:\"eth0\"  NetworkName:\"aws-cni\"  Netns:\"/var/run/netns/cni-cfaf09cc-342d-794e-978a-c7afa071a0e2\""}{"level":"debug","ts":"2024-10-10T21:51:34.996Z","caller":"ipamd/ipamd.go:1953","msg":"Total number of interfaces found: 2 "}{"level":"debug","ts":"2024-10-10T21:51:34.996Z","caller":"awsutils/awsutils.go:567","msg":"Found ENI MAC address: 0a:ff:f5:68:32:a5"}
{"level":"debug","ts":"2024-10-10T21:51:34.997Z","caller":"awsutils/awsutils.go:567","msg":"Found ENI: eni-0781745ef7092319e, MAC 0a:ff:f5:68:32:a5, device 0"}
{"level":"debug","ts":"2024-10-10T21:51:34.999Z","caller":"awsutils/awsutils.go:567","msg":"Found ENI MAC address: 0a:ff:fa:e1:d4:7b"}
{"level":"debug","ts":"2024-10-10T21:51:35.000Z","caller":"awsutils/awsutils.go:567","msg":"Found ENI: eni-038ebac53d7639b13, MAC 0a:ff:fa:e1:d4:7b, device 2"}
{"level":"debug","ts":"2024-10-10T21:51:35.001Z","caller":"networkutils/network.go:969","msg":"Found the Link that uses mac address 0a:ff:fa:e1:d4:7b and its index is 7 (attempt 1/5)"}
{"level":"debug","ts":"2024-10-10T21:51:35.001Z","caller":"rpc/rpc.pb.go:863","msg":"Pod vlandId: 2"}
{"level":"debug","ts":"2024-10-10T21:51:35.002Z","caller":"rpc/rpc.pb.go:863","msg":"VPC CIDR 172.21.0.0/16"}
{"level":"info","ts":"2024-10-10T21:51:35.002Z","caller":"rpc/rpc.pb.go:863","msg":"Send AddNetworkReply: IPv4Addr: 172.21.149.56, IPv6Addr: , DeviceNumber: -1, err: <nil>"}

So the difference is this fails

{"level":"debug","ts":"2024-10-10T21:51:34.301Z","caller":"networkutils/network.go:969","msg":"Found the Link that uses mac address 0a:ff:fa:e1:d4:7b and its index is 7 (attempt 1/5)"}
{"level":"info","ts":"2024-10-10T21:51:34.301Z","caller":"rpc/rpc.pb.go:863","msg":"Send AddNetworkReply: failed to get Branch ENI resource"}
{"level":"info","ts":"2024-10-10T21:51:34.339Z","caller":"rpc/rpc.pb.go:881","msg":"Received DelNetwork for Sandbox d78e79e2f3c65976885cf228da933b8d35471497f1bdfacbff8d24644f175222"}

and immediately after, this similar set of logs works

{"level":"debug","ts":"2024-10-10T21:51:35.001Z","caller":"networkutils/network.go:969","msg":"Found the Link that uses mac address 0a:ff:fa:e1:d4:7b and its index is 7 (attempt 1/5)"}
{"level":"debug","ts":"2024-10-10T21:51:35.001Z","caller":"rpc/rpc.pb.go:863","msg":"Pod vlandId: 2"}
{"level":"debug","ts":"2024-10-10T21:51:35.002Z","caller":"rpc/rpc.pb.go:863","msg":"VPC CIDR 172.21.0.0/16"}
{"level":"info","ts":"2024-10-10T21:51:35.002Z","caller":"rpc/rpc.pb.go:863","msg":"Send AddNetworkReply: IPv4Addr: 172.21.149.56, IPv6Addr: , DeviceNumber: -1, err: <nil>"}

So what is causing this Send AddNetworkReply: failed to get Branch ENI resource and how can I prevent it?

Thanks!

taer avatar Oct 10 '24 22:10 taer

the code shows

				val, branch := pod.Annotations["vpc.amazonaws.com/pod-eni"]
				if branch {

with the else being the error I see. That pod currently has that annotation.

    vpc.amazonaws.com/pod-eni: '[{"eniId":"eni-0f79fa0088da8b996","ifAddress":"0a:ff:c4:52:0f:4d","privateIp":"172.21.149.56","ipv6Addr":"","vlanId":2,"subnetCidr":"172.21.128.0/19","subnetV6Cidr":""}]'

So this seems like a race where something is responsible for adding json to the pod prior to security groups happening and it's not fast enough.

taer avatar Oct 10 '24 22:10 taer

This issue is stale because it has been open 60 days with no activity. Remove stale label or comment or this will be closed in 14 days

github-actions[bot] avatar Dec 10 '24 00:12 github-actions[bot]

#stillannoying

taer avatar Dec 10 '24 02:12 taer

This issue is stale because it has been open 60 days with no activity. Remove stale label or comment or this will be closed in 14 days

github-actions[bot] avatar Feb 09 '25 00:02 github-actions[bot]

Can this be addressed?

taer avatar Feb 10 '25 21:02 taer

This issue is stale because it has been open 60 days with no activity. Remove stale label or comment or this will be closed in 14 days

github-actions[bot] avatar Apr 12 '25 00:04 github-actions[bot]

Still an issue.

gnuletik avatar Apr 14 '25 20:04 gnuletik

Send AddNetworkReply: failed to get Branch ENI resource

This is expected when you have a pod churn in the cluster which uses branch ENIs. Branch ENIs are created by a different component https://github.com/aws/amazon-vpc-resource-controller-k8s

https://github.com/aws/amazon-vpc-resource-controller-k8s/blob/master/docs/images/sgp-pod-create.png VPC Resource controller makes EC2 calls to create branch ENIs (and/or trunk ENIs) during which CNI will show such warning msgs as there's some associated latency with EC2 calls.

As you suspected this is pretty harmless as vpc-rc ends up creating the interface eventually and IPAMD passes it to CNI.

jaydeokar avatar Apr 14 '25 20:04 jaydeokar

@jaydeokar Even with the WARM_TARGET settings enabled? I do now see it's not on all pods.. So I assume when a new node is drug into the cluster via something like Karpenter, it gets scheduled on the node before the resource controller adds the branch Eni?

Is there a gate of some sort that karpenter could attach to the node that the resource controller could remove when it's complete?

taer avatar Apr 15 '25 20:04 taer

Even with the WARM_TARGET settings enabled? I do now see it's not on all pods.. So I assume when a new node is drug into the cluster via something like Karpenter, it gets scheduled on the node before the resource controller adds the branch Eni?

WARM_TARGET settings is for non-branch ENI pods not for the vpc-resource-controller.

So I assume when a new node is drug into the cluster via something like Karpenter, it gets scheduled on the node before the resource controller adds the branch Eni?

No, the flow is Node gets added -> VPC Resource Controller adds a trunk ENI -> Node advertises the extended resource -> SGP Pod gets scheduled on the node -> Branch ENIs get created -> CNI assigns the IP

https://github.com/aws/amazon-vpc-resource-controller-k8s/blob/master/docs/images/sgp-pod-create.png

jaydeokar avatar Apr 26 '25 02:04 jaydeokar

@taer let us know if you face this issue consistently on your pods. Few events like these are expected as VPC-RC creates branch ENIs so this is not a real issue

jaydeokar avatar May 20 '25 23:05 jaydeokar

This issue is now closed. Comments on closed issues are hard for our team to see. If you need more assistance, please either tag a team member or open a new issue that references this one.

github-actions[bot] avatar May 20 '25 23:05 github-actions[bot]