SpringBoot+MDC+logback实现日志格式化输出
1、术语与定义
流水日志：是一种针对监控联机交易的非功能日志。通过记录交易在路径上各系统上的进出时间、执行状态等信息，来反映交易路径上各系统的健康状态。流水日志不应包括交易敏感信息，主要应用于交易链路追踪，运维交易类指标监控及告警等。
应用日志：指不用于交易统计，仅用于日志级别告警、监控及问题分析的日志。
1.1 日志格式
{
"txnDateTime": "2023-06-13 10:07:58.923",
"traceId": "531249c8-72ae-436c-b93e-292658e548b7",
"tranId": "--",
"tranCode": "test",
"level": "INFO",
"serviceName": "ORG",
"tranClass": "com.congee.org.controller.TestLogController",
"processStep": "Finish",
"status": "SS",
"elapsedTime": "5005ms",
"msg": "API EXEC TIME: [5038]ms",
"thread": "http-nio-8084-exec-1",
"logger": "com.congee.org.common.advice.ApiAccessAdvice"
}{
"txnDateTime": "2023-06-13 10:07:58.989",
"traceId": "531249c8-72ae-436c-b93e-292658e548b7",
"tranId": "--",
"tranCode": "test",
"level": "INFO",
"serviceName": "ORG",
"tranClass": "com.congee.org.controller.TestLogController",
"processStep": "Start",
"status": "--",
"elapsedTime": "0ms",
"msg": "API:/test/logtest::GET EXEC TIME: [5005]ms",
"thread": "gors-executor-1",
"logger": "com.congee.org.aop.async.ApiMonitorUtil"
}{
"txnDateTime": "2023-06-13 10:07:59.002",
"traceId": "531249c8-72ae-436c-b93e-292658e548b7",
"tranId": "--",
"tranCode": "test",
"level": "INFO",
"serviceName": "ORG",
"tranClass": "com.congee.org.controller.TestLogController",
"processStep": "Finish",
"status": "SS",
"elapsedTime": "5005ms",
"msg": "=========当前接口入参不需要加密，直接请求===========",
"thread": "http-nio-8084-exec-1",
"logger": "com.congee.org.common.advice.CustomResponseBodyAdvice"
}
1.2 日志字段定义
package com.congee.cimd.commons.constants;
/**
* @author congee
* @date 2023/6/13 15:26
* @description
*/
public interface MdcConstants {
/** 由接收外部请求或主动发起交易的第一个服务或交易生成 */
String TRACE_ID = "traceId";
/** 交易为交易量统计中的最小单位，也可以使用唯一的交易编号。 每笔交易的首记录和尾记录必须为‘-- */
String TRAN_ID = "tranId";
/** 服务名称 */
String SERVICE_NAME = "serviceName";
/** 交易分类 */
String TRAN_CLASS = "tranClass";
/** 填写交易码，调用方法等可识别单支交易的信息 */
String TRAN_CODE = "tranCode";
/** 执行阶段： 交易开始填写Start 交易结束填写Finish 交易途中可自主填写 */
String PROCESS_STEP = "processStep";
/** 交易耗时，单位:毫秒。Start阶段耗时为0，Finish阶段耗时为整个交易的耗时，其余阶段为每阶段的耗时 */
String ELAPSED_TIME = "elapsedTime";
/** 交易结束时描述请求处理的结果 SS - 成功 FF - 失败 TT - 超时/未明 交易途中可自主填写 */
String STATUS = "status";
String STRING_DEFAULT_VALUE = "--";
Integer INTEGER_DEFAULT_VALUE = 0;
}
1.3 部分重点字段含义
traceId：用于标识某一次具体的请求ID。当用户的请求进入系统后，会在RPC调用网络的第一层生成一个全局唯一的traceId，并且会随着每一层的RPC调用，不断往后传递，这样的话通过traceId就可以把一次用户请求在系统中调用的路径串联起来。
tranId：用于标识某一次RPC调用在分布式请求中的位置。请求到达每个服务后，服务都会为请求生成spanId。
2、logback.xml文件
<?xml version="1.0" encoding="UTF-8"?>
<configuration scan="true" scanPeriod="10 seconds">
<contextName>logback</contextName>
<property name="logPath" value="/congee/log/gors/"/>
<!--开发过程中打印到控制台的日志-->
<appender name="CONSOLE" class="ch.qos.logback.core.ConsoleAppender">
<target>System.out</target>
<filter class="ch.qos.logback.classic.filter.ThresholdFilter">
<level>debug</level>
</filter>
<encoder>
<pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} [%thread] %-5level %logger{50} - %msg%n</pattern>
<charset>UTF-8</charset>
</encoder>
</appender>
<!--info级别日志-->
<appender name="INFO_FILE" class="ch.qos.logback.core.rolling.RollingFileAppender">
<encoder>
<pattern>
<pattern>
{
"txnDateTime": "%date{yyyy-MM-dd HH:mm:ss.SSS}",
"traceId": "%X{traceId}",
"tranId": "%X{tranId}",
"tranCode": "%X{tranCode}",
"level": "%level",
"serviceName": "%X{serviceName}",
"tranClass": "%X{tranClass}",
"processStep": "%X{processStep}",
"status": "%X{status}",
"elapsedTime": "%X{elapsedTime}ms",
"msg": "%message",
"thread": "%thread",
"logger": "%logger{64}"
}
</pattern>
</pattern>
<charset>UTF-8</charset>
</encoder>
<rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
<fileNamePattern>${logPath}/log-info-%d{yyyy-MM-dd}.%i.log</fileNamePattern>
<timeBasedFileNamingAndTriggeringPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedFNATP">
<maxFileSize>2MB</maxFileSize>
</timeBasedFileNamingAndTriggeringPolicy>
<maxHistory>60</maxHistory>
</rollingPolicy>
<filter class="ch.qos.logback.classic.filter.LevelFilter">
<level>INFO</level>
<onMatch>ACCEPT</onMatch>
<onMismatch>DENY</onMismatch>
</filter>
</appender>
<!--应用日志：warn日志，只记录warn级别日志-->
<appender name="WARNING_FILE" class="ch.qos.logback.core.rolling.RollingFileAppender">
<encoder>
<pattern>
<pattern>
{
"txnDateTime": "%date{yyyy-MM-dd HH:mm:ss.SSS}",
"traceId": "%X{traceId}",
"tranId": "%X{traceId}",
"level": "%level",
"msg": "%message",
"thread": "%thread",
"logger": "%logger{64}"
}
</pattern>
</pattern>
<charset>UTF-8</charset>
</encoder>
<rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
<fileNamePattern>${logPath}/log-warning-%d{yyyy-MM-dd}.%i.log</fileNamePattern>
<timeBasedFileNamingAndTriggeringPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedFNATP">
<maxFileSize>2MB</maxFileSize>
</timeBasedFileNamingAndTriggeringPolicy>
<maxHistory>30</maxHistory>
</rollingPolicy>
<filter class="ch.qos.logback.classic.filter.LevelFilter">
<level>WARN</level>
<onMatch>ACCEPT</onMatch>
<onMismatch>DENY</onMismatch>
</filter>
</appender>
<appender name="ERROR_FILE" class="ch.qos.logback.core.rolling.RollingFileAppender">
<encoder>
<pattern>
<pattern>
{
"txnDateTime": "%date{yyyy-MM-dd HH:mm:ss.SSS}",
"traceId": "%X{traceId}",
"tranId": "%X{traceId}",
"level": "%level",
"msg": "%message",
"thread": "%thread",
"logger": "%logger{64}",
"statck_trace":"%exception{5}"
}
</pattern>
</pattern>
<charset>UTF-8</charset>
</encoder>
<rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
<fileNamePattern>${logPath}/log-error-%d{yyyy-MM-dd}.%i.log</fileNamePattern>
<timeBasedFileNamingAndTriggeringPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedFNATP">
<maxFileSize>100MB</maxFileSize>
</timeBasedFileNamingAndTriggeringPolicy>
<maxHistory>30</maxHistory>
</rollingPolicy>
<filter class="ch.qos.logback.classic.filter.ThresholdFilter">
<level>ERROR</level>
</filter>
</appender>
<!-- sql日志打印-->
<logger name="com.congee.org.mapper" level="DEBUG"/>
<!--开发环境:打印控制台-->
<springProfile name="dev">
<logger name="com.congee.org" level="info"/>
</springProfile>
<root level="info">
<appender-ref ref="CONSOLE"/>
<appender-ref ref="INFO_FILE"/>
<appender-ref ref="WARNING_FILE"/>
<appender-ref ref="ERROR_FILE"/>
</root>
</configuration>
日志配置文件中的%X{}占位符就是从MDC中拿到的数据；
日志配置文件生效顺序：logback.xml——>application.yml——>logback-spring.yml
3、MDC
MDC：（Mapped Diagnostic Context）映射诊断环境，是 log4j 和 logback 提供的一种方便在线多线程条件下记录日志的功能，可以看成是一个与当前线程绑定的 ThreadLocal，一个与当前线程绑定的哈希表，可以往其中添加键值对。
// 所在包：org.slf4j.MDC
// 常用操作
MDC.put(String key,String val);
MDC.get(String key);
MDC.remove(String key);
MDC.clear();
MDC.getCopyOfContextMap();
MDC.setContextMap(Map<String,String> contextMap);
MDC 中包含的内容可以被同一线程中执行的代码所访问。当前线程的子线程会继承其父线程中的 MDC 的内容。当需要记录日志时，只需要从 MDC 中获取所需的信息即可。
MDC 的内容则由程序在适当的时候保存进去。对于一个 Web 应用来说，通常是在请求被处理的最开始保存这些数据。
下面来看一个请求url到达后端所经过的处理：
用户发起请求----SpringMVC----—Spring-----—MyBatis–------mysql数据库
消息从浏览器发送到后端，请求会先到达Tomcat服务器；
将请求划分成动态、静态资源；然后处理动态资源；
动态的资源经过Filter过滤器；
过滤器放行后，中央控制器会根据访问分发到controller中；
controller操作执行完后，返回数据给浏览器；
如果想让每个controller被访问之前和后做一件事---- 拦截器；
尝试在过滤器（Filter）中进行处理，但是在拦截器里会做一些认证拦截的操作，也有日志打印的信息，这些与核心的业务处理之间的关联性不大。所以选择在AOP里进行操作。
4、AOP
关于AOP这部分内容在 Spring Boot利用AOP切面实现接口监控 这篇博客中有提到。
4.1 MDC通用方法
import cn.hutool.core.lang.UUID;
import cn.hutool.core.util.RandomUtil;
import com.congee.cimd.commons.constants.EConst;
import com.congee.cimd.commons.constants.MdcConstants;
import com.congee.cimd.tool.threadlocal.MyThreadLocal;
import com.congee.cimd.tool.threadlocal.ZkHttpContext;
import lombok.extern.slf4j.Slf4j;
import org.apache.commons.lang3.StringUtils;
import org.slf4j.MDC;
import javax.servlet.http.HttpServletRequest;
import java.time.LocalDateTime;
import java.time.format.DateTimeFormatter;
/**
* @author congee
* @date 2023/6/13 17:13
* @description
*/
@Slf4j
public abstract class MdcBaseUtil {
/**
* 初始化MDC中的值<br>
* 考虑异步请求、线程池、跨服务调用的情况<br>
* 跨服务调用，值从头部拿<br>
* 异步请求，在线程中拷贝再run
*
* @param req
*/
public void initMdcMap(HttpServletRequest req) {
String ptranceId = MDC.get(MdcConstants.TRACE_ID);
String tranceIdFromOtherService = req.getHeader(MdcConstants.TRACE_ID);
if (StringUtils.isBlank(ptranceId) && StringUtils.isBlank(tranceIdFromOtherService)) {
// 没有父线程，且不是被其他服务调用
// 生成traceId：标识某一次具体的请求ID
MDC.put(MdcConstants.TRACE_ID, generateTraceId(req, getSourceService()));
MDC.put(MdcConstants.TRAN_ID, MdcConstants.STRING_DEFAULT_VALUE);
} else {
// 当前是子线程
// or当前是被其它服务调用
String finalTranceId =
StringUtils.isNotBlank(ptranceId) ? ptranceId : tranceIdFromOtherService;
String finalTranId =
StringUtils.isNotBlank(ptranceId)
? UUID.fastUUID().toString()
: MdcConstants.STRING_DEFAULT_VALUE;
MDC.put(MdcConstants.TRACE_ID, finalTranceId);
MDC.put(MdcConstants.TRAN_ID, finalTranId);
}
ZkHttpContext context = new ZkHttpContext();
context.setTraceId(MDC.get(MdcConstants.TRACE_ID));
MyThreadLocal.set(context);
// 异步方法会开启一个新线程，想要异步线程和主线程共用一个traceId，可以进行拷贝+使用装饰器模式
// 设定日志必填项默认值以及初始化值
MDC.put(MdcConstants.SERVICE_NAME, getSourceService());
MDC.put(MdcConstants.TRAN_CLASS, MdcConstants.STRING_DEFAULT_VALUE);
MDC.put(MdcConstants.TRAN_CODE, MdcConstants.STRING_DEFAULT_VALUE);
MDC.put(MdcConstants.PROCESS_STEP, "Start");
MDC.put(MdcConstants.STATUS, MdcConstants.STRING_DEFAULT_VALUE);
MDC.put(MdcConstants.ELAPSED_TIME, String.valueOf(MdcConstants.INTEGER_DEFAULT_VALUE));
}
/**
* 获取当前所在服务，在具体使用时要进行实现，用类来继承这个抽象类
*
* @return
*/
public abstract String getSourceService();
/**
* 生成交易码<br>
* 交易来源（3-7位）+交易请求+交易时间（9位，到毫秒）+随机数（4位）
*
* @param req
* @param sourceService 交易来源（3-7位）
* @return
*/
private String generateTraceId(HttpServletRequest req, String sourceService) {
StringBuilder traceId = new StringBuilder();
String path = req.getServletPath();
String currTime = LocalDateTime.now().format(DateTimeFormatter.ofPattern(EConst.TIMESTAMP));
Integer randomInt = RandomUtil.randomInt(1000, 10000);
traceId.append(sourceService).append(path).append(currTime).append(randomInt);
return traceId.toString();
}
}
说明：
import com.congee.cimd.commons.constants.EConst;【自定义的常量】
import com.congee.cimd.commons.constants.MdcConstants;【上面1.2节中的定义】
import com.congee.cimd.tool.threadlocal.MyThreadLocal;【线程，根据ThreadLocal编写的自定义使用模版】
public class MyThreadLocal {
private MyThreadLocal(){
}
/**
* 存储本地变量
*/
private static final ThreadLocal<ZkHttpContext> LOCAL = new ThreadLocal<ZkHttpContext>();
public static void set(ZkHttpContext context){
LOCAL.set(context);
}
/**
* ZkHttpContext
* @return
*/
public static ZkHttpContext get(){
return LOCAL.get();
}
/**
* remove
*/
public static void remove(){
LOCAL.remove();
}
}
import com.congee.cimd.tool.threadlocal.ZkHttpContext;
@Data
public class ZkHttpContext {
private String userId;
private String userName;
private String tenantId;
private Integer userType;
private String token;
private String currentMode;
private String traceId;
}
4.2 在AOP切面进行日志内容赋值
import com.congee.cimd.commons.constants.MdcConstants;
import com.congee.org.aop.async.ApiMonitorUtil;
import com.congee.org.common.tool.MdcUtil;
import com.google.common.collect.ImmutableMap;
import lombok.extern.slf4j.Slf4j;
import org.aspectj.lang.JoinPoint;
import org.aspectj.lang.annotation.AfterReturning;
import org.aspectj.lang.annotation.AfterThrowing;
import org.aspectj.lang.annotation.Aspect;
import org.aspectj.lang.annotation.Before;
import org.aspectj.lang.annotation.Pointcut;
import org.slf4j.MDC;
import org.springframework.beans.factory.annotation.Autowired;
import org.springframework.stereotype.Component;
import org.springframework.web.context.request.RequestContextHolder;
import org.springframework.web.context.request.ServletRequestAttributes;
import javax.annotation.Resource;
import javax.servlet.http.HttpServletRequest;
import java.util.Map;
/**
* @author huiyun zhou
* @date 2023/3/28 09:50
* @description 接口监控
*/
@Slf4j
@Aspect
@Component
public class ApiMonitorAdvice {
@Autowired private ApiMonitorUtil apiMonitorUtil;
@Resource private MdcUtil mdcUtil;
ThreadLocal<Long> startTime = new ThreadLocal<>();
ThreadLocal<Map<String, String>> requestThreadLocal = new ThreadLocal<>();
/** 定义切面 */
@Pointcut(
"execution(* com.congee.org.controller..*.*(..)) || execution(* com.congee.org.controller3rd..*.*(..)) ")
public void pointCut() {}
@Before("pointCut()")
public void doBefore(JoinPoint joinPoint) throws Throwable {
startTime.set(System.currentTimeMillis());
HttpServletRequest request =
((ServletRequestAttributes) RequestContextHolder.getRequestAttributes()).getRequest();
requestThreadLocal.set(
ImmutableMap.of("servletPath", request.getServletPath(), "method", request.getMethod()));
// 日志改造相关内容
// 初始化MDC
mdcUtil.initMdcMap(request);
// 请求的方法名
String className = joinPoint.getTarget().getClass().getName();
String methodName = joinPoint.getSignature().getName();
MDC.put(MdcConstants.TRAN_CLASS, className);
MDC.put(MdcConstants.TRAN_CODE, methodName);
log.info("params:[{}]", joinPoint.getArgs());
}
/** 只有正常返回才会执行此方法 */
@AfterReturning(returning = "returnVal", pointcut = "pointCut()")
public void doAfterReturning(JoinPoint joinPoint, Object returnVal) {
long reqTime = System.currentTimeMillis() - startTime.get();
apiMonitorUtil.updateResTime(reqTime, requestThreadLocal.get());
// 日志改造相关内容
MDC.put(MdcConstants.TRAN_ID, MdcConstants.STRING_DEFAULT_VALUE);
MDC.put(MdcConstants.PROCESS_STEP, "Finish");
MDC.put(MdcConstants.ELAPSED_TIME, String.valueOf(reqTime));
MDC.put(MdcConstants.STATUS, "SS");
}
@AfterThrowing(pointcut = "pointCut()")
public void doAfterThrowing(JoinPoint joinPoint) {
long reqTime = System.currentTimeMillis() - startTime.get();
apiMonitorUtil.updateResTime(reqTime, requestThreadLocal.get());
// 日志改造相关内容
MDC.put(MdcConstants.TRAN_ID, MdcConstants.STRING_DEFAULT_VALUE);
MDC.put(MdcConstants.PROCESS_STEP, "Finish");
MDC.put(MdcConstants.ELAPSED_TIME, String.valueOf(reqTime));
MDC.put(MdcConstants.STATUS, "FF");
}
}
5、问题记录及解决方案
问题1：异步线程，线程池，定时任务无法打印
MDC在异步线程中不生效；因为MDC底层采用ThreadLocal 作为数据结构，我们调用MDC.put()方法传入的请求ID只在当前线程有效。
使用上面的方式（doFilter、AOP切面中设定MDC的值），发现异步线程，线程池，定时任务都无法打印，定时任务不说，没有这些参数，但是其他应该可以打印。
解决方法：
在创建MDCRunnable类时保存当前线程的MDC值，在执行run()方法时再将保存的MDC值拷贝到异步线程中去+装饰器模式
首先先新建一个任务适配器MdcTaskDecorator。
@Slf4j
public class MdcTaskDecorator implements TaskDecorator {
@Override
public Runnable decorate(Runnable runnable) {
// Right now: Web thread context !
// (Grab the current thread MDC data)
Map<String, String> contextMap = MDC.getCopyOfContextMap(); // 处理日志上下文传值
ZkHttpContext context =
MyThreadLocal.get(); // 处理父子线程上下文传值，解决feign跨服务调用时，A端的traceId信息没有传到B端这类问题
return () -> {
try {
// Right now: @Async thread context !
// (Restore the Web thread context's MDC data) when schedule use async,contextMap is null
if (contextMap != null && !contextMap.isEmpty()) {
MDC.setContextMap(contextMap);
MyThreadLocal.set(context);
}
runnable.run();
} catch (Exception e) {
throw e;
} finally {
MDC.clear();
MyThreadLocal.remove();
}
};
}
}
在线程池配置中增加executor.setTaskDecorator(new MdcTaskDecorator())的设置
@EnableAsync
@Configuration
public class ThreadPoolConfig {
private int corePoolSize = Runtime.getRuntime().availableProcessors() + 1;
private int maxPoolSize = corePoolSize * 2;
private static final int queueCapacity = 50;
private static final int keepAliveSeconds = 30;
@Bean(name = "threadPoolTaskExecutor")
public ThreadPoolTaskExecutor threadPoolTaskExecutor() {
ThreadPoolTaskExecutor executor = new ThreadPoolTaskExecutor();
executor.setMaxPoolSize(maxPoolSize);
executor.setCorePoolSize(corePoolSize);
executor.setQueueCapacity(queueCapacity);
executor.setKeepAliveSeconds(keepAliveSeconds);
executor.setTaskDecorator(new MdcTaskDecorator());
executor.setRejectedExecutionHandler(new ThreadPoolExecutor.CallerRunsPolicy());
return executor;
}
即可解决问题
问题2：跨服务之间如何传递 traceId
因为这边使用的是 FeignClient 进行服务之间的调用，只需要新增请求拦截器即可；再考虑到跨服务之间的数据传递，考虑在头部信息里进行传递
@Configuration
public class FeignInterceptor implements RequestInterceptor {
private static final String TRACE_ID = "traceId";
@Override
public void apply(RequestTemplate requestTemplate) {
requestTemplate.header(TRACE_ID, MDC.get(TRACE_ID));
}
}
最终可以实现在A端的请求，所生成的traceId，在调用B端的接口时，B的被调用接口的日志输出中traceId的值和A端是一致的；且如果A端调用B端接口时，是一个异步的方法，B端同样可以拿到这个traceId值。
1153
被折叠的 条评论
为什么被折叠?
到【灌水乐园】发言
