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
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.