AWS Lambda CloudWatch Logging

AWS does an awesome job in documenting its services and APIs, no questions about it. But during my quest of building Microservices Architecture on AWS Lambda I keep encountering those ‘places in between’, when using AWS Lambda together with other AWS Services just drops me into rabbit hole of trying to find the missing nuggets of knowledge or code samples to make things actually work together.

So today’s blog post is about debugging. Just plain old debugging. Nothing fancy, just plain old console.log() will do the trick. So you add your logs, deploy your lambda and head over to the CloudWatch console to nail that nasty lambda timeout bug which keeps you up at night.

Lets say you are not just playing but have a constant stream of function invocations .. so I bet you quickly hit upon to type ‘Task timed out’ in the search bar above the log stream, and bang - you see all the timed out lambdas. So far so good. Except it is only the last line of that lambda invocation which matches your expression.

But not to despair - you might have noticed that each Lambda invocations is framed in a START, END and REPORT log, which includes a RequestId unique to that invocation. And each log generated from within the lambda code also has the RequestIdprepended. So surely I should be able to type that RequestId value into the search and see all logs generated by that function invocation. Makes total sense, or? Thought so?

You are so wrong (like me) :). Yep, searching for the RequestId in the CloudWatch console does nada, nothing, nichts. No log, no game.

Next step deeper into the rabbit hole, fire up your browser and start searching … Grrrr! Why am I the only one who wants to get the logs of a lambda invocations grouped together. What am I missing? Yes, I could install yet another library but no thank you - I just want my transaction log.

So I open a query on our development chat and a dear colleague of mine comes to the rescue: Type "RequestId: <request-id-here>" in the search bar (including quotes). I was back in the game. And I could finally filter for the outer frame of the lambda invocation (START, END, and REPORT). But wait .. dude, where are MY logs? Why the hell would you (yes, you AWS - I am talking to you) prepend MY logs with the request id but then not show it together with the outer ones.

You got to be kidding me .. another frantic search across message boards and the world-wide-web. Finally a first hint two references across and hidden deep inside a thread on a message board

Wait what .. could it be a simple pattern matching .. not RequestId as in ‘the Request ID of a lambda invocation’ but as in literally RequestId: ?

And you might have guessed it, prepending my log with RequestId: now makes it show up as part of the invocation.

So here is the magic syntax to log within your lambda function and make it searchable as part of the request in the CloudWatch console.

export async function get(event, context) {

    console.log(
        "RequestId: " +
            context.awsRequestId +
            " UserId: " +
            userId +
            " Path: " +
            event.path +
            " Query: " +
            JSON.stringify(event.queryStringParameters)

May the (logging) power be strong in you.

References

Update after a comment from my former colleague Diogo:

He pointed me to the CloudWatch Insight console as an alternative method. After a couple of minutes of playing around I got the hang of it and it does indeed allow for filtering of the metadata of a log event such that all logs belonging to a single transaction can be shown.

At a basic level it is quite simple. You select the Log Group of your lambda endpoint, and then click together (or type) a filter expression like filter @requestId="da1515da-09c8-4112-b50b-27a4bb04f058". Pay attention to the time period the query should cover.

References