微服务的日志规范及链路追踪

一行Java

发布于 2022-04-06 15:56:58

6630

发布于 2022-04-06 15:56:58

前言

日志作为码农的铁杆儿基友,伴随着码农的一生, 特别是在生死关头 , 能拯救码农于水火 ;但是混乱的日志 , 有时候不仅不能协助解决问题 , 反而还会在那种紧张的氛围下让人变的更焦躁 , 毕竟涉及到看日志的时候 , 多半就是出现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>

 <!-- Spring cloud 链路追踪 -->
 <dependency>
 <groupId>org.springframework.cloud</groupId>
 <artifactId>spring-cloud-starter-sleuth</artifactId>
 <version>${spring-cloud-starter-sleuth.version}</version>
 </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{X-B3-TraceId},%X{X-B3-SpanId},%X{X-B3-ParentSpanId},%X{X-Span-Export}] [%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=}] [%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{X-B3-TraceId},%X{X-B3-SpanId},%X{X-B3-ParentSpanId},%X{X-Span-Export}]  // 本次请求sleuth用于链路追踪的ID
[%level{length=}]  // 日志级别
[%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=
spring.http.encoding.charset=utf-
spring.jackson.date-format=yyyy-MM-dd HH:mm:ss
spring.jackson.time-zone=GMT+
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() ==  || "unknown".equalsIgnoreCase(ip))
        {
            ip = request.getHeader("Proxy-Client-IP");
        }
 if (ip == null || ip.length() ==  || "unknown".equalsIgnoreCase(ip))
        {
            ip = request.getHeader("WL-Proxy-Client-IP");
        }
 if (ip == null || ip.length() ==  || "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
{
 // 请求的地址
 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);
 // 本机的IP
        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( / );
        }
 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 >/dev/null >& &

测试

http://localhost:8080/info
http://localhost:8080/err

// 日志输出如下
[2020-04-21T22:41:55.138+08:00] [c5358b03f3ae48,c5358b03f3ae48,,false] [INFO] [http-nio-8080-exec-1-23] [com.lupf.log4j2demo.controller.Log4j2Controller] [PC201301010100] [192.168.1.82] [:::::::] [log4j2-demo] [/info] [Log4j2Controller.java,,com.lupf.log4j2demo.controller.Log4j2Controller,info] [我是info日志!!!] ## ''
[2020-04-21T22:41:55.139+08:00] [c5358b03f3ae48,c5358b03f3ae48,,false] [WARN] [http-nio-8080-exec-1-23] [com.lupf.log4j2demo.controller.Log4j2Controller] [PC201301010100] [192.168.1.82] [:::::::] [log4j2-demo] [/info] [Log4j2Controller.java,,com.lupf.log4j2demo.controller.Log4j2Controller,info] [我是warn日志!!!] ## ''
[2020-04-21T22:41:55.140+08:00] [c5358b03f3ae48,c5358b03f3ae48,,false] [ERROR] [http-nio-8080-exec-1-23] [com.lupf.log4j2demo.controller.Log4j2Controller] [PC201301010100] [192.168.1.82] [:::::::] [log4j2-demo] [/info] [Log4j2Controller.java,,com.lupf.log4j2demo.controller.Log4j2Controller,info] [我是error日志!!!] ## ''
[2020-04-21T22:41:58.144+08:00] [a4fdb3865ffe00,a4fdb3865ffe00,,false] [ERROR] [http-nio-8080-exec-3-25] [com.lupf.log4j2demo.controller.Log4j2Controller] [PC201301010100] [192.168.1.82] [:::::::] [log4j2-demo] [/err] [Log4j2Controller.java,,com.lupf.log4j2demo.controller.Log4j2Controller,err] [我是异常日志!] ## ' java.lang.ArithmeticException: / by zero
  at com.lupf.log4j2demo.controller.Log4j2Controller.err(Log4j2Controller.java:)
  at com.lupf.log4j2demo.controller.Log4j2Controller$$FastClassBySpringCGLIB$$dec59ff5.invoke(<generated>)
  at org.springframework.cglib.proxy.MethodProxy.invoke(MethodProxy.java:)
 //...  此时省略部分日志
  at java.lang.Thread.run(Unknown Source)

好! 到这里 , 一个基础的基于AOP设置MDC自定义参数的方式已经实现好了 , 以上日志 , 当出现问题的时候 , 可以通过70c5358b03f3ae48,70c5358b03f3ae48,,false这个唯一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 ()
@Slf4j
public class TaskLogInfoInitAspect {
 /**
     * 任务唯一ID
     */
 private final String requestId = "X-B3-SpanId";
 /**
     * 应用的名称
     */
 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] [41896abcb049aba45a72d82933829489,,,] [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] [41896abcb049aba45a72d82933829489,,,] [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] [41896abcb049aba45a72d82933829489,,,] [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] [41896abcb049aba45a72d82933829489,,,] [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] [41896abcb049aba45a72d82933829489,,,] [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] [定时任务执行结束...] ## ''

这样 , 以上日志中 , 41896abcb049aba45a72d82933829489,,, 就可以作为本次定时任务日志的唯一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();
    mdcThreadPoolTaskExecutor.setMaxPoolSize();
    mdcThreadPoolTaskExecutor.setQueueCapacity();
 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] [7677c9a0a40ab4c8,7677c9a0a40ab4c8,,false] [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] [7677c9a0a40ab4c8,7677c9a0a40ab4c8,,false] [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] [7677c9a0a40ab4c8,7677c9a0a40ab4c8,,false] [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] [7677c9a0a40ab4c8,7677c9a0a40ab4c8,,false] [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] [7677c9a0a40ab4c8,7677c9a0a40ab4c8,,false] [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] [7677c9a0a40ab4c8,7677c9a0a40ab4c8,,false] [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 7677c9a0a40ab4c8,7677c9a0a40ab4c8,,false , 但是前三行是在父线程http-nio-8080-exec-6-39中执行的 , 后三条是在子线程initMdcThreadPoolTaskExecutor-3-58中执行的 , 其中自定义的MDC参数已经成功传递到的子线程中 .

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

本文参与腾讯云自媒体同步曝光计划，分享自微信公众号。

原始发表：2020-08-28，如有侵权请联系 cloudcommunity@tencent.com 删除

linux