preface
In the traditional system, if the log output can be provided, it can basically meet the requirements. However, once the system is divided into two or more systems, plus load balancing, the call link becomes complex.
Especially in the direction of further evolution towards micro services, if there is no reasonable planning of logs and link tracking, it will become extremely difficult to troubleshoot logs.
For example, for systems A, B and C, the calling link is A - > b - > C. if each set of services is dual active, the calling path has three possibilities of 2. If there are more systems and more services, the call link will grow exponentially.
Therefore, whether it is a few simple internal service calls or a complex microservice system, it needs a mechanism to realize the link tracking of logs. Let your systematic log output have formal beauty and harmonious rhythm like poetry.
In fact, there are many ready-made frameworks for log tracking, such as Sleuth, Zipkin and other components. But this is not the focus we want to talk about. This paper focuses on handwritten implementation of a simple log call link tracking function based on Spring Boot and LogBack. Based on this implementation pattern, you can implement it more finely.
Integrating Logback in Spring Boot
Spring Boot itself has built-in logging function. Here, the logback logging framework is used and the output results are formatted. Let's take a look at the built-in integration of SpringBoot with logback. The dependencies are as follows. When the project introduces:
<dependency>
<groupId>org.springframework.boot</groupId>
<artifactId>spring-boot-starter-web</artifactId>
</dependency>
Spring boot starter web indirectly introduces:
<dependency> <groupId>org.springframework.boot</groupId> <artifactId>spring-boot-starter</artifactId> </dependency>
Spring boot starter also introduces the starter of logging:
<dependency> <groupId>org.springframework.boot</groupId> <artifactId>spring-boot-starter-logging</artifactId> </dependency>
The required logback package is really introduced into 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>
Therefore, when we use it, we only need to put logback spring The XML configuration file can be placed in the resources directory. Theoretically, the configuration file is named logback XML is also supported, but the recommended name on the Spring Boot official website is: logback spring xml.
Then, in logback spring Configure log output in XML. Instead of pasting all the codes here, only the relevant log output format is pasted. Take 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"/>
In the expression of value attribute, we added a custom variable value requestId, which is displayed in the form of "[% 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 whole request link can be connected in series. If the system is also based on EKL and other log collection tools for unified collection, it is more convenient to view the call link of the whole log.
So how does the requestId variable come from and where is it stored? To understand this, let's first understand the MDC function provided by the logging framework.
What is MDC?
MDC(Mapped Diagnostic Contexts) is a thread safe container for storing diagnostic logs. MDC is a tool class provided by slf4j to adapt to other specific log implementation packages. At present, only logback and log4j support this function.
MDC is thread independent and thread safe. Generally, both HTTP and RPC requests are completed in their own independent threads, which is in good agreement with the mechanism of MDC.
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 one of the implementation classes of the interface MDCAdapter, BasicMDCAdapter:
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);
}
// ...
}
From the source code, we can see that there is an instance of InheritableThreadLocal in which the context data is saved through HashMap.
In addition, MDC provides several core interfaces such as put/get/clear to operate the data stored in ThreadLocal. And in logback XML, you can obtain the data stored in MDC by declaring "% X{requestId}" in layout, and print this information.
Based on these characteristics of MDC, it is often used for log link tracking, dynamic configuration of user-defined information (such as requestId, sessionId, etc.).
Practical use
After understanding some basic principles above, let's take a look at how to realize log tracking based on MDC function of log framework.
Tool preparation
First, define some tool classes. It is strongly recommended that you implement some operations in the form of tool classes, which is a part of writing elegant code and avoiding the need to change everything in the later modification.
The generation class of TraceID (the parameter name we define is requestId), which is generated by UUID. Of course, it can be generated by other methods according to your scene and needs.
public class TraceIdUtils {
/**
* Generate traceId
*
* @return TraceId Based on UUID
*/
public static String getTraceId() {
return UUID.randomUUID().toString().replace("-", "");
}
}
Operation tool class TraceIdContext for Context content:
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();
}
}
Through the tool class, it is convenient for all services to be used uniformly. For example, requestId can be defined uniformly to avoid being different everywhere. Not only the set method, but also the removal and cleaning methods are provided here.
It should be noted that MDC Use of the clear () method. If all threads are established through the new Thread method, after the thread dies, the stored data also dies, which is nothing. However, if the thread pool is used, the thread can be reused. If the MDC content of the previous thread is not cleared, obtaining this thread from the thread pool again will take out the previous data (dirty data), which will lead to some unexpected errors. Therefore, it must be cleared after the end of the current thread.
Filter interception
Since we want to track the log link, the most intuitive idea is to generate a request ID at the source of access, and then pass it all the way until the request is completed. Taking Http as an example, the request is intercepted through Filter, and the data is stored and transmitted through Http Header. When it comes to calls between systems, the caller sets the requestId to the Header, and the callee can take it from the Header.
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();
}
}
In the beforeRequest method, obtain the requestId from the Header. If it cannot be obtained, it will be regarded as the "source", generate a requestId and set it to the MDC. When the request is completed, remove the set requestId to prevent the thread pool problem mentioned above. Each service in the system can be realized in the above way, and the whole request link is connected in series.
Of course, the Filter defined above needs to be initialized. The instantiation method in Spring Boot is as follows:
@Configuration
public class TraceIdConfig {
@Bean
public TraceIdRequestLoggingFilter traceIdRequestLoggingFilter() {
return new TraceIdRequestLoggingFilter();
}
}
For ordinary system calls, the above methods can basically be met, and can be extended according to their own needs in practice. Filter is used here, which can also be implemented through interceptors, AOP of Spring, etc.
Feign in microservices
If your system calls based on Feign component in Spring Cloud, you can add requestId by implementing RequestInterceptor interceptor. The specific implementation is as follows:
@Configuration
public class FeignConfig implements RequestInterceptor {
@Override
public void apply(RequestTemplate requestTemplate) {
requestTemplate.header(TraceIdContext.TRACE_ID_KEY, TraceIdContext.getTraceId());
}
}
Result verification
After completing the above operations, make a request to a Controller and print the following log:
2021-04-13 10:58:31.092 cloud-sevice-consumer-demo [http-nio-7199-exec-1] INFO [ef76526ca96242bc8e646cdef3ab31e6] c.b.demo.controller.CityController - getCity 2021-04-13 10:58:31.185 cloud-sevice-consumer-demo [http-nio-7199-exec-1] WARN [ef76526ca96242bc8e646cdef3ab31e6] o.s.c.o.l.FeignBlockingLoadBalancerClient -
You can see that the requestid has been successfully added. When we check the log, we only need to find the key information of the request, and then the whole log can be connected in series according to the requestid value in the key information log.
Summary
Finally, let's review the whole process of log tracking: when the request arrives at the first server, the service checks whether the requestId exists. If it does not exist, create one and put it into the MDC; When a service calls other services, it passes the requestId through the Header; The logback of each service configures the output of requestId. So as to achieve the effect of concatenating logs from beginning to end.
In learning this article, if you only learn log tracing, it is a loss, because the article also involves the integration of SpringBoot on logback, the underlying implementation of MDC and the use of pits, filters, Feign's request interceptor, etc. If interested, everyone can spread and learn more knowledge.
New horizon of procedureOfficial account " "New horizons of program", a platform that enables you to improve your soft power and hard technology simultaneously, and provides a large amount of data
