SpringBoot日志的链路追踪

  |   0 评论   |   浏览

file

前言

日志作为码农的铁杆儿基友,伴随着码农的一生, 特别是在生死关头 , 能拯救码农于水火 , 但是混乱的日志 , 有时候不仅不能协助解决问题 , 反而还会带来负面的效果 , 毕竟涉及到看日志的时候 , 多半就是出现bug或者出现异常的情况 , 在一个火烧脚背的场景下 , 不能快速找到我们想要的日志 , 那么解决问题的效率将大大下降 ;

  • 如何能快速找到本次操作的所有日志呢 ?
    常用的做法就是用一个ID去贯穿本次请求的始终 , 当出现问题的时候 , 找到这个ID , 去筛选出所有的日志 , 逐个去排查问题所在 ;
  • 那这个ID怎么设置呢?
    • 请求的时候,自己生成一个, 自己在请求对象中带着 , 每次打日志的时候 , 打出来即可 !
      至于这个优缺点嘛 ! 只是解决了ID问题 , 但是带来了一堆的麻烦 , 几乎没有优点
    • 使用MDC(Mapped Diagnostic Contexts) !
      将本次请求的公共数据映射出来 , 那么当前线程下的所有日志都会默认输出对应的消息 , 一次配置 , 解放双手

使用log4j2规范日志

  • 导入Maven的资源

      <dependencies>
        <dependency>
            <groupId>org.springframework.boot</groupId>
            <artifactId>spring-boot-starter-web</artifactId>
            <!-- 排除默认的spring-boot-starter-logging -->
            <exclusions>
                <exclusion>
                    <groupId>org.springframework.boot</groupId>
                    <artifactId>spring-boot-starter-logging</artifactId>
                </exclusion>
            </exclusions>
        </dependency>
    
        <!-- 引入log4j2 -->
        <dependency>
            <groupId>org.springframework.boot</groupId>
            <artifactId>spring-boot-starter-log4j2</artifactId>
        </dependency>
        <dependency>
            <groupId>com.lmax</groupId>
            <artifactId>disruptor</artifactId>
            <version>3.3.11</version>
        </dependency>
    
        <!-- lombox -->
        <dependency>
            <groupId>org.projectlombok</groupId>
            <artifactId>lombok</artifactId>
        </dependency>
    
        <!-- fastjson -->
        <dependency>
            <groupId>com.alibaba</groupId>
            <artifactId>fastjson</artifactId>
            <version>1.2.60</version>
        </dependency>
    
        <dependency>
            <groupId>org.apache.commons</groupId>
            <artifactId>commons-lang3</artifactId>
        </dependency>
    
        <!-- aop 用于处理DMC -->
        <dependency>
            <groupId>org.springframework.boot</groupId>
            <artifactId>spring-boot-starter-aop</artifactId>
        </dependency>
    
        <dependency>
            <groupId>org.springframework.boot</groupId>
            <artifactId>spring-boot-starter-test</artifactId>
            <scope>test</scope>
            <exclusions>
                <exclusion>
                    <groupId>org.junit.vintage</groupId>
                    <artifactId>junit-vintage-engine</artifactId>
                </exclusion>
            </exclusions>
        </dependency>
    </dependencies>
    
    <dependencyManagement>
        <dependencies>
            <dependency>
                <groupId>org.springframework.boot</groupId>
                <artifactId>spring-boot-dependencies</artifactId>
                <version>${spring-boot.version}</version>
                <type>pom</type>
                <scope>import</scope>
            </dependency>
        </dependencies>
    </dependencyManagement>
    
    <build>
        <plugins>
            <plugin>
                <groupId>org.springframework.boot</groupId>
                <artifactId>spring-boot-maven-plugin</artifactId>
                <configuration>
                    <!-- 工程主入口-->
                    <mainClass>com.lupf.log4j2demo.Log4j2DemoApplication</mainClass>
                </configuration>
                <executions>
                    <execution>
                        <goals>
                            <goal>repackage</goal>
                        </goals>
                    </execution>
                </executions>
            </plugin>
        </plugins>
    </build>
    
  • 在resource目录下创建log4j2.xml

    <?xml version="1.0" encoding="UTF-8"?>
    <!--日志级别以及优先级排序: OFF > FATAL > ERROR > WARN > INFO > DEBUG > TRACE > ALL -->
    <!--Configuration后面的status,这个用于设置log4j2自身内部的信息输出,可以不设置,当设置成trace时,你会看到log4j2内部各种详细输出-->
    <!--monitorInterval:Log4j能够自动检测修改配置 文件和重新配置本身,设置间隔秒数-->
    <configuration status="WARN" monitorInterval="1800">
    
        <springProperty scope="context" name="OPEN_FILE_PATH" source="log.path"/>
        <springProperty scope="context" name="APP_NAME" source="spring.application.name"/>
    
        <Properties>
            <!-- ==============================================公共配置============================================== -->
            <!-- 设置日志文件的目录名称 -->
            <property name="logFileName">log4j2-demo</property>
    
            <!-- 日志默认存放的位置,可以设置为项目根路径下,也可指定绝对路径 -->
            <!-- 存放路径一:通用路径,window平台 -->
            <!-- <property name="basePath">d:/logs/${logFileName}</property> -->
            <!-- 存放路径二:web工程专用,java项目没有这个变量,需要删掉,否则会报异常,这里把日志放在web项目的根目录下 -->
            <!-- <property name="basePath">${web:rootDir}/${logFileName}</property> -->
            <!-- 存放路径三:web工程专用,java项目没有这个变量,需要删掉,否则会报异常,这里把日志放在tocmat的logs目录下 -->
            <property name="basePath">logs/${logFileName}</property>
    
            <!-- 控制台默认输出格式,"%-5level":日志级别,"%l":输出完整的错误位置,是小写的L,因为有行号显示,所以影响日志输出的性能 -->
            <property name="console_log_pattern">%d{yyyy-MM-dd HH:mm:ss.SSS} [%-5level] %l - %m%n</property>
            <!-- 日志文件默认输出格式,不带行号输出(行号显示会影响日志输出性能);%C:大写,类名;%M:方法名;%m:错误信息;%n:换行 -->
            <!-- <property name="log_pattern">%d{yyyy-MM-dd HH:mm:ss.SSS} [%-5level] %C.%M - %m%n</property> -->
            <!-- 日志文件默认输出格式,另类带行号输出(对日志输出性能未知);%C:大写,类名;%M:方法名;%L:行号;%m:错误信息;%n:换行 -->
            <property name="log_pattern">[%d{yyyy-MM-dd'T'HH:mm:ss.SSSZZ}] [%X{requestId}] [%level{length=5}] [%thread-%tid] [%logger] [%X{hostName}] [%X{localIp}] [%X{clientIp}] [%X{applicationName}] [%X{requestUri}] [%F,%L,%C,%M] [%m] ## '%ex'%n
            </property>
    
            <!-- 日志默认切割的最小单位 -->
            <property name="every_file_size">20MB</property>
            <!-- 日志默认输出级别 -->
            <property name="output_log_level">DEBUG</property>
    
            <!-- ===========================================所有级别日志配置=========================================== -->
            <!-- 日志默认存放路径(所有级别日志) -->
            <property name="rolling_fileName">${basePath}/all.log</property>
            <!-- 日志默认压缩路径,将超过指定文件大小的日志,自动存入按"年月"建立的文件夹下面并进行压缩,作为存档 -->
            <property name="rolling_filePattern">${basePath}/%d{yyyy-MM}/all-%d{yyyy-MM-dd-HH}-%i.log.gz</property>
            <!-- 日志默认同类型日志,同一文件夹下可以存放的数量,不设置此属性则默认为7个,filePattern最后要带%i才会生效 -->
            <property name="rolling_max">500</property>
            <!-- 日志默认同类型日志,多久生成一个新的日志文件,这个配置需要和filePattern结合使用;
                    如果设置为1,filePattern是%d{yyyy-MM-dd}到天的格式,则间隔一天生成一个文件
                    如果设置为12,filePattern是%d{yyyy-MM-dd-HH}到小时的格式,则间隔12小时生成一个文件 -->
            <property name="rolling_timeInterval">12</property>
            <!-- 日志默认同类型日志,是否对封存时间进行调制,若为true,则封存时间将以0点为边界进行调整,
                    如:现在是早上3am,interval是4,那么第一次滚动是在4am,接着是8am,12am...而不是7am -->
            <property name="rolling_timeModulate">true</property>
    
            <!-- ============================================Info级别日志============================================ -->
            <!-- Info日志默认存放路径(Info级别日志) -->
            <property name="info_fileName">${basePath}/info.log</property>
            <!-- Info日志默认压缩路径,将超过指定文件大小的日志,自动存入按"年月"建立的文件夹下面并进行压缩,作为存档 -->
            <property name="info_filePattern">${basePath}/%d{yyyy-MM}/info-%d{yyyy-MM-dd}-%i.log.gz</property>
            <!-- Info日志默认同一文件夹下可以存放的数量,不设置此属性则默认为7个 -->
            <property name="info_max">100</property>
            <!-- 日志默认同类型日志,多久生成一个新的日志文件,这个配置需要和filePattern结合使用;
                    如果设置为1,filePattern是%d{yyyy-MM-dd}到天的格式,则间隔一天生成一个文件
                    如果设置为12,filePattern是%d{yyyy-MM-dd-HH}到小时的格式,则间隔12小时生成一个文件 -->
            <property name="info_timeInterval">1</property>
            <!-- 日志默认同类型日志,是否对封存时间进行调制,若为true,则封存时间将以0点为边界进行调整,
                    如:现在是早上3am,interval是4,那么第一次滚动是在4am,接着是8am,12am...而不是7am -->
            <property name="info_timeModulate">true</property>
    
            <!-- ============================================Warn级别日志============================================ -->
            <!-- Warn日志默认存放路径(Warn级别日志) -->
            <property name="warn_fileName">${basePath}/warn.log</property>
            <!-- Warn日志默认压缩路径,将超过指定文件大小的日志,自动存入按"年月"建立的文件夹下面并进行压缩,作为存档 -->
            <property name="warn_filePattern">${basePath}/%d{yyyy-MM}/warn-%d{yyyy-MM-dd}-%i.log.gz</property>
            <!-- Warn日志默认同一文件夹下可以存放的数量,不设置此属性则默认为7个 -->
            <property name="warn_max">100</property>
            <!-- 日志默认同类型日志,多久生成一个新的日志文件,这个配置需要和filePattern结合使用;
                    如果设置为1,filePattern是%d{yyyy-MM-dd}到天的格式,则间隔一天生成一个文件
                    如果设置为12,filePattern是%d{yyyy-MM-dd-HH}到小时的格式,则间隔12小时生成一个文件 -->
            <property name="warn_timeInterval">1</property>
            <!-- 日志默认同类型日志,是否对封存时间进行调制,若为true,则封存时间将以0点为边界进行调整,
                    如:现在是早上3am,interval是4,那么第一次滚动是在4am,接着是8am,12am...而不是7am -->
            <property name="warn_timeModulate">true</property>
    
            <!-- ============================================Error级别日志============================================ -->
            <!-- Error日志默认存放路径(Error级别日志) -->
            <property name="error_fileName">${basePath}/error.log</property>
            <!-- Error日志默认压缩路径,将超过指定文件大小的日志,自动存入按"年月"建立的文件夹下面并进行压缩,作为存档 -->
            <property name="error_filePattern">${basePath}/%d{yyyy-MM}/error-%d{yyyy-MM-dd}-%i.log.gz</property>
            <!-- Error日志默认同一文件夹下可以存放的数量,不设置此属性则默认为7个 -->
            <property name="error_max">100</property>
            <!-- 日志默认同类型日志,多久生成一个新的日志文件,这个配置需要和filePattern结合使用;
                    如果设置为1,filePattern是%d{yyyy-MM-dd}到天的格式,则间隔一天生成一个文件
                    如果设置为12,filePattern是%d{yyyy-MM-dd-HH}到小时的格式,则间隔12小时生成一个文件 -->
            <property name="error_timeInterval">1</property>
            <!-- 日志默认同类型日志,是否对封存时间进行调制,若为true,则封存时间将以0点为边界进行调整,
                    如:现在是早上3am,interval是4,那么第一次滚动是在4am,接着是8am,12am...而不是7am -->
            <property name="error_timeModulate">true</property>
    
            <!-- ============================================控制台显示控制============================================ -->
            <!-- 控制台显示的日志最低级别 -->
            <property name="console_print_level">DEBUG</property>
    
        </Properties>
    
        <!--定义appender -->
        <appenders>
            <!-- =======================================用来定义输出到控制台的配置======================================= -->
            <Console name="Console" target="SYSTEM_OUT">
                <!-- 设置控制台只输出level及以上级别的信息(onMatch),其他的直接拒绝(onMismatch)-->
                <ThresholdFilter level="${console_print_level}" onMatch="ACCEPT" onMismatch="DENY"/>
                <!-- 设置输出格式,不设置默认为:%m%n -->
                <PatternLayout pattern="${console_log_pattern}"/>
            </Console>
    
            <!-- ================================打印root中指定的level级别以上的日志到文件================================ -->
            <RollingFile name="RollingFile" fileName="${rolling_fileName}" filePattern="${rolling_filePattern}">
                <PatternLayout pattern="${log_pattern}"/>
                <Policies>
                    <TimeBasedTriggeringPolicy interval="${rolling_timeInterval}" modulate="${warn_timeModulate}"/>
                    <SizeBasedTriggeringPolicy size="${every_file_size}"/>
                </Policies>
                <!-- 设置同类型日志,同一文件夹下可以存放的数量,如果不设置此属性则默认存放7个文件 -->
                <DefaultRolloverStrategy max="${rolling_max}"/>
            </RollingFile>
    
            <!-- =======================================打印INFO级别的日志到文件======================================= -->
            <RollingFile name="InfoFile" fileName="${info_fileName}" filePattern="${info_filePattern}">
                <PatternLayout pattern="${log_pattern}"/>
                <Policies>
                    <TimeBasedTriggeringPolicy interval="${info_timeInterval}" modulate="${info_timeModulate}"/>
                    <SizeBasedTriggeringPolicy size="${every_file_size}"/>
                </Policies>
                <DefaultRolloverStrategy max="${info_max}"/>
                <Filters>
                    <ThresholdFilter level="WARN" onMatch="DENY" onMismatch="NEUTRAL"/>
                    <ThresholdFilter level="INFO" onMatch="ACCEPT" onMismatch="DENY"/>
                </Filters>
            </RollingFile>
    
            <!-- =======================================打印WARN级别的日志到文件======================================= -->
            <RollingFile name="WarnFile" fileName="${warn_fileName}" filePattern="${warn_filePattern}">
                <PatternLayout pattern="${log_pattern}"/>
                <Policies>
                    <TimeBasedTriggeringPolicy interval="${warn_timeInterval}" modulate="${warn_timeModulate}"/>
                    <SizeBasedTriggeringPolicy size="${every_file_size}"/>
                </Policies>
                <DefaultRolloverStrategy max="${warn_max}"/>
                <Filters>
                    <ThresholdFilter level="ERROR" onMatch="DENY" onMismatch="NEUTRAL"/>
                    <ThresholdFilter level="WARN" onMatch="ACCEPT" onMismatch="DENY"/>
                </Filters>
            </RollingFile>
    
            <!-- =======================================打印ERROR级别的日志到文件======================================= -->
            <RollingFile name="ErrorFile" fileName="${error_fileName}" filePattern="${error_filePattern}">
                <PatternLayout pattern="${log_pattern}"/>
                <Policies>
                    <TimeBasedTriggeringPolicy interval="${error_timeInterval}" modulate="${error_timeModulate}"/>
                    <SizeBasedTriggeringPolicy size="${every_file_size}"/>
                </Policies>
                <DefaultRolloverStrategy max="${error_max}"/>
                <Filters>
                    <ThresholdFilter level="FATAL" onMatch="DENY" onMismatch="NEUTRAL"/>
                    <ThresholdFilter level="ERROR" onMatch="ACCEPT" onMismatch="DENY"/>
                </Filters>
            </RollingFile>
        </appenders>
    
        <!--定义logger,只有定义了logger并引入的appender,appender才会生效-->
        <loggers>
            <!-- 设置打印sql语句配置开始,以下两者配合使用,可以优化日志的输出信息,减少一些不必要信息的输出 -->
            <!-- 设置java.sql包下的日志只打印DEBUG及以上级别的日志,此设置可以支持sql语句的日志打印 -->
            <logger name="java.sql" level="DEBUG" additivity="false">
                <appender-ref ref="Console"/>
            </logger>
            <!-- 设置org.mybatis.spring包下的日志只打印WARN及以上级别的日志 -->
            <logger name="org.mybatis.spring" level="WARN" additivity="false">
                <appender-ref ref="Console"/>
            </logger>
            <!-- 设置org.mybatis.spring包下的日志只打印WARN及以上级别的日志 -->
            <logger name="org.springframework" level="WARN" additivity="false">
                <appender-ref ref="Console"/>
            </logger>
            <!-- 设置org.mybatis.spring包下的日志只打印WARN及以上级别的日志 -->
            <logger name="com.qfx.workflow.service" level="WARN" additivity="false">
                <appender-ref ref="Console"/>
            </logger>
            <!-- 设置打印sql语句配置结束 -->
    
            <!--建立一个默认的root的logger-->
            <root level="${output_log_level}">
                <appender-ref ref="RollingFile"/>
                <appender-ref ref="Console"/>
                <appender-ref ref="InfoFile"/>
                <appender-ref ref="WarnFile"/>
                <appender-ref ref="ErrorFile"/>
            </root>
        </loggers>
    
    </configuration>
    
    // 以上主要要说明的就是日志的格式
    [%d{yyyy-MM-dd'T'HH:mm:ss.SSSZZ}] [%X{requestId}] [%level{length=5}] [%thread-%tid] [%logger] [%X{hostName}] [%X{localIp}] [%X{clientIp}] [%X{applicationName}] [%X{requestUri}] [%F,%L,%C,%M] [%m] ## '%ex'%n
    // 其中%X打头的都是自定义的日志  需要通过DMC设置
    [%d{yyyy-MM-dd'T'HH:mm:ss.SSSZZ}]  //当前的时间
    [%X{requestId}]  // 本次请求的唯一ID
    [%level{length=5}]  // 日志级别
    [%thread-%tid]  // 线程id
    [%logger]  // loger对应的class
    [%X{hostName}]  // 服务部署的主机名
    [%X{localIp}]  // 服务部署的主机ip
    [%X{clientIp}]  //客户端请求的ip
    [%X{applicationName}]  //应用名称
    [%X{requestUri}]  // 调用的地址
    [%F,%L,%C,%M]  // 当前日志所处的类的信息 
    [%m]  // 打印的消息
    ## '%ex'  // 异常信息  使用单引号包裹起来是够了方便后续的logstash的
    %n  // 换行
    
  • 修改application.properties

    spring.application.name=log4j2-demo
    # 应用服务web访问端口
    server.port=8080
    spring.http.encoding.charset=utf-8
    spring.jackson.date-format=yyyy-MM-dd HH:mm:ss
    spring.jackson.time-zone=GMT+8
    spring.jackson.default-property-inclusion=non_null
    logging.config=classpath:log4j2.xml
    
  • 获取IP、主机等信息的工具类NetUtils

    import javax.servlet.http.HttpServletRequest;
    import java.net.InetAddress;
    import java.net.UnknownHostException;
    
    public class NetUtils
    {
        static InetAddress addr;
    
        static
        {
            try
            {
                addr = InetAddress.getLocalHost();
            }
            catch (UnknownHostException e)
            {
                e.printStackTrace();
            }
        }
    
        /**
         * 获取主机名
         *
         * @return
         */
        public static String getHostName()
        {
            if (null != addr)
            {
                return addr.getHostName();
            }
            return null;
        }
    
        /**
         * 获取本机IP
         *
         * @return
         */
        public static String getLocalIp()
        {
            if (null != addr)
            {
                return addr.getHostAddress();
            }
            return null;
        }
    
        /**
         * 在request中获取到客户端的IP
         *
         * @param request
         * @return
         */
        public static String getClientIP(HttpServletRequest request)
        {
            String ip = request.getHeader("x-forwarded-for");
            if (ip == null || ip.length() == 0 || "unknown".equalsIgnoreCase(ip))
            {
                ip = request.getHeader("Proxy-Client-IP");
            }
            if (ip == null || ip.length() == 0 || "unknown".equalsIgnoreCase(ip))
            {
                ip = request.getHeader("WL-Proxy-Client-IP");
            }
            if (ip == null || ip.length() == 0 || "unknown".equalsIgnoreCase(ip))
            {
                ip = request.getRemoteAddr();
            }
            return ip;
        }
    }
    
  • 上面日志输出中 , %X均为自定义输出 , 因此需要通过MDC的方式赋值 ;

    // 如
    [%X{localIp}]  // 服务部署的主机ip
    [%X{clientIp}]  //客户端请求的ip
    
  • AOP实现所有请求接口等MDC赋值

    import com.lupf.log4j2demo.utils.NetUtils;
    import org.apache.commons.lang3.StringUtils;
    import org.aspectj.lang.ProceedingJoinPoint;
    import org.aspectj.lang.annotation.Around;
    import org.aspectj.lang.annotation.Aspect;
    import org.slf4j.MDC;
    import org.springframework.beans.factory.annotation.Value;
    import org.springframework.core.annotation.Order;
    import org.springframework.stereotype.Component;
    import org.springframework.web.context.request.ServletRequestAttributes;
    
    import javax.servlet.http.HttpServletRequest;
    import javax.servlet.http.HttpServletResponse;
    
    import java.util.UUID;
    
    import static org.springframework.web.context.request.RequestContextHolder.getRequestAttributes;
    
    @Aspect
    @Component
    // 切面的顺序,越小越优先,对于多个切面Spring是使用责任链的模式 为了一开始将日志相关的参数初始化好,这里设置为最优先执行
    @Order(0)
    public class LogInfoInitAspect
    {
        // 请求唯一ID
        private final String requestId = "requestId";
        // 请求的地址
        private final String requestURI = "requestUri";
        // 请求的线程ID
        private final String applicationName = "applicationName";
        // 请求的IP
        private final String clientIp = "clientIp";
        // 本地主机的ip
        private final String localIp = "localIp";
        // 本机的hostname
        private final String hostName = "hostName";
    
        // 本应用的名称
        @Value("${spring.application.name}")
        public String appName;
    
        // 这里最好使用环绕通知,在执行完之后 将MDC中设置的值清空
        // 如果不使用环绕通知的话,可以使用Before设置值;使用After来清除值
        // 意思是将com.你的包路径.controller目录下以Controller结尾类的方法调用全部织入下面的代码块
        @Around("within(com.lupf.log4j2demo.controller..*Controller)")
        public Object initLogInfoController(ProceedingJoinPoint joinPoint) throws Throwable
        {
            // 请求对象
            HttpServletRequest request = ((ServletRequestAttributes) getRequestAttributes()).getRequest();
            // 响应对象
            HttpServletResponse response = ((ServletRequestAttributes) getRequestAttributes()).getResponse();
    
            // 获取客户端的IP
            String clientIp = NetUtils.getClientIP(request);
            if (StringUtils.isNotBlank(clientIp))
            {
                MDC.put(this.clientIp, clientIp);
            }
    
            // 获取请求地址
            String requestURI = request.getRequestURI();
            // 设置请求地址
            MDC.put(this.requestURI, requestURI);
            // 设置应用的名称
            MDC.put(applicationName, appName);
            // 生成当前请求的一个唯一UUID
            String requestId = UUID.randomUUID().toString();
            // 设置请求的唯一ID
            MDC.put(this.requestId, requestId);
            MDC.put(localIp, NetUtils.getLocalIp());
            MDC.put(hostName, NetUtils.getHostName());
            // 将次唯一ID设置为响应头
            response.setHeader(this.requestId, requestId);
    
            Object object = null;
            try
            {
                // 调用目标方法
                object = joinPoint.proceed();
                return object;
            }
            catch (Throwable throwable)
            {
                throwable.printStackTrace();
                throw throwable;
            }
            finally
            {
                // 注意,这里一定要清理掉
                // 否则可能会出现OOM的情况
                MDC.clear();
            }
        }
    }
    
  • 创建用于测试的Controller

    import lombok.extern.slf4j.Slf4j;
    import org.springframework.web.bind.annotation.GetMapping;
    import org.springframework.web.bind.annotation.RestController;
    
    @RestController
    @Slf4j
    public class Log4j2Controller
    {
        @GetMapping("info")
        public String info()
        {
            log.info("我是info日志!!!");
            log.warn("我是warn日志!!!");
            log.error("我是error日志!!!");
            return "ok";
        }
    
        @GetMapping("err")
        public String err()
        {
            try
            {
                System.out.println(1 / 0);
            }
            catch (Exception e)
            {
                log.error("我是异常日志!", e);
            }
            return "err";
        }
    }
    
  • 打包

    mvn clean package -Dmaven.test.skip=true
    // 打包之后 得到一个可运行的:log4j2-demo-0.0.1-SNAPSHOT.jar
    
  • 启动

    java -jar log4j2-demo-0.0.1-SNAPSHOT.jar 1>/dev/null 2>&1 &
    
  • 测试

    http://localhost:8080/info
    http://localhost:8080/err
    
    // 日志输出如下
    [2020-04-21T22:41:55.138+08:00] [b655875c-7052-427e-a5ce-b5d4183450d0] [INFO] [http-nio-8080-exec-1-23] [com.lupf.log4j2demo.controller.Log4j2Controller] [PC201301010100] [192.168.1.82] [0:0:0:0:0:0:0:1] [log4j2-demo] [/info] [Log4j2Controller.java,14,com.lupf.log4j2demo.controller.Log4j2Controller,info] [我是info日志!!!] ## ''
    [2020-04-21T22:41:55.139+08:00] [b655875c-7052-427e-a5ce-b5d4183450d0] [WARN] [http-nio-8080-exec-1-23] [com.lupf.log4j2demo.controller.Log4j2Controller] [PC201301010100] [192.168.1.82] [0:0:0:0:0:0:0:1] [log4j2-demo] [/info] [Log4j2Controller.java,15,com.lupf.log4j2demo.controller.Log4j2Controller,info] [我是warn日志!!!] ## ''
    [2020-04-21T22:41:55.140+08:00] [b655875c-7052-427e-a5ce-b5d4183450d0] [ERROR] [http-nio-8080-exec-1-23] [com.lupf.log4j2demo.controller.Log4j2Controller] [PC201301010100] [192.168.1.82] [0:0:0:0:0:0:0:1] [log4j2-demo] [/info] [Log4j2Controller.java,16,com.lupf.log4j2demo.controller.Log4j2Controller,info] [我是error日志!!!] ## ''
    [2020-04-21T22:41:58.144+08:00] [a441de74-47d5-4070-b4c1-cbb4a84a810e] [ERROR] [http-nio-8080-exec-3-25] [com.lupf.log4j2demo.controller.Log4j2Controller] [PC201301010100] [192.168.1.82] [0:0:0:0:0:0:0:1] [log4j2-demo] [/err] [Log4j2Controller.java,29,com.lupf.log4j2demo.controller.Log4j2Controller,err] [我是异常日志!] ## ' java.lang.ArithmeticException: / by zero
      at com.lupf.log4j2demo.controller.Log4j2Controller.err(Log4j2Controller.java:25)
      at com.lupf.log4j2demo.controller.Log4j2Controller$$FastClassBySpringCGLIB$$dec59ff5.invoke(<generated>)
      at org.springframework.cglib.proxy.MethodProxy.invoke(MethodProxy.java:218)
      //...  此时省略部分日志
      at java.lang.Thread.run(Unknown Source)
    
    

    好! 到这里 , 一个基础的基于AOP设置MDC自定义参数的方式已经实现好了 , 以上日志 , 当出现问题的时候 , 可以通过 b655875c-7052-427e-a5ce-b5d4183450d0这个唯一ID来筛选出本次请求的所有日志数据 , 来快速定位出问题 ;


思考

到这里 , 一个基础的日志规范已经实现了 , 但是在实际的业务开发过程中 , 并不是只是单纯的这种简单的业务请求流程 ; 比如还有定时任务 , 请求产生之后的异步任务(起一个线程去做耗时操作 , 主线程响应给前端用户) ; 那么在这种情况 , 定时任务没有走Controller , 所以没有走MDC流程 ; 后续的异步任务由于是一个新的线程 , 因此主线程设置的MDC无法获取到 ; 因此对应自定义日志输出也无法打印 ; 那么下面就来解决这两个常用且必须解决的问题


定时任务的MDC

和AOP切Controller一样 , 同样使用AOP去切task , 在切面中见MDC赋值

  • 创建一个简单的定时任务

    import lombok.extern.slf4j.Slf4j;
    import org.springframework.scheduling.annotation.Scheduled;
    import org.springframework.stereotype.Component;
    
    @Component
    @Slf4j
    public class TestTask {
    
        @Scheduled (cron = "1 * * * * ? ")
        public void log() {
            log.info("task 的info日志,threadid:{}", Thread.currentThread().getId());
            log.error("task 的error日志,threadid:{}", Thread.currentThread().getId());
            log.warn("task 的warn日志,threadid:{}", Thread.currentThread().getId());
        }
    }
    
  • 创建一个task的AOP

    import com.lupf.log4j2demo.utils.NetUtils;
    import lombok.extern.slf4j.Slf4j;
    import org.aspectj.lang.annotation.After;
    import org.aspectj.lang.annotation.Aspect;
    import org.aspectj.lang.annotation.Before;
    import org.slf4j.MDC;
    import org.springframework.beans.factory.annotation.Value;
    import org.springframework.core.annotation.Order;
    import org.springframework.stereotype.Component;
    
    import java.util.UUID;
    
    /**
     *
     */
    @Aspect
    @Component
    @Order (0)
    @Slf4j
    public class TaskLogInfoInitAspect {
        /**
         * 任务唯一ID
         */
        private final String requestId = "requestId";
        /**
         * 应用的名称
         */
        private final String applicationName = "applicationName";
    
        /**
         * 本地主机的ip
         */
        private final String localIp = "localIp";
    
        /**
         * 本机的hostname
         */
        private final String hostName = "hostName";
    
        /**
         * 本应用的名称
         */
        @Value ("${spring.application.name}")
        public String appName;
    
        /**
         * 执行前的初始化
         */
        @Before ("within(com.lupf.log4j2demo.task..*Task)"
            + "&& @annotation(org.springframework.scheduling.annotation.Scheduled)")
        public void initLogInfoTaskBefore() {
            // 设置应用的名称
            MDC.put(applicationName, appName);
            // 生成当前任务的一个唯一UUID
            String taskId = UUID.randomUUID().toString();
            // 设置请求的唯一ID
            MDC.put(this.requestId, taskId);
            MDC.put(localIp, NetUtils.getLocalIp());
            MDC.put(hostName, NetUtils.getHostName());
            log.info("定时任务切面触发...");
        }
    
        /**
         * 执行后的资源释放
         */
        @After ("within(com.lupf.log4j2demo.task..*Task)"
            + "&& @annotation(org.springframework.scheduling.annotation.Scheduled)")
        public void initLogInfoTaskAfter() {
            log.info("定时任务执行结束...");
            MDC.clear();
        }
    }
    
  • 入口类开启定时任务

    @EnableScheduling
    
  • 重新打包测试

    [2020-06-04T19:48:01.001+08:00] [6c864af5-1eac-4111-a31a-ba7c0e856485] [INFO] [scheduling-1-32] [com.lupf.log4j2demo.aop.TaskLogInfoInitAspect] [PC201301010100] [192.168.1.82] [] [log4j2-demo] [] [TaskLogInfoInitAspect.java,65,com.lupf.log4j2demo.aop.TaskLogInfoInitAspect,initLogInfoTaskBefore] [定时任务切面触发...] ## ''
    [2020-06-04T19:48:01.002+08:00] [6c864af5-1eac-4111-a31a-ba7c0e856485] [INFO] [scheduling-1-32] [com.lupf.log4j2demo.task.TestTask] [PC201301010100] [192.168.1.82] [] [log4j2-demo] [] [TestTask.java,18,com.lupf.log4j2demo.task.TestTask,log] [task 的info日志,threadid:32] ## ''
    [2020-06-04T19:48:01.002+08:00] [6c864af5-1eac-4111-a31a-ba7c0e856485] [ERROR] [scheduling-1-32] [com.lupf.log4j2demo.task.TestTask] [PC201301010100] [192.168.1.82] [] [log4j2-demo] [] [TestTask.java,19,com.lupf.log4j2demo.task.TestTask,log] [task 的error日志,threadid:32] ## ''
    [2020-06-04T19:48:01.002+08:00] [6c864af5-1eac-4111-a31a-ba7c0e856485] [WARN] [scheduling-1-32] [com.lupf.log4j2demo.task.TestTask] [PC201301010100] [192.168.1.82] [] [log4j2-demo] [] [TestTask.java,20,com.lupf.log4j2demo.task.TestTask,log] [task 的warn日志,threadid:32] ## ''
    [2020-06-04T19:48:01.002+08:00] [6c864af5-1eac-4111-a31a-ba7c0e856485] [INFO] [scheduling-1-32] [com.lupf.log4j2demo.aop.TaskLogInfoInitAspect] [PC201301010100] [192.168.1.82] [] [log4j2-demo] [] [TaskLogInfoInitAspect.java,71,com.lupf.log4j2demo.aop.TaskLogInfoInitAspect,initLogInfoTaskAfter] [定时任务执行结束...] ## ''
    

    这样 , 以上日志中 , 6c864af5-1eac-4111-a31a-ba7c0e856485
    就可以作为本次定时任务日志的唯一ID进行查找


异步子任务的MDC传递

  • 自定义线程池 , 将父线程的MDC传递给子线程

    /**
     * @author lupf
     * @date 2020/6/3 20:31
     * @desc
     */
    public class MdcThreadPoolTaskExecutor extends ThreadPoolTaskExecutor {
    
        /**
         * 所有线程都会委托给这个execute方法,在这个方法中我们把父线程的MDC内容赋值给子线程
         * https://logback.qos.ch/manual/mdc.html#managedThreads
         *
         * @param runnable
         */
        @Override
        public void execute(Runnable runnable) {
            // 获取父线程MDC中的内容,必须在run方法之前,
            // 否则等异步线程执行的时候有可能MDC里面的值已经被清空了,这个时候就会返回null
            Map<String, String> context = MDC.getCopyOfContextMap();
            super.execute(() -> run(runnable, context));
        }
    
        /**
         * 子线程委托的执行方法
         *
         * @param runnable {@link Runnable}
         * @param context  父线程MDC内容
         */
        private void run(Runnable runnable, Map<String, String> context) {
            // 校验是否为null 如果不校验,当content为null(父线程没有MDC)的时候,就会报空指针异常
            if (null != context) {
                // 将父线程的MDC内容传给子线程
                MDC.setContextMap(context);
            }
    
            try {
                // 执行异步操作
                runnable.run();
            } finally {
                // 清空MDC内容
                MDC.clear();
            }
        }
    }
    
  • 初始化线程池

    @Bean
    public MdcThreadPoolTaskExecutor initMdcThreadPoolTaskExecutor() {
        MdcThreadPoolTaskExecutor mdcThreadPoolTaskExecutor = new MdcThreadPoolTaskExecutor();
        mdcThreadPoolTaskExecutor.initialize();
        mdcThreadPoolTaskExecutor.setCorePoolSize(5);
        mdcThreadPoolTaskExecutor.setMaxPoolSize(15);
        mdcThreadPoolTaskExecutor.setQueueCapacity(30);
        return mdcThreadPoolTaskExecutor;
    }
    
  • 创建一个测试使用的Thread

    import lombok.extern.slf4j.Slf4j;
    
    /**
     * @author lupf
     * @date 2020/6/3 20:19
     * @desc
     */
    @Slf4j
    public class LogThread implements Runnable {
        @Override
        public void run() {
            log.info("我是线程中输出的info日志");
            log.warn("我是线程中输出的warn日志");
            log.error("我是线程中输出的error日志");
            String s = ThreadLocalConstant.threadLocal.get();
            log.info("LogThread threadlocal中的值:{}", s);
        }
    }
    
  • controller方法中添加线程测试

    @Autowired
    MdcThreadPoolTaskExecutor mdcThreadPoolTaskExecutor;
    
    @GetMapping ("info")
    public String info() {
        log.info("我是info日志!!!");
        log.warn("我是warn日志!!!");
        log.error("我是error日志!!!");
    
        // 由于线程池中是execute中解析的MDC传递,所以这里只能使用execute去执行
        // 如果使用submit方法,传递将失效
        mdcThreadPoolTaskExecutor.execute(new LogThread());
        return "ok";
    }
    
  • 启动并测试

    [2020-06-04T20:03:27.527+08:00] [3b0edc21-7104-489f-9c56-e9fe2f70ee35] [INFO] [http-nio-8080-exec-6-39] [com.lupf.log4j2demo.controller.Log4j2Controller] [PC201301010100] [192.168.1.82] [192.168.1.82] [log4j2-demo] [/info] [Log4j2Controller.java,21,com.lupf.log4j2demo.controller.Log4j2Controller,info] [我是info日志!!!] ## ''
    [2020-06-04T20:03:27.528+08:00] [3b0edc21-7104-489f-9c56-e9fe2f70ee35] [WARN] [http-nio-8080-exec-6-39] [com.lupf.log4j2demo.controller.Log4j2Controller] [PC201301010100] [192.168.1.82] [192.168.1.82] [log4j2-demo] [/info] [Log4j2Controller.java,22,com.lupf.log4j2demo.controller.Log4j2Controller,info] [我是warn日志!!!] ## ''
    [2020-06-04T20:03:27.528+08:00] [3b0edc21-7104-489f-9c56-e9fe2f70ee35] [ERROR] [http-nio-8080-exec-6-39] [com.lupf.log4j2demo.controller.Log4j2Controller] [PC201301010100] [192.168.1.82] [192.168.1.82] [log4j2-demo] [/info] [Log4j2Controller.java,23,com.lupf.log4j2demo.controller.Log4j2Controller,info] [我是error日志!!!] ## ''
    [2020-06-04T20:03:27.529+08:00] [3b0edc21-7104-489f-9c56-e9fe2f70ee35] [INFO] [initMdcThreadPoolTaskExecutor-3-58] [com.lupf.log4j2demo.thread.LogThread] [PC201301010100] [192.168.1.82] [192.168.1.82] [log4j2-demo] [/info] [LogThread.java,14,com.lupf.log4j2demo.thread.LogThread,run] [我是线程中输出的info日志] ## ''
    [2020-06-04T20:03:27.529+08:00] [3b0edc21-7104-489f-9c56-e9fe2f70ee35] [WARN] [initMdcThreadPoolTaskExecutor-3-58] [com.lupf.log4j2demo.thread.LogThread] [PC201301010100] [192.168.1.82] [192.168.1.82] [log4j2-demo] [/info] [LogThread.java,15,com.lupf.log4j2demo.thread.LogThread,run] [我是线程中输出的warn日志] ## ''
    [2020-06-04T20:03:27.531+08:00] [3b0edc21-7104-489f-9c56-e9fe2f70ee35] [ERROR] [initMdcThreadPoolTaskExecutor-3-58] [com.lupf.log4j2demo.thread.LogThread] [PC201301010100] [192.168.1.82] [192.168.1.82] [log4j2-demo] [/info] [LogThread.java,16,com.lupf.log4j2demo.thread.LogThread,run] [我是线程中输出的error日志] ## ''
    

    如上日志所示 , 所有日志都是一个ID 3b0edc21-7104-489f-9c56-e9fe2f70ee35 , 但是前三行是在父线程 http-nio-8080-exec-6-39中执行的 , 后三条是在子线程 initMdcThreadPoolTaskExecutor-3-58中执行的 , 其中自定义的MDC参数已经成功传递到的子线程中 .


基于此规则的日志,我们可以将日志通过ELK进行展示 , 详细的搭建过程请参考从0开始搭建一套完整的ELK分布式日志管理系统 : https://lupf.cn/articles/2020/04/23/1587622994136.html



标题:SpringBoot日志的链路追踪
作者:码霸霸
地址:https://lupf.cn/articles/2020/06/04/1591273110824.html