search

aws / aws-sam-cli

CLI tool to build, test, debug, and deploy Serverless applications using AWS SAM
https://aws.amazon.com/serverless/sam/
Apache License 2.0
6.51k stars 1.17k forks source link

Missing error handling in local Lambda environment for custom runtime #1205

Closed philipp94831 closed 5 years ago

philipp94831 commented 5 years ago

Description

I built a custom runtime. When running tests locally as documented, runtime errors are logged properly but the response payload is empty and FunctionError is not set. When deploying the Lambda to AWS and invoking it with the same payload, the response contains errorMessage and errorType, as well as the FunctionError field. Errors are returned as documented: https://github.com/bakdata/aws-lambda-r-runtime/blob/5793c17e9259fd93622a9162ee65a284cf029df2/runtime/src/runtime.R#L11 The concerning tests are annotated with unittest.skip: https://github.com/bakdata/aws-lambda-r-runtime/blob/5793c17e9259fd93622a9162ee65a284cf029df2/tests/test_runtime.py#L40

Steps to reproduce

Checkout 5793c17e9259fd93622a9162ee65a284cf029df2 of https://github.com/bakdata/aws-lambda-r-runtime/. The build process is described in the README.

Test execution:

pipenv install --dev
# Remove unittest.skip annotations
pipenv run python -m unittest

Observed result

Testing started at 21:09 ...
/usr/bin/python3.7 /home/philipp/.local/share/JetBrains/Toolbox/apps/PyCharm-P/ch-0/191.7141.48/helpers/pycharm/_jb_unittest_runner.py --target tests.test_runtime.TestRuntimeLayer.test_missing_source_file
Launching unittests with arguments python -m unittest tests.test_runtime.TestRuntimeLayer.test_missing_source_file in /home/philipp/dev/aws-lambda-r-runtime
2019-06-03 21:09:14 Using SAM Template at /home/philipp/dev/aws-lambda-r-runtime/template.yaml
2019-06-03 21:09:14 Changing event name from creating-client-class.iot-data to creating-client-class.iot-data-plane
2019-06-03 21:09:14 Changing event name from before-call.apigateway to before-call.api-gateway
2019-06-03 21:09:14 Changing event name from request-created.machinelearning.Predict to request-created.machine-learning.Predict
2019-06-03 21:09:14 Changing event name from before-parameter-build.autoscaling.CreateLaunchConfiguration to before-parameter-build.auto-scaling.CreateLaunchConfiguration
2019-06-03 21:09:14 Changing event name from before-parameter-build.route53 to before-parameter-build.route-53
2019-06-03 21:09:14 Changing event name from request-created.cloudsearchdomain.Search to request-created.cloudsearch-domain.Search
2019-06-03 21:09:14 Changing event name from docs.*.autoscaling.CreateLaunchConfiguration.complete-section to docs.*.auto-scaling.CreateLaunchConfiguration.complete-section
2019-06-03 21:09:14 Changing event name from before-parameter-build.logs.CreateExportTask to before-parameter-build.cloudwatch-logs.CreateExportTask
2019-06-03 21:09:14 Changing event name from docs.*.logs.CreateExportTask.complete-section to docs.*.cloudwatch-logs.CreateExportTask.complete-section
2019-06-03 21:09:14 Changing event name from before-parameter-build.cloudsearchdomain.Search to before-parameter-build.cloudsearch-domain.Search
2019-06-03 21:09:14 Changing event name from docs.*.cloudsearchdomain.Search.complete-section to docs.*.cloudsearch-domain.Search.complete-section
2019-06-03 21:09:14 Changing event name from creating-client-class.iot-data to creating-client-class.iot-data-plane
2019-06-03 21:09:14 Changing event name from before-call.apigateway to before-call.api-gateway
2019-06-03 21:09:14 Changing event name from request-created.machinelearning.Predict to request-created.machine-learning.Predict
2019-06-03 21:09:14 Changing event name from before-parameter-build.autoscaling.CreateLaunchConfiguration to before-parameter-build.auto-scaling.CreateLaunchConfiguration
2019-06-03 21:09:14 Changing event name from before-parameter-build.route53 to before-parameter-build.route-53
2019-06-03 21:09:14 Changing event name from request-created.cloudsearchdomain.Search to request-created.cloudsearch-domain.Search
2019-06-03 21:09:14 Changing event name from docs.*.autoscaling.CreateLaunchConfiguration.complete-section to docs.*.auto-scaling.CreateLaunchConfiguration.complete-section
2019-06-03 21:09:14 Changing event name from before-parameter-build.logs.CreateExportTask to before-parameter-build.cloudwatch-logs.CreateExportTask
2019-06-03 21:09:14 Changing event name from docs.*.logs.CreateExportTask.complete-section to docs.*.cloudwatch-logs.CreateExportTask.complete-section
2019-06-03 21:09:14 Changing event name from before-parameter-build.cloudsearchdomain.Search to before-parameter-build.cloudsearch-domain.Search
2019-06-03 21:09:14 Changing event name from docs.*.cloudsearchdomain.Search.complete-section to docs.*.cloudsearch-domain.Search.complete-section
2019-06-03 21:09:14 local start_lambda command is called
2019-06-03 21:09:14 No Parameters detected in the template
2019-06-03 21:09:14 12 resources found in the template
2019-06-03 21:09:14 Found Serverless function with name='ExampleFunction' and CodeUri='tests/R/'
2019-06-03 21:09:14 Found Serverless function with name='LowerCaseExtensionFunction' and CodeUri='tests/R/'
2019-06-03 21:09:14 Found Serverless function with name='MissingFunctionFunction' and CodeUri='tests/R/'
2019-06-03 21:09:14 Found Serverless function with name='MissingSourceFileFunction' and CodeUri='tests/R/'
2019-06-03 21:09:14 Found Serverless function with name='MultipleArgumentsFunction' and CodeUri='tests/R/'
2019-06-03 21:09:14 Found Serverless function with name='VariableArgumentsFunction' and CodeUri='tests/R/'
2019-06-03 21:09:14 Found Serverless function with name='MatrixFunction' and CodeUri='tests/R/'
2019-06-03 21:09:14 Found Serverless function with name='MissingLibraryFunction' and CodeUri='tests/R/'
2019-06-03 21:09:14 Found Serverless function with name='AWSFunction' and CodeUri='tests/R/'
2019-06-03 21:09:14 Trying paths: ['/home/philipp/.docker/config.json', '/home/philipp/.dockercfg']
2019-06-03 21:09:14 Found file at path: /home/philipp/.docker/config.json
2019-06-03 21:09:14 Found 'auths' section
2019-06-03 21:09:14 Found 'credsStore' section
2019-06-03 21:09:14 http://localhost:None "GET /v1.35/_ping HTTP/1.1" 200 2
2019-06-03 21:09:14 Looking for credentials via: env
2019-06-03 21:09:14 Looking for credentials via: assume-role
2019-06-03 21:09:14 Looking for credentials via: shared-credentials-file
2019-06-03 21:09:14 Found credentials in shared credentials file: ~/.aws/credentials
2019-06-03 21:09:14 Loading JSON file: /home/philipp/.local/lib/python3.6/site-packages/botocore/data/endpoints.json
2019-06-03 21:09:14 Event choose-service-name: calling handler <function handle_service_name_alias at 0x7ffa90d73048>
2019-06-03 21:09:14 Loading JSON file: /home/philipp/.local/lib/python3.6/site-packages/botocore/data/lambda/2015-03-31/service-2.json
2019-06-03 21:09:14 Event creating-client-class.lambda: calling handler <function add_generate_presigned_url at 0x7ffa90d94950>
2019-06-03 21:09:14 The s3 config key is not a dictionary type, ignoring its value of: None
2019-06-03 21:09:14 Setting lambda timeout as (60, 60)
2019-06-03 21:09:14 Loading JSON file: /home/philipp/.local/lib/python3.6/site-packages/botocore/data/_retry.json
2019-06-03 21:09:14 Registering retry handlers for service: lambda
2019-06-03 21:09:14 Trying paths: ['/home/philipp/.docker/config.json', '/home/philipp/.dockercfg']
2019-06-03 21:09:14 Found file at path: /home/philipp/.docker/config.json
2019-06-03 21:09:14 Found 'auths' section
2019-06-03 21:09:14 Found 'credsStore' section
2019-06-03 21:09:14 Starting the Local Lambda Service. You can now invoke your Lambda Functions defined in your template through the endpoint.
2019-06-03 21:09:14 Localhost server is starting up. Multi-threading = True
2019-06-03 21:09:14  * Running on http://127.0.0.1:3001/ (Press CTRL+C to quit)
2019-06-03 21:09:23 Found one Lambda function with name 'MissingSourceFileFunction'
2019-06-03 21:09:23 Invoking missing.handler (provided)
2019-06-03 21:09:23 No environment variables found for function 'MissingSourceFileFunction'
2019-06-03 21:09:23 Environment variables overrides data is standard format
2019-06-03 21:09:23 Loading AWS credentials from session with profile 'default'
2019-06-03 21:09:23 Resolving code path. Cwd=/home/philipp/dev/aws-lambda-r-runtime, CodeUri=tests/R/
2019-06-03 21:09:23 Resolved absolute path to code is /home/philipp/dev/aws-lambda-r-runtime/tests/R
2019-06-03 21:09:23 Code /home/philipp/dev/aws-lambda-r-runtime/tests/R is not a zip/jar file
2019-06-03 21:09:23 RuntimeLayer is a local Layer in the template
2019-06-03 21:09:23 Resolving code path. Cwd=/home/philipp/dev/aws-lambda-r-runtime, CodeUri=runtime/build/layer/
2019-06-03 21:09:23 http://localhost:None "GET /v1.35/images/samcli/lambda:provided-f11d82370eb968051a7eec2e6/json HTTP/1.1" 200 None
2019-06-03 21:09:23 Building image...
2019-06-03 21:09:24 Looking for auth config
2019-06-03 21:09:25 http://localhost:None "POST /v1.35/build?t=samcli%2Flambda%3Aprovided-f11d82370eb968051a7eec2e6&q=False&nocache=False&rm=True&forcerm=False&pull=True HTTP/1.1" 200 None
2019-06-03 21:09:28 http://localhost:None "GET /v1.35/images/2aa60ad3e9c1/json HTTP/1.1" 200 None
2019-06-03 21:09:28 Trying paths: ['/home/philipp/.docker/config.json', '/home/philipp/.dockercfg']
2019-06-03 21:09:28 Found file at path: /home/philipp/.docker/config.json
2019-06-03 21:09:28 Found 'auths' section
2019-06-03 21:09:28 Found 'credsStore' section
2019-06-03 21:09:28 http://localhost:None "GET /v1.35/images/samcli/lambda:provided-f11d82370eb968051a7eec2e6/json HTTP/1.1" 200 None
2019-06-03 21:09:28 Requested to skip pulling images ...

2019-06-03 21:09:28 Mounting /home/philipp/dev/aws-lambda-r-runtime/tests/R as /var/task:ro,delegated inside runtime container
2019-06-03 21:09:28 http://localhost:None "POST /v1.35/containers/create HTTP/1.1" 201 201
2019-06-03 21:09:28 http://localhost:None "GET /v1.35/containers/a8621dcfa4493ba44c26e12d7478f3d4e862f8779fa0957627bcfa56a2a8e3bf/json HTTP/1.1" 200 None
2019-06-03 21:09:28 http://localhost:None "GET /v1.35/containers/a8621dcfa4493ba44c26e12d7478f3d4e862f8779fa0957627bcfa56a2a8e3bf/json HTTP/1.1" 200 None
2019-06-03 21:09:29 http://localhost:None "POST /v1.35/containers/a8621dcfa4493ba44c26e12d7478f3d4e862f8779fa0957627bcfa56a2a8e3bf/start HTTP/1.1" 204 0
2019-06-03 21:09:29 Starting a timer for 300 seconds for function 'MissingSourceFileFunction'
2019-06-03 21:09:29 http://localhost:None "GET /v1.35/containers/a8621dcfa4493ba44c26e12d7478f3d4e862f8779fa0957627bcfa56a2a8e3bf/json HTTP/1.1" 200 None
2019-06-03 21:09:29 http://localhost:None "POST /containers/a8621dcfa4493ba44c26e12d7478f3d4e862f8779fa0957627bcfa56a2a8e3bf/attach?stdout=1&stderr=1&logs=1&stream=1&stdin=0 HTTP/1.1" 101 0
2019-06-03 19:09:30 ERROR::error: Source file does not exist: missing.[R|r]
 2019-06-03 19:09:30 ERROR::error: get_source_file_name(file_base_name)
START RequestId: 52fdfc07-2182-154f-163f-5f0f9a621d72 Version: $LATEST
END RequestId: 52fdfc07-2182-154f-163f-5f0f9a621d72
REPORT RequestId: 52fdfc07-2182-154f-163f-5f0f9a621d72  Init Duration: 521.31 ms    Duration: 0.00 ms   Billed Duration: 100 ms Memory Size: 3008 MB    Max Memory Used: 71 MB  
{
  "errorType": "simpleError",
  "errorMessage": "Error in get_source_file_name(file_base_name): Source file does not exist: missing.[R|r]\n"
}
2019-06-03 21:09:30 http://localhost:None "GET /v1.35/containers/a8621dcfa4493ba44c26e12d7478f3d4e862f8779fa0957627bcfa56a2a8e3bf/json HTTP/1.1" 200 None
2019-06-03 21:09:30 http://localhost:None "DELETE /v1.35/containers/a8621dcfa4493ba44c26e12d7478f3d4e862f8779fa0957627bcfa56a2a8e3bf?v=False&link=False&force=True HTTP/1.1" 204 0
2019-06-03 21:09:30 127.0.0.1 - - [03/Jun/2019 21:09:30] "POST /2015-03-31/functions/MissingSourceFileFunction/invocations HTTP/1.1" 200 -

Error
Traceback (most recent call last):
  File "/usr/lib/python3.7/unittest/case.py", line 59, in testPartExecutor
    yield
  File "/usr/lib/python3.7/unittest/case.py", line 615, in run
    testMethod()
  File "/home/philipp/dev/aws-lambda-r-runtime/tests/test_runtime.py", line 44, in test_missing_source_file
    json_payload = json.loads(raw_payload)
  File "/usr/lib/python3.7/json/__init__.py", line 348, in loads
    return _default_decoder.decode(s)
  File "/usr/lib/python3.7/json/decoder.py", line 337, in decode
    obj, end = self.raw_decode(s, idx=_w(s, 0).end())
  File "/usr/lib/python3.7/json/decoder.py", line 355, in raw_decode
    raise JSONDecodeError("Expecting value", s, err.value) from None
json.decoder.JSONDecodeError: Expecting value: line 1 column 1 (char 0)

Assertion failed

Assertion failed

Assertion failed

Assertion failed

Ran 1 test in 17.044s

FAILED (errors=1)

Process finished with exit code 1

Assertion failed

Assertion failed

Assertion failed

Assertion failed

Expected result

I expect the result payload to contain errorMessage and erroryType as well as FunctionError to be set.

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

  1. OS: Ubuntu 18.04.2 LTS
  2. sam --version: SAM CLI, version 0.16.1
invacuo commented 5 years ago

FWIW, I have a similar issue in ruby https://github.com/awslabs/aws-sam-cli/issues/1148

awood45 commented 5 years ago

I don't see where you're using the AWS SAM CLI in here, though I might be missing something. Can you give me the context of how you're running sam local, or which sam commands you're seeing an error with?

awood45 commented 5 years ago

I may be following this from the other opened issue #1148 - stand by while I validate that one.

awood45 commented 5 years ago

Closing this as an apparent duplicate of #1148 - feel free to reopen with more details if you think this is a distinct issue.