AWS API Gateway Cannot GET / when function sleeped for long time

Question

My current stack is AWS API Gateway --> AWS Lambda --> swagger-node + swagger-express-mw + aws-serverless-express.

So my Swagger API is hosted as one node.js Lambda Function and Invoked with aws_proxy from API Gateway. This works quite good. The only thing is that when the function sleeped for too long (cold start?) I get a Cannot GET / as Output from every URL I am calling first. From 2nd Request on, it runs very fast. Any ideas on that?

I don't think that it comes from API Gateway Integration Timeout as that are 30 seconds. The slowest invocation time of the function directly via lambda is around 2,5s and when it is called more often it is normally not more than 150ms. I also increased the Time of Lambda Timeout for that function to 10s so from there should also not come an error.

Logs from Test Request via API Gateway first Invocation

Response Body

Cannot GET /hello

Response Headers

{
    "x-powered-by": "Express",
    "x-content-type-options": "nosniff",
    "content-type": "text/html; charset=utf-8",
    "content-length": "18",
    "date": "Sun, 19 Feb 2017 15:00:11 GMT",
    "connection": "close",
    "X-Amzn-Trace-Id": "<TRACE-ID>"
}

Logs

Execution log for request test-request
Sun Feb 19 15:00:07 UTC 2017 : Starting execution for request: test-invoke-request
Sun Feb 19 15:00:07 UTC 2017 : HTTP Method: GET, Resource Path: /hello
Sun Feb 19 15:00:07 UTC 2017 : Method request path: {}
Sun Feb 19 15:00:07 UTC 2017 : Method request query string: {}
Sun Feb 19 15:00:07 UTC 2017 : Method request headers: {}
Sun Feb 19 15:00:07 UTC 2017 : Method request body before transformations: 
Sun Feb 19 15:00:07 UTC 2017 : Endpoint request URI: https://lambda.eu-central-1.amazonaws.com/2015-03-31/functions/arn:aws:lambda:eu-central-1:<ACCOUNT-ID>:function:api/invocations
Sun Feb 19 15:00:07 UTC 2017 : Endpoint request headers: {x-amzn-lambda-integration-tag=test-request, Authorization=**************************************************************************************************************************************************************************************************************************************************************************************************************************4b0637, X-Amz-Date=20170219T150007Z, x-amzn-apigateway-api-id=965h04axki, Accept=application/json, User-Agent=AmazonAPIGateway_965h04axki, X-Amz-Security-Token=<SECURITY-TOKEN>
Sun Feb 19 15:00:07 UTC 2017 : Endpoint request body after transformations: {"resource":"/hello","path":"/hello","httpMethod":"GET","headers":null,"queryStringParameters":null,"pathParameters":null,"stageVariables":null,"requestContext":{"accountId":"<ACCOUNT-ID>","resourceId":"ll6gw8","stage":"test-invoke-stage","requestId":"test-invoke-request","identity":{"cognitoIdentityPoolId":null,"accountId":"<ACCOUNT-ID>","cognitoIdentityId":null,"caller":"<ACCOUNT-ID>","apiKey":"test-invoke-api-key","sourceIp":"test-invoke-source-ip","accessKey":"<ACCESS-ID>","cognitoAuthenticationType":null,"cognitoAuthenticationProvider":null,"userArn":"arn:aws:iam::<ACCOUNT-ID>:root","userAgent":"Apache-HttpClient/4.5.x (Java/1.8.0_102)","user":"<ACCOUNT-ID>"},"resourcePath":"/hello","httpMethod":"GET","apiId":"965h04axki"},"body":null,"isBase64Encoded":false}
Sun Feb 19 15:00:11 UTC 2017 : Endpoint response body before transformations: {"statusCode":404,"body":"Cannot GET /hello\n","headers":{"x-powered-by":"Express","x-content-type-options":"nosniff","content-type":"text/html; charset=utf-8","content-length":"18","date":"Sun, 19 Feb 2017 15:00:11 GMT","connection":"close"},"isBase64Encoded":false}
Sun Feb 19 15:00:11 UTC 2017 : Endpoint response headers: {x-amzn-Remapped-Content-Length=0, x-amzn-RequestId=19f8554e-f6b4-11e6-8184-d3ccf0ccf643, Connection=keep-alive, Content-Length=267, Date=Sun, 19 Feb 2017 15:00:11 GMT, Content-Type=application/json}
Sun Feb 19 15:00:11 UTC 2017 : Method response body after transformations: Cannot GET /hello

Sun Feb 19 15:00:11 UTC 2017 : Method response headers: {x-powered-by=Express, x-content-type-options=nosniff, content-type=text/html; charset=utf-8, content-length=18, date=Sun, 19 Feb 2017 15:00:11 GMT, connection=close, X-Amzn-Trace-Id=Root=1-58a9b2f7-91fc7371e41d6ae9c2fbf64d}
Sun Feb 19 15:00:11 UTC 2017 : Successfully completed execution
Sun Feb 19 15:00:11 UTC 2017 : Method completed with status: 404

Logs from Test Request via API Gateway second Invocation

Response Body

"Hello, stranger!"

Response Headers

{
    "x-powered-by": "Express",
    "access-control-allow-origin": "*",
    "content-type": "application/json; charset=utf-8",
    "content-length": "18",
    "etag": "W/\"12-E1p7iNXxJ4trMdmFBhlU9Q\"",
    "date": "Mon, 13 Feb 2017 20:12:36 GMT",
    "connection": "close",
    "X-Amzn-Trace-Id": "<Trace-ID>"
}

Logs

Execution log for request test-request
Mon Feb 13 20:12:36 UTC 2017 : Starting execution for request: test-invoke-request
Mon Feb 13 20:12:36 UTC 2017 : HTTP Method: GET, Resource Path: /hello
Mon Feb 13 20:12:36 UTC 2017 : Method request path: {}
Mon Feb 13 20:12:36 UTC 2017 : Method request query string: {}
Mon Feb 13 20:12:36 UTC 2017 : Method request headers: {}
Mon Feb 13 20:12:36 UTC 2017 : Method request body before transformations: 
Mon Feb 13 20:12:36 UTC 2017 : Endpoint request URI: https://lambda.eu-central-1.amazonaws.com/2015-03-31/functions/arn:aws:lambda:eu-central-1:<LAMBDA-FUNCTION-ID>:function:api/invocations
Mon Feb 13 20:12:36 UTC 2017 : Endpoint request headers: {x-amzn-lambda-integration-tag=test-request, Authorization=*******************************************************************************************************************************************************************************************************************************************************************************************************************************************3e1b18, X-Amz-Date=20170213T201236Z, x-amzn-apigateway-api-id=965h04axki, X-Amz-Source-Arn=arn:aws:execute-api:eu-central-1:<ACCOUNT-ID>:965h04axki/null/GET/hello, Accept=application/json, User-Agent=AmazonAPIGateway_965h04axki, X-Amz-Security-Token=<TOKEN>
Mon Feb 13 20:12:36 UTC 2017 : Endpoint request body after transformations: {"resource":"/hello","path":"/hello","httpMethod":"GET","headers":null,"queryStringParameters":null,"pathParameters":null,"stageVariables":null,"requestContext":{"accountId":"<ACCOUNT-ID>","resourceId":"ll6gw8","stage":"test-invoke-stage","requestId":"test-invoke-request","identity":{"cognitoIdentityPoolId":null,"accountId":"<ACCOUNT-ID>","cognitoIdentityId":null,"caller":"427402682812","apiKey":"test-invoke-api-key","sourceIp":"test-invoke-source-ip","accessKey":"<ACCESS-KEY>","cognitoAuthenticationType":null,"cognitoAuthenticationProvider":null,"userArn":"arn:aws:iam::<ACCOUNT-ID>:root","userAgent":"Apache-HttpClient/4.5.x (Java/1.8.0_102)","user":"<ACCOUNT-ID>"},"resourcePath":"/hello","httpMethod":"GET","apiId":"965h04axki"},"body":null,"isBase64Encoded":false}
Mon Feb 13 20:12:36 UTC 2017 : Endpoint response body before transformations: {"statusCode":200,"body":"\"Hello, stranger!\"","headers":{"x-powered-by":"Express","access-control-allow-origin":"*","content-type":"application/json; charset=utf-8","content-length":"18","etag":"W/\"12-E1p7iNXxJ4trMdmFBhlU9Q\"","date":"Mon, 13 Feb 2017 20:12:36 GMT","connection":"close"},"isBase64Encoded":false}
Mon Feb 13 20:12:36 UTC 2017 : Endpoint response headers: {x-amzn-Remapped-Content-Length=0, x-amzn-RequestId=c3354327-f228-11e6-8c1d-ed11cc413770, Connection=keep-alive, Content-Length=315, Date=Mon, 13 Feb 2017 20:12:36 GMT, Content-Type=application/json}
Mon Feb 13 20:12:36 UTC 2017 : Method response body after transformations: "Hello, stranger!"
Mon Feb 13 20:12:36 UTC 2017 : Method response headers: {x-powered-by=Express, access-control-allow-origin=*, content-type=application/json; charset=utf-8, content-length=18, etag=W/"12-E1p7iNXxJ4trMdmFBhlU9Q", date=Mon, 13 Feb 2017 20:12:36 GMT, connection=close, X-Amzn-Trace-Id=Root=1-58a21334-8ea6c4b5944eebb873bc7d2e}
Mon Feb 13 20:12:36 UTC 2017 : Successfully completed execution
Mon Feb 13 20:12:36 UTC 2017 : Method completed with status: 200

Answer 1

I think the response "Cannot GET /" is coming from your Lambda function itself. Can you check API Gateway CW logs (or Test Invoke feature in console) to see what's different in the integration request and response in the first call?