Lambda development

There is a recurring thing that happens nearly every time I work on a serverless Function behind an API Gateway. I deploy the function, open a browser and navigate to the URL, and finally see an Internal server error. Bummer, something is broken. But what? Let’s check the logs! But to do that, I need to open CloudWatch logs, find the function, then find the appropriate log stream, and finally, I’ll see the logs.

And when I deploy a new version with a potential fix, I need to do it over again as the stream name is changed. This kills development time as well as my mood, especially when I have multiple managed functions.

Fortunately, all the above can be automated with the AWS CLI making the process nearly seamless.

As a working environment, I’ll use Terraform to manage the resources with a function definition as follows:

resource "aws_lambda_function" "function" {
	...
}

One-liner solution

The name of the lambda resource is aws_lambda_function.function. So to get the logs for this particular function, use this one-liner:

function get_logs (){ \
	FUNCTIONNAME=$( \
		terraform state show $1 | \
			awk '$1 == "function_name" {print $3}' \
	); aws logs get-log-events \
		--limit 100 \
		--log-group-name "/aws/lambda/$FUNCTIONNAME" \
		--log-stream-name "$( \
			aws logs describe-log-streams \
				--log-group-name "/aws/lambda/$FUNCTIONNAME" | \
					jq -r '.logStreams | sort_by(.lastEventTimestamp) | .[-1].logStreamName' \
		)" | \
			jq -r '.events[].message | gsub("\n$"; "")'; }; \
get_logs aws_lambda_function.function

This prints out the latest log messages for the function. No more opening the browser to see what’s wrong:

START RequestId: 0d8b63d1-84ca-4598-9f11-7e845ddd3553 Version: $LATEST
2019-05-28T14:07:41.142Z        0d8b63d1-84ca-4598-9f11-7e845ddd3553    INFO    Called at 2019-05-28T14:07:41.142Z
END RequestId: 0d8b63d1-84ca-4598-9f11-7e845ddd3553
REPORT RequestId: 0d8b63d1-84ca-4598-9f11-7e845ddd3553  Duration: 190.52 ms     Billed Duration: 200 ms         Memory Size: 128 MB     Max Memory Used: 73 MB

Watching

Getting the logs is a great start, but during development you’ll run this command a lot of times. To make it more convenient, it can be run in the background, constantly polling the latest logs.

Make a file called logs.sh with almost the same the content:

#!/bin/bash

function get_logs (){ \
	FUNCTIONNAME=$( \
		terraform state show $1 | \
			awk '$1 == "function_name" {print $3}' \
	); aws logs get-log-events \
		--limit 100 \
		--log-group-name "/aws/lambda/$FUNCTIONNAME" \
		--log-stream-name "$( \
			aws logs describe-log-streams \
				--log-group-name "/aws/lambda/$FUNCTIONNAME" | \
					jq -r '.logStreams | sort_by(.lastEventTimestamp) | .[-1].logStreamName' \
		)" | \
			jq -r '.events[].message | gsub("\n$"; "")'; }; \
get_logs "$@"

Notice the last line: get_logs "$@". This passes all parameters to the function so that it can be used by other programs, in this case, watch.

And call it with watch:

watch './logs.sh aws_lambda_function.function | tail -n $(($LINES - 2))'

This makes sure that if the log stream is changed, for example when you deploy a new version, it will use the latest one. You can run this in the background and see the latest logs almost instantly.

How it works

Function name

The first step is to extract the name of the function from the Terraform state:

terraform state show $1 | \
	awk '$1 == "function_name" {print $3}'

The terraform state show shows all the attributes for the function. awk then finds the appropriate value and outputs it. This then gets stored in the FUNCTIONNAME variable.

Log stream name

Since we know that the log group name is /aws/lambda/$FUNCTIONNAME, we only need to find the log stream that is currently in use. Different versions of the same function write to different streams, so we need to find all of them and get the one with the last write.

aws logs describe-log-streams \
				--log-group-name "/aws/lambda/$FUNCTIONNAME"

Gives back an array of logStreams under the group:

{
	"logStreams": [
		{
			"logStreamName": "2019/05/25/[$LATEST]0ac3ff2247db4889b712bcd7f93b5eb7",
			"creationTime": 1558796551243,
			"firstEventTimestamp": 1558796551618,
			"lastEventTimestamp": 1558802630109,
			"lastIngestionTime": 1558802645188,
			"uploadSequenceToken": "...",
			"arn": "...",
			"storedBytes": 0
		},
		...
	]
}

With several streams, we need to sort by the lastEventTimestamp and get the name with the latest timestamp:

| jq -r '.logStreams | sort_by(.lastEventTimestamp) | .[-1].logStreamName'

Log events

Having both the log group and the log stream we can get the log events:

aws logs get-log-events \
	--limit 100 \
	--log-group-name "/aws/lambda/$FUNCTIONNAME" \
	--log-stream-name "$(...)" | \
		jq -r '.events[].message | gsub("\n$"; "")'

This outputs the last 100 log events (set a different limit if you want more/less). Without a limit, it can download up to 1 MB of logs and with watch that can consume quite a large portion of bandwidth.

The gsub(...) is used to remove the trailing newlines from the messages.

Conclusion

Both Terraform and AWS provide the tools to write short CLI solutions for recurring problems. With a simple script like this one, you can more easily debug the problems with lambdas, making the whole process a lot less annoying.