Tracing Requests in AWS Serverless Applications

Operating Serverless APIs using Amazon API Gateway, AWS Lambda and Microservices (running in ECS) can be bit challenging if logging is not given any forethought. Best practice is to decide in while designing the application what needs to be logged, how the log messages can be correlated and finally where is it should be sent for aggregation. 

Its difficult to reconcile log events for a serverless API sent across multiple layers of application stack using CloudWatch log groups and log streams. Tracking down logs for a specific request or tailing request logs for a specific request can sometimes be a cumbersome experience. 

Debugging for a specific issue or Tracing a specific request can be made easy by using the x-amzn-requestid and x-amzn-trace-id that comes for free when using AWS API Gateway. Its easy to leverage these Ids and keep track of your request.  

In the following deployment diagram 

How to capture the request ID for a particular API request:

When the request enters AWS API Gateway, it automatically adds x-amzn-trace-id if the integration is thru any of the Amazon Load Balancers.
(https://aws.amazon.com/documentation/elastic-load-balancing/) 

Logs for an API Gateway API are always sent to a log group in the following format:

"API-Gateway-Execution-Logs_[API_ID]/[STAGE_NAME]"

The request ID for an individual API request is always returned by API Gateway in the "x-amzn-RequestId" response header. When API Gateway logs an individual API request, the request ID is always included in the first event in the request log:

"Start of request: [REQUEST_ID] details of the logs: "

Example :
(4ce618f9-49e0-11e8-8f10-e7bf1ec6275d) Endpoint request URI: https://xxxxx-nlb-yyyy.elb.region.amazonaws.com/test/123

To troubleshoot an individual API request, search for the request ID in the CloudWatch Logs console. 


How correlate API Gateway request IDs with Lambda request IDs:

Individual API requests are tracked independently across AWS services. Thus, an individual request to your API actually generates at least two request identifiers ("request IDs") – one for the API Gateway request and one for the Lambda invocation request.

To reduce time-to-diagnosis when analyzing logs, it is helpful to correlate both request IDs together in the logs. Log the API Gateway request ID from your Lambda function and send the API Gateway request ID ($context.requestId) to your Lambda function via a mapping template.

Then, in your Lambda function, log the API Gateway request ID along with the Lambda request ID. The Lambda request ID is automatically included in the log message.

exports.handler = function(event, context) { var apiRequestId = event.context['request-id']; var lambdaRequestId = context.awsRequestId; console.log("API Gateway Request ID: " + apiRequestId + "Lambda Request ID: " + context.awsRequestId);
var logprefix = "APIG: " + apiRequestId + " - "; console.log(logprefix + "hello world!"); ... }


Invoking this Lambda function produces these log messages in the "/aws/lambda/[FUNCTION_NAME]" log group:

2018-04-26T07:00:01.776Z a4d04215-ca91-4ba5-acec-ae31a8c74a84 API Gateway Request ID: b576fc5e-49cc-11e8-bedf-7f60f2b5620f) Lambda Request ID: a4d04215-ca91-4ba5-acec-ae31a8c74a84

2018-04-26T07:00:01.776Z a4d04215-ca91-4ba5-acec-ae31a8c74a84 APIG: b576fc5e-49cc-11e8-bedf-7f60f2b5620f - hello world!


How correlate API Gateway request IDs in Microservice Logs:

API Gateway would send the following headers to downstream via the Load Balancer
(4ce618f9-49e0-11e8-8f10-e7bf1ec6275d) Endpoint request headers: {x-amzn-apigateway-api-id=xxxxxxxx, Accept=application/json, x-amzn-requestid=4ce618f9-49e0-11e8-8f10-e7bf1ec6275d, User-Agent=AmazonAPIGateway_xxxxxxx, Host=xxxxx-nlb-yyyy.elb.region.amazonaws.com, X-Amzn-Trace-Id=Root=1-5ae2bc82-6806f8a7daf0e21efb077285}

Microservice needs to capture the x-amzn-requestid & X-Amzn-Trace-Id and append them to the application log messages.  Always its best to log application log messages in JSON format as it will be useful when querying in any log aggregator. 

{
"@timestamp": "2018-04-27T06:55:26.807+00:00",
"@version": 1,
"message": "reqid=6796 method=GET url=http://xxxxx:32785/test/123 status=200 duration=11ms",
"logger_name": "xxxxx.commons.logging.CommonsRequestLogger",
"thread_name": "qtp2003496028-29",
"level": "INFO",
"level_value": 20000,
"environment": "xxxxx",
"application_name": "xxxxx",
"application_version": "xxxxx",
 "x-amzn-requestid" : "4ce618f9-49e0-11e8-8f10-e7bf1ec6275d",
 "x-amzn-trace-id" : "Root=1-5ae2bc82-6806f8a7daf0e21efb077285"
}


Finally when all the logs are pushed to a log aggregator tool of choice like Splunk / Kibana / Sumo Logic / Loggly etc., all its needed is to query the x-amzn-requestid & X-Amzn-Trace-Id that was responded for the initial http request.