sam local start-api fails at runtime when function layer uses !Sub and function contains environment variables whose values use !GetAtt against custom resources

[danludwig]

Description

Seems to be an issue when a function resource references a layer using !Sub against a parameter default and also contains environment variables whose values come from !GetAtt against custom cloudformation resources.

Steps to reproduce

1. Install aws sam cli version 0.21.0
2. git clone https://github.com/danludwig/aws-sam-cli-bug-reports.git
3. cd ./v0.21.0/lambda-layer-sub-start-api
4. sam local start-api --region us-east-2
5. Invoke http://127.0.0.1:3000/hello
6. Examine runtime error stack trace

Observed result

$ sam local start-api --region us-east-2 --debug
Using SAM Template at C:\Users\Dan\Code\sam-inits\aws-sam-cli-bug-reports\v0.21.0\lambda-layer-sub-start-api\template.yaml
Telemetry endpoint configured to be https://aws-serverless-tools-telemetry.us-west-2.amazonaws.com/metrics
local start-api command is called
Collected default values for parameters: {'LayerArn': 'arn:aws:lambda:us-east-2:266595731643:layer:danludwig-example-nodejs-lambda-layer:1'}
Unable to process properties of HelloWorldFunction.AWS::Serverless::Function
2 resources found in the template
Found Serverless function with name='HelloWorldFunction' and CodeUri='hello-world/'
Collected default values for parameters: {'LayerArn': 'arn:aws:lambda:us-east-2:266595731643:layer:danludwig-example-nodejs-lambda-layer:1'}
Unable to process properties of HelloWorldFunction.AWS::Serverless::Function
2 resources found in the template
Found '1' API Events in Serverless function with name 'HelloWorldFunction'
Detected Inline Swagger definition
Lambda function integration not found in Swagger document at path='/hello' method='get'
Found '0' APIs in resource 'ServerlessRestApi'
Removed duplicates from '0' Explicit APIs and '1' Implicit APIs to produce '1' APIs
1 APIs found in the template
Mounting HelloWorldFunction at http://127.0.0.1:3000/hello [GET]
You can now browse to the above endpoints to invoke your functions. You do not need to restart/reload SAM CLI while working on your functions, changes will be reflected instantly/automatically. You only need to restart SAM CLI if you update your AWS SAM template
Localhost server is starting up. Multi-threading = True
2019-09-12 18:04:32  * Running on http://127.0.0.1:3000/ (Press CTRL+C to quit)
Constructed String representation of Event to invoke Lambda. Event: {"httpMethod": "GET", "body": null, "resource": "/hello", "requestContext": {"resourceId": "123456", "apiId": "1234567890", "resourcePath": "/hello", "httpMethod": "GET", "requestId": "c6af9ac6-7b61-11e6-9a41-93e8deadbeef", "accountId": "123456789012", "stage": "Prod", "identity": {"apiKey": null, "userArn": null, "cognitoAuthenticationType": null, "caller": null, "userAgent": "Custom User Agent String", "user": null, "cognitoIdentityPoolId": null, "cognitoAuthenticationProvider": null, "sourceIp": "127.0.0.1", "accountId": null}, "extendedRequestId": null, "path": "/hello"}, "queryStringParameters": null, "multiValueQueryStringParameters": null, "headers": {"Host": "127.0.0.1:3000", "Connection": "keep-alive", "Cache-Control": "max-age=0", "Upgrade-Insecure-Requests": "1", "User-Agent": "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/76.0.3809.132 Safari/537.36", "Sec-Fetch-Mode": "navigate", "Sec-Fetch-User": "?1", "Accept": "text/html,application/xhtml+xml,application/xml;q=0.9,image/webp,image/apng,*/*;q=0.8,application/signed-exchange;v=b3", "Sec-Fetch-Site": "none", "Accept-Encoding": "gzip, deflate, br", "Accept-Language": "en-US,en;q=0.9", "Cookie": "wcsid=hCs8Ivnip489601s3m39N0T736ABa6jC; hblid=JqAxztzl5LQ9taUg3m39N0Tr3jBka7A6; _okdetect=%7B%22token%22%3A%2215591474291400%22%2C%22proto%22%3A%22http%3A%22%2C%22host%22%3A%22127.0.0.1%3A4040%22%7D; olfsk=olfsk07417538033967341; _okbk=cd4%3Dtrue%2Cvi5%3D0%2Cvi4%3D1559147429573%2Cvi3%3Dactive%2Cvi2%3Dfalse%2Cvi1%3Dfalse%2Ccd8%3Dchat%2Ccd6%3D0%2Ccd5%3Daway%2Ccd3%3Dfalse%2Ccd2%3D0%2Ccd1%3D0%2C; _ok=1700-237-10-3483; _oklv=1559160363583%2ChCs8Ivnip489601s3m39N0T736ABa6jC", "X-Forwarded-Proto": "http", "X-Forwarded-Port": "3000"}, "multiValueHeaders": {"Host": ["127.0.0.1:3000"], "Connection": ["keep-alive"], "Cache-Control": ["max-age=0"], "Upgrade-Insecure-Requests": ["1"], "User-Agent": ["Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/76.0.3809.132 Safari/537.36"], "Sec-Fetch-Mode": ["navigate"], "Sec-Fetch-User": ["?1"], "Accept": ["text/html,application/xhtml+xml,application/xml;q=0.9,image/webp,image/apng,*/*;q=0.8,application/signed-exchange;v=b3"], "Sec-Fetch-Site": ["none"], "Accept-Encoding": ["gzip, deflate, br"], "Accept-Language": ["en-US,en;q=0.9"], "Cookie": ["wcsid=hCs8Ivnip489601s3m39N0T736ABa6jC; hblid=JqAxztzl5LQ9taUg3m39N0Tr3jBka7A6; _okdetect=%7B%22token%22%3A%2215591474291400%22%2C%22proto%22%3A%22http%3A%22%2C%22host%22%3A%22127.0.0.1%3A4040%22%7D; olfsk=olfsk07417538033967341; _okbk=cd4%3Dtrue%2Cvi5%3D0%2Cvi4%3D1559147429573%2Cvi3%3Dactive%2Cvi2%3Dfalse%2Cvi1%3Dfalse%2Ccd8%3Dchat%2Ccd6%3D0%2Ccd5%3Daway%2Ccd3%3Dfalse%2Ccd2%3D0%2Ccd1%3D0%2C; _ok=1700-237-10-3483; _oklv=1559160363583%2ChCs8Ivnip489601s3m39N0T736ABa6jC"], "X-Forwarded-Proto": ["http"], "X-Forwarded-Port": ["3000"]}, "pathParameters": null, "stageVariables": null, "path": "/hello", "isBase64Encoded": false}
Found one Lambda function with name 'HelloWorldFunction'
Invoking app.lambdaHandler (nodejs10.x)
Environment variables overrides data is standard format
Loading AWS credentials from session with profile 'None'
2019-09-12 18:04:35 Found credentials in shared credentials file: ~/.aws/credentials
Resolving code path. Cwd=C:\Users\Dan\Code\sam-inits\aws-sam-cli-bug-reports\v0.21.0\lambda-layer-sub-start-api, CodeUri=hello-world/
Resolved absolute path to code is C:\Users\Dan\Code\sam-inits\aws-sam-cli-bug-reports\v0.21.0\lambda-layer-sub-start-api\hello-world
Code C:\Users\Dan\Code\sam-inits\aws-sam-cli-bug-reports\v0.21.0\lambda-layer-sub-start-api\hello-world is not a zip/jar file
Skipping building an image since no layers were defined

Fetching lambci/lambda:nodejs10.x Docker container image......
Mounting C:\Users\Dan\Code\sam-inits\aws-sam-cli-bug-reports\v0.21.0\lambda-layer-sub-start-api\hello-world as /var/task:ro,delegated inside runtime container
Starting a timer for 3 seconds for function 'HelloWorldFunction'
2019-09-12T22:04:37.161Z        undefined       ERROR   Uncaught Exception      {"errorType":"Runtime.ImportModuleError","errorMessage":"Error: Cannot find module 'danludwig-example-nodejs-lambda-layer'","stack":["Runtime.ImportModuleError: Error: Cannot find module 'danludwig-example-nodejs-lambda-layer'","    at _loadUserApp (/var/runtime/UserFunction.js:100:13)","    at Object.module.exports.load (/var/runtime/UserFunction.js:140:17)","    at Object.<anonymous> (/var/runtime/index.js:36:30)","    at Module._compile (internal/modules/cjs/loader.js:776:30)","    at Object.Module._extensions..js (internal/modules/cjs/loader.js:787:10)","    at Module.load (internal/modules/cjs/loader.js:653:32)","    at tryModuleLoad (internal/modules/cjs/loader.js:593:12)","    at Function.Module._load (internal/modules/cjs/loader.js:585:3)","    at Function.Module.runMain (internal/modules/cjs/loader.js:829:12)","    at startup (internal/bootstrap/node.js:283:19)"]}
START RequestId: 52fdfc07-2182-154f-163f-5f0f9a621d72 Version: $LATEST
END RequestId: 52fdfc07-2182-154f-163f-5f0f9a621d72
REPORT RequestId: 52fdfc07-2182-154f-163f-5f0f9a621d72     Duration: 0.00 ms       Billed Duration: 100 ms Memory Size: 128 MB     Max Memory Used: 42 MB  
{
  "errorType": "Runtime.ImportModuleError",
  "errorMessage": "Error: Cannot find module 'danludwig-example-nodejs-lambda-layer'"
}
Function returned an invalid response (must include one of: body, headers, multiValueHeaders or statusCode in the response object). Response received:
2019-09-12 18:04:37 127.0.0.1 - - [12/Sep/2019 18:04:37] "GET /hello HTTP/1.1" 502 -
2019-09-12 18:04:37 127.0.0.1 - - [12/Sep/2019 18:04:37] "GET /favicon.ico HTTP/1.1" 403 -

Expected result

$ sam local start-api --region us-east-2
Mounting HelloWorldFunction at http://127.0.0.1:3000/hello [GET]
You can now browse to the above endpoints to invoke your functions. You do not need to restart/reload SAM CLI while working on your functions, changes will be reflected instantly/automatically. You only need to restart SAM CLI if you update your AWS SAM template
2019-09-12 18:05:14  * Running on http://127.0.0.1:3000/ (Press CTRL+C to quit)
Invoking app.lambdaHandler (nodejs10.x)
2019-09-12 18:05:16 Found credentials in shared credentials file: ~/.aws/credentials
arn:aws:lambda:us-east-2:266595731643:layer:danludwig-example-nodejs-lambda-layer:1 is already cached. Skipping download
Requested to skip pulling images ...

Mounting C:\Users\Dan\Code\sam-inits\aws-sam-cli-bug-reports\v0.21.0\lambda-layer-sub-start-api\hello-world as /var/task:ro,delegated inside runtime container
START RequestId: 52fdfc07-2182-154f-163f-5f0f9a621d72 Version: $LATEST
END RequestId: 52fdfc07-2182-154f-163f-5f0f9a621d72
REPORT RequestId: 52fdfc07-2182-154f-163f-5f0f9a621d72     Duration: 6.63 ms       Billed Duration: 100 ms Memory Size: 128 MB     Max Memory Used: 42 MB  
No Content-Type given. Defaulting to 'application/json'.
2019-09-12 18:05:17 127.0.0.1 - - [12/Sep/2019 18:05:17] "GET /hello HTTP/1.1" 200 -
2019-09-12 18:05:17 127.0.0.1 - - [12/Sep/2019 18:05:17] "GET /favicon.ico HTTP/1.1" 403 -

Additional environment details (Ex: Windows, Mac, Amazon Linux etc)

1. OS: Windows 10
2. sam --version: 0.21.0

The bug does not seem to surface when environemnt variable values only use !Ref against template parameters.

Commenting out environment variables which use !GetAtt against a custom resource cause the builds to succeed. For example, the following will result in a successful build:

      Environment:
        Variables:
          SAFE_ENVIRONMENT_VARIABLE_1:
            !Ref TemplateParameterOne
          # OFFENDING_ENVIRONMENT_VARIABLE:
          #   !GetAtt MyCustomResource.Parameter.Value
          SAFE_ENVIRONMENT_VARIABLE_2:
            !Ref MyCustomResource

[jfuss]

@danludwig Thanks for the report. This is currently the same as #1386. I have an explanation of the bug here: #1386 (comment).

I am going to close this as a duplicate and will add this case into our smoke tests to verify.

[danludwig]

@jfuss are you sure this is a duplicate? This issue is with !Sub and sam local start-api. I wrote up #1407 which sounds like it is probably a duplicate of #1386. They are similar so both could have the same root cause, just wanted to verify.

[jfuss]

@danludwig Yes I am sure. If you look at the output, you can see "Unable to process properties of HelloWorldFunction.AWS::Serverless::Function", which means we could not resolve the function completely (explanation here #1386 (comment)). The other reason is because when you comment out the OFFENDING_ENVIRONMNET_VARIABLE, everything start working again, which is due to the CLI being able to resolve all the intrinsics.

I also did very that the initial repro steps work with the PR I have out.