Lambda log entries intermittently taking 1 hour+ to arrive in Cloudwatch
I have a nodejs 14.x lambda function that is called intermittently, sometimes 10 or so calls from 1s to 5 mins apart, and then is left for a couple of days, there is no real pattern - the system is currently coming online, so client use is sporadic.
Sometimes (I counted 5 out of the last 25 invocations, spread across 3 days) the last log entry we make is delayed, from anywhere between 4-5 mins up to 1h50m in one case. Our log entries are timestamped with the logger call time, and the timestamps are in line with the other log calls in the execution. Other calls in the same execution are logged pretty much immediately. The worst example is shown here
The function is using middy to log the returned data in an after handler, and is the same for all invocations (i.e. we are not doing a different log call etc in some cases). The function has provisioned concurrency enabled to reduce the cold startup times.
Can anyone explain why this should be? This is running in us-east-2, and attached to our own VPC.
- Newest
- Most votes
- Most comments
When your function returns to the caller, the Lambda service freezes the execution environment and nothing happens there until there is another invocation, or until the execution environment is shutdown.
If you look at your trace you see that the last log message is printed after the END message. My assumption is that because you are using Node.js, the event loop is not empty when you return. This external blog explains it very well. The following documentation explains how to use callbackWaitsForEmptyEventLoop to resolve this.
Relevant content
- Accepted Answerasked 8 months ago
AWS OFFICIALUpdated a year ago- AWS OFFICIALUpdated 2 years ago
- AWS OFFICIALUpdated a year ago
Thank you for this, an experiment seems to indicate this is the cause, though it will take me a few days to get into the live system to prove, so accepting now.
Appreciate you taking time to answer my question, all the best.