1.13.1: Invalid lambda response received: Lambda response must be valid json

[BR0kEN-]

Description:

sam local start-api stopped triggering Lambda by HTTP request. Downgrading to 1.12.0 gives the expected result.

Steps to reproduce:

sam build --use-container --debug
sam local start-api --port 4004 --docker-network host --skip-pull-image --debug &
curl -X POST http://127.0.0.1:4004/api/v1/app/add

Observed result:

2020-12-02 19:41:11,763 | Constructed String representation of Event to invoke Lambda. Event: {"body": null, "headers": {"Accept": "*/*", "Accept-Encoding": "gzip, deflate", "Connection": "keep-alive", "Content-Length": "0", "Host": "127.0.0.1:4004", "User-Agent": "python-requests/2.23.0", "X-Forwarded-Port": "4004", "X-Forwarded-Proto": "http"}, "httpMethod": "POST", "isBase64Encoded": false, "multiValueHeaders": {"Accept": ["*/*"], "Accept-Encoding": ["gzip, deflate"], "Connection": ["keep-alive"], "Content-Length": ["0"], "Host": ["127.0.0.1:4004"], "User-Agent": ["python-requests/2.23.0"], "X-Forwarded-Port": ["4004"], "X-Forwarded-Proto": ["http"]}, "multiValueQueryStringParameters": null, "path": "/api/v1/app/add", "pathParameters": {"schema_app": "app", "schema_version": "v1"}, "queryStringParameters": null, "requestContext": {"accountId": "123456789012", "apiId": "1234567890", "domainName": "127.0.0.1:4004", "extendedRequestId": null, "httpMethod": "POST", "identity": {"accountId": null, "apiKey": null, "caller": null, "cognitoAuthenticationProvider": null, "cognitoAuthenticationType": null, "cognitoIdentityPoolId": null, "sourceIp": "127.0.0.1", "user": null, "userAgent": "Custom User Agent String", "userArn": null}, "path": "/api/{schema_version}/{schema_app}/add", "protocol": "HTTP/1.1", "requestId": "b5ee986a-61f4-4954-b68b-c2af1457d70c", "requestTime": "02/Dec/2020:15:39:25 +0000", "requestTimeEpoch": 1606923565, "resourceId": "123456", "resourcePath": "/api/{schema_version}/{schema_app}/add", "stage": "staging"}, "resource": "/api/{schema_version}/{schema_app}/add", "stageVariables": null, "version": "1.0"}
2020-12-02 19:41:11,764 | Found one Lambda function with name 'Locator'
2020-12-02 19:41:11,764 | Invoking handler_locator.handle (python3.7)
2020-12-02 19:41:11,764 | Environment variables overrides data is standard format
2020-12-02 19:41:11,764 | Resolving code path. Cwd=/Users/BR0kEN/projects/SANITIZED/.aws-sam/build, CodeUri=Locator
2020-12-02 19:41:11,764 | Resolved absolute path to code is /Users/BR0kEN/projects/SANITIZED/.aws-sam/build/Locator
2020-12-02 19:41:11,764 | Code /Users/BR0kEN/projects/SANITIZED/.aws-sam/build/Locator is not a zip/jar file
2020-12-02 19:41:11,783 | Requested to skip pulling images ...

2020-12-02 19:41:11,783 | Mounting /Users/BR0kEN/projects/SANITIZED/.aws-sam/build/Locator as /var/task:ro,delegated inside runtime container
2020-12-02 19:41:12,269 | Starting a timer for 180 seconds for function 'Locator'
2020-12-02 19:41:13,118 | No response from invoke container for Locator
2020-12-02 19:41:13,119 | Invalid lambda response received: Lambda response must be valid json
2020-12-02 19:41:13 127.0.0.1 - - [02/Dec/2020 19:41:13] "POST /api/v1/app/add HTTP/1.1" 502 -

Expected result:

2020-12-02 19:43:51,479 | Constructed String representation of Event to invoke Lambda. Event: {"body": null, "headers": {"Accept": "*/*", "Accept-Encoding": "gzip, deflate", "Connection": "keep-alive", "Content-Length": "0", "Host": "127.0.0.1:4004", "User-Agent": "python-requests/2.23.0", "X-Forwarded-Port": "4004", "X-Forwarded-Proto": "http"}, "httpMethod": "POST", "isBase64Encoded": false, "multiValueHeaders": {"Accept": ["*/*"], "Accept-Encoding": ["gzip, deflate"], "Connection": ["keep-alive"], "Content-Length": ["0"], "Host": ["127.0.0.1:4004"], "User-Agent": ["python-requests/2.23.0"], "X-Forwarded-Port": ["4004"], "X-Forwarded-Proto": ["http"]}, "multiValueQueryStringParameters": null, "path": "/api/v1/app/add", "pathParameters": {"schema_app": "app", "schema_version": "v1"}, "queryStringParameters": null, "requestContext": {"accountId": "123456789012", "apiId": "1234567890", "domainName": "127.0.0.1:4004", "extendedRequestId": null, "httpMethod": "POST", "identity": {"accountId": null, "apiKey": null, "caller": null, "cognitoAuthenticationProvider": null, "cognitoAuthenticationType": null, "cognitoIdentityPoolId": null, "sourceIp": "127.0.0.1", "user": null, "userAgent": "Custom User Agent String", "userArn": null}, "path": "/api/{schema_version}/{schema_app}/add", "protocol": "HTTP/1.1", "requestId": "03b60fd2-78ab-4fc4-bcfa-930e57bfd9ee", "requestTime": "02/Dec/2020:15:43:40 +0000", "requestTimeEpoch": 1606923820, "resourceId": "123456", "resourcePath": "/api/{schema_version}/{schema_app}/add", "stage": "staging"}, "resource": "/api/{schema_version}/{schema_app}/add", "stageVariables": null, "version": "1.0"}
2020-12-02 19:43:51,479 | Found one Lambda function with name 'Locator'
2020-12-02 19:43:51,480 | Invoking handler_locator.handle (python3.7)
2020-12-02 19:43:51,480 | Environment variables overrides data is standard format
2020-12-02 19:43:51,480 | Loading AWS credentials from session with profile 'None'
2020-12-02 19:43:51,492 | Resolving code path. Cwd=/Users/BR0kEN/projects/SANITIZED/.aws-sam/build, CodeUri=Locator
2020-12-02 19:43:51,493 | Resolved absolute path to code is /Users/BR0kEN/projects/SANITIZED/.aws-sam/build/Locator
2020-12-02 19:43:51,493 | Code /Users/BR0kEN/projects/SANITIZED/.aws-sam/build/Locator is not a zip/jar file
2020-12-02 19:43:51,500 | Image was not found.
Building image.........
2020-12-02 19:43:51,831 | Requested to skip pulling images ...

2020-12-02 19:43:51,832 | Mounting /Users/BR0kEN/projects/SANITIZED/.aws-sam/build/Locator as /var/task:ro,delegated inside runtime container
2020-12-02 19:43:52,374 | Starting a timer for 180 seconds for function 'Locator'
START RequestId: e1cdfb2a-7475-1d51-6178-88c4176b300c Version: $LATEST
[ERROR]	2020-12-02T15:43:53.738Z	e1cdfb2a-7475-1d51-6178-88c4176b300c	POST: handler failed.
Traceback (most recent call last):
  File "/var/task/src/controller.py", line 130, in _get_data_document_prepared_for_storage
    document = self._schema.get_data_document(request.body, update)
  File "/var/task/src/schema/schema.py", line 117, in get_data_document
    raise ValidationError(["no data provided"])
src.validation.errors.ValidationError: ['no data provided']

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/var/task/src/handler/handler.py", line 149, in handle_request
    return _handlers[method](HandlerRequest(method, resource, body, query))
  File "/var/task/src/controller.py", line 31, in create
    fields=self._get_data_document_prepared_for_storage(request, update=False),
  File "/var/task/src/controller.py", line 132, in _get_data_document_prepared_for_storage
    raise HandlerError(error_code, {"body": error.errors})
src.handler.handler.HandlerError: Invalid document
END RequestId: e1cdfb2a-7475-1d51-6178-88c4176b300c
REPORT RequestId: e1cdfb2a-7475-1d51-6178-88c4176b300c	Init Duration: 1349.40 ms	Duration: 46.97 ms	Billed Duration: 100 ms	Memory Size: 128 MB	Max Memory Used: 32 MB
2020-12-02 19:43:53 127.0.0.1 - - [02/Dec/2020 19:43:53] "POST /api/v1/app/add HTTP/1.1" 400 -

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

1. OS: macOS Big Sur 11.0.1 (20B29)
2. sam --version: 1.13.1

[sdwvit]

is there any workaround available? how do I downgrade?

[BR0kEN-]

@sdwvit

pip3 install aws-sam-cli==1.12.0

[AaronDDM]

Can confirm we are experiencing this. It did not occur in versions 1.3.0, 1.6.0. But I am not sure what version this bug was introduced in - we are getting this exact same issue in 1.13.2.

[smalec]

I'm getting the same error while trying to complete official tutorial: https://docs.aws.amazon.com/serverless-application-model/latest/developerguide/serverless-getting-started-hello-world.html.

Downgrading to 1.12.0 is not an option for those who use Lambda Images.

[meetreks]

Getting the same error as well. Looks like a known bug. Any resolution will be really helpful. Error notes attached below...

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
2020-12-08 20:13:25 * Running on http://127.0.0.1:3000/ (Press CTRL+C to quit)
Invoking app.lambda_handler (python3.6)
Skip pulling image and use local one: amazon/aws-sam-cli-emulation-image-python3.6:rapid-1.13.2.

Mounting C:\Users\rekharamesh\sai-sam-model.aws-sam\build\HelloWorldFunction as /var/task:ro,delegated inside runtime container
No response from invoke container for HelloWorldFunction
Invalid lambda response received: Lambda response must be valid json
2020-12-08 20:14:03 127.0.0.1 - - [08/Dec/2020 20:14:03] "←[35m←[1mGET /hello HTTP/1.1←[0m" 502 -
2020-12-08 20:14:03 127.0.0.1 - - [08/Dec/2020 20:14:03] "←[31m←[1mGET /favicon.ico HTTP/1.1←[0m" 403 -
Invoking app.lambda_handler (python3.6)
Skip pulling image and use local one: amazon/aws-sam-cli-emulation-image-python3.6:rapid-1.13.2.

Mounting C:\Users\rekharamesh\sai-sam-model.aws-sam\build\HelloWorldFunction as /var/task:ro,delegated inside runtime container
No response from invoke container for HelloWorldFunction
Invalid lambda response received: Lambda response must be valid json
2020-12-08 20:14:25 127.0.0.1 - - [08/Dec/2020 20:14:25] "←[35m←[1mGET /hello HTTP/1.1←[0m" 502 -
2020-12-08 20:14:25 127.0.0.1 - - [08/Dec/2020 20:14:25] "←[31m←[1mGET /favicon.ico HTTP/1.1←[0m" 403 -

[jefrnc]

I am having the same error 🤷‍♂️

[jfuss]

So I was doing some digging on #2436 and I think they are both related.

So between 1.12 and 1.13, we changed how we communicate with the container. In 1.12, we just execute the container to run the code. With 1.13, we updated to use aws-lambda-rie. aws-lambda-rie stands up an endpoint within the container to communicate with the runtime itself. Since we are not communicating over http with the container, SAM CLI exposes a port to communicate with. From what I can gather, Docker will not let you expose a port if you connect to the 'host' network. The problem is Docker doesn't fail if you configure a port and run on the host network, why docker why!?!?

This is why SAM CLI cannot communicate with the local function. I need to do some deeper investigation to see how we can get around this docker limitation. I am not trilled to have to move back to executing the container. Communicating over http gives us much more control and allows us to integrate nicely with aws-lambda-rie. Open to suggestion on this.

This only appears to break for the host network, so if you drop the --docker-network host or provide a non host network thing should work as expected.