Tracing Logs in Microservices Architecture using Spring Cloud Sleuth

In this post, we look at Tracing Logs using Spring Cloud Sleuth. It belongs to the Spring Cloud family of projects. It is an extremely powerful tool for enhancing logs in any application. However, its use becomes even more pronounced while building microservices using Spring Cloud.

So, let’s start understanding Spring Cloud Sleuth in detail.

Use of Spring Cloud Sleuth

Before diving into implementation details, let’s understand where and how we use Sleuth.

If you have worked for any length in a distributed or non-distributed application, you must have come across the need to access and analyze logs. Usually, to diagnose a problem in your application, you need to look at the logs to try and find out what went wrong.

However, most of the time, it is not easy to pin-point the exact logs you need to look at. It is often tough to correlate a particular log entry to a request in your application.

This can make it nearly impossible to diagnose a problem effectively. Often, developers have to resort to techniques like adding a unique id to each method in the request so that it becomes easy to identify logs.

This is where Spring Cloud Sleuth comes to the rescue. This module makes it possible to easily identify logs related to a specific job, request or thread. The beauty of this module is that it effortlessly integrates with popular logging frameworks like Logback or SLF4J. Basically, it adds unique identifiers that helps diagnose issues using logs.

Setting Up Sleuth in your Application

The first step towards using Spring Cloud Sleuth for tracing in your application is to include the library as a dependency in your application.

Below is the dependency item that needs to be added to the POM.xml file for your project.

<dependency>
	<groupId>org.springframework.cloud</groupId>
	<artifactId>spring-cloud-starter-sleuth</artifactId>
</dependency>

Note that you don’t need to include any versions. This is because our application leverages Spring Boot and the parent POM provides versions for each dependency.

If case you are not familiar with Spring Boot, I have a detailed guide on building Spring Boot Microservices.

Another important property that Spring Cloud Sleuth requires is the application.name. We add it in the application.properties file.

spring.application.name=product-consumer-app

Spring Cloud Sleuth in Action

With Spring Boot version 2.*, Spring Cloud Sleuth uses Brave as the internal tracing library. Basically, Brave adds unique ids to every web request entering our applications. These unique ids belong to traces and spans within our application.

But what is a trace or a span?

Traces can be thought of like a single web request or a job that is triggered in an application. Every step that is part of the request will have one and only one trace id.

However, Spans can be seen as sections of a request or a particular job. In other words, a single trace can consist of several spans where each span correlates to particular step of the overall request.

This can be extremely useful for an application developer. Using a combination of trace id and span id, one can pinpoint the exact location of an issue. Basically, it makes reading the logs of our application quite easy.

So now let’s see Spring Cloud Sleuth in action.

Creating a Test Controller

To test Sleuth, let’s just create a simple REST controller in our Spring Boot application.

@RestController
public class SleuthTestController {

    Logger logger = Logger.getLogger("SleuthTestController");

    @GetMapping("/wake-up-sleuth")
    public String wakeUpSLeuth(){
        logger.info("Wake Up Sleuth");
        return "Logging success";
    }
}

If we start the application now and hit the end-point http://localhost:8086/wake-up-sleuth, we should see the below log getting generated.

2019-06-09 08:38:44.638  INFO [product-consumer-app,9cbe06b35ad945e9,9cbe06b35ad945e9,false] 4689 --- [nio-8086-exec-1] SleuthTestController                     : Wake Up Sleuth

Even though this looks like a normal log entry, there is a special part in the beginning. That is the core information added by Sleuth. The format of this information is as follows:

[application name, traceId, spanId, export]

Application Name is the name we set in the application.properties file in the previous step. This is crucial to effective logging because it can be used to aggregate logs from multiple instances.

TraceId is the id that is assigned to every request.

SpanId is used to track a unit of work. Each request can have multiple steps. And each step can have its unique SpanId.

Export is a flag that indicates whether a particular log should be exported to a log aggregation tool such as Zipkin.

Multi-Step Request

Let’s enhance our tiny application a bit by adding a small service layer to back our controller.

@Service
public class SleuthService {

    Logger logger = Logger.getLogger("SleuthService");

    public void sameSpanWork(){
        logger.info("Doing some work");

    }
}

Also, we add another end-point to test the service.

@GetMapping("/same-span-sleuth")
    public String sameSpanSleuth(){
        logger.info("Same span work initiated");
        sleuthService.sameSpanWork();
        return "Logging success for same span";
}

If we restart our application and visit the new end-point, we should see logs as below:

2019-06-09 08:58:02.341  INFO [product-consumer-app,bcd708f8e18bbafd,bcd708f8e18bbafd,false] 5251 --- [nio-8086-exec-1] SleuthTestController                     : Same span work initiated
2019-06-09 08:58:02.342  INFO [product-consumer-app,bcd708f8e18bbafd,bcd708f8e18bbafd,false] 5251 --- [nio-8086-exec-1] SleuthService                            : Doing some work

Note that the traceId and spanId in these two log entries is the same. Using traceId alone, a developer can easily trace the entire request.

Basically, this is the default behavior. Each request gets a single traceId and spanId. However, for more complex requirements, you can also manually add spans for each step.

Manual Span Addition

To test this feature out, let’s add another end-point to our Sleuth controller.

@GetMapping("/new-span-sleuth")
    public String newSpanSleuth(){
        logger.info("New span work initiated");
        sleuthService.newSpanWork();
        return "Logging success for new span";
}

Also, we add the below method in our Sleuth service class.

@Service
public class SleuthService {

    Logger logger = Logger.getLogger("SleuthService");

    @Autowired
    private Tracer tracer;

    public void sameSpanWork(){
        logger.info("Doing some work");

    }

    public void newSpanWork(){
        logger.info("Original span going on");

        Span newSpan = tracer.nextSpan().name("new sleuth span").start();

        try(Tracer.SpanInScope span = tracer.withSpanInScope(newSpan.start())){
            logger.info("This work is being done in the new span");
        }finally {
            newSpan.finish();
        }

        logger.info("Back to original span");
    }
}

Note that we also added a new object belonging to the Tracer class. This Tracer instance is created by Spring Cloud Sleuth during application start-up and made available in the context using dependency injection.

Traces are manually started and stopped. And that’s what we are doing in this method. We start the trace in a try-catch block and finish it in the finally block.

If we restart the application and visit the newly created end-point, we should see log entries as below. Notice that the third log entry has a different spanId even though the traceId is same.

Using this feature it becomes extremely easy to pinpoint specific steps in the life-cycle of a request.

2019-06-09 09:16:51.410  INFO [product-consumer-app,0ebf1c258ab7f823,0ebf1c258ab7f823,false] 6125 --- [nio-8086-exec-1] SleuthTestController                     : New span work initiated
2019-06-09 09:16:51.410  INFO [product-consumer-app,0ebf1c258ab7f823,0ebf1c258ab7f823,false] 6125 --- [nio-8086-exec-1] SleuthService                            : Original span going on
2019-06-09 09:16:51.411  INFO [product-consumer-app,0ebf1c258ab7f823,7d4b060ff51d04db,false] 6125 --- [nio-8086-exec-1] SleuthService                            : This work is being done in the new span
2019-06-09 09:16:51.413  INFO [product-consumer-app,0ebf1c258ab7f823,0ebf1c258ab7f823,false] 6125 --- [nio-8086-exec-1] SleuthService                            : Back to original span

Conclusion

With this we are done with implementing Spring Cloud Sleuth in our application. We saw what Sleuth brings to the table when it comes to distributed tracing. Also, we looked at the steps involved in handling traceId and spanId across multiple steps.

The code for this post is available on Github.

Sound off your comments and queries in the comments section below.

Happy Learning!