1. Overview
In this tutorial, we’ll introduce Spring Cloud Sleuth, a powerful tool for enhancing logs in any application, but especially in a system built up of multiple services. For the purposes of this tutorial, we’ll focus on using Sleuth in a monolith application, not across microservices.
We’ve all had the unfortunate experience of trying to diagnose a problem with a scheduled task, a multi-threaded operation, or a complex web request. Often, even when there is logging, it’s hard to tell what actions need to be correlated together to create a single request.
This can make diagnosing a complex action very difficult, or even impossible, often resulting in solutions like passing a unique id to each method in the request to identify the logs.
In comes Sleuth. This library makes it possible to identify logs pertaining to a specific job, thread, or request. Sleuth integrates effortlessly with logging frameworks, like Logback and SLF4J, to add unique identifiers that help track and diagnose issues using logs.
Let’s take a look at how it works.
2. Setup
We’ll start by creating a Spring Boot web project in our favorite IDE, and adding this dependency to our pom.xml file:
<dependency>
<groupId>org.springframework.cloud</groupId>
<artifactId>spring-cloud-starter-sleuth</artifactId>
</dependency>
Our application runs with Spring Boot, and the parent pom provides versions for each entry. The latest version of this dependency can be found here: spring-cloud-starter-sleuth.
Additionally, we’ll add an application name to instruct Sleuth to identify this application’s logs.
In our application.properties file, we’ll add this line:
spring.application.name=Baeldung Sleuth Tutorial
3. Sleuth Configurations
Sleuth is capable of enhancing logs in many situations. Starting with version 2.0.0, Spring Cloud Sleuth uses Brave as the tracing library that adds unique ids to each web request that enters our application. Furthermore, the Spring team has added support for sharing these ids across thread boundaries.
Traces can be thought of like a single request or job that’s triggered in an application. All the various steps in that request, even across application and thread boundaries, will have the same traceId.
Spans, on the other hand, can be thought of as sections of a job or request. A single trace can be composed of multiple spans each correlating to a specific step or section of the request. Using trace and span ids, we can pinpoint exactly when and where our application is as it processes a request, making reading our logs much easier.
In our examples, we’ll explore these capabilities in a single application.
3.1. Simple Web Request
First, we’ll create a controller class to be an entry point to work with:
@RestController
public class SleuthController {
@GetMapping("/")
public String helloSleuth() {
logger.info("Hello Sleuth");
return "success";
}
}
Let’s run our application, and navigate to “http://localhost:8080”. We’ll watch the logs for output that looks like:
2017-01-10 22:36:38.254 INFO
[Baeldung Sleuth Tutorial,4e30f7340b3fb631,4e30f7340b3fb631,false] 12516
--- [nio-8080-exec-1] c.b.spring.session.SleuthController : Hello Sleuth
This looks like a normal log, except for the part in the beginning between the brackets. This is the core information that Spring Sleuth has added. This data follows the format of:
[application name, traceId, spanId, export]
- Application name – This is the name we set in the properties file, and can be used to aggregate logs from multiple instances of the same application.
- TraceId – This is an id that’s assigned to a single request, job, or action. Something like each unique user initiated web request will have its own traceId.
- SpanId – Tracks a unit of work. Think of a request that consists of multiple steps. Each step could have its own spanId and be tracked individually. By default, any application flow will start with the same TraceId and SpanId.
- Export – This property is a boolean that indicates whether or not this log was exported to an aggregator like Zipkin. Zipkin is beyond the scope of this article, but plays an important role in analyzing logs created by Sleuth.
By now, we should have some idea of the power of this library. Let’s take a look at another example to further demonstrate how integral this library is to logging.
3.2. Simple Web Request With Service Access
We’ll start by creating a service with a single method:
@Service
public class SleuthService {
public void doSomeWorkSameSpan() {
Thread.sleep(1000L);
logger.info("Doing some work");
}
}
Now let’s inject our service into our controller, and add a request mapping method that accesses it:
@Autowired
private SleuthService sleuthService;
@GetMapping("/same-span")
public String helloSleuthSameSpan() throws InterruptedException {
logger.info("Same Span");
sleuthService.doSomeWorkSameSpan();
return "success";
}
Finally, we’ll restart the application and navigate to “http://localhost:8080/same-span”. We’ll watch for log output that looks like:
2017-01-10 22:51:47.664 INFO
[Baeldung Sleuth Tutorial,b77a5ea79036d5b9,b77a5ea79036d5b9,false] 12516
--- [nio-8080-exec-3] c.b.spring.session.SleuthController : Same Span
2017-01-10 22:51:48.664 INFO
[Baeldung Sleuth Tutorial,b77a5ea79036d5b9,b77a5ea79036d5b9,false] 12516
--- [nio-8080-exec-3] c.baeldung.spring.session.SleuthService : Doing some work
Take note that the trace and span ids are the same between the two logs, even though the messages originate from two different classes. This makes it trivial to identify each log during a request by searching for the traceId of that request.
This is the default behavior, one request gets a single traceId and spanId, but we can manually add spans as we see fit. Let’s take a look at an example that uses this feature.
3.3. Manually Adding a Span
To start, we’ll add a new controller:
@GetMapping("/new-span")
public String helloSleuthNewSpan() {
logger.info("New Span");
sleuthService.doSomeWorkNewSpan();
return "success";
}
And now we’ll add the new method inside our service:
@Autowired
private Tracer tracer;
// ...
public void doSomeWorkNewSpan() throws InterruptedException {
logger.info("I'm in the original span");
Span newSpan = tracer.nextSpan().name("newSpan").start();
try (SpanInScope ws = tracer.withSpanInScope(newSpan.start())) {
Thread.sleep(1000L);
logger.info("I'm in the new span doing some cool work that needs its own span");
} finally {
newSpan.finish();
}
logger.info("I'm in the original span");
}
Note that we also added a new object, Tracer. The tracer instance is created by Spring Sleuth during startup, and is made available to our class through dependency injection.
Traces must be manually started and stopped. To accomplish this, code that runs in a manually created span is placed inside a try-finally block to ensure the span is closed regardless of the operation’s success. Also notice that new span has to be placed in the scope.
Let’s restart the application, and navigate to “http://localhost:8080/new-span”. We’ll watch for the log output that looks like:
2017-01-11 21:07:54.924
INFO [Baeldung Sleuth Tutorial,9cdebbffe8bbbade,9cdebbffe8bbbade,false] 12516
--- [nio-8080-exec-6] c.b.spring.session.SleuthController : New Span
2017-01-11 21:07:54.924
INFO [Baeldung Sleuth Tutorial,9cdebbffe8bbbade,9cdebbffe8bbbade,false] 12516
--- [nio-8080-exec-6] c.baeldung.spring.session.SleuthService :
I'm in the original span
2017-01-11 21:07:55.924
INFO [Baeldung Sleuth Tutorial,9cdebbffe8bbbade,1e706f252a0ee9c2,false] 12516
--- [nio-8080-exec-6] c.baeldung.spring.session.SleuthService :
I'm in the new span doing some cool work that needs its own span
2017-01-11 21:07:55.924
INFO [Baeldung Sleuth Tutorial,9cdebbffe8bbbade,9cdebbffe8bbbade,false] 12516
--- [nio-8080-exec-6] c.baeldung.spring.session.SleuthService :
I'm in the original span
We can see that the third log shares the traceId with the others, but it has a unique spanId. This can be used to locate different sections in a single request for more fine-grained tracing.
Now let’s take a look at Sleuth’s support for threads.
3.4. Spanning Runnables
To demonstrate the threading capabilities of Sleuth, we’ll first add a configuration class to set up a thread pool:
@Configuration
public class ThreadConfig {
@Autowired
private BeanFactory beanFactory;
@Bean
public Executor executor() {
ThreadPoolTaskExecutor threadPoolTaskExecutor
= new ThreadPoolTaskExecutor();
threadPoolTaskExecutor.setCorePoolSize(1);
threadPoolTaskExecutor.setMaxPoolSize(1);
threadPoolTaskExecutor.initialize();
return new LazyTraceExecutor(beanFactory, threadPoolTaskExecutor);
}
}
It’s important to note here the use of LazyTraceExecutor. This class comes from the Sleuth library, and it’s a special kind of executor that will propagate our traceIds to new threads, and create new spanIds in the process.
Now we’ll wire this executor into our controller, and use it in a new request mapping method:
@Autowired
private Executor executor;
@GetMapping("/new-thread")
public String helloSleuthNewThread() {
logger.info("New Thread");
Runnable runnable = () -> {
try {
Thread.sleep(1000L);
} catch (InterruptedException e) {
e.printStackTrace();
}
logger.info("I'm inside the new thread - with a new span");
};
executor.execute(runnable);
logger.info("I'm done - with the original span");
return "success";
}
With our runnable in place, we’ll restart our application, and navigate to “http://localhost:8080/new-thread”. We’ll watch for log output that looks like:
2017-01-11 21:18:15.949
INFO [Baeldung Sleuth Tutorial,96076a78343c364d,96076a78343c364d,false] 12516
--- [nio-8080-exec-9] c.b.spring.session.SleuthController : New Thread
2017-01-11 21:18:15.950
INFO [Baeldung Sleuth Tutorial,96076a78343c364d,96076a78343c364d,false] 12516
--- [nio-8080-exec-9] c.b.spring.session.SleuthController :
I'm done - with the original span
2017-01-11 21:18:16.953
INFO [Baeldung Sleuth Tutorial,96076a78343c364d,e3b6a68013ddfeea,false] 12516
--- [lTaskExecutor-1] c.b.spring.session.SleuthController :
I'm inside the new thread - with a new span
Much like the previous example, we can see that all the logs share the same traceId, but the log coming from the runnable has a unique span that will track the work done in that thread. Remember that this happens because of the LazyTraceExecutor. If we were to use a normal executor, we would continue to see the same spanId used in the new thread.
Now let’s look into Sleuth’s support for @Async methods.
3.5. @Async Support
To add async support, we’ll first modify our ThreadConfig class to enable this feature:
@Configuration
@EnableAsync
public class ThreadConfig extends AsyncConfigurerSupport {
//...
@Override
public Executor getAsyncExecutor() {
ThreadPoolTaskExecutor threadPoolTaskExecutor = new ThreadPoolTaskExecutor();
threadPoolTaskExecutor.setCorePoolSize(1);
threadPoolTaskExecutor.setMaxPoolSize(1);
threadPoolTaskExecutor.initialize();
return new LazyTraceExecutor(beanFactory, threadPoolTaskExecutor);
}
}
Note that we extend AsyncConfigurerSupport to specify our async executor, and use LazyTraceExecutor to ensure traceIds and spanIds are propagated correctly. We also added @EnableAsync to the top of our class.
Now we’ll add an async method to our service:
@Async
public void asyncMethod() {
logger.info("Start Async Method");
Thread.sleep(1000L);
logger.info("End Async Method");
}
We’ll call into this method from our controller:
@GetMapping("/async")
public String helloSleuthAsync() {
logger.info("Before Async Method Call");
sleuthService.asyncMethod();
logger.info("After Async Method Call");
return "success";
}
Finally, we’ll restart our service and navigate to “http://localhost:8080/async”. We’ll watch for the log output that looks like:
2017-01-11 21:30:40.621
INFO [Baeldung Sleuth Tutorial,c187f81915377fff,c187f81915377fff,false] 10072
--- [nio-8080-exec-2] c.b.spring.session.SleuthController :
Before Async Method Call
2017-01-11 21:30:40.622
INFO [Baeldung Sleuth Tutorial,c187f81915377fff,c187f81915377fff,false] 10072
--- [nio-8080-exec-2] c.b.spring.session.SleuthController :
After Async Method Call
2017-01-11 21:30:40.622
INFO [Baeldung Sleuth Tutorial,c187f81915377fff,8a9f3f097dca6a9e,false] 10072
--- [lTaskExecutor-1] c.baeldung.spring.session.SleuthService :
Start Async Method
2017-01-11 21:30:41.622
INFO [Baeldung Sleuth Tutorial,c187f81915377fff,8a9f3f097dca6a9e,false] 10072
--- [lTaskExecutor-1] c.baeldung.spring.session.SleuthService :
End Async Method
We can see here that much like our runnable example, Sleuth propagates the traceId into the async method, and adds a unique spanId.
Now we’ll work through an example using spring support for scheduled tasks.
3.6. @Scheduled Support
Finally, we’ll look at how Sleuth works with @Scheduled methods. To do this, we’ll update our ThreadConfig class to enable scheduling:
@Configuration
@EnableAsync
@EnableScheduling
public class ThreadConfig extends AsyncConfigurerSupport
implements SchedulingConfigurer {
//...
@Override
public void configureTasks(ScheduledTaskRegistrar scheduledTaskRegistrar) {
scheduledTaskRegistrar.setScheduler(schedulingExecutor());
}
@Bean(destroyMethod = "shutdown")
public Executor schedulingExecutor() {
return Executors.newScheduledThreadPool(1);
}
}
Note that we implemented the SchedulingConfigurer interface, and overrode its configureTasks method. We also added @EnableScheduling to the top of our class.
Next, we’ll add a service for our scheduled tasks:
@Service
public class SchedulingService {
private Logger logger = LoggerFactory.getLogger(this.getClass());
@Autowired
private SleuthService sleuthService;
@Scheduled(fixedDelay = 30000)
public void scheduledWork() throws InterruptedException {
logger.info("Start some work from the scheduled task");
sleuthService.asyncMethod();
logger.info("End work from scheduled task");
}
}
In this class, we created a single scheduled task with a fixed delay of 30 seconds.
Now let’s restart our application, and wait for our task to be executed. We’ll watch the console for output like this:
2017-01-11 21:30:58.866
INFO [Baeldung Sleuth Tutorial,3605f5deaea28df2,3605f5deaea28df2,false] 10072
--- [pool-1-thread-1] c.b.spring.session.SchedulingService :
Start some work from the scheduled task
2017-01-11 21:30:58.866
INFO [Baeldung Sleuth Tutorial,3605f5deaea28df2,3605f5deaea28df2,false] 10072
--- [pool-1-thread-1] c.b.spring.session.SchedulingService :
End work from scheduled task
We can see here that Sleuth has created new trace and span ids for our task. Each instance of a task will get it’s own trace and span by default.
4. Conclusion
In this article, we learned how Spring Sleuth can be used in a variety of situations inside a single web application. We can use this technology to easily correlate logs from a single request, even when that request spans multiple threads.
By now, we can appreciate how Spring Cloud Sleuth can help us keep our sanity when debugging a multi-threaded environment. By identifying each operation in a traceId and each step in a spanId, we can really begin to break down our analysis of complex jobs in our logs.
Even if we don’t go to the cloud, Spring Sleuth is likely a critical dependency in almost any project; it’s seamless to integrate, and is a massive addition of value.
From here we may want to investigate other features of Sleuth. It can support tracing in distributed systems using RestTemplate, across messaging protocols used by RabbitMQ and Redis, and through a gateway like Zuul.
As always, the source code is available over on Github.