serverless-localstack icon indicating copy to clipboard operation
serverless-localstack copied to clipboard

Published 20 hours ago • verified publisher icon localstack

Deployment to the `localstack` works randomly

Open grzegorz-bielski opened this issue 4 years ago • 7 comments

I'm encountering an issue where only one deployment out of dozes works correctly.

When I try to call my endpoint:

curl -X POST http://localhost:4566/restapis/<deployment-id>/local/_user_request_/register

then in most cases, this results in an error.

Here are full logs from working deployment - from docker-compose up to API call

localstack_1  | Waiting for all LocalStack services to be ready
localstack_1  | 2020-10-18 15:49:23,632 CRIT Supervisor is running as root.  Privileges were not dropped because no user is specified in the config file.  If you intend to run as root, you can set user=root in the config file to avoid this message.
localstack_1  | 2020-10-18 15:49:23,636 INFO supervisord started with pid 13
localstack_1  | 2020-10-18 15:49:24,641 INFO spawned: 'dashboard' with pid 19
localstack_1  | 2020-10-18 15:49:24,645 INFO spawned: 'infra' with pid 20
localstack_1  | 2020-10-18 15:49:24,652 INFO success: dashboard entered RUNNING state, process has stayed up for > than 0 seconds (startsecs)
localstack_1  | 2020-10-18 15:49:24,653 INFO exited: dashboard (exit status 0; expected)
localstack_1  | (. .venv/bin/activate; exec bin/localstack start --host)
localstack_1  | LocalStack version: 0.12.0
localstack_1  | Starting local dev environment. CTRL-C to quit.
localstack_1  | 2020-10-18T15:49:25:DEBUG:bootstrap.py: Loading plugins - scope "services", module "localstack": <function register_localstack_plugins at 0x7f2edba83ca0>
localstack_1  | 2020-10-18 15:49:26,473 INFO success: infra entered RUNNING state, process has stayed up for > than 1 seconds (startsecs)
localstack_1  | 2020-10-18T15:49:29:INFO:localstack.utils.analytics.profiler: Execution of "load_plugin_from_path" took 3591.369867324829ms
localstack_1  | 2020-10-18T15:49:29:INFO:localstack.utils.analytics.profiler: Execution of "load_plugins" took 3591.7928218841553ms
localstack_1  | Waiting for all LocalStack services to be ready
localstack_1  | Starting edge router (https port 4566)...
localstack_1  | 2020-10-18T15:49:30:INFO:localstack.utils.analytics.profiler: Execution of "prepare_environment" took 1052.7760982513428ms
localstack_1  | Starting mock API Gateway service on http port 4566 ...
localstack_1  | 2020-10-18T15:49:30:INFO:localstack.multiserver: Starting multi API server process on port 53437
localstack_1  | [2020-10-18 15:49:30 +0000] [21] [INFO] Running on http://0.0.0.0:53437 (CTRL + C to quit)
localstack_1  | 2020-10-18T15:49:30:INFO:hypercorn.error: Running on http://0.0.0.0:53437 (CTRL + C to quit)
localstack_1  | [2020-10-18 15:49:30 +0000] [21] [INFO] Running on https://0.0.0.0:4566 (CTRL + C to quit)
localstack_1  | 2020-10-18T15:49:30:INFO:hypercorn.error: Running on https://0.0.0.0:4566 (CTRL + C to quit)
localstack_1  | Starting mock CloudFormation service on http port 4566 ...
localstack_1  | Starting mock CloudWatch service on http port 4566 ...
localstack_1  | Starting mock DynamoDB service on http port 4566 ...
localstack_1  | Starting mock DynamoDB Streams service on http port 4566 ...
localstack_1  | Starting mock IAM service on http port 4566 ...
localstack_1  | Starting mock STS service on http port 4566 ...
localstack_1  | Starting mock Kinesis service on http port 4566 ...
localstack_1  | Starting mock Lambda service on http port 4566 ...
localstack_1  | Starting mock CloudWatch Logs service on http port 4566 ...
localstack_1  | Starting mock S3 service on http port 4566 ...
localstack_1  | Initializing DynamoDB Local with the following configuration:
localstack_1  | Port:	50673
localstack_1  | InMemory:	true
localstack_1  | DbPath:	null
localstack_1  | SharedDb:	true
localstack_1  | shouldDelayTransientStatuses:	false
localstack_1  | CorsParams:	*
localstack_1  |
localstack_1  | Listening at http://:::36851
localstack_1  | 2020-10-18 15:49:31,363:API:  * Running on http://0.0.0.0:57929/ (Press CTRL+C to quit)
localstack_1  | 2020-10-18 15:49:31,448:API:  * Running on http://0.0.0.0:36943/ (Press CTRL+C to quit)
localstack_1  | Waiting for all LocalStack services to be ready
localstack_1  | Ready.
localstack_1  | 2020-10-18T15:49:41:INFO:localstack.utils.analytics.profiler: Execution of "start_api_services" took 10947.968006134033ms
localstack_1  | 2020-10-18T15:50:00:DEBUG:localstack.services.cloudformation.cloudformation_listener: Error response for CloudFormation action "DescribeStacks" (400) POST /: b'<ErrorResponse xmlns="http://cloudformation.amazonaws.com/doc/2010-05-15/">\n  <Error>\n    <Type>Sender</Type>\n    <Code>ValidationError</Code>\n    <Message>Stack with id newsletter-app-local does not exist</Message>\n  </Error>\n  <RequestId>cf4c737e-5ae2-11e4-a7c9-ad44eEXAMPLE</RequestId>\n</ErrorResponse>'
localstack_1  | 2020-10-18T15:50:00:DEBUG:localstack.services.cloudformation.cloudformation_starter: Currently processing stack resource newsletter-app-local/ServerlessDeploymentBucket: None
localstack_1  | 2020-10-18T15:50:00:DEBUG:localstack.services.cloudformation.cloudformation_starter: Deploying CloudFormation resource (update=False, exists=False, updateable=False): {'Type': 'AWS::S3::Bucket', 'Properties': {'BucketEncryption': {'ServerSideEncryptionConfiguration': [{'ServerSideEncryptionByDefault': {'SSEAlgorithm': 'AES256'}}]}, 'BucketName': 'newsletter-app-local-serverlessdeploymentbucket-hd6jkqynky2e'}}
localstack_1  | 2020-10-18T15:50:00:DEBUG:localstack.utils.cloudformation.template_deployer: Running action "create" for resource type "S3::Bucket" id "ServerlessDeploymentBucket"
localstack_1  | 2020-10-18T15:50:00:DEBUG:localstack.utils.cloudformation.template_deployer: Request for resource type "S3::Bucket" in region us-east-1: create_bucket {'Bucket': 'newsletter-app-local-serverlessdeploymentbucket-hd6jkqynky2e', 'ACL': 'public-read'}
localstack_1  | 2020-10-18T15:50:00:DEBUG:localstack.services.cloudformation.cloudformation_starter: Currently processing stack resource newsletter-app-local/ServerlessDeploymentBucketPolicy: None
localstack_1  | 2020-10-18T15:50:00:DEBUG:localstack.services.cloudformation.cloudformation_starter: Deploying CloudFormation resource (update=False, exists=False, updateable=False): {'Type': 'AWS::S3::BucketPolicy', 'Properties': {'Bucket': 'newsletter-app-local-serverlessdeploymentbucket-hd6jkqynky2e', 'PolicyDocument': {'Statement': [{'Action': 's3:*', 'Effect': 'Deny', 'Principal': '*', 'Resource': ['arn:aws:s3:::newsletter-app-local-serverlessdeploymentbucket-hd6jkqynky2e/*'], 'Condition': {'Bool': {'aws:SecureTransport': False}}}]}}}
localstack_1  | 2020-10-18T15:50:00:DEBUG:localstack.utils.cloudformation.template_deployer: Running action "create" for resource type "S3::BucketPolicy" id "ServerlessDeploymentBucketPolicy"
localstack_1  | 2020-10-18T15:50:00:DEBUG:localstack.utils.cloudformation.template_deployer: Request for resource type "S3::BucketPolicy" in region us-east-1: put_bucket_policy {'Bucket': 'newsletter-app-local-serverlessdeploymentbucket-hd6jkqynky2e', 'Policy': '{"Statement": [{"Action": "s3:*", "Effect": "Deny", "Principal": "*", "Resource": ["arn:aws:s3:::newsletter-app-local-serverlessdeploymentbucket-hd6jkqynky2e/*"], "Condition": {"Bool": {"aws:SecureTransport": false}}}]}'}
localstack_1  | 2020-10-18T15:50:00:WARNING:localstack.services.cloudformation.cloudformation_starter: Unable to determine physical_resource_id for resource <class 'localstack.services.cloudformation.service_models.S3BucketPolicy'>
localstack_1  | 2020-10-18T15:50:00:DEBUG:localstack.services.cloudformation.cloudformation_starter: Running CloudFormation stack deployment loop iteration 1
localstack_1  | 2020-10-18T15:50:05:WARNING:localstack.services.awslambda.lambda_api: Function not found: arn:aws:lambda:us-east-1:000000000000:function:newsletter-app-local-register
localstack_1  | 2020-10-18T15:50:05:DEBUG:localstack.services.cloudformation.cloudformation_starter: Currently processing stack resource newsletter-app-local/RegisterLambdaVersion1DiUbYf41cRntnDPG80oBXDuf5UDLhp6QZQ8ilsR3k: None
localstack_1  | 2020-10-18T15:50:05:DEBUG:localstack.services.cloudformation.cloudformation_starter: Currently processing stack resource newsletter-app-local/RegisterLambdaFunction: None
localstack_1  | 2020-10-18T15:50:05:DEBUG:localstack.services.cloudformation.cloudformation_starter: Currently processing stack resource newsletter-app-local/IamRoleLambdaExecution: None
localstack_1  | 2020-10-18T15:50:05:DEBUG:localstack.services.cloudformation.cloudformation_starter: Resource IamRoleLambdaExecution need not be deployed (is_updateable=False): {'Type': 'AWS::IAM::Role', 'Properties': {'AssumeRolePolicyDocument': {'Version': '2012-10-17', 'Statement': [{'Effect': 'Allow', 'Principal': {'Service': ['lambda.amazonaws.com']}, 'Action': ['sts:AssumeRole']}]}, 'Policies': [{'PolicyName': 'newsletter-app-local-lambda', 'PolicyDocument': {'Version': '2012-10-17', 'Statement': [{'Effect': 'Allow', 'Action': ['logs:CreateLogStream', 'logs:CreateLogGroup'], 'Resource': ['arn:aws:logs:us-east-1:000000000000:log-group:/aws/lambda/newsletter-app-local*:*']}, {'Effect': 'Allow', 'Action': ['logs:PutLogEvents'], 'Resource': ['arn:aws:logs:us-east-1:000000000000:log-group:/aws/lambda/newsletter-app-local*:*:*']}]}}], 'Path': '/', 'RoleName': 'newsletter-app-local-us-east-1-lambdaRole'}} True
localstack_1  | 2020-10-18T15:50:05:WARNING:localstack.services.awslambda.lambda_api: Function not found: arn:aws:lambda:us-east-1:000000000000:function:newsletter-app-local-register
localstack_1  | 2020-10-18T15:50:05:DEBUG:localstack.services.cloudformation.cloudformation_starter: Deploying CloudFormation resource (update=False, exists=False, updateable=False): {'Type': 'AWS::Lambda::Function', 'Properties': {'Code': {'S3Bucket': 'newsletter-app-local-serverlessdeploymentbucket-hd6jkqynky2e', 'S3Key': 'serverless/newsletter-app/local/1603036200016-2020-10-18T15:50:00.016Z/newsletter-app.zip'}, 'FunctionName': 'newsletter-app-local-register', 'Handler': 'handler.register', 'MemorySize': 1024, 'Role': 'arn:aws:iam::000000000000:role/newsletter-app-local-us-east-1-lambdaRole', 'Runtime': 'nodejs12.x', 'Timeout': 6, 'Environment': {'Variables': {'AWS_NODEJS_CONNECTION_REUSE_ENABLED': '1'}}}, 'DependsOn': ['RegisterLogGroup']}
localstack_1  | 2020-10-18T15:50:05:DEBUG:localstack.utils.cloudformation.template_deployer: Running action "create" for resource type "Lambda::Function" id "RegisterLambdaFunction"
localstack_1  | 2020-10-18T15:50:05:DEBUG:localstack.utils.cloudformation.template_deployer: Request for resource type "Lambda::Function" in region us-east-1: create_function {'FunctionName': 'newsletter-app-local-register', 'Runtime': 'nodejs12.x', 'Role': 'arn:aws:iam::000000000000:role/newsletter-app-local-us-east-1-lambdaRole', 'Handler': 'handler.register', 'Code': {'S3Bucket': 'newsletter-app-local-serverlessdeploymentbucket-hd6jkqynky2e', 'S3Key': 'serverless/newsletter-app/local/1603036200016-2020-10-18T15:50:00.016Z/newsletter-app.zip'}, 'Environment': {'Variables': {'AWS_NODEJS_CONNECTION_REUSE_ENABLED': '1'}}, 'Timeout': 6, 'MemorySize': 1024}
localstack_1  | 2020-10-18T15:50:06:DEBUG:localstack.services.cloudformation.cloudformation_starter: Resource RegisterLambdaVersion1DiUbYf41cRntnDPG80oBXDuf5UDLhp6QZQ8ilsR3k need not be deployed (is_updateable=False): {'Type': 'AWS::Lambda::Version', 'DeletionPolicy': 'Retain', 'Properties': {'FunctionName': 'newsletter-app-local-register', 'CodeSha256': 'B4w4zFpL5b96wC+KezO4nOMWK08QLigxtHNHVi7doUo='}} True
localstack_1  | 2020-10-18T15:50:06:DEBUG:localstack.services.cloudformation.cloudformation_starter: Currently processing stack resource newsletter-app-local/ApiGatewayMethodRegisterPost: None
localstack_1  | 2020-10-18T15:50:06:DEBUG:localstack.services.cloudformation.cloudformation_starter: Currently processing stack resource newsletter-app-local/ApiGatewayResourceRegister: None
localstack_1  | 2020-10-18T15:50:06:DEBUG:localstack.services.cloudformation.cloudformation_starter: Currently processing stack resource newsletter-app-local/ApiGatewayRestApi: None
localstack_1  | 2020-10-18T15:50:06:DEBUG:localstack.services.cloudformation.cloudformation_starter: Deploying CloudFormation resource (update=False, exists=False, updateable=False): {'Type': 'AWS::ApiGateway::RestApi', 'Properties': {'Name': 'local-newsletter-app', 'EndpointConfiguration': {'Types': ['EDGE']}, 'Policy': '', 'MinimumCompressionSize': 1024}}
localstack_1  | 2020-10-18T15:50:06:DEBUG:localstack.utils.cloudformation.template_deployer: Running action "create" for resource type "ApiGateway::RestApi" id "ApiGatewayRestApi"
localstack_1  | 2020-10-18T15:50:06:DEBUG:localstack.utils.cloudformation.template_deployer: Request for resource type "ApiGateway::RestApi" in region us-east-1: create_rest_api {'name': 'local-newsletter-app'}
localstack_1  | 2020-10-18T15:50:06:DEBUG:localstack.services.cloudformation.cloudformation_starter: Updating resource id: 608eab7b - yt690zs955, 608eab7b - {'Type': 'AWS::ApiGateway::RestApi', 'Properties': {'Name': 'local-newsletter-app', 'EndpointConfiguration': {'Types': ['EDGE']}, 'Policy': '', 'MinimumCompressionSize': 1024}}
localstack_1  | 2020-10-18T15:50:06:INFO:localstack.services.cloudformation.cloudformation_starter: Updating resource ID from 608eab7b to yt690zs955 (us-east-1)
localstack_1  | 2020-10-18T15:50:06:DEBUG:localstack.services.cloudformation.cloudformation_starter: Deploying CloudFormation resource (update=False, exists=False, updateable=False): {'Type': 'AWS::ApiGateway::Resource', 'Properties': {'ParentId': '06ucno224r', 'PathPart': 'register', 'RestApiId': 'yt690zs955'}}
localstack_1  | 2020-10-18T15:50:06:DEBUG:localstack.utils.cloudformation.template_deployer: Running action "create" for resource type "ApiGateway::Resource" id "ApiGatewayResourceRegister"
localstack_1  | 2020-10-18T15:50:06:DEBUG:localstack.utils.cloudformation.template_deployer: Request for resource type "ApiGateway::Resource" in region us-east-1: create_resource {'restApiId': 'yt690zs955', 'pathPart': 'register', 'parentId': '06ucno224r'}
localstack_1  | 2020-10-18T15:50:06:DEBUG:localstack.services.cloudformation.cloudformation_starter: Updating resource id: d78afed8 - mnf7mogao2, <moto.apigateway.models.Resource object at 0x7f2ed548fbb0> - {'Type': 'AWS::ApiGateway::Resource', 'Properties': {'ParentId': '06ucno224r', 'PathPart': 'register', 'RestApiId': 'yt690zs955'}}
localstack_1  | 2020-10-18T15:50:06:INFO:localstack.services.cloudformation.cloudformation_starter: Updating resource ID from d78afed8 to mnf7mogao2 (us-east-1)
localstack_1  | 2020-10-18T15:50:06:DEBUG:localstack.services.cloudformation.cloudformation_starter: Currently processing stack resource newsletter-app-local/RegisterLogGroup: None
localstack_1  | 2020-10-18T15:50:06:DEBUG:localstack.services.cloudformation.cloudformation_starter: Resource RegisterLogGroup need not be deployed (is_updateable=False): {'Type': 'AWS::Logs::LogGroup', 'Properties': {'LogGroupName': '/aws/lambda/newsletter-app-local-register'}} True
localstack_1  | 2020-10-18T15:50:06:WARNING:localstack.services.cloudformation.cloudformation_starter: Unable to determine physical_resource_id for resource <class 'moto.apigateway.models.Resource'>
localstack_1  | 2020-10-18T15:50:06:DEBUG:localstack.services.cloudformation.cloudformation_starter: Deploying CloudFormation resource (update=False, exists=False, updateable=False): {'Type': 'AWS::ApiGateway::Method', 'Properties': {'HttpMethod': 'POST', 'RequestParameters': {}, 'ResourceId': 'mnf7mogao2', 'RestApiId': 'yt690zs955', 'ApiKeyRequired': False, 'AuthorizationType': 'NONE', 'Integration': {'IntegrationHttpMethod': 'POST', 'Type': 'AWS_PROXY', 'Uri': 'arn:aws:apigateway:us-east-1:lambda:path/2015-03-31/functions/arn:aws:lambda:us-east-1:000000000000:function:newsletter-app-local-register/invocations'}, 'MethodResponses': []}}
localstack_1  | 2020-10-18T15:50:06:DEBUG:localstack.utils.cloudformation.template_deployer: Running action "create" for resource type "ApiGateway::Method" id "ApiGatewayMethodRegisterPost"
localstack_1  | 2020-10-18T15:50:06:DEBUG:localstack.utils.cloudformation.template_deployer: Request for resource type "ApiGateway::Method" in region us-east-1: put_method {'restApiId': 'yt690zs955', 'resourceId': 'mnf7mogao2', 'httpMethod': 'POST', 'authorizationType': 'NONE', 'requestParameters': {}}
localstack_1  | 2020-10-18T15:50:06:WARNING:localstack.services.cloudformation.cloudformation_starter: Unable to determine physical_resource_id for resource <class 'moto.apigateway.models.Method'>
localstack_1  | 2020-10-18T15:50:06:DEBUG:localstack.services.cloudformation.cloudformation_starter: Currently processing stack resource newsletter-app-local/IamRoleLambdaExecution: True
localstack_1  | 2020-10-18T15:50:06:DEBUG:localstack.services.cloudformation.cloudformation_starter: Currently processing stack resource newsletter-app-local/ApiGatewayDeployment1603036192856: None
localstack_1  | 2020-10-18T15:50:07:DEBUG:localstack.utils.cloudformation.template_deployer: Extract resource attribute: ApiGateway::RestApi RootResourceId
localstack_1  | 2020-10-18T15:50:07:DEBUG:localstack.utils.cloudformation.template_deployer: Extract resource attribute: ApiGateway::Resource PhysicalResourceId
localstack_1  | 2020-10-18T15:50:07:DEBUG:localstack.services.cloudformation.cloudformation_starter: Deploying CloudFormation resource (update=False, exists=False, updateable=False): {'Type': 'AWS::ApiGateway::Deployment', 'Properties': {'RestApiId': 'yt690zs955', 'StageName': 'local'}, 'DependsOn': ['ApiGatewayMethodRegisterPost']}
localstack_1  | 2020-10-18T15:50:07:DEBUG:localstack.utils.cloudformation.template_deployer: Running action "create" for resource type "ApiGateway::Deployment" id "ApiGatewayDeployment1603036192856"
localstack_1  | 2020-10-18T15:50:07:DEBUG:localstack.utils.cloudformation.template_deployer: Request for resource type "ApiGateway::Deployment" in region us-east-1: create_deployment {'restApiId': 'yt690zs955', 'stageName': 'local'}
localstack_1  | 2020-10-18T15:50:07:DEBUG:localstack.services.cloudformation.cloudformation_starter: Updating resource id: 6e9e3d02 - fdkpztr76i, {'id': '6e9e3d02', 'stageName': 'local', 'description': '', 'createdDate': 1603036206} - {'Type': 'AWS::ApiGateway::Deployment', 'Properties': {'RestApiId': 'yt690zs955', 'StageName': 'local'}, 'DependsOn': ['ApiGatewayMethodRegisterPost']}
localstack_1  | 2020-10-18T15:50:07:INFO:localstack.services.cloudformation.cloudformation_starter: Updating resource ID from 6e9e3d02 to fdkpztr76i (us-east-1)
localstack_1  | 2020-10-18T15:50:07:WARNING:localstack.services.cloudformation.cloudformation_starter: Unable to determine physical_resource_id for resource <class 'moto.apigateway.models.Deployment'>
localstack_1  | 2020-10-18T15:50:07:DEBUG:localstack.services.cloudformation.cloudformation_starter: Currently processing stack resource newsletter-app-local/ApiGatewayRestApi: False
localstack_1  | 2020-10-18T15:50:07:DEBUG:localstack.services.cloudformation.cloudformation_starter: Currently processing stack resource newsletter-app-local/RegisterLogGroup: True
localstack_1  | 2020-10-18T15:50:07:DEBUG:localstack.services.cloudformation.cloudformation_starter: Currently processing stack resource newsletter-app-local/ApiGatewayResourceRegister: False
localstack_1  | 2020-10-18T15:50:07:DEBUG:localstack.services.cloudformation.cloudformation_starter: Currently processing stack resource newsletter-app-local/RegisterLambdaPermissionApiGateway: None
localstack_1  | 2020-10-18T15:50:07:WARNING:moto: No Moto CloudFormation support for AWS::Lambda::Permission
localstack_1  | 2020-10-18T15:50:07:DEBUG:localstack.services.cloudformation.cloudformation_starter: Currently processing stack resource newsletter-app-local/RegisterLambdaFunction: False
localstack_1  | 2020-10-18T15:50:07:DEBUG:localstack.services.cloudformation.cloudformation_starter: Unable to resolve attribute reference ['IamRoleLambdaExecution', 'Arn'] in resource map keys ['ServerlessDeploymentBucket', 'ServerlessDeploymentBucketPolicy', 'RegisterLogGroup', 'IamRoleLambdaExecution', 'RegisterLambdaFunction', 'RegisterLambdaVersion1DiUbYf41cRntnDPG80oBXDuf5UDLhp6QZQ8ilsR3k', 'ApiGatewayRestApi', 'ApiGatewayResourceRegister', 'ApiGatewayMethodRegisterPost', 'ApiGatewayDeployment1603036192856', 'RegisterLambdaPermissionApiGateway']
localstack_1  | 2020-10-18T15:50:07:DEBUG:localstack.services.cloudformation.cloudformation_starter: Currently processing stack resource newsletter-app-local/ServerlessDeploymentBucket: False
localstack_1  | 2020-10-18T15:50:07:DEBUG:localstack.services.cloudformation.cloudformation_starter: Deploying CloudFormation resource (update=True, exists=False, updateable=False): {'Type': 'AWS::S3::Bucket', 'Properties': {'BucketEncryption': {'ServerSideEncryptionConfiguration': [{'ServerSideEncryptionByDefault': {'SSEAlgorithm': 'AES256'}}]}, 'BucketName': 'newsletter-app-local-serverlessdeploymentbucket-5511xxiqe44l'}}
localstack_1  | 2020-10-18T15:50:07:WARNING:localstack.utils.cloudformation.template_deployer: Unable to update resource type "S3::Bucket", id "ServerlessDeploymentBucket"
localstack_1  | 2020-10-18T15:50:07:DEBUG:localstack.services.cloudformation.cloudformation_starter: Running CloudFormation stack deployment loop iteration 1
localstack_1  | 2020-10-18T15:50:12:WARNING:localstack.services.cloudformation.cloudformation_starter: Unable to resolve "Ref" attribute for: {'Ref': 'RegisterLambdaVersion1DiUbYf41cRntnDPG80oBXDuf5UDLhp6QZQ8ilsR3k'} - RegisterLambdaVersion1DiUbYf41cRntnDPG80oBXDuf5UDLhp6QZQ8ilsR3k - <class 'moto.awslambda.models.LambdaVersion'>
localstack_1  | 2020-10-18T15:51:17:DEBUG:localstack.services.awslambda.lambda_api: Running Lambda function arn:aws:lambda:us-east-1:000000000000:function:newsletter-app-local-register from API Gateway invocation: POST /register
localstack_1  | 2020-10-18T15:51:17:INFO:localstack.services.awslambda.lambda_executors: Determined main container target IP: 172.17.0.2
localstack_1  | 2020-10-18T15:51:17:INFO:localstack.services.awslambda.lambda_executors: Running lambda cmd: CONTAINER_ID="$(docker create -i   -e AWS_NODEJS_CONNECTION_REUSE_ENABLED="$AWS_NODEJS_CONNECTION_REUSE_ENABLED" -e AWS_ACCESS_KEY_ID="$AWS_ACCESS_KEY_ID" -e AWS_SECRET_ACCESS_KEY="$AWS_SECRET_ACCESS_KEY" -e DOCKER_LAMBDA_USE_STDIN="$DOCKER_LAMBDA_USE_STDIN" -e LOCALSTACK_HOSTNAME="$LOCALSTACK_HOSTNAME" -e EDGE_PORT="$EDGE_PORT" -e _HANDLER="$_HANDLER" -e AWS_LAMBDA_FUNCTION_TIMEOUT="$AWS_LAMBDA_FUNCTION_TIMEOUT" -e AWS_LAMBDA_FUNCTION_NAME="$AWS_LAMBDA_FUNCTION_NAME" -e AWS_LAMBDA_FUNCTION_VERSION="$AWS_LAMBDA_FUNCTION_VERSION" -e AWS_LAMBDA_FUNCTION_INVOKED_ARN="$AWS_LAMBDA_FUNCTION_INVOKED_ARN" -e AWS_LAMBDA_COGNITO_IDENTITY="$AWS_LAMBDA_COGNITO_IDENTITY" -e NODE_TLS_REJECT_UNAUTHORIZED="$NODE_TLS_REJECT_UNAUTHORIZED"   --rm "lambci/lambda:nodejs12.x" "handler.register")";docker cp "/tmp/localstack/zipfile.77f5af52/." "$CONTAINER_ID:/var/task"; docker start -ai "$CONTAINER_ID";
localstack_1  | 2020-10-18T15:51:18:DEBUG:localstack.services.awslambda.lambda_executors: Lambda arn:aws:lambda:us-east-1:000000000000:function:newsletter-app-local-register result / log output:
localstack_1  | {"statusCode":200,"body":"{\n  \"message\": \"Go Serverless Webpack (Typescript) v1.0! Your function executed successfully!\",\n  \"input\": {\n    \"path\": \"/register\",\n    \"headers\": {\n      \"Remote-Addr\": \"172.17.0.1\",\n      \"Host\": \"localhost:4566\",\n      \"User-Agent\": \"curl/7.64.1\",\n      \"Accept\": \"*/*\",\n      \"X-Forwarded-For\": \"172.17.0.1, localhost:4566, 127.0.0.1, localhost:4566\",\n      \"x-localstack-edge\": \"https://localhost:4566\",\n      \"Authorization\": \"AWS4-HMAC-SHA256 Credential=LocalStackDummyAccessKey/20160623/us-east-1/apigateway/aws4_request, SignedHeaders=content-type;host;x-amz-date;x-amz-target, Signature=1234\"\n    },\n    \"multiValueHeaders\": {\n      \"Remote-Addr\": [\n        \"172.17.0.1\"\n      ],\n      \"Host\": [\n        \"localhost:4566\"\n      ],\n      \"User-Agent\": [\n        \"curl/7.64.1\"\n      ],\n      \"Accept\": [\n        \"*/*\"\n      ],\n      \"X-Forwarded-For\": [\n        \"172.17.0.1, localhost:4566, 127.0.0.1, localhost:4566\"\n      ],\n      \"x-localstack-edge\": [\n        \"https://localhost:4566\"\n      ],\n      \"Authorization\": [\n        \"AWS4-HMAC-SHA256 Credential=LocalStackDummyAccessKey/20160623/us-east-1/apigateway/aws4_request, SignedHeaders=content-type;host;x-amz-date;x-amz-target, Signature=1234\"\n      ]\n    },\n    \"pathParameters\": {},\n    \"body\": \"\",\n    \"isBase64Encoded\": false,\n    \"resource\": \"/restapis/yt690zs955/local/_user_request_/register\",\n    \"httpMethod\": \"POST\",\n    \"queryStringParameters\": {},\n    \"multiValueQueryStringParameters\": {},\n    \"requestContext\": {\n      \"path\": \"/local/register\",\n      \"accountId\": \"000000000000\",\n      \"resourceId\": \"mnf7mogao2\",\n      \"stage\": \"local\",\n      \"identity\": {\n        \"accountId\": \"000000000000\",\n        \"sourceIp\": \"127.0.0.1\",\n        \"userAgent\": \"curl/7.64.1\"\n      },\n      \"httpMethod\": \"POST\",\n      \"protocol\": \"HTTP/1.1\",\n      \"requestTime\": \"2020-10-18T15:51:17.323Z\",\n      \"requestTimeEpoch\": 1603036277323\n    },\n    \"stageVariables\": {}\n  }\n}"}
localstack_1  | > START RequestId: 02991f59-6b7e-11fb-b598-6685b68604ea Version: $LATEST
localstack_1  | > END RequestId: 02991f59-6b7e-11fb-b598-6685b68604ea
localstack_1  | > REPORT RequestId: 02991f59-6b7e-11fb-b598-6685b68604ea	Init Duration: 253.10 ms	Duration: 8.99 ms	Billed Duration: 100 ms	Memory Size: 1536 MB	Max Memory Used: 44 MB
localstack_1  | 2020-10-18T15:51:18:INFO:localstack.services.edge: Unable to find forwarding rule for host "04e6873a557a:4566", path "/", target header "", auth header "", data "b''"
^CGracefully stopping... (press Ctrl+C again to force)

and here are full logs from the broken one:

Starting newsletter-app_localstack_1 ... done
Attaching to newsletter-app_localstack_1
localstack_1  | Waiting for all LocalStack services to be ready
localstack_1  | 2020-10-18 15:52:10,025 CRIT Supervisor is running as root.  Privileges were not dropped because no user is specified in the config file.  If you intend to run as root, you can set user=root in the config file to avoid this message.
localstack_1  | 2020-10-18 15:52:10,029 INFO supervisord started with pid 14
localstack_1  | 2020-10-18 15:52:11,034 INFO spawned: 'dashboard' with pid 20
localstack_1  | 2020-10-18 15:52:11,038 INFO spawned: 'infra' with pid 21
localstack_1  | 2020-10-18 15:52:11,045 INFO success: dashboard entered RUNNING state, process has stayed up for > than 0 seconds (startsecs)
localstack_1  | 2020-10-18 15:52:11,046 INFO exited: dashboard (exit status 0; expected)
localstack_1  | (. .venv/bin/activate; exec bin/localstack start --host)
localstack_1  | LocalStack version: 0.12.0
localstack_1  | Starting local dev environment. CTRL-C to quit.
localstack_1  | 2020-10-18T15:52:11:DEBUG:bootstrap.py: Loading plugins - scope "services", module "localstack": <function register_localstack_plugins at 0x7f67048e0ca0>
localstack_1  | 2020-10-18 15:52:12,844 INFO success: infra entered RUNNING state, process has stayed up for > than 1 seconds (startsecs)
localstack_1  | 2020-10-18T15:52:15:INFO:localstack.utils.analytics.profiler: Execution of "load_plugin_from_path" took 3491.328001022339ms
localstack_1  | 2020-10-18T15:52:15:INFO:localstack.utils.analytics.profiler: Execution of "load_plugins" took 3491.597890853882ms
localstack_1  | Waiting for all LocalStack services to be ready
localstack_1  | Starting edge router (https port 4566)...
localstack_1  | Starting mock API Gateway service on http port 4566 ...
localstack_1  | 2020-10-18T15:52:17:INFO:localstack.utils.analytics.profiler: Execution of "prepare_environment" took 2052.669048309326ms
localstack_1  | 2020-10-18T15:52:17:INFO:localstack.multiserver: Starting multi API server process on port 42565
localstack_1  | [2020-10-18 15:52:17 ﹍0000] [22] [INFO] Running on http://0.0.0.0:42565 (CTRL﹍  C to quit)
localstack_1  | 2020-10-18T15:52:17:INFO:hypercorn.error: Running on http://0.0.0.0:42565 (CTRL + C to quit)
localstack_1  | [2020-10-18 15:52:17 ﹍0000] [22] [INFO] Running on https://0.0.0.0:4566 (CTRL﹍  C to quit)
localstack_1  | 2020-10-18T15:52:17:INFO:hypercorn.error: Running on https://0.0.0.0:4566 (CTRL + C to quit)
localstack_1  | Starting mock CloudFormation service on http port 4566 ...
localstack_1  | Starting mock CloudWatch service on http port 4566 ...
localstack_1  | Starting mock DynamoDB service on http port 4566 ...
localstack_1  | Starting mock DynamoDB Streams service on http port 4566 ...
localstack_1  | Starting mock IAM service on http port 4566 ...
localstack_1  | Starting mock STS service on http port 4566 ...
localstack_1  | 2020-10-18 15:52:18,574:API:  * Running on http://0.0.0.0:56771/ (Press CTRL+C to quit)
localstack_1  | 2020-10-18 15:52:18,657:API:  * Running on http://0.0.0.0:34279/ (Press CTRL+C to quit)
localstack_1  | Starting mock Kinesis service on http port 4566 ...
localstack_1  | Starting mock Lambda service on http port 4566 ...
localstack_1  | Starting mock CloudWatch Logs service on http port 4566 ...
localstack_1  | Starting mock S3 service on http port 4566 ...
localstack_1  | Initializing DynamoDB Local with the following configuration:
localstack_1  | Port:	53093
localstack_1  | InMemory:	true
localstack_1  | DbPath:	null
localstack_1  | SharedDb:	true
localstack_1  | shouldDelayTransientStatuses:	false
localstack_1  | CorsParams:	*
localstack_1  |
localstack_1  | Listening at http://:::47241
localstack_1  | Waiting for all LocalStack services to be ready
localstack_1  | Ready.
localstack_1  | 2020-10-18T15:52:28:INFO:localstack.utils.analytics.profiler: Execution of "start_api_services" took 10924.87096786499ms
localstack_1  | 2020-10-18T15:52:47:DEBUG:localstack.services.cloudformation.cloudformation_listener: Error response for CloudFormation action "DescribeStacks" (400) POST /: b'<ErrorResponse xmlns="http://cloudformation.amazonaws.com/doc/2010-05-15/">\n  <Error>\n    <Type>Sender</Type>\n    <Code>ValidationError</Code>\n    <Message>Stack with id newsletter-app-local does not exist</Message>\n  </Error>\n  <RequestId>cf4c737e-5ae2-11e4-a7c9-ad44eEXAMPLE</RequestId>\n</ErrorResponse>'
localstack_1  | 2020-10-18T15:52:47:DEBUG:localstack.services.cloudformation.cloudformation_starter: Currently processing stack resource newsletter-app-local/ServerlessDeploymentBucket: None
localstack_1  | 2020-10-18T15:52:47:DEBUG:localstack.services.cloudformation.cloudformation_starter: Deploying CloudFormation resource (update=False, exists=False, updateable=False): {'Type': 'AWS::S3::Bucket', 'Properties': {'BucketEncryption': {'ServerSideEncryptionConfiguration': [{'ServerSideEncryptionByDefault': {'SSEAlgorithm': 'AES256'}}]}, 'BucketName': 'newsletter-app-local-serverlessdeploymentbucket-i2ih8b11ngsx'}}
localstack_1  | 2020-10-18T15:52:47:DEBUG:localstack.utils.cloudformation.template_deployer: Running action "create" for resource type "S3::Bucket" id "ServerlessDeploymentBucket"
localstack_1  | 2020-10-18T15:52:47:DEBUG:localstack.utils.cloudformation.template_deployer: Request for resource type "S3::Bucket" in region us-east-1: create_bucket {'Bucket': 'newsletter-app-local-serverlessdeploymentbucket-i2ih8b11ngsx', 'ACL': 'public-read'}
localstack_1  | 2020-10-18T15:52:47:DEBUG:localstack.services.cloudformation.cloudformation_starter: Currently processing stack resource newsletter-app-local/ServerlessDeploymentBucketPolicy: None
localstack_1  | 2020-10-18T15:52:47:DEBUG:localstack.services.cloudformation.cloudformation_starter: Deploying CloudFormation resource (update=False, exists=False, updateable=False): {'Type': 'AWS::S3::BucketPolicy', 'Properties': {'Bucket': 'newsletter-app-local-serverlessdeploymentbucket-i2ih8b11ngsx', 'PolicyDocument': {'Statement': [{'Action': 's3:*', 'Effect': 'Deny', 'Principal': '*', 'Resource': ['arn:aws:s3:::newsletter-app-local-serverlessdeploymentbucket-i2ih8b11ngsx/*'], 'Condition': {'Bool': {'aws:SecureTransport': False}}}]}}}
localstack_1  | 2020-10-18T15:52:47:DEBUG:localstack.utils.cloudformation.template_deployer: Running action "create" for resource type "S3::BucketPolicy" id "ServerlessDeploymentBucketPolicy"
localstack_1  | 2020-10-18T15:52:47:DEBUG:localstack.utils.cloudfor

The second one ends with botocore.errorfactory.NotFoundException: An error occurred (NotFoundException) when calling the GetStage operation: Invalid stage identifier specified Could it be some kind of race condition?

My setup:

    MacOS 10.15.6
    Docker Desktop 2.4.0.0
    node v12.12.0

docker-compose.yml

version: "3.8"
services:
  localstack:
    image: localstack/localstack:latest
    network_mode: bridge
    ports:
      - "4566:4566"
      - "4571:4571"
    environment:
      - SERVICES=s3,lambda,cloudformation,apigateway,dynamodb,sts,iam
      - HOST_TMP_FOLDER=${TMPDIR}
      - DEBUG=true
      - DOCKER_HOST=unix:///var/run/docker.sock
    volumes:
      - "${TMPDIR:-/tmp/localstack}:/tmp/localstack"
      - "/var/run/docker.sock:/var/run/docker.sock"

Run with TMPDIR=./localstack-tmp$TMPDIR docker-compose up And rm -rf ./localstack-tmp for cleanup after each run

sls

Framework Core: 2.6.0
Plugin: 4.0.4
SDK: 2.3.2
Components: 3.2.1

serverless.ts

import type { Serverless } from 'serverless/aws';

const serverlessConfiguration: Serverless = {
  service: {
    name: 'newsletter-app',
  },
  frameworkVersion: '2',
  custom: {
    webpack: {
      webpackConfig: './webpack.config.js',
      includeModules: true
    },
    localstack: {
      stages: ['local'],
      docker: { 
        sudo: true
       }
    }
  },
  plugins: ['serverless-webpack', 'serverless-localstack'],
  provider: {
    name: 'aws',
    runtime: 'nodejs12.x',
    apiGateway: {
      minimumCompressionSize: 1024,
    },
    environment: {
      AWS_NODEJS_CONNECTION_REUSE_ENABLED: '1',
    },
  },
  functions: {
    register: {
      handler: 'handler.register',
      events: [
        {
          http: {
            method: 'post',
            path: 'register',
          }
        }
      ]
    }
  },
}

module.exports = serverlessConfiguration;

I'm running it every time with sls deploy --stage local after the localstack is ready

Issue is synchronized with this Jira Task by Unito

grzegorz-bielski avatar Oct 18 '20 16:10 grzegorz-bielski

I also experience this issue with localstack/localstack:latest on both macos and ubuntu 20.20

edholland avatar Oct 23 '20 21:10 edholland

Same here: while calling API gateway => Lambda, got this:

"Unable to run Lambda function on API Gateway message: An error occurred (NotFoundException) when calling the GetStage operation: Invalid stage identifier specified Traceback (most recent call last):"

sls deployment also has some problems, if I put region, then it failed; if I put mountCode: true, deployment failed. Without them, it got deployed.

I use python

eragon-ni avatar Oct 26 '20 03:10 eragon-ni

Same here. Did you try to run awslocal apigateway get-stages --rest-api-id <api-id> ? In my case it is empty, however the same template is working in live. Also the cloudformation describe-stack-events doesn't show anything meaningful.

MatteoGioioso avatar Nov 19 '20 05:11 MatteoGioioso

I also experience this! When requesting my API I get the following error: NotFoundException: An error occurred (NotFoundException) when calling the GetStage operation: Invalid stage identifier specified

Anyone with a fix to this issue?

martin-sommerseth avatar Nov 25 '20 12:11 martin-sommerseth

I encountered the same error. For my own issue the superficial workaround was to add an explicit DependsOn directive from my AWS::Serverless::API resource to all AWS::Serverless::Function resources that were referred to in the API swagger definition.

The deeper cause is a corner case issue in the way moto/cloudformation/parsing.py and localstack/services/cloudformation/cloudformation_starter.py interact when resources are coming in 'incorrect' dependency order and when there are no DependsOn directives to help moto. When moto then raises an exception it gets swallowed by localstack initialize_resources which then takes over for subsequent dependency passes in its run_dependencies_deployment_loop.

Problem seems to be that any remaining top-level resources of cloudformation template json get discarded here.

Issue arises with a cloudformation template with following resources in this order:

  1. fooLambda: a AWS::Lambda::Function that refers to fooLambdaRole but without an explicit DependsOn directive
  2. fooLambdaRole: an AWS::IAM::Role
  3. fooAPI: an AWS::ApiGateway::RestApi with a swagger definition containing a Ref to fooLambda (w/o a DependsOn)
  4. fooDeployment and fooStage: AWS::ApiGateway::Deployment and AWS::ApiGateway::Stage resources respectively

When deploying the fooDeployment and fooStage resources don't get created at all and an a rest API call then fails with the NotFoundException: An error occurred (NotFoundException) when calling the GetStage operation: Invalid stage identifier specified.

If the order of 1. and 2. are flipped, or if an appropriate DependsOn directive is added to either fooLambda or fooAPI , then fooLambdaRole gets created before fooLambda before fooAPI and everything works as expected.

What happens is that the moto<->localstack interaction postpones fooLambda creation to a second pass because the fooLambdaRole is not yet created. This causes fooAPI swagger reference to fooLambda to raise an exception and fooDeployment and fooStage are never iterated by moto. As fooAPI and fooLambda appear in dependencies structure they will be properly created by localstack in secondary pass, but fooDeployment and fooStage don't and won't.

The DependsOn directive fixes the issue for me, but I don't think this is required by AWS itself. This was hard to debug as the actual proximal missing Ref exception by fooAPI was swallowed.

I suspect the issues others are having might result from a similar template configuration exception that gets swallowed and which prevents subsequent resource creation. Especially when using AWS::Serverless stuff, where the sam-translate seems to create the underlying resources in funky order and without those DependsOn directives

iridiankin avatar Dec 28 '20 21:12 iridiankin

Thanks for the update @iridiankin @martin-sommerseth @MatteoGioioso .

The deeper cause is a corner case issue in the way moto/cloudformation/parsing.py and localstack/services/cloudformation/cloudformation_starter.py interact when resources are coming in 'incorrect' dependency order and when there are no DependsOn directives to help moto. When moto then raises an exception it gets swallowed by localstack initialize_resources which then takes over for subsequent dependency passes in its run_dependencies_deployment_loop.

Great analysis, thanks for digging into this. Please note that we have recently pushed some significant changes - in essence, the new CloudFormation implementation in LocalStack is now entirely independent of moto's (i.e., no longer using the convoluted integration with parsing.py, etc).

Can you please pull the latest Docker image and give it another try? Please let us know if the problem still persists with latest - we'll be happy to look into it, if we can get to a reproducible test case with the new version. Thanks for your help!

whummer avatar Dec 28 '20 21:12 whummer

I fixed this issue adding DependsOn: on the lambdas:

DependsOn:
  - SomeSQS
  - SomeBucket

CloudFormation logs will complain unrecognized property 'DependsOn' but this seems to help localstack.

bertrandmc avatar Mar 18 '22 09:03 bertrandmc

Closing this issue due to inactivity. Please let us know if you still experience issues with the latest version of the serverless-plugin, and the latest localstack version.

steffyP avatar Oct 13 '23 09:10 steffyP