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