SpringBoot日志的链路追踪

  |   0 评论   |   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://blog.lupf.cn/articles/2020/06/04/1591273110824.html