AWS Lambda PowerTools
Logging and dashboards using Lambda PowerTools and CDK
One of the key challenges with serverless applications and microservices in general is monitoring for application issues, and tracing issues across multiple functions and services.
There are some very good commercial solutions to assist as your needs become more complex — like Dashbird, and you can build your own using an ELK stack/AWS OpenSearch — but at a basic level the first challenge is getting useful log detail out of Lambda functions in the first place.
By default Lambda outputs to logs using std out functions like console.log or print, and results in a string log being written to CloudWatch The problem with text logs obviously is they are hard to parse and process.
Enter PowerTools — a suite of log helpers from AWS Labs that assist with standardising log, trace and metric output to CloudWatch in JSON format.
PowerTools are available for Python, Java, .Net and more recently for TypeScript and JavaScript, which we will review here.
PowerTools and CloudWatch Logs Concepts
I’m sure anyone using Lambda is familiar with the CloudWatch logs it generates. No doubt we all start using system out in our favourite language to send custom log entries to the logs:
console.log('Event: ', JSON.stringify(event));
console.warn('Received some invalid data');It works, but it doesn’t make it easy to find the logs we are looking for or to create metrics or alarms from the data. CloudWatch Log Insights and metrics filters need JSON logs to be useful (it is possible to create text filters, they are just harder to use and less reliable).
There are a couple of tricks to outputting JSON, including using newline and tab characters to coerce CloudWatch into separating JSON data from the message. Libraries like Winston can also help to create standard log formats. But these workarounds always seemed either a bit hacky or overkill.
Now PowerTools makes it quite simple to add CloudWatch specific structured logs to Lambda, with the added benefit of including metrics and tracing (X-Ray) helpers.
There’s some good documentation on how to use PowerTools included on the homepage, but I also had to work a few things out the hard way. Hopefully I can shortcut some of that for you here.
PowerTools Components
Logger
A logger utility to standardise and send structured JSON logs to CloudWatch. Includes methods to add standard attributes to all logs, set sampling rates, and embed Lambda context information in the logs.
Tracer
A wrapper for the X-Ray SDK used to send traces to the X-Ray service. Greatly simplifies adding custom segments and annotations to traces and segmenting calls to AWS services and HTTP API’s.
Metrics
Sends logs in standard Embedded Metric Format to CloudWatch for use in metrics filters and alarms. The metrics module makes it simple to create your own custom metrics to log application specific events and counters.
MiddleWare
There are a few ways to add the PowerTools handlers to your Lambda functions: TypeScript class Decorators; manually; and the Middy middleware library. By far the easiest option is Middy, and it offers some additional libraries and API’s that may be useful in other ways. Unless you are a TypeScript guru and want full control — just use middy.
Installation
TypeScript PowerTools can be installed from npm or added as an AWS shared Lambda layer. In the test project we are creating our own custom layer so we can include Middy.
Configuration
The PowerTools instances take configuration from environment variables or parameters (or a combination of both). The docs are clear so I won’t go into the detail here. In the test project below we use a CDK custom construct to configure standard settings across all our functions.
The Test Project
I wanted to test a few common components to get started, so created a simple application with a CRUD API to create some items in a DynamoDB table. To make it easy to create test data there’s also a StepFunction that will iterate through some API sequences to generate the data, and some randomness thrown in to generate some errors.
The test project used here uses CDK custom constructs to create standard Lambda functions including PowerTools settings and default CloudWatch metric widgets. There’s an introduction to the constructs concept used here in my previous article.
The “application” provides an API for creating items of a particular colour (Red or Blue).
I have also included CDK code to generate a CloudWatch dashboard, and Log Insights queries based on the new log format. Configuring CloudWatch in the console interface is a challenge, but I will demonstrate how simple it is to create widgets, queries and even a dashboard using CDK.
The full code for the project is available on GitHub.
Key Components in the GitHub Project
src/
├───lambda
│ ├───create-data
│ ├───delete-data
│ └───read-data
└───stackslib/constructs/
├───custom-api
├───custom-nodejs-fnc
├───custom-table
└───tools-layer
The Lambda functions can be found in the src/lambda folder. They provide examples for integrating the PowerTools modules using the Middy middleware library (definitely the easiest way to do it).
The lib/constructs folder includes the custom constructs used to standardise resources.
Lambda Handler with PowerTools
The Lambda handler is wrapped by middy, with the PowerTools logger, metrics and tracers injected into the function.
Check out the key components in our create/update function here:
Notes:
- The logger, tracer and metrics instances are created outside the handler and will be re-used in warm starts (lines 9–11)
- We wrap the AWS SDK client with the tracer (line 14). This will create a unique segment in X-Ray traces for the DynamoDb calls
- We add a correlationId for tracking batch operations (lines 34–36). The correlationId can be used in filters and searches to find logs for related calls across all of our functions. For example the StepFunction Data Generator here will use a single correlationId in all API calls in an invocation, and we will be able to see the logs from calls to create, update, read and delete functions through a filter for the correlationId
- Logging is enabled at different error levels based on the PowerTools log level from the environment variables (lines 41, 52)
- We add a custom metric to track the count of colours for the items we create (lines 47–49). The singleMetric method allows us to add a dimension that will not apply to other metrics in the current instance. In this example we are adding a “feature” dimension to indicate our colour count comes from this colourPicker service in our app.
- We write custom error logs and count client and internal errors (lines 59–67). PowerTools will format the error object into JSON for us when we log an Error object (line 65)
- The handler is wrapped by middy, with simple methods to inject the PowerTools into our function (lines 73–76). Note we are using the clearState option in the logger (line 76) — it is required to ensure the correlationId is reset on warm start invocations.
Creating the Lambda Function in CDK
The Lambda functions all require PowerTools environment variables, a tools layer, and other standard settings like enabling tracing. The simplest way to do this is to create a custom construct with the base settings we need.
We can also take advantage of the custom construct to create a standard set of metrics and dashboard widgets for use with each function.
Here we are wrapping the CDK NodeJsFunction construct for bundling TypeScript into a Lambda function, and adding our own settings and additional metrics outputs:
Notes:
- We are using our own Lambda Layer to add the PowerTools modules, plus middy and moment. We exclude these npm modules from the bundling process as they are already available in the environment via the layer (line 16)
- W set logging and function defaults to ensure consistency across functions (lines 56 to 74)
- Metrics and dashboard widgets for CloudWatch are created (lines 105 to 250). All of our functions will include these standard metrics.
- Dashboard widgets are exported for use in a service dashboard (line 255). This provides a standard set of widgets and order to make it simple to create the dashboard.
Similarly the custom constructs used to create the DynamoDb table and the API Gateway instance create and export metrics and widgets for use in the dashboard.
CDK Stacks
The project creates three CloudFormation stacks:
- Application Stack: creates the API, Lambda functions and DynamoDb table. Uses the custom constructs to create the standard resources. Exports the API details and metrics/dashboard widgets for use in the other stacks
- Dashboard Stack: includes CloudWatch queries and creates the service dashboard
- StepFunction Stack: includes a data-generation StepFunction used to create demo data and logs
The application and StepFunction stacks are straightforward and you can review the code in GitHub.
The Dashboard stack creates Logs Insights queries and a Dashboard for viewing logs and metrics from the functions, API and table:
Notes:
- We get the graph widgets, log groups, and metrics from the custom constructs (lines 12–19)
- Log Insight queries are created and the log groups from all of our Lambda functions are attached (lines 43 to 69). We create queries based on the log level and the correlationId’s written by the PowerTools logger.
- An X-Ray Group is created to filter by the service name (line 75). In an application or environment with multiple services this makes it simpler to review the Service Map and traces in X-Ray
- A CloudWatch Dashboard is created for the application (line 86)
- We create a custom graph to show the results from our colour picker (line 95). This uses the custom metrics written from the create function to count the colours of each item created (to make it more interesting we are writing BLACK for missing colour selections, and PURPLE if both red and blue are selected).
- Then we add the dashboard widgets for the DynamoDb table, API Gateway, and the Lambda Functions (lines 153 to 159). The widgets and layout is created in the custom constructs for consistency
Setup and Creating Data
Review the Readme in the GitHub repository for setup and data creation details.
Creating test data:
- The StepFunction data generator is run to create some items and logs. It includes some randomness to create warnings and errors.
- All of the CRUD methods are used in the data generator so we will have logs and metrics from all of the functions
- Each run of the StepFunction will create a correlationId that is used for all function calls. We can filter logs, metrics and X-Ray using the correlationId
Reviewing the Results
We can review the results of the tests in CloudWatch Logs, Log Insights, Metrics, the custom Dashboard and in X-Ray.
CloudWatch Logs
At a basic level we can view logs by function in the CloudWatch log group.
Example — logging the event in the Create function:
Note that we have the correlationId and service name included in all function logs.
We can manually enter filter queries here to quickly find events within the log group and stream:
The limitation with that is that we can only view and filter one function log group and one log stream at a time.
Log Insights
Log Insights however make it possible to view and filter multiple log groups and streams at once, and save our queries for future use.
In our CDK stack we created saved queries that were linked to all of the Lambda function log groups. The queries use the log level and correlationId fields from the JSON logs.
Here we are using the ErrorLevel query to review error logs from all the application functions:
We have also created a correlationId query for convenience, but we do have to manually enter an id into the query before use:
X-Ray
We can also review the service map and traces in X-Ray. The X-Ray service will trace events through the various AWS services and even out to external HTTP calls.
In our case we are using a StepFunction to call the application API Gateway, which then calls Lambda functions that write to DynamoDb. We can see all of the interactions in the service map. Here we have used the Group Filter (ToolsDemo) created in the CDK stack to show results only from our demo application:
From the traces panel we can use the ToolsDemo group, but can also query by correlationId, as we added that field as an annotation in the PowerTools tracer:
Note here we only have one trace for each correlationId (and 4 that did not use a correlationId). The reason is that when creating the test data the StepFunction runs a single invocation to invoke all of the API functions, using the same correlationId. This means that X-Ray sees all of the activity as a single trace. If we made separate calls using curl or Postman and sent the same correlationId then we would see multiple traces for the id.
If we select and view a trace we will see all of the service calls as segments, with detailed data for each operation:
In the above image we can see two calls to the Create function, the first a success and the second is a fail. The ## index.handler segment is created by PowerTools, and will include any service calls made inside our Lambda handler. Here we can see the DynamoDb call in the successful iteration.
It is possible to create your own segments using the PowerTools tracer if it will help with your monitoring. For example if you want to track the total time of a specific piece of application code.
If we select the handler segment as above, then on the right side panel we can view the error:
If we select a successful handler, then we can view the result:
Note logging the response is enabled by default, if you may have sensitive data in the Lambda response you will want to disable it using the POWERTOOLS_TRACER_CAPTURE_RESPONSE variable.
CloudWatch Dashboard
We can use the custom metrics, log queries and JSON log filters to create graph widgets and a dashboard for our application.
The Lambda create function writes a custom metric to count the items of each colour as they are created. In our dashboard we can use the custom metrics to display results:
The Lambda custom construct above created a set of standard metrics which are now included for each function on the dashboard:
Note above that we are also displaying the error logs here using the Log Insights query. For the read function below we don’t have any errors.
The Cold vs Warm starts, Error log filter, and the Error/Warning counts all come from queries to our PowerTools JSON logs. The Duration stats are a standard Lambda metric. I’ve included both as a demo on how to use CDK to create the graph widgets and add to the dashboard.
While not related to the PowerTools logging, for fun I have have included metrics for the API Gateway and DynamoDb table, also exported from the custom constructs:
Wrap Up
There’s a lot more that can be done with the custom logging and metrics, this is just a taste and hopefully will help you get started.
Check out the full demo project on GitHub and install and play around with it yourself. It is surprising how easy it is to create the widgets and dashboard in particular in CDK, and there are many other standard service metrics that can be included if needed.
PowerTools will take a little more work to implement, but using the custom constructs to standardise function setup can definitely help.
Hope that helps you all, please leave a comment if you have any questions or suggestions.
About the Author
Mark is a 20+yr IT industry veteran, with technical expertise and entrepreneurial experience in a range of fields. For many years now his passion has been building on AWS, and he holds certifications including Solution Architect Professional and the Advanced Networking Specialty. He wants you to know that he is an infrastructure and architecture expert who writes code, not a professional software developer — just in case you spot something odd.
Mark has spent the last few years in the banking industry, were he is currently building and leading a team focused on using AWS serverless technologies to reduce costs and speed up the time to market for new services and products.
You can also find Mark on:
GitHub — https://github.com/markilott
LinkedIn — https://www.linkedin.com/in/markilott/
