SpringBoot log4j2日志追踪

写在前面本文只讨论非分布式体系的日志追踪，如果项目使用了微服务、RPC等分布式框架的话，日志追踪有很成熟的框架，Google的Dapper,阿里的EagleEye，Twitter基于Google的Dapper论文开发的Zipkin通过本文将了解到什么是MDC、MDC应用中存在的问题、如何解决存在的问题MDC介绍简介：MDC（Mapped Diagnostic Context，映射调试上下文）是 l

Java_Chuck

1951人浏览 · 2020-09-04 16:26:46

Java_Chuck · 2020-09-04 16:26:46 发布

写在前面

本文只讨论非分布式体系的日志追踪，如果项目使用了微服务、RPC等分布式框架的话，日志追踪有很成熟的框架，Google的Dapper,阿里的EagleEye，Twitter基于Google的Dapper论文开发的Zipkin

通过本文将了解到什么是MDC、MDC应用中存在的问题、如何解决存在的问题

MDC介绍

简介：

MDC（Mapped Diagnostic Context，映射调试上下文）是 log4j 、logback及log4j2 提供的一种方便在多线程条件下记录日志的功能。MDC 可以看成是一个与当前线程绑定的哈希表，可以往其中添加键值对。MDC 中包含的内容可以被同一线程中执行的代码所访问。当前线程的子线程会继承其父线程中的 MDC 的内容。当需要记录日志时，只需要从 MDC 中获取所需的信息即可。MDC 的内容则由程序在适当的时候保存进去。对于一个 Web 应用来说，通常是在请求被处理的最开始保存这些数据

API说明：

clear() => 移除所有MDC
get (String key) => 获取当前线程MDC中指定key的值
getContext() => 获取当前线程MDC的MDC
put(String key, Object o) => 往当前线程的MDC中存入指定的键值对
remove(String key) => 删除当前线程MDC中指定的键值对

优点：

代码简洁，日志风格统一，不需要在log打印中手动拼写traceId，即LOGGER.info("traceId:{} ", traceId)

这里使用log4j2打印日志

SpringBoot中使用log4j2可以参考SpringBoot log4j2日志之旅

pom.xml

       <dependency>
            <groupId>org.springframework.boot</groupId>
            <artifactId>spring-boot-starter-web</artifactId>
            <exclusions>
                <exclusion>
                    <artifactId>spring-boot-starter-logging</artifactId>
                    <groupId>org.springframework.boot</groupId>
                </exclusion>
                <exclusion>
                    <groupId>org.springframework.boot</groupId>
                    <artifactId>spring-boot-starter-tomcat</artifactId>
                </exclusion>
            </exclusions>
        </dependency>
        <dependency>
            <groupId>org.springframework.boot</groupId>
            <artifactId>spring-boot-starter-jetty</artifactId>
        </dependency>
        <!-- log4j2 start -->
        <dependency>
            <groupId>org.springframework.boot</groupId>
            <artifactId>spring-boot-starter-log4j2</artifactId>
        </dependency>
        <!-- log4j2 end -->

log4j2.xml

这里的关键是

<PatternLayout pattern="%d{yyyy-MM-dd HH:mm:ss.SSS} [%X{traceId}] [%p] [%t] %c(%F:%L) - %m%n" />

%X{traceId}对应的就是MDC.put(Constants.TRACE_ID, traceId);

<?xml version="1.0" encoding="UTF-8"?>
<Configuration monitorinterval="10" status="debug">
  <Properties>
    <Property name="infoFile">./logs/info.log</Property>
    <Property name="infoFilePattern">./logs/info.log.%d{yyyy-MM-dd}_%i</Property>
    <Property name="errorFile">./logs/error.log</Property>
    <Property name="errorFilePattern">./logs/error.log.%d{yyyy-MM-dd}_%i</Property>
    <Property name="layoutPattern">%d{yyyy-MM-dd HH:mm:ss.SSS} [%p] [%t] %c(%F:%L) - %m%n</Property>
  </Properties>

  <Appenders>

    <Console name="stdout">
<!--      <PatternLayout pattern="%d{yyyy-MM-dd HH:mm:ss.SSS} [%p] [%t] %c(%F:%L) - %m%n"/>-->
      <!-- 添加日志追踪traceId -->
      <PatternLayout pattern="%d{yyyy-MM-dd HH:mm:ss.SSS} [%X{traceId}] [%p] [%t] %c(%F:%L) - %m%n" />
    </Console>

    <RollingFile fileName="${infoFile}" filePattern="${infoFilePattern}" name="infoAppender">

      <!--显示INFO级别日志-->
      <ThresholdFilter level="INFO" onMatch="ACCEPT"  onMismatch="DENY"/>
      <PatternLayout pattern="${layoutPattern}"/>

      <!--每个文件最多只能2G-->
      <Policies>
        <SizeBasedTriggeringPolicy size="2 GB" />
        <TimeBasedTriggeringPolicy modulate="true"/>
      </Policies>

      <!--删除超过15天的日志-->
      <DefaultRolloverStrategy>
        <Delete basePath="./logs" maxDepth="2">
          <IfLastModified age="30d" />
        </Delete>
      </DefaultRolloverStrategy>
    </RollingFile>


    <RollingFile fileName="${errorFile}" filePattern="${errorFilePattern}" name="errorAppender">

      <ThresholdFilter level="ERROR" onMatch="ACCEPT"  onMismatch="DENY"/>
      <PatternLayout pattern="${layoutPattern}"/>
      <Policies>
        <SizeBasedTriggeringPolicy size="2 GB" />
        <TimeBasedTriggeringPolicy modulate="true"/>
      </Policies>
    </RollingFile>
  </Appenders>

  <Loggers>

    <!--additivity="false"表示在该logger中输出的日志不会再延伸到父层logger。这里如果改为true，则会延伸到Root Logger，遵循Root Logger的配置也输出一次。-->
    <Logger name="org.springframework.boot.autoconfigure" level="DEBUG" additivity="true">
      <AppenderRef ref="stdout"/>
    </Logger>
    <!-- druid配置 start -->
    <logger name="druid.sql.Statement" level="debug" additivity="false">
      <appender-ref ref="stdout"/>
    </logger>
    <logger name="druid.sql.ResultSet" level="debug" additivity="false">
      <appender-ref ref="stdout"/>
    </logger>
    <!-- druid配置 end -->

    <Root level="INFO">
      <AppenderRef ref="stdout"/>
      <AppenderRef ref="infoAppender"/>
      <AppenderRef ref="errorAppender"/>
    </Root>
  </Loggers>

</Configuration>

接口的日志追踪，traceId可以在拦截器中添加，也可以在过滤器中添加

{

    @Bean
    public RequestContextListener requestContextListener() {
        return new RequestContextListener();
    }

    @Override
    public void addInterceptors(InterceptorRegistry registry) {
        // 方式一：拦截器中添加traceId
        // registry.addInterceptor(new LogInterceptor())
        // .addPathPatterns("/**")
        // .excludePathPatterns("/static/**", "/templates/**");
    }

    @Bean
    public FilterRegistrationBean<LogTraceFilter> logTraceFilter() {
        // 方式二：过滤器中添加traceId
        final FilterRegistrationBean<LogTraceFilter> filterRegistrationBean = new FilterRegistrationBean<>();
        final LogTraceFilter logTraceFilter = new LogTraceFilter();
        filterRegistrationBean.setFilter(logTraceFilter);
        filterRegistrationBean.setName("logTraceFilter");
        filterRegistrationBean.addUrlPatterns("/*");
        filterRegistrationBean.setOrder(Ordered.HIGHEST_PRECEDENCE);
        return filterRegistrationBean;
    }

}

方式一：拦截器添加traceId

package com.foo.bar.interceptor;

import com.foo.bar.constant.Constants;
import com.foo.bar.utils.TraceIdUtil;
import org.slf4j.MDC;
import org.springframework.web.servlet.HandlerInterceptor;
import org.springframework.web.servlet.ModelAndView;

import javax.servlet.http.HttpServletRequest;
import javax.servlet.http.HttpServletResponse;


/**
 * 日志追踪拦截器
 * @author foo
 */
public class LogInterceptor implements HandlerInterceptor {

    @Override
    public boolean preHandle(HttpServletRequest request, HttpServletResponse response, Object handler) throws Exception {
        //如果有上层调用就用上层的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 {
        // Do nothing because of no business
    }

    @Override
    public void afterCompletion(HttpServletRequest request, HttpServletResponse response, Object handler, Exception ex)
            throws Exception {
        //调用结束后删除
        MDC.remove(Constants.TRACE_ID);
    }
}

方式二：过滤器添加traceId

package com.foo.bar.filter;

import com.foo.bar.constant.Constants;
import com.foo.bar.utils.TraceIdUtil;
import org.slf4j.MDC;
import org.springframework.web.filter.OncePerRequestFilter;

import javax.servlet.FilterChain;
import javax.servlet.ServletException;
import javax.servlet.http.HttpServletRequest;
import javax.servlet.http.HttpServletResponse;
import java.io.IOException;

/**
 * @author: foo
 * @create: 2020-09-04 11:02
 */
public class LogTraceFilter extends OncePerRequestFilter {


    @Override
    protected void doFilterInternal(HttpServletRequest request, HttpServletResponse response, FilterChain filterChain) throws ServletException, IOException {
        preHandle(request);
        filterChain.doFilter(request, response);
        afterCompletion();
    }

    /**
     * 过滤前处理
     * @param request 请求
     * @return
     */
    public void preHandle(HttpServletRequest request) {
        //如果有上层调用就用上层的ID
        String traceId = request.getHeader(Constants.TRACE_ID);
        if (traceId == null) {
            traceId = TraceIdUtil.getTraceId();
        }

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

    /**
     * 过滤后处理
     */
    public void afterCompletion() {
        //调用结束后删除
        MDC.remove(Constants.TRACE_ID);
    }
}

constant.java

package com.foo.bar.constant;

/**
 * 常量类
 * @author foo
 */
public class Constants {

    private Constants(){
        throw new UnsupportedOperationException();
    }

    /**
     * 日志追踪ID
     */
    public static final String TRACE_ID = "traceId";

}

TraceIdUtil.java

package com.foo.bar.utils;

import java.util.UUID;

/**
 * traceId生成工具类
 * @author foo
 */
public class TraceIdUtil {

    private TraceIdUtil() {
        throw new UnsupportedOperationException("Utility class");
    }

    /**
     * 获取traceId
     * @return
     */
    public static String getTraceId() {
        return UUID.randomUUID().toString().replace("-", "").toUpperCase();
    }
}

MDC 存在的问题

子线程中打印日志丢失traceId
kafka等中间件打印日志丢失traceId

子线程中打印日志丢失traceId

开启异步注解@EnableAsync

package com.foo.bar;

import org.springframework.boot.SpringApplication;
import org.springframework.boot.autoconfigure.SpringBootApplication;
import org.springframework.scheduling.annotation.EnableAsync;

/**
 * @author foo
 */
@EnableAsync
@SpringBootApplication
public class FooBarApplication {

    public static void main(String[] args) {
        SpringApplication.run(FooBarApplication.class, args);
    }

}

配置异步线程池

package com.foo.bar.config;

import lombok.extern.slf4j.Slf4j;
import org.springframework.context.annotation.Bean;
import org.springframework.context.annotation.Configuration;
import org.springframework.context.annotation.Primary;
import org.springframework.scheduling.concurrent.ThreadPoolTaskExecutor;

import java.util.concurrent.Executor;
import java.util.concurrent.ThreadPoolExecutor;

/**
 * 线程池配置
 *
 * @author foo
 */
@Slf4j
@Configuration
public class ExecutorConfig {

    @Bean
    @Primary
    public Executor asyncServiceExecutor() {
        log.info("start asyncServiceExecutor");
        ThreadPoolTaskExecutor executor = new ThreadPoolTaskExecutor();
        //配置核心线程数
        executor.setCorePoolSize(10);
        //配置最大线程数
        executor.setMaxPoolSize(200);
        //配置队列大小
        executor.setQueueCapacity(99999);
        //配置线程池中的线程的名称前缀
        executor.setThreadNamePrefix("async-service-");

        // 设置拒绝策略：当pool已经达到max size的时候，如何处理新任务
        // CALLER_RUNS：不在新线程中执行任务，而是有调用者所在的线程来执行
        executor.setRejectedExecutionHandler(new ThreadPoolExecutor.CallerRunsPolicy());
        //执行初始化
        executor.initialize();
        return executor;
    }

}

测试Controller

package com.foo.bar.controller;

import com.foo.bar.service.HelloService;
import lombok.RequiredArgsConstructor;
import lombok.extern.slf4j.Slf4j;
import org.springframework.web.bind.annotation.GetMapping;
import org.springframework.web.bind.annotation.RestController;

/**
 * @author: foo
 * @create: 2020-09-04 14:15
 */
@RestController
@Slf4j
@RequiredArgsConstructor
public class HelloController {

    private final HelloService helloService;

    @GetMapping("/hello")
    public String hello(){
        log.info("Hello World! hello无异步追踪！");
        helloService.hello();
        return "Hello World!";
    }

    @GetMapping("/hello-async")
    public String helloAsync(){
        log.info("Hello World! hello-async异步追踪！");
        helloService.helloAsync();
        return "Hello World!";
    }
}

测试Service

package com.foo.bar.service;

import lombok.extern.slf4j.Slf4j;
import org.springframework.scheduling.annotation.Async;
import org.springframework.stereotype.Service;

/**
 * @author: foo
 * @create: 2020-09-04 14:21
 */
@Service
@Slf4j
public class HelloService {

    public void hello(){
        log.info("进入hello业务方法");
    }

    @Async
    public void helloAsync(){
        log.info("进入helloAsync业务方法");
    }
}

测试结果：异步线程丢失了traceId

解决子线程日志打印丢失traceId问题

子线程在打印日志的过程中traceId将丢失，解决方式为重写线程池

线程池封装类：ThreadPoolExecutorMdcWrapper.java

package com.foo.bar.config;

import com.foo.bar.utils.ThreadMdcUtil;
import lombok.extern.slf4j.Slf4j;
import org.slf4j.MDC;
import org.springframework.scheduling.concurrent.ThreadPoolTaskExecutor;
import org.springframework.util.concurrent.ListenableFuture;

import java.util.concurrent.Callable;
import java.util.concurrent.Future;
import java.util.concurrent.ThreadPoolExecutor;

/**
 * spring线程池封装类
 * @author foo
 */
@Slf4j
public class ThreadPoolTaskExecutorWrapper extends ThreadPoolTaskExecutor {

    private void showThreadPoolInfo(String prefix){
        ThreadPoolExecutor threadPoolExecutor = getThreadPoolExecutor();

        if(null==threadPoolExecutor){
            return;
        }

        log.info("{}, {},taskCount [{}], completedTaskCount [{}], activeCount [{}], queueSize [{}]",
                this.getThreadNamePrefix(),
                prefix,
                threadPoolExecutor.getTaskCount(),
                threadPoolExecutor.getCompletedTaskCount(),
                threadPoolExecutor.getActiveCount(),
                threadPoolExecutor.getQueue().size());
    }

    @Override
    public void execute(Runnable task) {
        showThreadPoolInfo("1. do execute");
        super.execute(ThreadMdcUtil.wrap(task, MDC.getCopyOfContextMap()));

    }

    @Override
    public void execute(Runnable task, long startTimeout) {
        showThreadPoolInfo("2. do execute");
        super.execute(ThreadMdcUtil.wrap(task, MDC.getCopyOfContextMap()), startTimeout);

    }

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

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

    @Override
    public ListenableFuture<?> submitListenable(Runnable task) {
        showThreadPoolInfo("1. do submitListenable");
        return super.submitListenable(ThreadMdcUtil.wrap(task, MDC.getCopyOfContextMap()));
    }

    @Override
    public <T> ListenableFuture<T> submitListenable(Callable<T> task) {
        showThreadPoolInfo("2. do submitListenable");
        return super.submitListenable(ThreadMdcUtil.wrap(task, MDC.getCopyOfContextMap()));
    }
}

线程traceId封装工具类：ThreadMdcUtil.java

package com.foo.bar.utils;

import com.foo.bar.constant.Constants;
import org.slf4j.MDC;

import java.util.Map;
import java.util.concurrent.Callable;


/**
 * 线程MDC工具类
 * @author foo
 */
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();
            }
        };
    }
}

说明【以封装Runnable为例】：

判断当前线程对应MDC的Map是否存在，存在则设置
设置MDC中的traceId值，不存在则新生成，针对不是子线程的情况，如果是子线程，MDC中traceId不为null
执行run方法

代码等同于以下写法，会更直观

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

重新返回的是包装后的Runnable，在该任务执行之前【runnable.run()】先将主线程的Map设置到当前线程中【即MDC.setContextMap(context)】，这样子线程和主线程MDC对应的Map就是一样的了

修改ExecutorConfig.java的asyncServiceExecutor方法，将ThreadPoolTaskExecutor executor = new ThreadPoolTaskExecutor()改为ThreadPoolTaskExecutor executor = new ThreadPoolTaskExecutorWrapper()，如下所示：

package com.foo.bar.config;

import lombok.extern.slf4j.Slf4j;
import org.springframework.context.annotation.Bean;
import org.springframework.context.annotation.Configuration;
import org.springframework.context.annotation.Primary;
import org.springframework.scheduling.concurrent.ThreadPoolTaskExecutor;

import java.util.concurrent.Executor;
import java.util.concurrent.ThreadPoolExecutor;

/**
 * 线程池配置
 *
 * @author foo
 */
@Slf4j
@Configuration
public class ExecutorConfig {

    @Bean
    @Primary
    public Executor asyncServiceExecutor() {
        log.info("start asyncServiceExecutor");
        ThreadPoolTaskExecutor executor = new ThreadPoolTaskExecutorWrapper();
        //配置核心线程数
        executor.setCorePoolSize(10);
        //配置最大线程数
        executor.setMaxPoolSize(200);
        //配置队列大小
        executor.setQueueCapacity(99999);
        //配置线程池中的线程的名称前缀
        executor.setThreadNamePrefix("async-service-");

        // 设置拒绝策略：当pool已经达到max size的时候，如何处理新任务
        // CALLER_RUNS：不在新线程中执行任务，而是有调用者所在的线程来执行
        executor.setRejectedExecutionHandler(new ThreadPoolExecutor.CallerRunsPolicy());
        //执行初始化
        executor.initialize();
        return executor;
    }

}

重新测试异步线程日志追踪，异步子线程中的traceId与父线程程一致了，OK。

kafka等中间件打印日志丢失traceId

解决方式可以通过AOP切入onMessage这个方法

package com.foo.bar.aspect;


import org.aspectj.lang.ProceedingJoinPoint;
import org.aspectj.lang.annotation.Around;
import org.aspectj.lang.annotation.Aspect;
import org.aspectj.lang.annotation.Pointcut;
import org.slf4j.MDC;
import org.springframework.stereotype.Component;

import com.foo.bar.constant.Constants;
import com.foo.bar.utils.TraceIdUtil;

import lombok.RequiredArgsConstructor;
import lombok.extern.slf4j.Slf4j;

/**
 * MDC日志kafka切面
 *
 * @author foo
 * @date 2020/9/7 14:36
 */
@Aspect
@Component
@Slf4j
@RequiredArgsConstructor
public class MdcKafkaAspect {

    /**
     * 定义切入点
     * 通过@Pointcut注解声明频繁使用的切点表达式
     */
    @Pointcut("execution(* onMessage(..)) && target(org.springframework.kafka.listener.MessageListener)")
    public void messageListener() {
        // This func is intentionally empty. Nothing special is needed here.
    }

    @Around(value = "messageListener()")
    public void wrapOnMessage(ProceedingJoinPoint joinPoint) throws Throwable {
        try {
            MDC.put(Constants.TRACE_ID, TraceIdUtil.getTraceId());
            joinPoint.proceed();
        } finally {
            MDC.clear();
        }
    }
}

参考：

向您推荐>>Eolink开发者社区

权威｜前沿｜技术｜干货｜国内首个API全生命周期开发者社区

更多推荐

ELK实现containerd的容器日志采集展示【基于logging的全栈监测】

企业级ELK Stack构建介绍

云原生

深入理解 Mocha 测试框架：从零实现一个 Mocha

前言什么是自动化测试自动化测试在很多团队中都是Devops环节中很难执行起来的一个环节，主要原因在于测试代码的编写工作很难抽象，99%的场景都需要和业务强绑定，而且写测试代码的编写工作量往往比编写实际业务代码的工作量更多。在一些很多业务场景中投入产出比很低，适合写自动化测试的应该是那些中长期业务以及一些诸如组件一样的基础库。自动化测试是个比较大的概念，其中分类也比较多，比如单元测试，端对端测试，集

云原生

(20200916 Solved)docker-compose up创建容器自动退出

问题描述如题，创建容器后自动退出了。并且docker start container无效解决方案原因是缺失了控制终端的配置，需要在docker-compose.yml中增加tty:true ，有时候这样也不行，需要再增加一个command:/bin/bash，命令不一定是这个，需要是一个不会退出的命令，然后用-d后台启动容器。Referencesdocker-compose启动容器后自动退出...