Challenge of analyzing logs in microservice architecture

Modern software systems are often developed using microservice architecture. In this architecture applications are designed as a collection of small components built around business needs. That means that one user request is most often handled by multiple components. In environments with many concurrent users this architecture can make it very difficult to track requests split between different log sources.

Example of logs from different components:

16:53:21.139 INFO [main] OrderController : Received new order request
16:53:21.148 INFO [main] OrderController : Creating new order
16:53:21.222 INFO [main] OrderController : Received new order request
16:53:21.258 INFO [main] OrderController : Creating new order
16:53:21.299 INFO [main] OrderController : Successfully created new order
16:53:21.350 INFO [main] OrderController : Successfully created new order
16:53:21.152 INFO [main] ProcessManager : Started process for new order
16:53:21.260 INFO [main] ProcessManager : Started process for new order
16:53:21.288 INFO [main] ProcessManager : Finished process for new order
16:53:21.333 INFO [main] ProcessManager : Finished process for new order

One improvement would be to add an user identifier in every log line. That would enable us to easily analyze all the requests in one component. Another improvement would be to introduce a request identifier that would be logged in all the components handling one request. That way we could correlate logs from all the components regarding one user request.

If we were to add those details manually, it would look something like:

logger.info("userId: {}, requestId: {}, Received new order request", userId, requestId):

This method would be very error prone and especially hard to implement in existing components with a lot of code already written. It is very easy to forget to add additional information or make a mistake that will log wrong data.

Better logging with MDC

Alternative solution is to use Mapped Diagnostic Context (MDC). This enables us to easily add contextual information to each user request. MDC provides a key/value structure that we can populate at the beginning of processing user requests. MDC will keep that information separately for each running thread and automatically include it in every log line that is produced.

MDC is supported by all the major Java logging frameworks: log4j, log4j2 and logback. In a typical web application, we would populate MDC data in an interceptor, so that it is automatically done on each HTTP request.

Example of interceptor:

public class MdcInterceptor implements HandlerInterceptor {

@Override
public boolean preHandle(HttpServletRequest request, HttpServletResponse response, Objectandler) throws Exception {
MDC.put("userId", request.getHeader("X-User-Id"));
MDC.put("requestId", request.getHeader("X-Request-Id"));
return true;
}
@Override

public void afterCompletion(HttpServletRequest request, HttpServletResponse response, Object handler, Exception ex) throws Exception {
MDC.clear();
}
}

Now we can use MDC data in our logging configuration, by using %X pattern specifier, followed by our MDC key:

… %date{ISO8601} %-5level [%thread] [%X{userId} %X{requestId}] %logger{100} : %msg%n ...

Example of logs with MDC data populated:

16:53:21.139 INFO [main] [178 21961] OrderController : Received new order request
16:53:21.148 INFO [main] [178 21961] OrderController : Creating new order
16:53:21.222 INFO [main] [442 21962] OrderController : Received new order request
16:53:21.258 INFO [main] [442 21962] OrderController : Creating new order
16:53:21.299 INFO [main] [178 21961] OrderController : Successfully created new order
16:53:21.350 INFO [main] [442 21962] OrderController : Successfully created new order
16:53:21.152 INFO [main] [178 21961] ProcessManager : Started process for new order
16:53:21.260 INFO [main] [442 21962] ProcessManager : Started process for new order
16:53:21.288 INFO [main] [178 21961] ProcessManager : Finished process for new order
16:53:21.333 INFO [main] [442 21962] ProcessManager : Finished process for new order

Now we can more easily analyze the logs and extract information from specific user or specific user request scattered throughout different logs.

Spring Cloud Sleuth

One disadvantage of the proposed solution is that we have to populate HTTP headers manually each time a microservice endpoint is called. We have to make sure that on the first user request MDC data is properly generated and then propagated to each component handling user request
throughout the system.

Alternative solution is to use Spring Cloud Sleuth – including this library will automatically add additional information like request IDs in your logs. But more importantly Sleuth also has support for propagating such information throughout different microservice components whether they are communicating synchronously using HTTP or asynchronously using Kafka.