binxio/cfn-secret-provider

The parameter already exists error when updating cloudformation stack containing Custom::RSAKey

Closed this issue · 9 comments

Occasionally when updating a cloud formation stack that contains a Custom::RSAKey the following error is thrown:

Failed to create resource. An error occurred (ParameterAlreadyExists) when calling the PutParameter operation: The parameter already exists. To overwrite this value, set the overwrite option in the request to true.

This has also been observed when deleting and recreating the stack.

The fix is to manually delete the parameter in the SSM parameter store.

I wonder whether, as per the suggestion in the error message, the code could be changed to overwrite existing parameters ?

I value the functionality to not overwrite an existing parameter. It prevents for secrets accidentally being hijacked by a CFN stack.

Sometimes, when an error occurs quickly after all the create commands have been issued, CloudFormation immediately tries to cancel all outstanding creates by issuing a delete command.. However the resource provider already completed successfully and returned a new physical resource id. When CFN does not use this one, but instead sends its own physical resource id, the resource provider does not delete the newly created parameter.

Can you tell me in when situation you encounter this problem?

Alternatively, it may be that the Lambda exceeds its timeout limit while the parameter was created but the result not successfully returned. For RSA Key generation we have upped the timeout to 30s... What is the timeout that you have set?

I saw this today in cloudformation when creating a new stack which was odd. The stack name was unique, it had never used before and the name of the Custom::RSAKey included the stack name.

iisEC2PrivateKey:
    Type: Custom::RSAKey
    Properties:
      Description: Private key part of the key pair used to access the EC2 instance
      KeyFormat: TraditionalOpenSSL
      Name: !Sub
        - ${environmentType}-${AWS::StackName}-privatekey
        - environmentType: !FindInMap
            - EnvironmentConfigs
            - !Ref 'AWS::AccountId'
            - EnvironmentType
      ServiceToken: !Sub 'arn:aws:lambda:${AWS::Region}:${AWS::AccountId}:function:binxio-cfn-secret-provider'

When I deleted the stack, it did not delete the parameter so I had to do it manually.

This is the cloudformation output showing the error:

16:36:07 UTC+0000	ROLLBACK_COMPLETE	AWS::CloudFormation::Stack	PFWS01-March2018-2	
16:36:05 UTC+0000	DELETE_COMPLETE	AWS::EC2::SecurityGroup	iisElbSecurityGroup	
16:35:07 UTC+0000	DELETE_IN_PROGRESS	AWS::EC2::SecurityGroup	iisElbSecurityGroup	
16:35:06 UTC+0000	DELETE_COMPLETE	AWS::EC2::SecurityGroup	iisWebServerSecurityGroup	
16:35:05 UTC+0000	DELETE_COMPLETE	AWS::ElasticLoadBalancingV2::LoadBalancer	iisElb	
16:35:05 UTC+0000	DELETE_COMPLETE	AWS::IAM::Role	iisWebServerRole	
16:35:05 UTC+0000	DELETE_IN_PROGRESS	AWS::ElasticLoadBalancingV2::LoadBalancer	iisElb	
16:35:04 UTC+0000	DELETE_IN_PROGRESS	AWS::EC2::SecurityGroup	iisWebServerSecurityGroup	
16:35:04 UTC+0000	DELETE_IN_PROGRESS	AWS::IAM::Role	iisWebServerRole	
16:35:04 UTC+0000	DELETE_COMPLETE	AWS::ElasticLoadBalancingV2::TargetGroup	iisElbTargetGroup443	
16:35:04 UTC+0000	DELETE_COMPLETE	Custom::RSAKey	iisEC2PrivateKey	
16:35:03 UTC+0000	DELETE_IN_PROGRESS	AWS::ElasticLoadBalancingV2::TargetGroup	iisElbTargetGroup443	
16:35:03 UTC+0000	DELETE_COMPLETE	AWS::ElasticLoadBalancingV2::TargetGroup	iisElbTargetGroup80	
16:35:03 UTC+0000	DELETE_COMPLETE	AWS::IAM::Policy	iisWebServerRolePolicy	
16:35:03 UTC+0000	DELETE_COMPLETE	AWS::EC2::SecurityGroupIngress	iisWebServerAdditionalSecurityGroupIngress	
16:35:03 UTC+0000	DELETE_COMPLETE	AWS::S3::BucketPolicy	iisElbLogsBucketPolicy	
16:35:02 UTC+0000	DELETE_IN_PROGRESS	AWS::ElasticLoadBalancingV2::TargetGroup	iisElbTargetGroup80	
16:35:02 UTC+0000	DELETE_IN_PROGRESS	AWS::S3::BucketPolicy	iisElbLogsBucketPolicy	
16:35:02 UTC+0000	DELETE_COMPLETE	AWS::ElasticLoadBalancingV2::Listener	iisElbListener443	
16:35:02 UTC+0000	DELETE_IN_PROGRESS	AWS::EC2::SecurityGroupIngress	iisWebServerAdditionalSecurityGroupIngress	
16:35:02 UTC+0000	DELETE_COMPLETE	AWS::IAM::InstanceProfile	iisWebServerRoleInstanceProfile	
16:35:02 UTC+0000	DELETE_IN_PROGRESS	AWS::ElasticLoadBalancingV2::Listener	iisElbListener443	
16:35:01 UTC+0000	DELETE_COMPLETE	AWS::ElasticLoadBalancingV2::Listener	iisElbListener80	
16:35:01 UTC+0000	DELETE_IN_PROGRESS	AWS::IAM::Policy	iisWebServerRolePolicy	
16:35:01 UTC+0000	DELETE_IN_PROGRESS	AWS::ElasticLoadBalancingV2::Listener	iisElbListener80	
16:35:01 UTC+0000	DELETE_IN_PROGRESS	AWS::IAM::InstanceProfile	iisWebServerRoleInstanceProfile	
16:35:01 UTC+0000	DELETE_IN_PROGRESS	Custom::RSAKey	iisEC2PrivateKey	
16:34:50 UTC+0000	ROLLBACK_IN_PROGRESS	AWS::CloudFormation::Stack	PFWS01-March2018-2	The following resource(s) failed to create: [iisEC2PrivateKey]. . Rollback requested by user.
16:34:49 UTC+0000	CREATE_FAILED	Custom::RSAKey	iisEC2PrivateKey	Failed to create resource. An error occurred (ParameterAlreadyExists) when calling the PutParameter operation: The parameter already exists. To overwrite this value, set the overwrite option in the request to true.
16:34:48 UTC+0000	CREATE_IN_PROGRESS	Custom::RSAKey	iisEC2PrivateKey	Resource creation Initiated
16:33:31 UTC+0000	CREATE_COMPLETE	AWS::IAM::InstanceProfile	iisWebServerRoleInstanceProfile	
16:33:29 UTC+0000	CREATE_COMPLETE	AWS::ElasticLoadBalancingV2::Listener	iisElbListener80	
16:33:29 UTC+0000	CREATE_COMPLETE	AWS::ElasticLoadBalancingV2::Listener	iisElbListener443	
16:33:29 UTC+0000	CREATE_IN_PROGRESS	AWS::ElasticLoadBalancingV2::Listener	iisElbListener80	Resource creation Initiated
16:33:29 UTC+0000	CREATE_IN_PROGRESS	AWS::ElasticLoadBalancingV2::Listener	iisElbListener443	Resource creation Initiated
16:33:29 UTC+0000	CREATE_IN_PROGRESS	AWS::ElasticLoadBalancingV2::Listener	iisElbListener80	
16:33:28 UTC+0000	CREATE_IN_PROGRESS	AWS::ElasticLoadBalancingV2::Listener	iisElbListener443	
16:33:26 UTC+0000	CREATE_COMPLETE	AWS::ElasticLoadBalancingV2::TargetGroup	iisElbTargetGroup80	
16:33:26 UTC+0000	CREATE_COMPLETE	AWS::ElasticLoadBalancingV2::TargetGroup	iisElbTargetGroup443	
16:33:25 UTC+0000	CREATE_IN_PROGRESS	AWS::ElasticLoadBalancingV2::TargetGroup	iisElbTargetGroup80	Resource creation Initiated
16:33:25 UTC+0000	CREATE_IN_PROGRESS	AWS::ElasticLoadBalancingV2::TargetGroup	iisElbTargetGroup443	Resource creation Initiated
16:33:25 UTC+0000	CREATE_IN_PROGRESS	AWS::ElasticLoadBalancingV2::TargetGroup	iisElbTargetGroup80	
16:33:24 UTC+0000	CREATE_IN_PROGRESS	AWS::ElasticLoadBalancingV2::TargetGroup	iisElbTargetGroup443	
16:33:22 UTC+0000	CREATE_COMPLETE	AWS::ElasticLoadBalancingV2::LoadBalancer	iisElb	
16:31:37 UTC+0000	CREATE_COMPLETE	AWS::IAM::Policy	iisWebServerRolePolicy	
16:31:31 UTC+0000	CREATE_IN_PROGRESS	AWS::IAM::Policy	iisWebServerRolePolicy	Resource creation Initiated
16:31:30 UTC+0000	CREATE_IN_PROGRESS	AWS::IAM::InstanceProfile	iisWebServerRoleInstanceProfile	Resource creation Initiated
16:31:30 UTC+0000	CREATE_IN_PROGRESS	AWS::IAM::Policy	iisWebServerRolePolicy	
16:31:30 UTC+0000	CREATE_IN_PROGRESS	AWS::IAM::InstanceProfile	iisWebServerRoleInstanceProfile	
16:31:28 UTC+0000	CREATE_COMPLETE	AWS::IAM::Role	iisWebServerRole	
16:31:24 UTC+0000	CREATE_COMPLETE	AWS::EC2::SecurityGroupIngress	iisWebServerAdditionalSecurityGroupIngress	
16:31:23 UTC+0000	CREATE_IN_PROGRESS	AWS::EC2::SecurityGroupIngress	iisWebServerAdditionalSecurityGroupIngress	Resource creation Initiated
16:31:23 UTC+0000	CREATE_IN_PROGRESS	AWS::EC2::SecurityGroupIngress	iisWebServerAdditionalSecurityGroupIngress	
16:31:21 UTC+0000	CREATE_COMPLETE	AWS::EC2::SecurityGroup	iisWebServerSecurityGroup	
16:31:21 UTC+0000	CREATE_IN_PROGRESS	AWS::ElasticLoadBalancingV2::LoadBalancer	iisElb	Resource creation Initiated
16:31:19 UTC+0000	CREATE_IN_PROGRESS	AWS::EC2::SecurityGroup	iisWebServerSecurityGroup	Resource creation Initiated
16:31:19 UTC+0000	CREATE_IN_PROGRESS	AWS::ElasticLoadBalancingV2::LoadBalancer	iisElb	
16:31:18 UTC+0000	CREATE_IN_PROGRESS	AWS::EC2::SecurityGroup	iisWebServerSecurityGroup	
16:31:17 UTC+0000	CREATE_COMPLETE	AWS::EC2::SecurityGroup	iisElbSecurityGroup	
16:31:15 UTC+0000	CREATE_COMPLETE	AWS::S3::BucketPolicy	iisElbLogsBucketPolicy	
16:31:15 UTC+0000	CREATE_IN_PROGRESS	AWS::S3::BucketPolicy	iisElbLogsBucketPolicy	Resource creation Initiated
16:31:15 UTC+0000	CREATE_IN_PROGRESS	AWS::EC2::SecurityGroup	iisElbSecurityGroup	Resource creation Initiated
16:31:14 UTC+0000	CREATE_IN_PROGRESS	AWS::IAM::Role	iisWebServerRole	Resource creation Initiated
16:31:14 UTC+0000	CREATE_IN_PROGRESS	AWS::EC2::SecurityGroup	iisElbSecurityGroup	
16:31:14 UTC+0000	CREATE_IN_PROGRESS	AWS::S3::BucketPolicy	iisElbLogsBucketPolicy	
16:31:13 UTC+0000	CREATE_IN_PROGRESS	AWS::IAM::Role	iisWebServerRole	
16:31:13 UTC+0000	CREATE_IN_PROGRESS	Custom::RSAKey	iisEC2PrivateKey	
16:31:10 UTC+0000	CREATE_IN_PROGRESS	AWS::CloudFormation::Stack	PFWS01-March2018-2	User Initiated

Just had another example of this error message which I thought worth sharing.
I am creating a brand new stack and received the error "Failed to create resource. An error occurred (ParameterAlreadyExists) when calling the PutParameter operation: The parameter already exists. To overwrite this value, set the overwrite option in the request to true"

If I look in parameter store I can see a parameter that has been created by the stack:

dev-PFWS01-March2018-3-privatekey (this was not here previously)

Manually deleting this parameter and running the stack again works showing that the error is intermittent. I suspect some kind of ordering internally with cloud formation but as yet I have been unable to find the appropriate "dependson" to permanently fix it.

I suspect that the lambda times out before the response is sent but after the key was created. What is the timeout that you have set for the lambda? Can you check the lambda log file?

This is the output from the Lambda in cloudwatch logs:

[INFO] 2018-03-16T12:58:36.168Z Found credentials in environment variables.
[INFO] 2018-03-16T12:58:36.264Z Starting new HTTPS connection (1): sts.amazonaws.com
[INFO] 2018-03-16T12:58:36.700Z Starting new HTTPS connection (1): sts.amazonaws.com
[INFO] 2018-03-16T12:58:37.25Z Starting new HTTPS connection (1): sts.amazonaws.com
[INFO] 2018-03-16T12:58:37.475Z Starting new HTTPS connection (1): sts.amazonaws.com
[INFO] 2018-03-16T12:58:37.824Z Starting new HTTPS connection (1): sts.amazonaws.com
START RequestId: bce7f76d-2919-11e8-b683-279633f78f6e Version: $LATEST
[INFO] 2018-03-16T12:58:40.779Z bce7f76d-2919-11e8-b683-279633f78f6e Starting new HTTPS connection (1): ssm.eu-west-1.amazonaws.com
END RequestId: bce7f76d-2919-11e8-b683-279633f78f6e
REPORT RequestId: bce7f76d-2919-11e8-b683-279633f78f6e Duration: 3003.13 ms Billed Duration: 3000 ms Memory Size: 128 MB Max Memory Used: 85 MB
2018-03-16T12:58:41.145Z bce7f76d-2919-11e8-b683-279633f78f6e Task timed out after 3.00 seconds

[INFO] 2018-03-16T12:58:41.453Z Found credentials in environment variables.
[INFO] 2018-03-16T12:58:41.574Z Starting new HTTPS connection (1): sts.amazonaws.com
[INFO] 2018-03-16T12:58:42.1Z Starting new HTTPS connection (1): sts.amazonaws.com
[INFO] 2018-03-16T12:58:42.325Z Starting new HTTPS connection (1): sts.amazonaws.com
[INFO] 2018-03-16T12:58:42.780Z Starting new HTTPS connection (1): sts.amazonaws.com
[INFO] 2018-03-16T12:58:43.126Z Starting new HTTPS connection (1): sts.amazonaws.com
START RequestId: bce7f76d-2919-11e8-b683-279633f78f6e Version: $LATEST
[INFO] 2018-03-16T12:59:37.180Z bce7f76d-2919-11e8-b683-279633f78f6e Starting new HTTPS connection (1): ssm.eu-west-1.amazonaws.com
END RequestId: bce7f76d-2919-11e8-b683-279633f78f6e
REPORT RequestId: bce7f76d-2919-11e8-b683-279633f78f6e Duration: 2307.61 ms Billed Duration: 2400 ms Memory Size: 128 MB Max Memory Used: 83 MB
START RequestId: f1fc8707-2919-11e8-a792-adb73c80d681 Version: $LATEST
END RequestId: f1fc8707-2919-11e8-a792-adb73c80d681
REPORT RequestId: f1fc8707-2919-11e8-a792-adb73c80d681 Duration: 374.17 ms Billed Duration: 400 ms Memory Size: 128 MB Max Memory Used: 84 MB
START RequestId: 66a9cd5e-291b-11e8-9f5e-55bd5fbc5bc5 Version: $LATEST
[INFO] 2018-03-16T13:10:31.199Z 66a9cd5e-291b-11e8-9f5e-55bd5fbc5bc5 Resetting dropped connection: ssm.eu-west-1.amazonaws.com
END RequestId: 66a9cd5e-291b-11e8-9f5e-55bd5fbc5bc5
REPORT RequestId: 66a9cd5e-291b-11e8-9f5e-55bd5fbc5bc5 Duration: 1831.67 ms Billed Duration: 1900 ms Memory Size: 128 MB Max Memory Used: 84 MB
START RequestId: 6ab9d7d3-291b-11e8-8749-d7a427454833 Version: $LATEST
[INFO] 2018-03-16T13:10:36.701Z 6ab9d7d3-291b-11e8-8749-d7a427454833 Starting new HTTPS connection (1): ec2.eu-west-1.amazonaws.com
END RequestId: 6ab9d7d3-291b-11e8-8749-d7a427454833
REPORT RequestId: 6ab9d7d3-291b-11e8-8749-d7a427454833 Duration: 464.15 ms Billed Duration: 500 ms Memory Size: 128 MB Max Memory Used: 85 MB

As you can see, there is a message in the log:

 Task timed out after 3.00 seconds

Please set the timeout of on the lambda to 30 seconds. that should probably solve your problem.

Is 3 seconds the default timeout? Is it worth adding a longer timeout to the template?

@reidca, I have already changed the timeout in the template to 30 seconds. :-)