preface

In traditional systems, if you can provide log output, you can basically meet the requirements. But once the system is divided into two or more systems, coupled with load balancing and so on, the call link becomes complicated.

In particular, as microservices evolve, it becomes extremely difficult to troubleshoot logs without proper log planning and link tracing.

For example, system A, B, and C have the call link A -> B -> C. If each service is hypermetro, the call path has 2 to the power of 3 possibilities. If there are more systems and more services, the call links will grow exponentially.

Therefore, whether it is a few simple internal service calls or a complex microservice system, a mechanism is needed to implement log link tracing. Let your system log output, like poetry, the beauty of form, and a harmonious rhythm.

There are already many frameworks for log tracking, such as Sleuth, Zipkin, and others. But this is not the point we want to talk about, this article focuses on the implementation of a simple log call link tracking function based on Spring Boot, LogBack handwriting. Based on this implementation pattern, you can implement more fine-grained.

Logback is integrated in Spring Boot

Spring Boot has built-in logging, using the Logback logging framework and formatting the output. Take a look at SpringBoot’s built-in integration with Logback, with the following dependencies. When the project introduced:

<dependency>
    <groupId>org.springframework.boot</groupId>
    <artifactId>spring-boot-starter-web</artifactId>
</dependency>
Copy the code

Spring-boot-starter-web indirectly introduces:

<dependency>
  <groupId>org.springframework.boot</groupId>
  <artifactId>spring-boot-starter</artifactId>
</dependency>
Copy the code

Spring-boot-starter introduces the logging starter:

<dependency>
  <groupId>org.springframework.boot</groupId>
  <artifactId>spring-boot-starter-logging</artifactId>
</dependency>
Copy the code

The required logback package is actually introduced in logging:

<dependency>
  <groupId>ch.qos.logback</groupId>
  <artifactId>logback-classic</artifactId>
</dependency>
<dependency>
  <groupId>org.apache.logging.log4j</groupId>
  <artifactId>log4j-to-slf4j</artifactId>
</dependency>
<dependency>
  <groupId>org.slf4j</groupId>
  <artifactId>jul-to-slf4j</artifactId>
</dependency>
Copy the code

Therefore, we can use the logback-spring. XML configuration file in the Resources directory. In theory, the configuration file name logback. XML is supported, but the Spring Boot website recommends logback-spring.xml.

Then configure log output in logback-spring. XML. Instead of Posting all the code here, just post the relevant log output format, using console output as an example:

<property name="CONSOLE_LOG_PATTERN" value="%d{yyyy-MM-dd HH:mm:ss.SSS} %contextName [%thread] %-5level [%X{requestId}] %logger{36} - %msg%n"/>
Copy the code

In the expression of the value attribute, we have added the custom variable value requestId, represented by “[%X{requestId}]”.

This requestId is the unique identifier we use to track the log. If a request uses the same requestId from beginning to end, the entire request link can be connected. If the system also collects logs based on EKL and other log collection tools, it is more convenient to view the call link of the entire log.

So how and where did this requestId variable come from? To understand this, we need to take a look at the MDC capabilities provided by the logging framework.

What is MDC?

MDC(Mapped Diagnostic Contexts) is a thread-safe container for storing Diagnostic logs. MDC is a utility class provided by SLF4J that ADAPTS to other specific logging implementation packages, currently supported only by Logback and Log4j.

MDC is thread-independent and thread-safe. Generally, HTTP or RPC requests are completed in separate threads, which fits nicely with the MDC mechanism.

When using the MDC function, we mainly use the PUT method, which indirectly calls the PUT method of the MDCAdapter interface.

Take a look at the code in BasicMDCAdapter, one of the implementation classes of interface MDCAdapter:

public class BasicMDCAdapter implements MDCAdapter { private InheritableThreadLocal<Map<String, String>> inheritableThreadLocal = new InheritableThreadLocal<Map<String, String>>() { @Override protected Map<String, String> childValue(Map<String, String> parentValue) { if (parentValue == null) { return null; } return new HashMap<String, String>(parentValue); }}; public void put(String key, String val) { if (key == null) { throw new IllegalArgumentException("key cannot be null"); } Map<String, String> map = inheritableThreadLocal.get(); if (map == null) { map = new HashMap<String, String>(); inheritableThreadLocal.set(map); } map.put(key, val); } / /... }Copy the code

An instance of InheritableThreadLocal is held internally using HashMap to hold context data.

In addition, MDC provides several core interfaces, such as PUT, GET, and Clear, for manipulating data stored in ThreadLocal. In logback. XML, you can print the data stored in the MDC by declaring %X{requestId} in layout.

Based on these features, MDC is often used to track log links and dynamically configure user-defined information (such as requestId and sessionId).

Practical use

Now that you’ve seen the basics, let’s look at how to implement log tracing based on the MDC functionality of the logging framework.

Preparing Tools

Start by defining some utility classes. It is highly recommended that you implement some operations in the form of utility classes. This is part of writing elegant code and avoiding the need to change everything later.

TraceID (we defined the parameter named requestId) generation class, here using the UUID to generate, of course, depending on your scenario and needs, through other methods to generate.

Public class TraceIdUtils {/** * Generate traceId ** @return traceId Based on UUID */ public static String getTraceId() {return UUID.randomUUID().toString().replace("-", ""); }}Copy the code

TraceIdContext: TraceIdContext:

public class TraceIdContext { public static final String TRACE_ID_KEY = "requestId"; public static void setTraceId(String traceId) { if (StringLocalUtil.isNotEmpty(traceId)) { MDC.put(TRACE_ID_KEY, traceId); } } public static String getTraceId() { String traceId = MDC.get(TRACE_ID_KEY); return traceId == null ? "" : traceId; } public static void removeTraceId() { MDC.remove(TRACE_ID_KEY); } public static void clearTraceId() { MDC.clear(); }}Copy the code

Using utility classes, all services can be used in a unified manner. For example, requestId can be defined in a unified manner to avoid different services. Not only are set methods provided, but also methods to remove and clean them up.

Note the use of the MDC.clear() method. If all threads are created using the new Thread method, the stored data dies when the Thread dies, which is fine. In the case of a thread pool, however, threads can be reused. If the MDC content of the previous thread is not removed, retrieving the thread from the pool will fetch the previous data (dirty data), which can cause unexpected errors. Therefore, it must be removed after the current thread is finished.

The Filter to intercept

Since we want to implement log link tracing, the most intuitive idea is to generate a request ID at the source of the access and pass it along until the request completes. Using Http as an example, Filter is used to intercept requests and data is stored and passed through Http headers. When it comes to inter-system calls, the caller sets the requestId to the Header, from which the called can fetch it.

Definition of Filter:

public class TraceIdRequestLoggingFilter extends AbstractRequestLoggingFilter { @Override protected void beforeRequest(HttpServletRequest request, String message) { String requestId = request.getHeader(TraceIdContext.TRACE_ID_KEY); if (StringLocalUtil.isNotEmpty(requestId)) { TraceIdContext.setTraceId(requestId); } else { TraceIdContext.setTraceId(TraceIdUtils.getTraceId()); } } @Override protected void afterRequest(HttpServletRequest request, String message) { TraceIdContext.removeTraceId(); }}Copy the code

In the beforeRequest method, obtain the requestId from the Header. If the requestId cannot be obtained, it is regarded as the source. Generate a requestId and set it to the MDC. When this request completes, the set requestId is removed to prevent the thread pool problems mentioned above. Each service in the system can be implemented in this way, and the entire request link is strung together.

Of course, the Filter defined above needs to be initialized and instantiated in Spring Boot as follows:

@Configuration public class TraceIdConfig { @Bean public TraceIdRequestLoggingFilter traceIdRequestLoggingFilter() { return new TraceIdRequestLoggingFilter(); }}Copy the code

For ordinary system call, the above method has basically been able to meet, in practice can be based on their own needs to expand on this basis. The Filter is used here, which can also be implemented through interceptors, Spring’s AOP, and so on.

Feign in microservices

If your system is called based on the Feign component in the Spring Cloud, you can add requestId by implementing the RequestInterceptor interceptor. The concrete implementation is as follows:

@Configuration public class FeignConfig implements RequestInterceptor { @Override public void apply(RequestTemplate requestTemplate) { requestTemplate.header(TraceIdContext.TRACE_ID_KEY, TraceIdContext.getTraceId()); }}Copy the code

results

When this is done, a request to a Controller will print the following log:

The 2021-04-13 10:58:31. 092 cloud - sevice - consumer - demo [HTTP - nio - 7199 - exec - 1] INFO [ef76526ca96242bc8e646cdef3ab31e6] C.B.D emo. Controller. CityController - getCity 10:58:31 2021-04-13. 185 cloud - sevice - consumer - demo [HTTP - nio - 7199 - exec - 1) WARN [ef76526ca96242bc8e646cdef3ab31e6] o.s.c.o.l.FeignBlockingLoadBalancerClient -Copy the code

You can see that requestID has been added successfully. When sifting through logs, we can simply find the key information of the request, and then string the entire log together based on the requestId value of the key information in the log.

summary

Finally, let’s review the entire log tracing process: When the request arrives at the first server, the service checks for the presence of the requestId, and if not, creates one and puts it into MDC. When a service calls another service, it passes the requestId through the Header. The logback for each service configures the output of requestId. This results in a series of logs from beginning to end.

If you only learn log tracing in this article, it’s a loss, as it also covers SpringBoot’s integration with Logback, MDC’s underlying implementation and pits, the use of filters, Feign’s request interceptor, and so on. If interested, each can diverge, learn more knowledge points.

Program new horizon

The public account “program new vision”, a platform for simultaneous improvement of soft power and hard technology, provides massive information