Question posted in 
I have a Node Lambda that I want to run each minute at the 45th second, so I built a script to invoke it once a minute.
const command = new InvokeCommand({
FunctionName: "BalancerNoVPC",
InvocationType: "Event",
});
const response = await client.send(command);
log.info("Req ID: " + response.$metadata.requestId);
This works fine, the invocation response has "StatusCode": 202 and logs show the invocation resolves with the request ID when it is supposed to do it
2024-12-06T10:15:45: INFO { m: 'Invoking Lambda' }
2024-12-06T10:15:45: INFO { m: 'Req ID: 3dc0a16d-a77d-4449-a1ff-92fbab6a929e' }
2024-12-06T10:15:45: INFO { m: 'Sleeping for 59916 ms' }
However, the execution takes a very long time when no cold start is involved. The first time it was invoked, the START event in CloudWatch was logged at 09:59:46.077Z and Init Duration was reported to be 736.98ms. It later timed out 30s later and exited, which is in line with what I’m expecting.
However, all subsequent invocation started more than 10s later than the expected.
2024-12-06T10:15:56.195Z START RequestId: 3dc0a16d-a77d-4449-a1ff-92fbab6a929e Version: $LATEST
2024-12-06T10:16:15.166Z END RequestId: 3dc0a16d-a77d-4449-a1ff-92fbab6a929e
2024-12-06T10:16:15.166Z REPORT RequestId: 3dc0a16d-a77d-4449-a1ff-92fbab6a929e Duration: 30000.00 ms Billed Duration: 30000 ms Memory Size: 128 MB Max Memory Used: 93 MB Status: timeout
Even though the START is logged at the 56th second, it still exited only ~20s later and logged a duration of 30s. So it seems like the start time for the duration is correct, but the actual execution starts more than 10s late. I am fairly sure about this because this lambda invokes other ones (which are delayed roughly 10s as well) that consistently miss the beginning of the minute (and log errors accordingly). The soft limit for concurrent executions is 1000 and I’m not anywhere close (I’m running around 21 lambdas per minute).
I thought this could be due to asynchronous invocations, however I’m observing the same behaviour both with InvocationType: "Event" and InvocationType: "RequestResponse". Ironically the only time it executes on time is when it performs a cold start, from then on it’s always late.
2
Answers
As suggested in the comments, I added a timeout to exit gracefully and this eliminated the delay in subsequent executions. Cannot find any reference to how timeouts can affect future executions but apparently they do add several seconds of delay.
TL;DR
You are probably experiencing multiple executions of the code outside your handler within the same Lambda execution environment because of the timeout.
Long version
Let’s say we have the following code that will trigger a timeout depending on current second:
And the logs for 6 invocations. The first 3 invocations ended with a timeout, while the rest did not.
What we can see from the logs:
{seconds: x} / { waitTime: 3500 }).Those logs are from the same log stream so we can assume that is coming from the same Lambda execution environment.
So it’s possible that your code outside the handler was executed each time even though you were in the same Lambda execution environment.
The fact that you fixed your timeout issue possibly results in a cleaner Lambda execution environment state after the first invocation. That could explain how it fixed your timeout delay for future warmed invocations.