Spring Boot + MDC implements full link call log tracking, which is called elegance..

Author: is he Tiantian there\
Source: Juejin cn/post/6844904101483020295

A previous article briefly introduced MDC. This time, we will have an in-depth understanding of MDC in combination with specific cases and specific problems in production.

Introduction to MDC

1. Introduction:

MDC (Mapped Diagnostic Context) is a function provided by log4j, logback and log4j2 to facilitate logging under multi-threaded conditions. MDC can be regarded as a hash table bound to the current thread, and key value pairs can be added to it. The content contained in MDC can be accessed by code executed in the same thread.

The child thread of the current thread will inherit the contents of the MDC in its parent thread. When logging is required, you only need to obtain the required information from MDC. The content of MDC is saved by the program at an appropriate time. For a Web application, this data is usually saved at the beginning of the request being processed.

2. API Description:

  • clear(): remove all MDC s
  • get (String key): get the value of the specified key in the MDC of the current thread
  • getContext(): get the MDC of the current thread
  • put(String key, Object o): store the specified key value pair into the MDC of the current thread
  • remove(String key): deletes the key value pair specified in the MDC of the current thread

3. Advantages:

The code is concise and the log style is unified. There is no need to spell traceid manually in log printing, that is, logger info("traceId:{} ", traceId).

MDC usage

1. Add interceptor

public class LogInterceptor implements HandlerInterceptor {
    @Override
    public boolean preHandle(HttpServletRequest request, HttpServletResponse response, Object handler) throws Exception {
        //If there is an upper layer call, use the upper layer ID
        String traceId = request.getHeader(Constants.TRACE_ID);
        if (traceId == null) {
            traceId = TraceIdUtil.getTraceId();
        }

        MDC.put(Constants.TRACE_ID, traceId);
        return true;
    }

    @Override
    public void postHandle(HttpServletRequest request, HttpServletResponse response, Object handler, ModelAndView modelAndView)
            throws Exception {
    }

    @Override
    public void afterCompletion(HttpServletRequest request, HttpServletResponse response, Object handler, Exception ex)
            throws Exception {
        //Delete after call
        MDC.remove(Constants.TRACE_ID);
    }
}

2. Modify log format

<property name="pattern">[TRACEID:%X{traceId}] %d{HH:mm:ss.SSS} %-5level %class{-1}.%M()/%L - %msg%xEx%n</property>

The key point is% X{traceId}, which is consistent with the key name in MDC

Simple use is so easy, but in some cases, traceId will not be obtained.

Problems in MDC

  • traceId is missing from the print log in the child thread
  • traceId missing from HTTP call

If the traceId is lost, solve it one by one, and never optimize it in advance.

Solve the problems of MDC

The trace ID is lost in the printing of the child thread log

The traceId of the child thread will be lost in the process of printing the log. The solution is to rewrite the thread pool. For the case of directly creating a thread with new, do not omit [this usage should be avoided in practical application]. Rewriting the thread pool is nothing more than a encapsulation of the task.

Thread pool encapsulation class: threadpoolexecutormdcwrapper java

public class ThreadPoolExecutorMdcWrapper extends ThreadPoolExecutor {
    public ThreadPoolExecutorMdcWrapper(int corePoolSize, int maximumPoolSize, long keepAliveTime, TimeUnit unit,
                                        BlockingQueue<Runnable> workQueue) {
        super(corePoolSize, maximumPoolSize, keepAliveTime, unit, workQueue);
    }

    public ThreadPoolExecutorMdcWrapper(int corePoolSize, int maximumPoolSize, long keepAliveTime, TimeUnit unit,
                                        BlockingQueue<Runnable> workQueue, ThreadFactory threadFactory) {
        super(corePoolSize, maximumPoolSize, keepAliveTime, unit, workQueue, threadFactory);
    }

    public ThreadPoolExecutorMdcWrapper(int corePoolSize, int maximumPoolSize, long keepAliveTime, TimeUnit unit,
                                        BlockingQueue<Runnable> workQueue, RejectedExecutionHandler handler) {
        super(corePoolSize, maximumPoolSize, keepAliveTime, unit, workQueue, handler);
    }

    public ThreadPoolExecutorMdcWrapper(int corePoolSize, int maximumPoolSize, long keepAliveTime, TimeUnit unit,
                                        BlockingQueue<Runnable> workQueue, ThreadFactory threadFactory,
                                        RejectedExecutionHandler handler) {
        super(corePoolSize, maximumPoolSize, keepAliveTime, unit, workQueue, threadFactory, handler);
    }

    @Override
    public void execute(Runnable task) {
        super.execute(ThreadMdcUtil.wrap(task, MDC.getCopyOfContextMap()));
    }

    @Override
    public <T> Future<T> submit(Runnable task, T result) {
        return super.submit(ThreadMdcUtil.wrap(task, MDC.getCopyOfContextMap()), result);
    }

    @Override
    public <T> Future<T> submit(Callable<T> task) {
        return super.submit(ThreadMdcUtil.wrap(task, MDC.getCopyOfContextMap()));
    }

    @Override
    public Future<?> submit(Runnable task) {
        return super.submit(ThreadMdcUtil.wrap(task, MDC.getCopyOfContextMap()));
    }
}

explain:

  • Inherit the ThreadPoolExecutor class and re execute the method of the task
  • Wrap the task once through ThreadMdcUtil

Thread traceId encapsulation tool class: threadmdcutil java

public class ThreadMdcUtil {
    public static void setTraceIdIfAbsent() {
        if (MDC.get(Constants.TRACE_ID) == null) {
            MDC.put(Constants.TRACE_ID, TraceIdUtil.getTraceId());
        }
    }

    public static <T> Callable<T> wrap(final Callable<T> callable, final Map<String, String> context) {
        return () -> {
            if (context == null) {
                MDC.clear();
            } else {
                MDC.setContextMap(context);
            }
            setTraceIdIfAbsent();
            try {
                return callable.call();
            } finally {
                MDC.clear();
            }
        };
    }

    public static Runnable wrap(final Runnable runnable, final Map<String, String> context) {
        return () -> {
            if (context == null) {
                MDC.clear();
            } else {
                MDC.setContextMap(context);
            }
            setTraceIdIfAbsent();
            try {
                runnable.run();
            } finally {
                MDC.clear();
            }
        };
    }
}

Description [take encapsulating Runnable as an example]:

  • Judge whether the MDC Map corresponding to the current thread exists, and set if it exists
  • Set the traceId value in MDC. If it does not exist, it will be generated. For the case that it is not a child thread, if it is a child thread, the traceId in MDC will not be null
  • Execute run method

The code is equivalent to the following writing method, which will be more intuitive

public static Runnable wrap(final Runnable runnable, final Map<String, String> context) {
        return new Runnable() {
            @Override
            public void run() {
                if (context == null) {
                    MDC.clear();
                } else {
                    MDC.setContextMap(context);
                }
                setTraceIdIfAbsent();
                try {
                    runnable.run();
                } finally {
                    MDC.clear();
                }
            }
        };
    }

The wrapped Runnable is returned again. Before the task is executed, [runnable.run()] first sets the Map of the main thread to the current thread [i.e. MDC.setContextMap(context)], so that the Map corresponding to the MDC of the sub thread and the main thread is the same.

traceId missing from HTTP call

When using HTTP to call the third-party service interface, the traceId will be lost, and the HTTP calling tool needs to be modified. When sending, add the traceId in the request header, add the interceptor in the lower callee, obtain the traceId in the header and add it to the MDC.

There are many ways to call http. The more common ones are HttpClient, OKHttp and RestTemplate, so only the solutions of these HTTP calls are given.

1,HttpClient:

Implement HttpClient Interceptor:

public class HttpClientTraceIdInterceptor implements HttpRequestInterceptor {
    @Override
    public void process(HttpRequest httpRequest, HttpContext httpContext) throws HttpException, IOException {
        String traceId = MDC.get(Constants.TRACE_ID);
        //If there is a traceId in the current thread call, the traceId will be passed through
        if (traceId != null) {
            //Add request body
            httpRequest.addHeader(Constants.TRACE_ID, traceId);
        }
    }
}

Implement the HttpRequestInterceptor interface and rewrite the process method

If the calling thread contains traceId, you need to pass the obtained traceId down through the header in the request.

Add interceptors for HttpClient:

private static CloseableHttpClient httpClient = HttpClientBuilder.create()
            .addInterceptorFirst(new HttpClientTraceIdInterceptor())
            .build();

Add an interceptor for HttpClient through the addInterceptorFirst method.

2,OKHttp:

Implement OKHttp Interceptor:

public class OkHttpTraceIdInterceptor implements Interceptor {
    @Override
    public Response intercept(Chain chain) throws IOException {
        String traceId = MDC.get(Constants.TRACE_ID);
        Request request = null;
        if (traceId != null) {
            //Add request body
            request = chain.request().newBuilder().addHeader(Constants.TRACE_ID, traceId).build();
        }
        Response originResponse = chain.proceed(request);

        return originResponse;
    }
}

Implement the Interceptor interceptor and rewrite the Interceptor method. The implementation logic is similar to that of HttpClient. If the traceId of the current thread can be obtained, it will be transmitted downward.

Add interceptors for OkHttp:

  private static OkHttpClient client = new OkHttpClient.Builder()
            .addNetworkInterceptor(new OkHttpTraceIdInterceptor())
            .build();

Call the addNetworkInterceptor method to add an interceptor.

3,RestTemplate:

Implement RestTemplate Interceptor:

public class RestTemplateTraceIdInterceptor implements ClientHttpRequestInterceptor {
    @Override
    public ClientHttpResponse intercept(HttpRequest httpRequest, byte[] bytes, ClientHttpRequestExecution clientHttpRequestExecution) throws IOException {
        String traceId = MDC.get(Constants.TRACE_ID);
        if (traceId != null) {
            httpRequest.getHeaders().add(Constants.TRACE_ID, traceId);
        }

        return clientHttpRequestExecution.execute(httpRequest, bytes);
    }
}

Implement the clienthttprequeinterceptor interface and rewrite the intercept method. The rest of the logic is the same without repeating the description.

Add interceptors for RestTemplate:

restTemplate.setInterceptors(Arrays.asList(new RestTemplateTraceIdInterceptor()));

Call the setInterceptors method to add an interceptor.

4. Third party service Interceptor:

The whole process of HTTP calling the third-party service interface requires the cooperation of the third-party service. The third-party service needs to add an interceptor to get the traceId in the request header and add it to the MDC.

public class LogInterceptor implements HandlerInterceptor {
    @Override
    public boolean preHandle(HttpServletRequest request, HttpServletResponse response, Object handler) throws Exception {
        //If there is an upper layer call, use the upper layer ID
        String traceId = request.getHeader(Constants.TRACE_ID);
        if (traceId == null) {
            traceId = TraceIdUtils.getTraceId();
        }
        
        MDC.put("traceId", traceId);
        return true;
    }

    @Override
    public void postHandle(HttpServletRequest request, HttpServletResponse response, Object handler, ModelAndView modelAndView)
            throws Exception {
    }

    @Override
    public void afterCompletion(HttpServletRequest request, HttpServletResponse response, Object handler, Exception ex)
            throws Exception {
        MDC.remove(Constants.TRACE_ID);
    }
}

explain:

  • Get the traceId from the request header first
  • If the traceId cannot be obtained from the request header, it indicates that it is not a third-party call and a new traceId is directly generated
  • Store the generated traceId in MDC

In addition to adding interceptors, you also need to add traceId printing in the log format, as follows:

 <property name="pattern">[TRACEID:%X{traceId}] %d{HH:mm:ss.SSS} %-5level %class{-1}.%M()/%L - %msg%xEx%n</property>

Note: you need to add% X{traceId}

Recent hot article recommendations:

1.1000 + Java interview questions and answers (2022 latest version)

2.Hot! The Java collaboration is coming...

3.Spring Boot 2.x tutorial, too complete!

4.20w programmer red envelope cover, get it quickly...

5.Java development manual (Songshan version) is the latest release. Download it quickly!

Feel good, don't forget to like + forward!

Keywords: Java

Added by michalurban on Wed, 02 Mar 2022 04:07:56 +0200