SpringBoot: generation of project traceId/log printing

Preface¶

When viewing the service log, when the service is adjusted too frequently and the log is refreshed too quickly, it will affect the efficiency of joint debugging, testing, and online troubleshooting. Can a unique identifier be given to each requested log? Later use this representation to match and directly retrieve the log of the request? Introduce the main topic of this article, "traceId".

MDC¶

MDC defines Mapped Diagnostic Context, that is, mapping diagnostic environment.

MDC is a function provided by log4j and logback to facilitate logging under multi-threaded conditions.

MDC can be seen as a hash table bound to the current thread, and key-value pairs can be added to it.

How to use MDC¶

• ​ Set value to MDC: MDC.put(key, value);
• ​ Get the value from MDC: MDC.get(key);
• ​ Print the contents of the MDC to the log: %X{key};

Initialize TraceId and set value to MDC¶

Here is mainly to use the aspect, set the MDC before the method is executed, and erase the MDC after the method is executed. There are many specific implementation methods, such as filters, interceptors, AOP, and so on. I personally recommend the implementation of Filter, because Filter is the first encountered by the request and the last encountered before the response to the front end.

Filter implementation¶

@Slf4j
@WebFilter(filterName = "traceIdFilter", urlPatterns = "/*")
@Order(0)
@Component
public class TraceIdFilter implements Filter {
    /**
     * 日志跟踪标识
     */
    public static final String TRACE_ID = "TRACE_ID";

    @Override
    public void init(FilterConfig filterConfig) {
    }

    @Override
    public void doFilter(ServletRequest servletRequest, ServletResponse servletResponse, FilterChain filterChain)
            throws IOException, ServletException {
        MDC.put(TRACE_ID, UUID.randomUUID().toString());
        filterChain.doFilter(servletRequest, servletResponse);
    }

    @Override
    public void destroy() {
        MDC.clear();
    }
}

Interceptor implementation¶

@Component
public class TraceIdInterceptor extends HandlerInterceptorAdapter {
    private static final String TRACE_ID = "TRACE_ID";

    @Override
    public boolean preHandle(HttpServletRequest request, HttpServletResponse response, Object handler) {
        MDC.put(TRACE_ID, UUID.randomUUID().toString());
        return true;
    }

    @Override
    public void afterCompletion(HttpServletRequest request, HttpServletResponse response, Object handler, @Nullable Exception ex) {
        MDC.clear();
    }
}

@Configuration
public class WebConfig implements WebMvcConfigurer {

    @Override
    public void addInterceptors(InterceptorRegistry registry) {
        registry.addInterceptor(new TraceIdInterceptor());
    }
}

Configure traceId in the log print configuration pattern

Compared with the previous one, only [%X{TRACE_ID}] is added, [%X{***}] is a template, and the middle attribute name is entered by us using MDC put.

%d{yyyy-MM-dd} [%thread] %-5level %logger{50} - [%X{TRACE_ID}] - %msg%n

Asynchronous method log print traceId¶

The asynchronous method will start a new thread. We want the asynchronous method and the main thread to share the same traceId. First, create a new task adapter MdcTaskDecorator.

public class MdcTaskDecorator implements TaskDecorator {
    @Override
    public Runnable decorate(Runnable runnable) {
        Map<String, String> map = MDC.getCopyOfContextMap();
        return () -> {
            try {
                MDC.setContextMap(map);
                String traceId = MDC.get(TRACE_ID);
                if (StringUtils.isBlank(traceId)) {
                    traceId = UUID.randomUUID().toString();
                    MDC.put(TRACE_ID, traceId);
                }
                runnable.run();
            } finally {
                MDC.clear();
            }
        };
    }
}

Add the setting of executor.setTaskDecorator(new MdcTaskDecorator()) in the thread pool configuration.

@EnableAsync
@Configuration
public class ThreadPoolConfig {
    private int corePoolSize = Runtime.getRuntime().availableProcessors() + 1;
    private int maxPoolSize = corePoolSize * 2;
    private static final int queueCapacity = 50;
    private static final int keepAliveSeconds = 30;

    @Bean(name = "threadPoolTaskExecutor")
    public ThreadPoolTaskExecutor threadPoolTaskExecutor() {
        ThreadPoolTaskExecutor executor = new ThreadPoolTaskExecutor();
        executor.setMaxPoolSize(maxPoolSize);
        executor.setCorePoolSize(corePoolSize);
        executor.setQueueCapacity(queueCapacity);
        executor.setKeepAliveSeconds(keepAliveSeconds);
        executor.setTaskDecorator(new MdcTaskDecorator());
        executor.setRejectedExecutionHandler(new ThreadPoolExecutor.CallerRunsPolicy());
        return executor;
    }
}

Use the specified thread pool to execute business code

@Async("threadPoolTaskExecutor")
public void testThreadPoolTaskExecutor(){
    log.info("Async test");
}

Return traceId in response DTO¶

@Data
@AllArgsConstructor
public class RetResult<T> {

    private Integer code;

    private String msg;

    private T data;

    private String traceId;

    public RetResult(Integer code, String msg, T data) {
        this.code = code;
        this.msg = msg;
        this.data = data;
        this.traceId = MDC.get(TRACE_ID);
    }

    public static <T> RetResult<T> success(T t) {
        return new RetResult<>(RetCode.SUCCESS.getCode(), "ok", t);
    }

    public static <T> RetResult<T> success() {
        return new RetResult<>(RetCode.SUCCESS.getCode(), "ok", null);
    }

    public static <T> RetResult<T> fail() {
        return new RetResult<>(RetCode.FAIL.getCode(), "fail", null);
    }

    public static <T> RetResult<T> fail(String msg) {
        return new RetResult<>(RetCode.FAIL.getCode(), msg, null);
    }

    public static <T> RetResult<T> fail(Integer code, String msg) {
        return new RetResult<>(code, msg, null);
    }

}