Microservices platform with Spring Cloud – part 4

So far in the series, we have pretty good distributes system up and running. We’ve seen how to set up basic infrastructure, how to perform reliable communication between services, and how to expose services to the outside world. We used pretty simple examples, but they represent the principle that would be use in real world applications. In this post, we will discuss logging in distributed environment.

Logging in microservices

One important aspect when working with microservices is monitoring their behavior after deployment. Monitoring is really big subject on it’s own, and various tools and techniques are developed to solve particular problems. In this post and the next, we will focus mostly on runtime metrics and logging.

Logging is particularly important for troubleshooting problems identified during service operations. Just like in monolith applications, logs provide valuable information about what is going during service operation. But, unlike monolith applications, this information is usually distributed between individual service logs and can be impossible to process manually. Each service has it’s own log files, and following logging info from one log file to another is just not an option. That’s where tools like Splunk or ELK stack come in play. These tools aggregate logs from multiple sources and provide powerful searching and filtering functionality.

Another aspect that needs to be taken into account is how to follow processing flow of requests as they travel from service to service. Although Splunk and ELK provide fine grained search, it’s hard to correlate search results without additional information. The usual way to accomplish this is to assign unique identifier to each request that comes into system. As the request propagates through the system, it’s identifier remains the same. That piece of information allows logging tools to correlate search results, giving an overview of log statements related to that particular request.

Fortunately,  various tools are developed which provide this functionality. Spring Cloud provides Sleuth, which seamlessly integrates into Spring based application. Using Sleuth, we can easily add logging and tracing capabilities to our microservices. We will show how to use Sleuth to enable logging and tracing.

Spring Sleuth to the rescue

Sleuth adds two types of IDs to logging statements, which are associated with HTTP requests. These trace ID and span ID. Trace ID can be explained as “parent” for span IDs. For example, looking at our sample system, when a request arrives to Zuul edge service, it will be assigned trace ID. Then, as the request propagates through user service and messaging service, requests keep the same trace ID, but each “hop” to different service has different span ID. Each log entry will have trace ID and span ID fields associated with it.

Add logging statements to our services

Now it’s time to apply what is said above to out distributed system. We will add logging support to Zuul proxy, user service and messaging service, and then see Sleuth in action. As usual, complete source code can be found on Github.

First things we need to do is add Sleuth dependency to POMs. This will automatically configure Sleuth with default value, but we will later add custom configuration for logging. Add the following dependency to service POMs and Zuul POM.

What’s this logstash-logback-encoder , you may ask? It’s something we will use in the next part of the post to create JSON formatted log files, which can be easily imported to Logstash/Splunk. For now, just take my word for it and include it ;-).

When you add Sleuth dependency, Spring Boot automatically configures it with default values. That means that you can immediately start logging. We just need to configure SLF4J logger and log some information:

This is sample logging configuration for Zuul filter that we created in previous post. We can do the same for other services (see the complete source code in Github):

If you now run the whole system and invoke Zuul proxy endpoint, you will see the following log output in the console for each service:

The first section after INFO represents service name, trace ID and span ID. As you can see, trace ID is the same for each log entry, while span IDs are different. This information allows easy tracking of log entries using Splunk, ELK or similar tools.

Log files: text, JSON and more

So far, we have a tracing/logging system that works great. There’s only one problem: it only logs to console. And logs which are not persistent are not really valuable. In this section, we will configure our logging tools to write logs to files. We will want to have both plain text and JSON log file. The reason for this is clear: plain text files are readable for humans, and JSON is readable for machines. Our final goal is to import JSON logs to Splunk/Logstash. These tools digest JSON much better then plain text files, and it will make search much more efficient.

Since we use SLF4J as our logging library, we will configure Logback backend to write to console, plain text file and JSON file. This configuration is based on this sample file:

Save this file as  src/main/resources/logback.xml . This file has few changes from original file. It will save text logs under target/<app_name>.log  and target/<app_name.json , so they are not added to version control. If you now run the services and invoke user controller, you will see that log files are populated with log information. Sample JSON output:

This output can be easily imported into log aggregation tools and perform search by various criteria.

Importing logs to Logstash

Logstash is the “L” in ELK stack. It’s a tool that collects logs from various sources, indexes them and converts to format which is suitable for search. The final step in logging pipeline would be to automatically import log files to log aggregator tool and have each new entry imported as soon as it is written to file. For this step, we will use Logstash as log aggregator.

Setting up Logstash server is out of scope of this post, but detailed instructions can be found in Elasticsearch documentation. Another option would be to use ready-made installation, such as virtual machine image or Docker container. Main principle of operation is that on service side we have some client tool, such as Logstash Filebeat, which continually monitors log files and sends updates to Logstash, which in turn process these updates and sends them to Elasticsearch.

Examples of Filebeat configuration and usage can be found here.

Bonus points: Tracing requests with Zipkin

One added benefit of Sleuth is that it also provides tracing capabilities and easily integrates with tools like Zipkin. Zipkin provides tools monitor and troubleshoot timing and latency information, so we can discover bottlenecks in system performance. Sleuth can be configured to automatically send these information to Zipkin server.

Again, to keep this post short, we won’t go to details at this time. But, you can take a look at this great article about using Sleuth with Zipkin.

Conclusion

In this post, we’ve seen how to add support for logging and tracing in our distributed system. It’s really easy to add this using Sleuth and integrate it with various monitoring tools.

I admit, there are some things left hanging in the air, like ELK stack and Zipkin configuration and usage. But, I wanted to keep this post focused to Spring Cloud tools. In some later posts, I plan to write detailed overview of integrating these two tools. Stay tuned!!

Previous posts in this series

 

Leave a Comment

Your email address will not be published. Required fields are marked *