MDC full link tracking

Posted by groovey on Wed, 09 Feb 2022 05:58:03 +0100

Reprint: How to implement full link call log tracing in SpringBoot? This method is elegant!

code: https://github.com/Yong-Wang-Brave/springboot-log-master

Author: is he Tiantian there

Source: Juejin cn/post/6844904101483020295

Write in front

Through this article, we will understand what MDC is, the problems existing in MDC application and how to solve the existing problems

Introduction to MDC

brief 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 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

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) = > delete the key value pair specified in the MDC of the current thread

advantage:

  • 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)

I can only think of this for the time being

MDC usage

  • 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);
      }
  }

  • 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}. traceId is consistent with the key name in MDC. It is so easy to use, 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 new thread, 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

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 interceptor for HttpClient

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

Add an interceptor for HttpClient through the addInterceptorFirst method

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

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, and the description is not repeated

  • Add interceptors for RestTemplate

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

Call the setInterceptors method to add an interceptor

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>

% X{traceId} needs to be added

Project source code address

https://github.com/TiantianUpup/springboot-log/tree/master/springboot-trace

Topics: Spring Boot

Hot Topics

©2024 Programmer Think