Serverless architectures are microservices by default, you need correlation IDs to help debug issues that spans across multiple functions, and possibly different event source types — asynchronous, synchronous and streams. This is the last of a 3-part mini series on managing your AWS Lambda logs. If you haven’t read yet, please give it a read now. We’ll be building on top of the basic infrastructure of shipping logs from CloudWatch Logs detailed in that post. part 1 part 1 : centralise logging part 2: tips and tricks Why correlation IDs? As your architecture becomes more complex, many services have to work together in order to deliver the features your users want. Microservice death stars, circa 2015. When everything works, it’s like watching an orchestra, lots of small pieces all acting independently whilst at the same time collaborating to form a whole that’s greater than the sum of its parts. However, when things don’t work, it’s a pain in the ass to debug. Finding that one clue is like finding needle in the haystack as there are so many moving parts, and they’re all constantly moving. Imagine you’re an engineer at Twitter and trying to debug why a user’s tweet was not delivered to one of his followers’ timeline. “Let me cross reference the logs from hundreds of services and find the logs that mention the author’s user ID, the tweet ID, or the recipient’s user ID, and put together a story of how the tweet flowed through our system and why it wasn’t delivered to the recipient’s timeline.” “What about logs that don’t explicitly mention those fields?” “mm… let me get back to you on that…” Needle in the haystack. This is the problem that correlation IDs solve in the microservice world — to tag every log message with the relevant context so that it’s easy to find them later on. Aside from common IDs such as user ID, order ID, tweet ID, etc. you might also want to include the X-Ray trace ID in every log message. That way, if you’re then you can use it to quickly load up the relevant trace in the X-Ray console. using X-Ray with Lambda By default, Lambda automatically generates a _X_AMZN_TRACE_ID value in the environment variable. Also, if you’re going to add a bunch of correlation IDs to every log message then you should consider switching to JSON. Then you need to update the function we introduced in part 1 to handle log messages that are formatted as JSON. ship-logs Enable debug logging on entire call chain Another common problem people run into, is that by the time we realise there’s a problem in production we find out that the crucial piece of information we need to debug the problem is logged as DEBUG, and we disable DEBUG logs in production because they’re too noisy. “Darn it, now we have to enable debug logging and redeploy all these services! What a pain!” “Don’t forget to disable debug logging and redeploy them, after you’ve found the problem ;-)” Fortunately it doesn’t have to be a catch-22 situation. You can enable DEBUG logging on the by: entire call chain make the decision to enable DEBUG logging (for say, 5% of all requests) at the edge service pass the decision on all outward requests alongside the correlation IDs on receiving the request from the edge service, possibly through async event sources such as SNS, the intermediate services will capture this decision and turn on DEBUG logging if asked to do so the intermediate services will also pass that decision on all outward requests alongside the correlation IDs The edge service decides to turn DEBUG logging on for 5% of requests, that decision is captured and passed along throughout the entire call chain, through HTTP requests, SNS message and Kinesis events. Capture and forward correlation IDs With that out of the way, let’s dive into some code to see how you can actually make it work. If you want to follow along, then the code is available in this , and the architecture of the demo project looks like this: repo The demo project consists of an edge API, api-a, which initialises a bunch of correlation IDs as well as the decision on whether or not to turn on debug logging. It’ll pass these along through HTTP requests to api-b, Kinesis events and SNS messages. Each of these downstream function would in turn capture and pass them along to api-c. _lambda-correlation-id-demo - How to track correlation IDs across APIs, SNS and Kinesis events_github.com theburningmonk/lambda-correlation-id-demo We can take advantage of the fact that concurrency is now managed by the platform, which means we can safely use global variables to store contextual information relevant for the current invocation. In the handler function we can capture incoming correlation IDs in global variables, and then include them in log messages, as well as any outgoing messages/HTTP requests/events, etc. To abstract away the implementation details, let’s create a module that makes it easy to fetch and update these context data: requestContext And then add a module which: log disables DEBUG logging by default enables DEBUG logging if explicitly overriden via environment variables or a field was captured in the incoming request alongside other correlation IDs Debug-Log-Enabled logs messages as JSON Once we start capturing correlation IDs, our log messages would look something like this: Notice that I have also captured the from the incoming request, as well as the decision to not enable DEBUG logging. User-Agent Now let’s see how we can capture and forward correlation IDs through API Gateway and outgoing HTTP requests. API Gateway You can capture and pass along correlation IDs via HTTP headers. The trick is making sure that everyone in the team follows the same conventions. To standardise these conventions (what to name headers that are correlation IDs, etc.) you can provide a factory function that your developers can use to create API handlers. Something like this perhaps: When you need to implement another HTTP endpoint, pass your handler code to this factory function. Now, with minimal change, all your logs will have the captured correlation IDs (as well as , whether to enable debug logging, etc.). User-Agent The function in our earlier architecture looks something like this: api-a Since this is the API on the edge, so it initialises the using the AWS Request ID for its invocation. This, along with several other pieces of contextual information is recorded with every log message. x-correlation-id By adding a custom HTTP module like , you can also make it easy to include these contextual information in outgoing HTTP requests. Encapsulating these conventions in an easy-to-use library also helps you standardise the approach across your team. this one In the function above, we made a HTTP request to the endpoint. Looking in the logs, you can see the aforementioned contextual information has been passed along. api-a api-b In this case, we also have the from the original user-initiated request to . This is useful because when I look at the logs for intermediate services, I often miss the context of what platform the user is using which makes it harder to correlate the information I gather from the logs to the symptoms the user describes in their bug reports. User-Agent api-a When the function (see ) makes its own outbound HTTP request to it’ll pass along all of these contextual information plus anything we add in the function itself. api-b here api-c api-b Log message for when api-b calls api-c with the custom HTTP module. Notice it includes the “x-correlation-character-b” header which is set by the api-b function. When you see the corresponding log message in ’s logs, you’ll see all the context from both and . api-c api-a api-b SNS To capture and forward correlation IDs through SNS messages, you can use message attributes. In the function above, we also published a message to SNS (omitted from the code snippet above) with a custom module which includes the captured correlation IDs as message attributes, see below. api-a sns When this SNS message is delivered to a Lambda function, you can see the correlation IDs in the field of the SNS event. MessageAttributes Let’s create a factory function to standardise the process of capturing incoming correlation IDs via SNS message attributes. snsHandler We can use this factory function to quickly create SNS handler functions. The log messages from these handler functions will have access to the captured correlation IDs. If you use the aforementioned custom module to make outgoing HTTP requests then they’ll be included as HTTP headers automatically. http For instance, the following SNS handler function would capture incoming correlation IDs, include them in log messages, and pass them on when making a HTTP request to (see architecture diagram). api-c Log message for when the SNS handler function calls api-c with the custom HTTP module. Notice it includes the “x-correlation-source-type” header which is set by the SNS handler function. Those correlation IDs (including the one added by the SNS handler function) are included as HTTP headers. Kinesis Streams Unfortunately, with Kinesis and DynamoDB Streams, there’s no way to tag additional information with the payload. Instead, in order to pass correlation IDs along, we’d have to modify the actual payload itself. Let’s create a module for sending events to a Kinesis stream, so that we can insert a field to the payload to carry the correlation IDs. kinesis __context On the receiving end, we can take it out, use it to set the current , and delete this field before passing it on to the Kinesis handler function for processing. The sender and receiver functions won’t even notice we modified the payload. requestContext __context Wait, there’s one more problem — our Lambda function will receive a batch of Kinesis records, each with its own context. How will we consolidate that? The simplest way is to force the handler function to process records one at a time. That’s what we’ve done in the factory function here. kinesisHandler The handler function (created with the factory function) would process one record at at time, and won’t have to worry about managing the request context. All of its log messages would have the right correlation IDs, and outgoing HTTP requests, SNS messages and Kinesis events would also pass those correlation IDs along. kinesisHandler Log message for when the kinesis handler function calls api-c. When api-c receives the invocation event, you can see the correlation IDs have been passed along via HTTP headers. This approach is simple, developers working on Kinesis handler functions won’t have to worry about the implementation details of how correlation IDs are captured and passed along, and things “just work”. However, it also removes the opportunity to optimize by processing all the records in a batch. Perhaps your handler function has to persist the events to a persistence store that’s better suited for storing large payloads rather than lots of small ones. This simple approach is not the right fit for every situation, an alternative would be to leave the field on the Kinesis records and let the handler function deal with them as it sees fit. In which case you would also need to update the shared libraries — the , , and modules we have talked about so far — to give the caller to option to pass in a as override. __context log http sns kinesis requestContext This way, the handler function can process the Kinesis records in a batch. Where it needs to log or make a network call in the context of a specific record, it can extract and pass the request context along as need be. The End That’s it, folks. A blueprint for how to capture and forward correlation IDs through 3 of the most commonly used event sources for Lambda. Here’s an annotated version of the architecture diagram earlier, showing the flow of data as they’re captured and forwarded from one invocation to another, through HTTP headers, message attributes, Kinesis record data. You can find a deployable version of the code you have seen in this post in this . It’s intended for demo sessions in my O’Reilly course detailed below, so documentation is seriously lacking at the moment, but hopefully this post gives you a decent idea of how the project is held together. repo Other event sources There are plenty of that we didn’t cover in this post. event sources It’s not possible to pass correlation IDs through every event source, as some do not originate from your system — eg. CloudWatch Events that are triggered by API calls made by AWS service. And it might be hard to pass correlation IDs through, say, DynamoDB Streams — the only way (that I can think of) for it to work is to include the correlation IDs as fields in the row (which, might not be such a bad idea but it does have cost implications). Hi, my name is . I’m an and the author of . 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. Yan Cui AWS Serverless Hero Production-Ready Serverless You can contact me via , and . Email Twitter 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 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. BEST PRACTICES You can also get off the face price with the code . 40% ytcui Get your copy . here

Too Long; Didn't Read

Developers: Build Less. Deliver More. [Learn how]	

Capture and forward correlation IDs through different Lambda event sources

Too Long; Didn't Read

Yan Cui

About Author

TOPICS

THIS ARTICLE WAS FEATURED IN...

Capture and forward correlation IDs through different Lambda event sources

Too Long; Didn't Read

Yan Cui

About Author

TOPICS

THIS ARTICLE WAS FEATURED IN...

RELATED STORIES