Logging in a monolith (spring) service

Overview

Logging is one of the most complicated parts of micro-services. Often, there will the millions of requests coming to services and they go through complex pipelines like having an threads. async executables etc.;. It is hard for someone to correlate what actions are performed to cater a single web request just by looking at logs. This makes it difficult to diagnose if there is an issue with a web request.

A good logging system should record entire system activity, along with users activity and how system responded to every user interaction. It should provide holistic view on end to end system interaction. End to end interaction means from request origin to sending response back. In order, to achieve that we require a good tracing library that integrates with our threadpool executors, async jobs etc;. and propagate unique id across them.

Logging in spring application

To implement a good logging system which we described in above section, we use sleuth library provided by spring-cloud framework. This integrates well with libraries like logback, slf4j to add identifiers so that we can trace and diagnose issues using logs.

Sleuth overview

Sleuth in general injects two unique identifiers for tracing

Trace id : This is a unique id assigned to a request or an action.

Span id: This is a unique id assigned to single unit of work that happens with in a request.

.---------------.------------.-----------.
|     type      | request id |  span id  |
:---------------+------------+-----------:
| Single thread | same       | same      |
:---------------+------------+-----------:
| Thread pool   | same       | different |
:---------------+------------+-----------:
| Async         | same       | different |
'---------------'------------'-----------'

In general, every request spans with a single Trace id and every other runnable or an async tasks will have different span ids. Above is a simple table that depicts the same.

Implementation

Step-1: Injecting sleuth dependency into application.

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

To resolve transitive dependency for version management with spring cloud in clean manner we introduce dependency management tag like this

<dependencyManagement>
    <dependencies>
        <dependency>
            <groupId>org.springframework.cloud</groupId>
            <artifactId>spring-cloud-sleuth</artifactId>
            <version>${spring-cloud-sleuth.version}</version>
            <type>pom</type>
            <scope>import</scope>
        </dependency>
    </dependencies>
</dependencyManagement>

Step-2: Formatting logs to accommodate trace id. We can change the pattern in our logback config file to incorporate trace id.

<property name="logPattern"
          value="[EX] %d{YYYY-MM-dd HH:mm:ss.SSS} %5p [%X{X-B3-TraceId}] [%X{X-B3-SpanId:-}] [%C{0}] - %msg%n"/>

Explanation: Logs in our application will be formatted and printed with 3 components

1. EX : This is usually application name which we can take it from configuration for simplicity I used constant.
2. X-B3-TraceId : This is unique id that is generated by sleuth library in order to identify single request flow.
3. X-B3-SpanId : This is unique id that is generated by sleuth library in order to identify sub-request flow with in a request.

Step-3: Creating a bean configuration to use sleuth executor service for application. Bean configuration code is as below

@Bean
public Executor executor() {
    ThreadPoolTaskExecutor threadPoolTaskExecutor = new ThreadPoolTaskExecutor();
    threadPoolTaskExecutor.setCorePoolSize(1);
    threadPoolTaskExecutor.setMaxPoolSize(1);
    threadPoolTaskExecutor.initialize();

    return new LazyTraceExecutor(beanFactory, threadPoolTaskExecutor);
}

When you run your applications now with a stub for running a thread, you will see logs as below

Explanation:
1. 0c57108116317306 : Trace id that is common from end to end of the request.

2. 0c57108116317306,17d6b0ae22a8f28f : Span id that gets changed when a thread gets executed.

Step-4: Creating an configuration for executing async executables. Configuration to extend sleuth async configuration support.

public class SleuthConfig extends AsyncConfigurerSupport{

    @Autowired
    private BeanFactory beanFactory;

    @Override
    public Executor getAsyncExecutor() {
        ThreadPoolTaskExecutor threadPoolTaskExecutor = new ThreadPoolTaskExecutor();
        threadPoolTaskExecutor.setCorePoolSize(1);
        threadPoolTaskExecutor.setMaxPoolSize(1);
        threadPoolTaskExecutor.initialize();

        return new LazyTraceExecutor(beanFactory, threadPoolTaskExecutor);
    }

}

When spring executes the methods with async annotation it will take the executors from this configuration and use it to propagate trace and request ids.

Explanation: Same as above we have same request id for entire request and different span id for the async threads.

Step-5: Configuring traceability for async threads that are executed using CompletableFuture class. This is tricky as we need to pass executor service within our stub call. Defining a bean to get TraceableExecutorService

@Bean
public TraceableExecutorService traceableExecutorService(BeanFactory factory) {
    return new TraceableExecutorService(factory, Executors.newFixedThreadPool(100));
}

Now above bean is passed to our stub call where we are using CompletableFuture class.

CompletableFuture.supplyAsync(() -> {
    log.info("In callable async thread");
    return null;
},executor);

executor variable in the above call is object create from TraceableExecutorService bean. Logs for the same can be seen as below

Explanation: Same as above

While the underlying concept for TraceId and SpanId will not change when using any of the feature, it is the configuration that differs.

Complete code can be found here.

Conclusion

By now we have seen how we can use sleuth to improve sanity of the application by improving sanity of our monolith application. You may want to explore implementing trace and span ids which is not covered as part of this article. While the underlying concepts remain same in case of micro-service architecture we can cover how to improve traceability of a micro-service architecture system in another article.

Resources

https://docs.spring.io/spring-cloud-sleuth/docs/current-SNAPSHOT/reference/html/integrations.html