【SpringBoot应用篇】SpringBoot+MDC+自定义Filter操作traceId实现日志链路追踪
【SpringBoot应用篇】SpringBoot+MDC+自定义Filter操作traceId实现日志链路追踪
解决的问题
接口报错，如何快速定位问题？这个需要日志的辅助，一般错误日志中有详细的堆栈信息，具体是哪行代码报错，都可以看到。线程日志交差打印，要想快速定位问题，前提是要能够快速定位日志。
日志量一般都是很大的，如何能够从大量日志中找到自己需要的日志呢？
依赖原始的logback配置，很难从某服务庞杂的日志中，单独找寻出某次线程API调用的全部日志。
解决方案
1、服务端入口处可以生成一个唯一的id，记做：traceId
2、日志中均需要输出traceId的值
3、接口返回值中，添加一个通用的字段：traceId，将上面的traceId作为这个字段的值
- Controller层返回的统一返回值对象R
- 全局异常处理返回的统一返回值对象R
5、这样前端发现接口有问题的时候，直接将这个traceId提供给我们，我们便可以在日志中快速查询出对应的日志。使用 grep 'traceId' xxx.log 语句就能准确的定位到目标日志。
MDC
-
日志追踪目标是每次请求级别的，也就是说同一个接口的每次请求，都应该有不同的traceId。
-
每次接口请求，都是一个单独的线程，所以自然我们很容易考虑到通过
ThreadLocal实现上述需求。 -
考虑到logback本身已经提供了类似的功能MDC，所以直接使用MDC进行实现。
-
关于MDC的简述
- Mapped Diagnostic Context，即：映射诊断环境。
- MDC是 log4j 和 logback 提供的一种方便在多线程条件下记录日志的功能。
- MDC 可以看成是一个与当前线程绑定的哈希表，可以往其中添加键值对。
-
关于MDC的关键操作
- 向MDC中设置值：
MDC.put(key, value); - 从MDC中取值：
MDC.get(key); - 将MDC中内容打印到日志中：
%X{key}
- 向MDC中设置值：
假定已经解决了traceId的存放问题，那么何时进行traceId的存放呢？其实有多重实现思路，例如：过滤器、AOP、拦截器等等。
具体逻辑
yml
server:
port: 8081
spring:
profiles:
active: dev
application:
name: springboot-log
main:
allow-bean-definition-overriding: true
logback-spring.xml
<?xml version="1.0" encoding="UTF-8"?>
<configuration scan="true" scanPeriod="10 seconds">
<!-- 日志级别从低到高分为TRACE < DEBUG < INFO < WARN < ERROR < FATAL，如果设置为WARN，则低于WARN的信息都不会输出 -->
<!-- scan:当此属性设置为true时，配置文件如果发生改变，将会被重新加载，默认值为true -->
<!-- scanPeriod:设置监测配置文件是否有修改的时间间隔，如果没有给出时间单位，默认单位是毫秒。当scan为true时，此属性生效。默认的时间间隔为1分钟。 -->
<!-- debug:当此属性设置为true时，将打印出logback内部日志信息，实时查看logback运行状态。默认值为false。 -->
<contextName>logback</contextName>
<!-- name的值是变量的名称，value的值时变量定义的值。通过定义的值会被插入到logger上下文中。定义变量后，可以使“${}”来使用变量。 -->
<property name="log.path" value="logs/log" />
<!-- 彩色日志 -->
<!-- 配置格式变量：CONSOLE_LOG_PATTERN 彩色日志格式 -->
<!-- magenta:洋红 -->
<!-- boldMagenta:粗红-->
<!-- cyan:青色 -->
<!-- white:白色 -->
<!-- magenta:洋红 -->
<property name="CONSOLE_LOG_PATTERN"
value="%X{traceId}|%yellow(%date{yyyy-MM-dd HH:mm:ss}) |%highlight(%-5level) |%blue(%thread) |%blue(%file:%line) |%green(%logger) |%cyan(%msg%n)"/>
<!--输出到控制台-->
<appender name="CONSOLE" class="ch.qos.logback.core.ConsoleAppender">
<!--此日志appender是为开发使用，只配置最底级别，控制台输出的日志级别是大于或等于此级别的日志信息-->
<!-- 例如：如果此处配置了INFO级别，则后面其他位置即使配置了DEBUG级别的日志，也不会被输出 -->
<!--<filter class="ch.qos.logback.classic.filter.ThresholdFilter">
<level>INFO</level>
</filter>-->
<encoder>
<Pattern>${CONSOLE_LOG_PATTERN}</Pattern>
<!-- 设置字符集 -->
<charset>UTF-8</charset>
</encoder>
</appender>
<!--输出到文件-->
<!-- 时间滚动输出 level为 INFO 日志 -->
<appender name="INFO_FILE" class="ch.qos.logback.core.rolling.RollingFileAppender">
<!-- 正在记录的日志文件的路径及文件名 -->
<file>${log.path}/log_info.log</file>
<!--日志文件输出格式-->
<encoder>
<pattern>%X{traceId} %d{yyyy-MM-dd HH:mm:ss.SSS} [%thread] %-5level %logger{50} - %msg%n</pattern>
<charset>UTF-8</charset>
</encoder>
<!-- 日志记录器的滚动策略，按日期，按大小记录 -->
<rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
<!-- 每天日志归档路径以及格式 -->
<fileNamePattern>${log.path}/info/log-info-%d{yyyy-MM-dd}.%i.log</fileNamePattern>
<timeBasedFileNamingAndTriggeringPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedFNATP">
<maxFileSize>100MB</maxFileSize>
</timeBasedFileNamingAndTriggeringPolicy>
<!--日志文件保留天数-->
<maxHistory>15</maxHistory>
</rollingPolicy>
<!-- 此日志文件只记录info级别的 -->
<filter class="ch.qos.logback.classic.filter.LevelFilter">
<level>INFO</level>
<onMatch>ACCEPT</onMatch>
<onMismatch>DENY</onMismatch>
</filter>
</appender>
<!-- 时间滚动输出 level为 WARN 日志 -->
<appender name="WARN_FILE" class="ch.qos.logback.core.rolling.RollingFileAppender">
<!-- 正在记录的日志文件的路径及文件名 -->
<file>${log.path}/log_warn.log</file>
<!--日志文件输出格式-->
<encoder>
<pattern>%X{traceId} %d{yyyy-MM-dd HH:mm:ss.SSS} [%thread] %-5level %logger{50} - %msg%n</pattern>
<charset>UTF-8</charset> <!-- 此处设置字符集 -->
</encoder>
<!-- 日志记录器的滚动策略，按日期，按大小记录 -->
<rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
<fileNamePattern>${log.path}/warn/log-warn-%d{yyyy-MM-dd}.%i.log</fileNamePattern>
<timeBasedFileNamingAndTriggeringPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedFNATP">
<maxFileSize>100MB</maxFileSize>
</timeBasedFileNamingAndTriggeringPolicy>
<!--日志文件保留天数-->
<maxHistory>15</maxHistory>
</rollingPolicy>
<!-- 此日志文件只记录warn级别的 -->
<filter class="ch.qos.logback.classic.filter.LevelFilter">
<level>warn</level>
<onMatch>ACCEPT</onMatch>
<onMismatch>DENY</onMismatch>
</filter>
</appender>
<!-- 时间滚动输出 level为 ERROR 日志 -->
<appender name="ERROR_FILE" class="ch.qos.logback.core.rolling.RollingFileAppender">
<!-- 正在记录的日志文件的路径及文件名 -->
<file>${log.path}/log_error.log</file>
<!--日志文件输出格式-->
<encoder>
<pattern>%X{traceId} %d{yyyy-MM-dd HH:mm:ss.SSS} [%thread] %-5level %logger{50} - %msg%n</pattern>
<charset>UTF-8</charset> <!-- 此处设置字符集 -->
</encoder>
<!-- 第一种方式:日志记录器的滚动策略，按日期，按大小记录 -->
<rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
<fileNamePattern>${log.path}/error/log-error-%d{yyyy-MM-dd}.%i.log</fileNamePattern>
<timeBasedFileNamingAndTriggeringPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedFNATP">
<maxFileSize>100MB</maxFileSize>
</timeBasedFileNamingAndTriggeringPolicy>
<!--日志文件保留天数-->
<maxHistory>15</maxHistory>
</rollingPolicy>
<!-- 第二种方式:指定日志文件拆分和压缩规则 -->
<!-- 指定日志文件拆分和压缩规则 -->
<!-- <rollingPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedRollingPolicy">-->
<!-- <!– 通过指定压缩文件名称，来确定分割文件方式–>-->
<!-- <fileNamePattern>${log.path}/error/log-error-%d{yyyy-MM-dd}.log%i.zip</fileNamePattern>-->
<!-- <!– 文件拆分大小 –>-->
<!-- <maxFileSize>1MB</maxFileSize>-->
<!-- <!–日志文件保留天数–>-->
<!-- <maxHistory>15</maxHistory>-->
<!-- </rollingPolicy>-->
<!-- 此日志文件只记录ERROR级别的 -->
<filter class="ch.qos.logback.classic.filter.LevelFilter">
<level>ERROR</level>
<onMatch>ACCEPT</onMatch>
<onMismatch>DENY</onMismatch>
</filter>
</appender>
<!--
<logger>用来设置某一个包或者具体的某一个类的日志打印级别、以及指定<appender>。
<logger>仅有一个name属性，
一个可选的level和一个可选的addtivity属性。
name:用来指定受此logger约束的某一个包或者具体的某一个类。
level:用来设置打印级别，大小写无关：TRACE, DEBUG, INFO, WARN, ERROR, ALL 和 OFF，
如果未设置此属性，那么当前logger将会继承上级的级别。
-->
<!--
使用mybatis的时候，sql语句是debug下才会打印，而这里我们只配置了info，所以想要查看sql语句的话，有以下两种操作：
第一种把<root level="INFO">改成<root level="DEBUG">这样就会打印sql，不过这样日志那边会出现很多其他消息
第二种就是单独给mapper下目录配置DEBUG模式，代码如下，这样配置sql语句会打印，其他还是正常DEBUG级别：
<logger name="cn.zysheep.mapper" level="INFO" />
-->
<!--结合spring多环境使用 开发环境:打印控制台-->
<springProfile name="dev">
<!--
root节点是必选节点，用来指定最基础的日志输出级别，只有一个level属性
level:用来设置打印级别，大小写无关：TRACE, DEBUG, INFO, WARN, ERROR, ALL 和 OFF，不写level属性,默认是DEBUG
可以包含零个或多个appender元素。
-->
<root level="INFO">
<appender-ref ref="CONSOLE" />
<appender-ref ref="INFO_FILE" />
<appender-ref ref="WARN_FILE" />
<appender-ref ref="ERROR_FILE" />
</root>
</springProfile>
<!--结合spring多环境使用:生产环境:输出到文件-->
<springProfile name="pro">
<root level="INFO">
<appender-ref ref="ERROR_FILE" />
<appender-ref ref="WARN_FILE" />
</root>
</springProfile>
</configuration>
TraceIdUtil操作工具类
/**
* <p>traceId工具类</P>
*
*/
public class TraceIdUtil {
public static final String TRACE_ID = "traceId";
/**
* 当traceId为空时，显示的traceId。随意。
*/
private static final String DEFAULT_TRACE_ID = "0";
/**
* 设置traceId
*/
public static void setTraceId(String traceId) {
//如果参数为空，则设置默认traceId
traceId = StringUtils.isBlank(traceId) ? DEFAULT_TRACE_ID : traceId;
//将traceId放到MDC中
MDC.put(TRACE_ID, traceId);
}
/**
* 获取traceId
*/
public static String getTraceId() {
//获取
String traceId = MDC.get(TRACE_ID);
//如果traceId为空，则返回默认值
return StringUtils.isBlank(traceId) ? DEFAULT_TRACE_ID : traceId;
}
/**
* 判断traceId为默认值
*/
public static Boolean defaultTraceId(String traceId) {
return DEFAULT_TRACE_ID.equals(traceId);
}
/**
* 生成traceId
*/
public static String genTraceId() {
return UUID.randomUUID().toString();
}
/**
* 判断traceId为默认值
*/
public static void removeTraceId() {
MDC.clear();
}
}
TraceIdFilter自定义过滤器
/**
* <p>traceId过滤器,用于设置traceId</P>
*
*/
@WebFilter(urlPatterns = "/*", filterName = "traceIdFilter")
@Order(1)
public class TraceIdFilter extends GenericFilterBean {
public static Logger logger = LoggerFactory.getLogger(TraceIdFilter.class);
@Override
public void doFilter(ServletRequest request, ServletResponse response, FilterChain filterChain) throws IOException, ServletException {
//traceId初始化
initTraceId((HttpServletRequest) request);
//执行后续过滤器
long st = System.currentTimeMillis();
try {
filterChain.doFilter(request, response);
} finally {
long et = System.currentTimeMillis();
logger.info("请求地址:{},耗时(ms):{}", ((HttpServletRequest) request).getRequestURI(), (et - st));
TraceIdUtil.removeTraceId();
}
}
/**
* traceId初始化
*/
private void initTraceId(HttpServletRequest request) {
//尝试获取http请求中的traceId
String traceId = request.getParameter("traceId");
//如果当前traceId为空或者为默认traceId，则生成新的traceId
if (StringUtils.isBlank(traceId) || TraceIdUtil.defaultTraceId(traceId)){
traceId = TraceIdUtil.genTraceId();
}
//设置traceId
TraceIdUtil.setTraceId(traceId);
}
@Override
public void destroy() {
TraceIdUtil.removeTraceId();
}
}
GlobalExceptionHandler全局异常处理类
@Slf4j
@RestControllerAdvice
public class GlobalExceptionHandler {
@ExceptionHandler(Exception.class)
public R<String> otherExceptionHandler(Exception ex, HttpServletRequest request) {
log.warn("Exception:", ex);
return R.result(ExceptionCode.SYSTEM_BUSY.getCode(), StringUtils.EMPTY, ExceptionCode.SYSTEM_BUSY.getMsg()).setPath(request.getRequestURI());
}
}
TraceIdAspect切面
@Component
@Aspect
@Order
public class TraceIdAspect {
/**
* 切点:
* 1、所有controller包及其子包下的所有方法
* 2、所有GlobalExceptionHandler类中的所有方法
*/
@Pointcut("execution(public * cn.zysheep.controller..*.*(..)) || execution(* cn.zysheep.exception.GlobalExceptionHandler.*(..))")
public void pointCut() {}
@Around("pointCut()")
public Object around(ProceedingJoinPoint pjp) throws Throwable {
Object object = pjp.proceed();
if (object instanceof R) {
((R<?>) object).setTraceId(TraceIdUtil.getTraceId());
}
return object;
}
}
UserController
@RestController
@RequestMapping("/user")
public class UserController {
private static final Logger log = LoggerFactory.getLogger(UserController.class);
@GetMapping(value = "query")
public R findByPage() throws InterruptedException {
log.info("开始执行查询用户业务");
TimeUnit.MILLISECONDS.sleep(500);
log.info("查询用户业务执行结束");
return R.success();
}
@GetMapping("/exception")
public R exception() {
log.info("开始执行业务");
//这里模拟了一个错误，10/0，会报错
System.out.println(10 / 0);
log.info("业务执行结束");
return R.success();
}
}
测试验证
多线程处理
MDCUtil工具类
/**
* <p>
* 封装MDC用于向线程池传递
* </p>
*/
public class MDCUtil {
// 设置MDC中的traceId值，不存在则新生成，针对不是子线程的情况，
// 如果是子线程，MDC中traceId不为null
public static void setTraceIdIfAbsent() {
if (MDC.get(TraceIdUtil.TRACE_ID) == null) {
MDC.put(TraceIdUtil.TRACE_ID, TraceIdUtil.getTraceId());
}
}
public static <T> Callable<T> wrap(final Callable<T> callable, final Map<String, String> context) {
return () -> {
if (CollectionUtils.isEmpty(context)) {
MDC.clear();
} else {
MDC.setContextMap(context);
}
setTraceIdIfAbsent();
try {
return callable.call();
} finally {//清除子线程的，避免内存溢出，就和ThreadLocal.remove()一个原因
MDC.clear();
}
};
}
public static Runnable wrap(final Runnable runnable, final Map<String, String> context) {
return () -> {
if (context == null) {
MDC.clear();
} else {
MDC.setContextMap(context);
}
setTraceIdIfAbsent();
try {
runnable.run();
} finally {
MDC.clear();
}
};
}
public static void setMDCContextMap(final Map<String, String> context) {
if (CollectionUtils.isEmpty(context)) {
MDC.clear();
} else {
MDC.setContextMap(context);
}
}
}
ThreadPoolMdcWrapper
public class ThreadPoolMdcWrapper extends ThreadPoolTaskExecutor {
public ThreadPoolMdcWrapper() {
}
@Override
public void execute(Runnable task) {
super.execute(MDCUtil.wrap(task, MDC.getCopyOfContextMap()));
}
@Override
public void execute(Runnable task, long startTimeout) {
super.execute(MDCUtil.wrap(task, MDC.getCopyOfContextMap()), startTimeout);
}
@Override
public <T> Future<T> submit(Callable<T> task) {
return super.submit(MDCUtil.wrap(task, MDC.getCopyOfContextMap()));
}
@Override
public Future<?> submit(Runnable task) {
return super.submit(MDCUtil.wrap(task, MDC.getCopyOfContextMap()));
}
@Override
public ListenableFuture<?> submitListenable(Runnable task) {
return super.submitListenable(MDCUtil.wrap(task, MDC.getCopyOfContextMap()));
}
@Override
public <T> ListenableFuture<T> submitListenable(Callable<T> task) {
return super.submitListenable(MDCUtil.wrap(task, MDC.getCopyOfContextMap()));
}
}
ContextTransferTaskDecorator
public class ContextTransferTaskDecorator implements TaskDecorator {
@Override
public Runnable decorate(Runnable runnable) {
Map<String, String> context = MDC.getCopyOfContextMap();
RequestAttributes requestAttributes = RequestContextHolder.currentRequestAttributes();
return () -> {
try {
MDC.setContextMap(context);
RequestContextHolder.setRequestAttributes(requestAttributes);
runnable.run();
} finally {
MDC.clear();
RequestContextHolder.resetRequestAttributes();
}
};
}
}
ThreadPoolConfig
@Configuration
public class ThreadPoolConfig {
@Bean("poolTaskExecutor")
public ThreadPoolTaskExecutor threadPoolTaskExecutor() {
ThreadPoolTaskExecutor taskExecutor = new ThreadPoolMdcWrapper();
//核心线程数，默认为1
taskExecutor.setCorePoolSize(5);
//最大线程数，默认为Integer.MAX_VALUE
taskExecutor.setMaxPoolSize(10);
//队列最大长度，一般需要设置值>=notifyScheduledMainExecutor.maxNum；默认为Integer.MAX_VALUE
taskExecutor.setQueueCapacity(200);
//线程池维护线程所允许的空闲时间，默认为60s
taskExecutor.setKeepAliveSeconds(60);
taskExecutor.setThreadNamePrefix("sif-async-executor-");
//线程池对拒绝任务（无线程可用）的处理策略
taskExecutor.setRejectedExecutionHandler(new ThreadPoolExecutor.AbortPolicy());
taskExecutor.setTaskDecorator(new ContextTransferTaskDecorator());
// 初始化线程池
taskExecutor.initialize();
return taskExecutor;
}
}
UserController
@RestController
@RequestMapping("/user")
public class UserController {
private static final Logger log = LoggerFactory.getLogger(UserController.class);
@Resource(name = "poolTaskExecutor")
private ThreadPoolTaskExecutor threadPoolExecutor;
@GetMapping("/t1")
public R test1(){
log.info("开始....");
CompletableFuture.runAsync(() ->{
log.info("异步中....");
}, threadPoolExecutor);
log.info("结束....");
return R.success();
}
@GetMapping("/t2")
public R test2(){
log.info("开始....");
threadPoolExecutor.execute(() ->{
log.info("线程池中....");
});
log.info("结束....");
return R.success();
}
}
测试验证
原文地址：https://blog.csdn.net/qq_45297578/article/details/145134116
免责声明：本站文章内容转载自网络资源，如本站内容侵犯了原著者的合法权益，可联系本站删除。更多内容请关注自学内容网（zxcms.com）！