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, to which key value pairs can be added. The content contained in MDC can be accessed by code executed in the same thread.

The child thread of the current thread inherits 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): stores 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

It is so easy to use, but in some cases, traceId cannot be obtained

Problems with MDC

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

• Missing traceId for HTTP call

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

Solve problems in MDC

The trace ID is missing from the child thread log printing

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 new thread, do not omit [this usage should be avoided in practical application]. Rewriting the thread pool is nothing more than encapsulating 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 the MDC. If it does not exist, it will be generated. If it is not a child thread, the traceId in the 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

• Judge whether the MDC Map corresponding to the current thread exists, and set if it exists

• Set the traceId value in the MDC. If it does not exist, it will be generated. If it is not a child thread, the traceId in the MDC will not be null

• Execute run method

Missing traceId for HTTP call

When using HTTP to call the third-party service interface, the traceId will be lost. The HTTP calling tool needs to be modified. When sending, add the traceId in the request header, add an 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 to 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 transmitted transparently
        if (traceId != null) {
            //Add request body
            httpRequest.addHeader(Constants.TRACE_ID, traceId);
        }
    }
}

Implement the HttpRequestInterceptor interface and override 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}

Original address: How to implement full link call log tracking in SpringBoot? This method is called elegance!

If you think this article is helpful to you, please praise it, pay attention and support it