How to log timed out Lambda invocations

Strange, there are no error logs…

Fortunately, we have enabled X-Ray tracing and I’m able to quickly find one of the traces for these 5XX errors.

Sadly, the traces don’t offer any explanation for the error.

After fumbling around aimlessly for a while for clues, a moment of genius struck. I just so happens to notice the function’s timeout value is set to 1 second. The Duration from the trace was 1.3 seconds.

Aha, the Lambda function probably timed out! Now that I have a suspected cause, I’m able to get the confirmation by looking for "Task timed out"messages in the logs. And sure enough, I'm able to find them.

And now I can start the real investigation into what happened and find out what caused the function to time out.

This would have been much easier if only I had an error log message that informs me about these time outs!

If all this sounded awful, then you’re in luck. Today, we’re gonna see how we can log an error message when a Lambda function times out.

Pre-emptively log timeout messages

Hold on to your hats, because the solution is mind-bogglingly simple! All you have to do is to log the error message just before the invocation times out ;-)

The context object for a Node.js function has a very useful method called getRemainingTimeInMillis. It returns the number of milliseconds left in the current invocation. So, we can schedule a callback to be actioned JUST before the function times out and preemptively logs the timeout event.

Sure, you might get the odd false positives in the logs. But that is still a lot better than not having any error logs when the function does time out!

This is a cross-cutting concern that should be encapsulated into a middleware. If you’re using Node.js then you should consider using the middy middleware engine. Here, I can write a very simple middleware to log timeout errors:

Couple of things to note about this code:

• ln21: we schedule a callback to be executed 10ms before the function times out.
• ln33/ln38: if the function completes before the scheduled callback runs then we will cancel the callback using bluebird's Promise.cancel.
• ln18: this is important. If you don't set callbackWaitsForEmptyEventLoopto false then the invocation won't complete until the callback has executed. That would make every invocation last longer!
• ln24: capture the invocation event when the function times out. This is useful for replaying the invocation locally to debug the problem.
• ln2: we are using the logger from dazn-lambda-powertools so it'll automatically populate any captured correlation IDs in the logs. For more details, check the README in the repo.

If you want to see this middleware in action then take a look at this demo project. Once deployed, I can curl the HTTP endpoint and see an error message for timeouts.

So that’s it! The approach is really simple. And we will add this middleware to the dazn-lambda-powertools project soon so you will be able to use it via NPM.

Hi, my name is Yan Cui. I’m an AWS Serverless Hero and the author of Production-Ready Serverless. I have run production workload at scale in AWS for nearly 10 years and I have been an architect or principal engineer with a variety of industries ranging from banking, e-commerce, sports streaming to mobile gaming. I currently work as an independent consultant focused on AWS and serverless.

You can contact me via Email, Twitter and LinkedIn.

Check out my new course, Complete Guide to AWS Step Functions.

In this course, we’ll cover everything you need to know to use AWS Step Functions service effectively. Including basic concepts, HTTP and event triggers, activities, design patterns and best practices.

Get your copy here.

Come learn about operational BEST PRACTICES for AWS Lambda: CI/CD, testing & debugging functions locally, logging, monitoring, distributed tracing, canary deployments, config management, authentication & authorization, VPC, security, error handling, and more.

You can also get 40% off the face price with the code ytcui.

Get your copy here.

Originally published at https://theburningmonk.com on May 23, 2019.

How to log timed out Lambda invocations was originally published in Hacker Noon on Medium, where people are continuing the conversation by highlighting and responding to this story.