Lambda Task Timed Out

0

I'm at the end of my tether with this, I've spent the last few days debugging and I can't figure it out... So I really hope you can help.

We have Laravel Vapor, which is a REST API Gateway that invokes a Lambda function. We've suddenly started getting "Task Timed Out" in our Lambda logs, which is resulting in a 504 in the response. But they're very random and can be on any url/method. The majority of requests are served, but they seem to be getting progressively worse and much more noticable. We haven't changed anything in these Lambdas that would cause anything like this and I've even logged some output to see if it's being hit inside the request on the Lambda. When it times out, it doesn't even hit it or log anything. It just starts the request and ends with a timeout 30 seconds later.

The lambda will happily serve a random number of requests, timeout, bootstrap itself, then start serving requests again. It started happening at exactly 2022-02-11 03:22AM UTC, but it was barely noticable at first at less than 1% of requests, now it's happening 10-20% of the time...

Has anyone else had this issue recently? Do you know what the cause could be for the Lambda function to hang and timeout before it even processes anything?

Really hope you can help.

Logs

START RequestId: 6d46f01e-a5c3-455a-8a66-c8f4611d3378 Version: 341
Loaded Composer autoload file
Preparing to add secrets to runtime
Injecting secret [GOOGLE_CHAT_LOG] into runtime.
Injecting secret [SALESFORCE_KEY] into runtime.
Injecting secret [SALESFORCE_SECRET] into runtime.
Preparing to boot FPM
Ensuring ready to start FPM
Starting FPM Process...
[09-Mar-2022 23:02:58] NOTICE: fpm is running, pid 11
Creating storage directory: /tmp/storage/app
Creating storage directory: /tmp/storage/bootstrap/cache
Creating storage directory: /tmp/storage/framework/cache
Creating storage directory: /tmp/storage/framework/views
Caching Laravel configuration
[09-Mar-2022 23:02:58] NOTICE: ready to handle connections
{
    "message": "Registering services...",
    "context": {
        "aws_request_id": "6d46f01e-a5c3-455a-8a66-c8f4611d3378"
    },
    "level": 100,
    "level_name": "DEBUG",
    "channel": "production",
    "datetime": "2022-03-09T23:02:58.982349+00:00",
    "extra": {}
}
END RequestId: 6d46f01e-a5c3-455a-8a66-c8f4611d3378
REPORT RequestId: 6d46f01e-a5c3-455a-8a66-c8f4611d3378	Duration: 9568.25 ms	Billed Duration: 10511 ms	Memory Size: 1024 MB	Max Memory Used: 173 MB	Init Duration: 942.58 ms	

START RequestId: 63a9a91b-bc1d-4c68-8463-66cb75985b60 Version: 341
{
    "message": "Registering services...",
    "context": {
        "aws_request_id": "63a9a91b-bc1d-4c68-8463-66cb75985b60"
    },
    "level": 100,
    "level_name": "DEBUG",
    "channel": "production",
    "datetime": "2022-03-09T23:03:10.654139+00:00",
    "extra": {}
}
END RequestId: 63a9a91b-bc1d-4c68-8463-66cb75985b60
REPORT RequestId: 63a9a91b-bc1d-4c68-8463-66cb75985b60	Duration: 742.54 ms	Billed Duration: 743 ms	Memory Size: 1024 MB	Max Memory Used: 173 MB	

START RequestId: 28daf037-7ba2-4dd9-8c75-ebc8438f842d Version: 341
{
    "message": "Registering services...",
    "context": {
        "aws_request_id": "28daf037-7ba2-4dd9-8c75-ebc8438f842d"
    },
    "level": 100,
    "level_name": "DEBUG",
    "channel": "production",
    "datetime": "2022-03-09T23:03:11.440119+00:00",
    "extra": {}
}
END RequestId: 28daf037-7ba2-4dd9-8c75-ebc8438f842d
REPORT RequestId: 28daf037-7ba2-4dd9-8c75-ebc8438f842d	Duration: 155.84 ms	Billed Duration: 156 ms	Memory Size: 1024 MB	Max Memory Used: 173 MB	

START RequestId: 1fb42599-b992-4942-bef3-d661ba06688a Version: 341
{
    "message": "Registering services...",
    "context": {
        "aws_request_id": "1fb42599-b992-4942-bef3-d661ba06688a"
    },
    "level": 100,
    "level_name": "DEBUG",
    "channel": "production",
    "datetime": "2022-03-09T23:03:12.563417+00:00",
    "extra": {}
}
END RequestId: 1fb42599-b992-4942-bef3-d661ba06688a
REPORT RequestId: 1fb42599-b992-4942-bef3-d661ba06688a	Duration: 118.53 ms	Billed Duration: 119 ms	Memory Size: 1024 MB	Max Memory Used: 173 MB	

START RequestId: 77cea2c8-5a65-47ab-a561-bc113b5556e5 Version: 341
{
    "message": "Registering services...",
    "context": {
        "aws_request_id": "77cea2c8-5a65-47ab-a561-bc113b5556e5"
    },
    "level": 100,
    "level_name": "DEBUG",
    "channel": "production",
    "datetime": "2022-03-09T23:03:14.835781+00:00",
    "extra": {}
}
END RequestId: 77cea2c8-5a65-47ab-a561-bc113b5556e5
REPORT RequestId: 77cea2c8-5a65-47ab-a561-bc113b5556e5	Duration: 12438.48 ms	Billed Duration: 12439 ms	Memory Size: 1024 MB	Max Memory Used: 173 MB	

START RequestId: 13973db2-9d28-4362-b5a8-953044b9450a Version: 341
END RequestId: 13973db2-9d28-4362-b5a8-953044b9450a
REPORT RequestId: 13973db2-9d28-4362-b5a8-953044b9450a	Duration: 30030.79 ms	Billed Duration: 30000 ms	Memory Size: 1024 MB	Max Memory Used: 173 MB	
2022-03-09T23:04:26.276Z 13973db2-9d28-4362-b5a8-953044b9450a Task timed out after 30.03 seconds

Loaded Composer autoload file
Preparing to add secrets to runtime
Injecting secret [CHATGO_TOKEN] into runtime.
Injecting secret [GOOGLE_CHAT_LOG] into runtime.
Injecting secret [PRESENTGO_SALT] into runtime.
Injecting secret [PRESENTGO_TOKEN] into runtime.
Injecting secret [SALESFORCE_KEY] into runtime.
Injecting secret [SALESFORCE_SECRET] into runtime.
Preparing to boot FPM
Ensuring ready to start FPM
Starting FPM Process...
[09-Mar-2022 23:04:26] NOTICE: fpm is running, pid 11
Caching Laravel configuration

START RequestId: 16794c27-a580-4146-b46f-a2ca7a015067 Version: 341
[09-Mar-2022 23:04:26] NOTICE: ready to handle connections
{
    "message": "Registering services...",
    "context": {
        "aws_request_id": "16794c27-a580-4146-b46f-a2ca7a015067"
    },
    "level": 100,
    "level_name": "DEBUG",
    "channel": "production",
    "datetime": "2022-03-09T23:04:27.710860+00:00",
    "extra": {}
}
END RequestId: 16794c27-a580-4146-b46f-a2ca7a015067
REPORT RequestId: 16794c27-a580-4146-b46f-a2ca7a015067	Duration: 8087.31 ms	Billed Duration: 8088 ms	Memory Size: 1024 MB	Max Memory Used: 175 MB	

START RequestId: ce332a20-d13a-41ba-b292-4cb807bab4b9 Version: 341
{
    "message": "Registering services...",
    "context": {
        "aws_request_id": "ce332a20-d13a-41ba-b292-4cb807bab4b9"
    },
    "level": 100,
    "level_name": "DEBUG",
    "channel": "production",
    "datetime": "2022-03-09T23:04:35.795969+00:00",
    "extra": {}
}
END RequestId: ce332a20-d13a-41ba-b292-4cb807bab4b9
REPORT RequestId: ce332a20-d13a-41ba-b292-4cb807bab4b9	Duration: 186.44 ms	Billed Duration: 187 ms	Memory Size: 1024 MB	Max Memory Used: 175 MB	

START RequestId: f550b6be-dd58-48f6-813d-8117b7f5622f Version: 341
{
    "message": "Registering services...",
    "context": {
        "aws_request_id": "f550b6be-dd58-48f6-813d-8117b7f5622f"
    },
    "level": 100,
    "level_name": "DEBUG",
    "channel": "production",
    "datetime": "2022-03-09T23:04:42.026286+00:00",
    "extra": {}
}

END RequestId: f550b6be-dd58-48f6-813d-8117b7f5622f
REPORT RequestId: f550b6be-dd58-48f6-813d-8117b7f5622f	Duration: 216.05 ms	Billed Duration: 217 ms	Memory Size: 1024 MB	Max Memory Used: 175 MB	
2 Answers
2

I would like to share my previous experience

The AWS API Gateway waits max 29 seconds for a response from a lambda function. After 29 seconds, if there is not response, the API Gateway will return a timeout to user request. So, when the lambda takes more than 29 seconds, I refer to this AWS Blog Post API Gateway ==> SQS ==> Lambda

hai
answered 2 years ago
1

It would seem that your Lambda function has a maximum runtime of 30 seconds - this is configurable and you can increase it. The maximum runtime is there to ensure that a runaway tasks (or things stuck in a loop) don't run forever.

The duration of your function is highly variable: some invocations run in under a second, others are taking 8 and 12 seconds to run. What's causing that? Is it possible that the delay you're seeing there is pushing runtimes beyond 30 seconds?

Definitely look at X-Ray even if you turn it back off again afterwards it may give you visibility.

Otherwise the other suggestion is: Raise a support case. They can look into the service and the logs around your function - definitely more visibility than we have from here (on the forum).

profile pictureAWS
EXPERT
answered 2 years ago
  • It's set to 30 because of API gateway and has always taken much less than 30 seconds to run. I increased to 90 seconds and the same thing happens. It's like the Lambda isn't being invoked properly. I'll check out x-ray, thanks.

  • Ok, having API Gateway in the mix will definitely give you a hard maximum for the Lambda function. So definitely check out why the function runtime is so variable.

You are not logged in. Log in to post an answer.

A good answer clearly answers the question and provides constructive feedback and encourages professional growth in the question asker.

Guidelines for Answering Questions