Fails to create one of three NAT gateways

[randomvariable]

/kind bug

What steps did you take and what happened:
[A clear and concise description of what the bug is.]
Create a 3 AZ cluster as part of conformance tests, but AWSCluster reports:

  Normal  SuccessfulCreateNATGateway        7m25s  aws-controller  Created new NAT Gateway "nat-0559e53ef0a233357"
  Normal  SuccessfulCreateNATGateway        5m54s  aws-controller  Created new NAT Gateway "nat-09baa58ba673f971d"
  Normal  SuccessfulCreateNATGateway        2m37s  aws-controller  Created new NAT Gateway "nat-080cd55b42083d439"
  Normal  SuccessfulCreateNATGateway        50s    aws-controller  Created new NAT Gateway "nat-000c63fc65239c676"

VPC console shows a failed VPC with error "Elastic IP address [eipalloc-0bf842e00beae91a4] is already associated"

CAPA itself doesn't "notice" as it's not checking for Failed states, just that there is a NAT gateway:

I0618 19:06:09.751959       1 natgateways.go:190] controllers/AWSCluster "msg"="NAT gateway for subnet is now available" "awsCluster"="cluster-ohy1cth5s64jdrgefucu" "cluster"="cluster-ohy1cth5s64jdrgefucu" "namespace"="conformance-tests-hlpse1" "nat-gateway-id"="nat-0559e53ef0a233357" "subnet-id"="subnet-04660efa0e619433a"
I0618 19:11:13.494754       1 natgateways.go:190] controllers/AWSCluster "msg"="NAT gateway for subnet is now available" "awsCluster"="cluster-ohy1cth5s64jdrgefucu" "cluster"="cluster-ohy1cth5s64jdrgefucu" "namespace"="conformance-tests-hlpse1" "nat-gateway-id"="nat-080cd55b42083d439" "subnet-id"="subnet-0eccbea0870a3758d"
I0618 19:13:14.984888       1 natgateways.go:190] controllers/AWSCluster "msg"="NAT gateway for subnet is now available" "awsCluster"="cluster-ohy1cth5s64jdrgefucu" "cluster"="cluster-ohy1cth5s64jdrgefucu" "namespace"="conformance-tests-hlpse1" "nat-gateway-id"="nat-000c63fc65239c676" "subnet-id"="subnet-09fbbe2fc71eb29d3"

What did you expect to happen:

Anything else you would like to add:
[Miscellaneous information that will assist in solving the issue.]

Environment:

• Cluster-api-provider-aws version: c718d8e
• Kubernetes version: (use kubectl version):
• OS (e.g. from /etc/os-release):

[ncdc]

Were those 4 NAT gateways all for the same cluster? If so, why did it create 4?

Where specifically do we need to add additional checks?

[randomvariable]

I didn't go too deep into it, I saw it in passing when looking at the cluster creation slowdown in e2e.

Looks like it tried to create 3, and the 3rd one failed because it reused one of the other NAT gateway's Elastic IP, and then created a 4th one successfully. Seems to be fairly consistent, at least in eu-west-1.

We should maybe report on failed NAT gateways with an event or log, and it looks like a race in the way ec2.getOrAllocateAddress() is being used for the NAT Gateway, in that the allocation of the EIP happens late in the process of the NAT gateway creation, so the same EIP gets handed out to multiple NAT gateway creation requests.

[detiber]

/milestone v0.5.5
/priority important-soon

[aaroniscode]

I was seeing this a bunch recently testing a recent PR. Will reproduce and see if I can trace the root cause.

/assign
/lifecycle active

[ncdc]

@aaroniscode any luck root causing this?

[aaroniscode]

@ncdc yes, found root cause and wrote a small AWS CLI script that reproduces. Will update the ticket this morning with my results and a suggested solution.

[aaroniscode]

@ncdc @randomvariable ok, so did some digging here and believe I found the root cause of the issue.

When a NAT gateway is created, we pass the EIP required for creation. Sometimes (maybe often), after a NAT gateway is considered "available", the EIP is not yet associated to the NAT gateway and it can take another 15-30 seconds, I've observed.

So when the code goes to create the 2nd or 3rd NAT gateways, it calls a function getOrAllocateAddress in eips.go. That function queries all existing EIPs and uses any existing if they don't have an associationID. Since it can take upwards of 30 seconds for the previously created NAT gateway to have the EIP associated, this function can return the same EIP that was intended for the previous NAT gateway.

I wrote a small script to demonstate this: https://gist.github.com/aaroniscode/0a1baffe1d376be6ca924f149b1df9da

Right after the 2nd NAT gateway became available, the describe on the EIPs showed

Aarons-MacBook :: ~/capa » ./nat-test.sh
eipalloc-08790646a2df4fe52
nat-0f1669abea6d10996
pending.....................................................
{
    "Addresses": [
        {
            "PublicIp": "35.155.183.153",
            "AllocationId": "eipalloc-08790646a2df4fe52",
            "Domain": "vpc",
            "PublicIpv4Pool": "amazon",
            "NetworkBorderGroup": "us-west-2"
        },
        {
            "PublicIp": "35.162.156.16",
            "AllocationId": "eipalloc-092f643a388e17588",
            "AssociationId": "eipassoc-0f3da48b49a9621fb",
            "Domain": "vpc",
            "NetworkInterfaceId": "eni-0b96950c4d75d713f",
            "NetworkInterfaceOwnerId": "787734544525",
            "PrivateIpAddress": "172.31.18.192",
            "PublicIpv4Pool": "amazon",
            "NetworkBorderGroup": "us-west-2"
        }
    ]
}

Quick thoughts on solutions.

Option 1 -- Get rid of the getOrAllocateAddress function and only use the allocateAddress function. Essentially always creating a new EIP for each NAT gateway. Possible concerns with this solution include abandoned EIPs if there is an error creating a NAT gateway and another one is created.

Option 2 -- Name the NAT gateways and EIPs consistent with other naming in CAPA that includes their AZ. Then in getOrAllocateAddress if we have an EIP that isn't associated, we would look to find the one in the intended AZ. This would also prevent CAPA from just taking any EIPs that are allocated but not associated in the users account that may have been intended for another purpose.

Let me know your thoughts. I'm thinking Option 2 makes the most sense.

[detiber]

Option 1 -- Get rid of the getOrAllocateAddress function and only use the allocateAddress function. Essentially always creating a new EIP for each NAT gateway. Possible concerns with this solution include abandoned EIPs if there is an error creating a NAT gateway and another one is created.

Originally we did this and it lead to problems with having orphaned EIPs if we weren't able to attach it after creating it, which led relatively quickly to hitting the EIP default limit on accouunts.

Option 2 -- Name the NAT gateways and EIPs consistent with other naming in CAPA that includes their AZ. Then in getOrAllocateAddress if we have an EIP that isn't associated, we would look to find the one in the intended AZ. This would also prevent CAPA from just taking any EIPs that are allocated but not associated in the users account that may have been intended for another purpose.

Unfortunately there isn't a way to name the EIPs, which is what led to the use of getOrAllocateAddress originally.

I think there are likely a couple of options to resolve:

1. Add some error handling around the call to CreateNatGateway that will use exponential backoff and retry getOrAllocateAddress
2. Refactor getOrAllocateAddress and CreateNatGateway in a way that we batch up the description of resources and attempt to create all of the resources we need in a single method/function (will still require multiple aws api calls)

The first is probably the least effort, but will also likely increase the time for network creation.

The second will still likely need some exponential backoff and retries in the event that we are re-reconciling following an error, but should greatly improve the runtime of the happy path case.

[aaroniscode]

Unfortunately there isn't a way to name the EIPs, which is what led to the use of getOrAllocateAddress originally.

@detiber Maybe I'm missing something, but I think we wait in getOrAllocateAddress to tag the EIP including with a name before we return from the function. And we name all the EIP's exactly the same. If you don't think it's a bad solution, I think I can whip up a quick naming filter for EIP to resolve this issue without refactoring for right now.

func (s *Service) allocateAddress(role string) (string, error) {
	out, err := s.scope.EC2.AllocateAddress(&ec2.AllocateAddressInput{
		Domain: aws.String("vpc"),
	})

	if err != nil {
		record.Warnf(s.scope.AWSCluster, "FailedAllocateEIP", "Failed to allocate Elastic IP for %q: %v", role, err)
		return "", errors.Wrap(err, "failed to allocate Elastic IP")
	}

	if err := wait.WaitForWithRetryable(wait.NewBackoff(), func() (bool, error) {
		if err := tags.Apply(&tags.ApplyParams{
			EC2Client: s.scope.EC2,
			BuildParams: infrav1.BuildParams{
				ClusterName: s.scope.Name(),
				ResourceID:  *out.AllocationId,
				Lifecycle:   infrav1.ResourceLifecycleOwned,
				Name:        aws.String(fmt.Sprintf("%s-eip-%s", s.scope.Name(), role)),
				Role:        aws.String(role),
				Additional:  s.scope.AdditionalTags(),
			},
		}); err != nil {
			return false, err
		}
		return true, nil
	}, awserrors.EIPNotFound); err != nil {
		record.Eventf(s.scope.AWSCluster, "FailedAllocateAddress", "Failed to tag elastic IP %q: %v", aws.StringValue(out.AllocationId), err)
		return "", errors.Wrapf(err, "failed to tag Elastic IP %q", aws.StringValue(out.AllocationId))
	}

	return aws.StringValue(out.AllocationId), nil
}

Regarding your Option 1, we do have error handling around the call to CreateNatGateway so it does eventually create the gateway after the error. With this error happening often, it significantly increases the time to create the NAT gateways.

Agreed Option 2 (refactor to batch) is probably the best, and I would think we would want to create all the NAT gateways in parallel, vs in serial today, though that is a much bigger change.