New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Ignore ENIs returning 404 on metadata request #194

Closed
wants to merge 2 commits into
base: master
from

Conversation

Projects
None yet
4 participants
@deiwin
Copy link

deiwin commented Oct 5, 2018

Issue #, if available:

Description of changes:

This fixes an issue where sometimes new ENIs cannot be attached to an instance,
if an ENI was recently detached from the same instance. There's been cases
where this scenario causes new ENI attaching to be impossible for more than
5 minutes, causing new pods to fail to start on that node.

An example failure scenario:

  • More than enough IPs available in the warm IP pool
  • An ENI is deleted/detached
  • Many CronJobs get scheduled on the node
  • Not enough IPs available in the warm IP pool
  • An ENI is added/attached
  • IP allocation from the recently attached ENI fails for 5+ minutes because:
    • network/interfaces/macs/ includes the recently detached ENI's mac, but
    • network/interfaces/macs/<MAC>/device-number/ returns 404 Not Found
  • New pods don't get IPs, because the IPs from the recently attached ENI are
    not available until the metadata cache clears
Click to expand annotated log excerpt showing the issue in action
# Four ENIs
2018-10-04T22:54:22Z [DEBUG] Total number of interfaces found: 4
2018-10-04T22:54:22Z [DEBUG] Found eni: eni-02900675dacdab027, mac 06:4c:dd:d0:be:a8, device 0
2018-10-04T22:54:22Z [DEBUG] Found eni: eni-0b92f047b2e22725d, mac 06:8e:da:83:de:22, device 4
2018-10-04T22:54:22Z [DEBUG] Found eni: eni-0ec6a9cacf25ab7a3, mac 06:8f:44:b6:4d:7a, device 3
2018-10-04T22:54:22Z [DEBUG] Found eni: eni-086fb1ba2dd981648, mac 06:f9:4f:21:d9:94, device 2

# One can be removed
2018-10-04T22:54:27Z [DEBUG] FreeENI: found a deletable ENI eni-0b92f047b2e22725d
2018-10-04T22:54:27Z [INFO] FreeENI eni-0b92f047b2e22725d: IP address pool stats: free 14 addresses, total: 42, assigned: 27
2018-10-04T22:54:27Z [DEBUG] Start freeing eni eni-0b92f047b2e22725d

# Takes a bit to remove
2018-10-04T22:54:33Z [DEBUG] Not able to delete eni yet (attempt 2/20): InvalidParameterValue: Network interface 'eni-0b92f047b2e22725d' is currently in use.
        status code: 400, request id: 22c39e5b-7971-4eb2-8fce-cdc6fd6225dc

# But is finally successful
2018-10-04T22:54:38Z [INFO] Successfully deleted eni: eni-0b92f047b2e22725d
2018-10-04T22:54:38Z [INFO] Successfully freed eni: eni-0b92f047b2e22725d
2018-10-04T22:54:38Z [DEBUG] Successfully decreased IP Pool
2018-10-04T22:54:38Z [DEBUG] IP pool stats: total = 42, used = 27, c.currentMaxAddrsPerENI = 14, c.maxAddrsPerENI = 14

# But soon enough, it's needed again (because of CronJobs)
2018-10-04T22:55:08Z [DEBUG] IP pool stats: total = 42, used = 30, c.currentMaxAddrsPerENI = 14, c.maxAddrsPerENI = 14
2018-10-04T22:55:08Z [DEBUG] Start increasing IP Pool size
2018-10-04T22:55:08Z [INFO] createENI: use primary interface's config, [0xc4204acb80], subnet-9124bdda
2018-10-04T22:55:08Z [INFO] Created a new eni: eni-0e36e322abb522eb2

# New ENI is attached
2018-10-04T22:55:08Z [DEBUG] Discovered device number is used: 0
2018-10-04T22:55:08Z [DEBUG] Discovered device number is used: 2
2018-10-04T22:55:08Z [DEBUG] Discovered device number is used: 1
2018-10-04T22:55:08Z [DEBUG] Found a free device number: 3
2018-10-04T22:55:09Z [INFO] Successfully created and attached a new eni eni-0e36e322abb522eb2 to instance

# But IP allocation fails, because it's not visible in EC2Metadata yet (interface count is still 4)
2018-10-04T22:55:09Z [INFO] Trying to allocate 14 IP address on eni eni-0e36e322abb522eb2
2018-10-04T22:55:09Z [DEBUG] Total number of interfaces found: 4
2018-10-04T22:55:09Z [DEBUG] Found eni mac address : 06:4c:dd:d0:be:a8
2018-10-04T22:55:09Z [DEBUG] Using device number 0 for primary eni: eni-02900675dacdab027
2018-10-04T22:55:09Z [DEBUG] Found eni: eni-02900675dacdab027, mac 06:4c:dd:d0:be:a8, device 0
2018-10-04T22:55:09Z [DEBUG] Found cidr 10.4.128.0/20 for eni 06:4c:dd:d0:be:a8
2018-10-04T22:55:09Z [DEBUG] Found ip addresses [10.4.138.88 10.4.133.165 10.4.128.166 10.4.135.64 10.4.142.65 10.4.129.34 10.4.129.12 10.4.142.111 10.4.143.200 10.4.130.11 10.4.132.86 10.4.141.17 10.4.136.210 10.4.141.51 10.4.139.147] on eni 06:4c:dd:d0:be:a8
2018-10-04T22:55:09Z [DEBUG] Found eni mac address : 06:8e:da:83:de:22
2018-10-04T22:55:09Z [ERROR] Failed to retrieve the device-number of eni 06:8e:da:83:de:22,  EC2MetadataError: failed to make EC2Metadata request
caused by: <?xml version="1.0" encoding="iso-8859-1"?>
<!DOCTYPE html PUBLIC "-//W3C//DTD XHTML 1.0 Transitional//EN"
         "http://www.w3.org/TR/xhtml1/DTD/xhtml1-transitional.dtd">
<html xmlns="http://www.w3.org/1999/xhtml" xml:lang="en" lang="en">
 <head>
  <title>404 - Not Found</title>
 </head>
 <body>
  <h1>404 - Not Found</h1>
 </body>
</html>

2018-10-04T22:55:09Z [WARN] Failed to increase pool, error trying to discover attached enis: get attached enis: failed to retrieve eni metadata for eni: 06:8e:da:83:de:22/: get eni metadata: failed to retrieve device and eni from metadata service: 06:8e:da:83:de:22: failed to retrieve device-number for eni 06:8e:da:83:de:22: EC2MetadataError: failed to make EC2Metadata request
caused by: <?xml version="1.0" encoding="iso-8859-1"?>
<!DOCTYPE html PUBLIC "-//W3C//DTD XHTML 1.0 Transitional//EN"
         "http://www.w3.org/TR/xhtml1/DTD/xhtml1-transitional.dtd">
<html xmlns="http://www.w3.org/1999/xhtml" xml:lang="en" lang="en">
 <head>
  <title>404 - Not Found</title>
 </head>
 <body>
  <h1>404 - Not Found</h1>
 </body>
</html>

# But even when it becomes available (interface count is 5 now), IPs can't be allocated because of the previously removed ENI returning 404
2018-10-04T22:55:19Z [DEBUG] Total number of interfaces found: 5
2018-10-04T22:55:19Z [DEBUG] Found eni mac address : 06:2b:0f:67:1b:02
2018-10-04T22:55:19Z [DEBUG] Found eni: eni-0e36e322abb522eb2, mac 06:2b:0f:67:1b:02, device 4
2018-10-04T22:55:19Z [DEBUG] Found cidr 10.4.128.0/20 for eni 06:2b:0f:67:1b:02
2018-10-04T22:55:19Z [DEBUG] Found ip addresses [10.4.137.10 10.4.136.70 10.4.128.7 10.4.134.39 10.4.136.109 10.4.141.46 10.4.131.72 10.4.131.169 10.4.142.180 10.4.138.116 10.4.138.214 10.4.130.48 10.4.138.253 10.4.143.153 10.4.133.153] on eni 06:2b:0f:67:1b:02
2018-10-04T22:55:19Z [DEBUG] Found eni mac address : 06:4c:dd:d0:be:a8
2018-10-04T22:55:19Z [DEBUG] Using device number 0 for primary eni: eni-02900675dacdab027
2018-10-04T22:55:19Z [DEBUG] Found eni: eni-02900675dacdab027, mac 06:4c:dd:d0:be:a8, device 0
2018-10-04T22:55:19Z [DEBUG] Found cidr 10.4.128.0/20 for eni 06:4c:dd:d0:be:a8
2018-10-04T22:55:19Z [DEBUG] Found ip addresses [10.4.138.88 10.4.133.165 10.4.128.166 10.4.135.64 10.4.142.65 10.4.129.34 10.4.129.12 10.4.142.111 10.4.143.200 10.4.130.11 10.4.132.86 10.4.141.17 10.4.136.210 10.4.141.51 10.4.139.147] on eni 06:4c:dd:d0:be:a8
2018-10-04T22:55:19Z [DEBUG] Found eni mac address : 06:8e:da:83:de:22
2018-10-04T22:55:19Z [ERROR] Failed to retrieve the device-number of eni 06:8e:da:83:de:22,  EC2MetadataError: failed to make EC2Metadata request
caused by: <?xml version="1.0" encoding="iso-8859-1"?>
<!DOCTYPE html PUBLIC "-//W3C//DTD XHTML 1.0 Transitional//EN"
         "http://www.w3.org/TR/xhtml1/DTD/xhtml1-transitional.dtd">
<html xmlns="http://www.w3.org/1999/xhtml" xml:lang="en" lang="en">
 <head>
  <title>404 - Not Found</title>
 </head>
 <body>
  <h1>404 - Not Found</h1>
 </body>
</html>

2018-10-04T22:55:19Z [WARN] Failed to increase pool, error trying to discover attached enis: get attached enis: failed to retrieve eni metadata for eni: 06:8e:da:83:de:22/: get eni metadata: failed to retrieve device and eni from metadata service: 06:8e:da:83:de:22: failed to retrieve device-number for eni 06:8e:da:83:de:22: EC2MetadataError: failed to make EC2Metadata request
caused by: <?xml version="1.0" encoding="iso-8859-1"?>
<!DOCTYPE html PUBLIC "-//W3C//DTD XHTML 1.0 Transitional//EN"
         "http://www.w3.org/TR/xhtml1/DTD/xhtml1-transitional.dtd">
<html xmlns="http://www.w3.org/1999/xhtml" xml:lang="en" lang="en">
 <head>
  <title>404 - Not Found</title>
 </head>
 <body>
  <h1>404 - Not Found</h1>
 </body>
</html>

# And soon enough IP allocation for pods starts failing
2018-10-04T23:00:05Z [DEBUG] AssignIPv4Address: IP address pool stats: total:42, assigned 39
2018-10-04T23:00:05Z [DEBUG] AssignPodIPv4Address, skip ENI eni-0ec6a9cacf25ab7a3 that does not have available addresses
2018-10-04T23:00:05Z [INFO] DataStore has no available IP addresses
2018-10-04T23:00:05Z [INFO] Send AddNetworkReply: IPv4Addr , DeviceNumber: 0, err: datastore: no available IP addresses
# 28 times altogether in this instance
2018-10-04T23:00:06Z [INFO] Send AddNetworkReply: IPv4Addr , DeviceNumber: 0, err: datastore: no available IP addresses
2018-10-04T23:00:07Z [INFO] Send AddNetworkReply: IPv4Addr , DeviceNumber: 0, err: datastore: no available IP addresses
2018-10-04T23:00:07Z [INFO] Send AddNetworkReply: IPv4Addr , DeviceNumber: 0, err: datastore: no available IP addresses
2018-10-04T23:00:08Z [INFO] Send AddNetworkReply: IPv4Addr , DeviceNumber: 0, err: datastore: no available IP addresses
2018-10-04T23:00:09Z [INFO] Send AddNetworkReply: IPv4Addr , DeviceNumber: 0, err: datastore: no available IP addresses
2018-10-04T23:00:10Z [INFO] Send AddNetworkReply: IPv4Addr , DeviceNumber: 0, err: datastore: no available IP addresses
2018-10-04T23:00:11Z [INFO] Send AddNetworkReply: IPv4Addr , DeviceNumber: 0, err: datastore: no available IP addresses
2018-10-04T23:00:12Z [INFO] Send AddNetworkReply: IPv4Addr , DeviceNumber: 0, err: datastore: no available IP addresses
2018-10-04T23:00:13Z [INFO] Send AddNetworkReply: IPv4Addr , DeviceNumber: 0, err: datastore: no available IP addresses
2018-10-04T23:00:14Z [INFO] Send AddNetworkReply: IPv4Addr , DeviceNumber: 0, err: datastore: no available IP addresses
2018-10-04T23:00:15Z [INFO] Send AddNetworkReply: IPv4Addr , DeviceNumber: 0, err: datastore: no available IP addresses
2018-10-04T23:00:16Z [INFO] Send AddNetworkReply: IPv4Addr , DeviceNumber: 0, err: datastore: no available IP addresses
2018-10-04T23:00:18Z [INFO] Send AddNetworkReply: IPv4Addr , DeviceNumber: 0, err: datastore: no available IP addresses
2018-10-04T23:00:19Z [INFO] Send AddNetworkReply: IPv4Addr , DeviceNumber: 0, err: datastore: no available IP addresses
2018-10-04T23:00:20Z [INFO] Send AddNetworkReply: IPv4Addr , DeviceNumber: 0, err: datastore: no available IP addresses
2018-10-04T23:00:21Z [INFO] Send AddNetworkReply: IPv4Addr , DeviceNumber: 0, err: datastore: no available IP addresses
2018-10-04T23:00:22Z [INFO] Send AddNetworkReply: IPv4Addr , DeviceNumber: 0, err: datastore: no available IP addresses
2018-10-04T23:00:23Z [INFO] Send AddNetworkReply: IPv4Addr , DeviceNumber: 0, err: datastore: no available IP addresses
2018-10-04T23:00:24Z [INFO] Send AddNetworkReply: IPv4Addr , DeviceNumber: 0, err: datastore: no available IP addresses
2018-10-04T23:00:26Z [INFO] Send AddNetworkReply: IPv4Addr , DeviceNumber: 0, err: datastore: no available IP addresses
2018-10-04T23:00:27Z [INFO] Send AddNetworkReply: IPv4Addr , DeviceNumber: 0, err: datastore: no available IP addresses
2018-10-04T23:00:28Z [INFO] Send AddNetworkReply: IPv4Addr , DeviceNumber: 0, err: datastore: no available IP addresses
2018-10-04T23:00:29Z [INFO] Send AddNetworkReply: IPv4Addr , DeviceNumber: 0, err: datastore: no available IP addresses
2018-10-04T23:00:30Z [INFO] Send AddNetworkReply: IPv4Addr , DeviceNumber: 0, err: datastore: no available IP addresses
2018-10-04T23:00:31Z [INFO] Send AddNetworkReply: IPv4Addr , DeviceNumber: 0, err: datastore: no available IP addresses
2018-10-04T23:00:32Z [INFO] Send AddNetworkReply: IPv4Addr , DeviceNumber: 0, err: datastore: no available IP addresses
2018-10-04T23:00:33Z [INFO] Send AddNetworkReply: IPv4Addr , DeviceNumber: 0, err: datastore: no available IP addresses

# Finally getting the IPs allocated, 7.5 minutes later
2018-10-04T23:02:24Z [DEBUG] UnAssignIPv4Address: IP address pool stats: total:42, assigned 30, pod(Name: call-router-call-sweeper-1538693940-d7slh, Namespace: default, Container 34bf7f8f3f1784eefca0deb94c0224dd43fa0fd2fbdf51acddbe7cce8f01cdfa)
2018-10-04T23:02:29Z [DEBUG] Total number of interfaces found: 5
2018-10-04T23:02:29Z [ERROR] Failed to retrieve the device-number of eni 06:8e:da:83:de:22,  EC2MetadataError: failed to make EC2Metadata request
2018-10-04T23:02:39Z [DEBUG] Total number of interfaces found: 4
2018-10-04T23:02:40Z [DEBUG] Successfully increased IP Pool
2018-10-04T23:02:40Z [DEBUG] IP pool stats: total = 56, used = 29, c.currentMaxAddrsPerENI = 14, c.maxAddrsPerENI = 14
.

I confirmed, that this fixes the issue with the following commands:

# Create 30 pods
kubectl run deiwin-test --image=ubuntu --image-pull-policy='IfNotPresent' --replicas=30 --overrides='{"spec": {"template": {"spec": {"nodeSelector": {"kubernetes.io/hostname": "<NODE>"}}}}}' -- sleep infinity
# Remove all of them, once they all have IPs
kubectl scale --replicas=0 deploy/deiwin-test
# Add them back, if logs show an ENI was deleted
kubectl scale --replicas=30 deploy/deiwin-test

With these changes, even though I get a [WARN] Failed to retrieve the device-number of eni message, with the 404 response, IP allocation is still successful.

By submitting this pull request, I confirm that my contribution is made under the terms of the Apache 2.0 license.

deiwin added some commits Oct 5, 2018

Test current behavior on failed ENI metadata request
This will contrast the special behavior added in the next commit and will guard
against regressions.
Ignore ENIs returning 404 on metadata request
This fixes an issue where sometimes new ENIs cannot be attached to an instance,
if an ENI was recently detached from the same instance. There's been cases
where this scenario causes new ENI attaching to be impossible for more than
5 minutes, causing new pods to fail to start on that node.

An example failure scenario:
* More than enough IPs available in the warm IP pool
* An ENI is deleted/detached
* Many CronJobs get scheduled on the node
* Not enough IPs available in the warm IP pool
* An ENI is added/attached
* IP allocation from the recently attached ENI fails for 5+ minutes because:
  * `network/interfaces/macs/` includes the recently detached ENI's mac, but
  * `network/interfaces/macs/<MAC>/device-number/` returns 404 Not Found
* New pods don't get IPs, because the IPs from the recently attached ENI are
  not available until the metadata cache clears

Log excerpts showing this behavior will be added to the PR.

mockMetadata.EXPECT().GetMetadata(metadataMACPath).Return(primaryMAC+" "+eni2MAC, nil)

eniNotFoundErr := awserr.New("EC2MetadataError", "failed to make EC2Metadata request", errors.New(

This comment has been minimized.

@deiwin

deiwin Oct 5, 2018

Author

This error is constructed exactly like it is in the AWS SDK, with the HTML copied from logs (visible in the PR message, if expanded).

@devkid

This comment has been minimized.

Copy link

devkid commented Nov 5, 2018

Would it be possible to have this pull request merged? We just suffered the same problem, and this workaround would be much appreciated.

@deiwin

This comment has been minimized.

Copy link
Author

deiwin commented Nov 5, 2018

@devkid, you can also consider setting the WARM_ENI_TARGET to something very high, like 20, for a workaround. This way all ENIs are always attached immediately when aws-node starts and there's no constant detaching and re-attaching.

@devkid

This comment has been minimized.

Copy link

devkid commented Nov 5, 2018

We currently have that set to 1, because we are quite short of IPs in our existing subnets 😉

@liwenwu-amazon

This comment has been minimized.

Copy link
Contributor

liwenwu-amazon commented Nov 12, 2018

These errors can be critical, If CNI ignores them, in some other deployment scenarios, it can lead to workloads being scheduled to a non-functional nodes.

@liwenwu-amazon

This comment has been minimized.

Copy link
Contributor

liwenwu-amazon commented Nov 12, 2018

In your case, can you use set WARM_ENI_TARGET=<num-of-enis of the instance> so that CNI will NOT perform add/delete ENI in a very rapid fashion.

@deiwin

This comment has been minimized.

Copy link
Author

deiwin commented Nov 12, 2018

In your case, can you use set WARM_ENI_TARGET=<num-of-enis of the instance> so that CNI will NOT perform add/delete ENI in a very rapid fashion.

We've done exactly that and I don't mind this PR being closed.

@johanneswuerbach

This comment has been minimized.

Copy link

johanneswuerbach commented Nov 12, 2018

Out of curiosity if changing WARM_ENI_TARGET resolves this issue, shouldn't it be the default then or the implementation made robust enough to handle "add/delete ENI in a very rapid fashion"?

@devkid

This comment has been minimized.

Copy link

devkid commented Nov 13, 2018

I don't get this whole discussion. There is an obvious bug / failure in handling of eventual consistency which seems to be fixed by this pull request. Why suggest all kinds of workarounds instead of merging it? I haven't seen any comment about the pull request itself.

Setting WARM_ENI_TARGET to the maximum number of ENIs of an instance is not feasible considering that you would need to store this environment variable on each node and would need to modify the aws-node daemonset to read this environment variable from disk (when you have different instance types, which we do). Also it consumes at least one additional unused IP per ENI from the selected subnets, which I consider wasteful.

@liwenwu-amazon

This comment has been minimized.

Copy link
Contributor

liwenwu-amazon commented Nov 13, 2018

@devkid
These errors can be critical, If CNI ignores them, in some other deployment scenarios, it can lead to workloads being scheduled to a non-functional nodes

@deiwin

This comment has been minimized.

Copy link
Author

deiwin commented Nov 13, 2018

Setting WARM_ENI_TARGET to the maximum number of ENIs of an instance is not feasible considering that you would need to store this environment variable on each node and would need to modify the aws-node daemonset to read this environment variable from disk (when you have different instance types, which we do).

That's not really true. You can just set it to e.g. 20, which will work for all instances, because it's above their max.

@devkid

This comment has been minimized.

Copy link

devkid commented Nov 13, 2018

@deiwin

That's not really true. You can just set it to e.g. 20, which will work for all instances, because it's above their max.

True, didn't think of this. The problem with wasted IPs remains.

@liwenwu-amazon

These errors can be critical, If CNI ignores them, in some other deployment scenarios, it can lead to workloads being scheduled to a non-functional nodes.

Can you elaborate on these scenarios? With the current behavior, this is already the case. As long as the the detached ENI is still showing up in the metadata, the IPAMD is basically stuck and doing nothing. New pods still get scheduled on such nodes and can't be started until the ENI disappears from the metadata list and IPAMD continues to work.

@deiwin

This comment has been minimized.

Copy link
Author

deiwin commented Feb 8, 2019

Looks like this solution will not be accepted. We're avoiding this issue by always setting WARM_ENI_TARGET to 20.

@deiwin deiwin closed this Feb 8, 2019

@deiwin

This comment has been minimized.

Copy link
Author

deiwin commented Feb 8, 2019

These errors can be critical, If CNI ignores them, in some other deployment scenarios, it can lead to workloads being scheduled to a non-functional nodes.

For the record, I don't see how that can be the case. The ENIs for which the metadata request fails are ignored by IPAMD with the suggested implementation.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment