目录
- 1. 概述
- 1.1. 需求
- 1.2. 思路
- 2. 功能实现
- 2.1 依赖选取
- 2.2 编写logBack.xml
- 2.3 日志拦截
- 2.4 封装请求为HttpServletRequestWrapper
- 2.5 AOP
- 2.6 日志监听
- 3. 后记
1. 概述
1.1. 需求
背景：拆分支付系统的日志，把每笔单子的日志单独拎出来存库。每笔单子会有多次前后端交互，以及多次后端与第三方的交互，我们需要把这笔单子的所有交互流程从日志中提炼出来，合到一块儿，然后存库。
需求：把单笔单子的明细展示、费用预结算、状态查询、回调通知的日志都提炼出来存库。
1.2. 思路
- 线程区分：因为前端会同时存在多次不同请求到后端（并发情况），所以要给日志打印中加上一个ThreadName来区分不同的线程；
- 请求区分：要区分不同的请求，需要给不同请求都单独配置一个特定的requestId；
- 固定requestId：因为一笔订单会有多个流程也就是多次请求，要保证每次请求的requestId都相同，为了不改库表结构，可以将requestId存入redis缓存，其key值可以取：固定前缀+订单号。因此，每次前端的请求都要传订单号作为参数；
- 内存暂存日志：使用
currentHashMap暂时将日志写入内存，方便后续取出对应日志，并存表； - 编写一个
logBack.xml，要支持AppenderBase的日志监听； - 编写一个拦截器：拦截请求，给每次请求都初始化requestId;
- 编写一个aop：打印方法调用的入参、返参以及其他自定义日志；
- 编写一个日志监听器：监听日志打印，从而截取拼接需要的日志。
2. 功能实现
2.1 依赖选取
我选择使用lombok搭配slf4j来打印日志，依赖如下：
<dependency>
<groupId>org.projectlombok</groupId>
<artifactId>lombok</artifactId>
<optional>true</optional>
</dependency>
其他依赖：
Json操作
<dependency>
<groupId>com.alibaba.fastjson2</groupId>
<artifactId>fastjson2</artifactId>
<version>2.0.45</version>
</dependency>
Springbootweb：
<dependency>
<groupId>org.springframework.boot</groupId>
<artifactId>spring-boot-starter-web</artifactId>
</dependency>
2.2 编写logBack.xml
注意：
- 为了保证跨平台的一致性，建议使用 logback.xml 作为 Logback 的配置文件名。这样做可以避免在不同操作系统或不同环境中出现文件名识别的问题。
- 将 logback.xml 存放在 src/main/resources 目录下是一种标准且推荐的做法，这样可以确保 Logback 能够正确加载配置文件，并使项目结构更加清晰和一致。
案例：
<configuration>
<!-- 定义日志文件的存储路径 -->
<property name="LOG_PATH" value="./logs"/>
<!-- 定义日志文件的最大大小和保留时间 -->
<property name="MAX_FILE_SIZE" value="10MB"/>
<property name="MAX_HISTORY" value="30"/>
<property name="TOTAL_SIZE_CAP" value="3GB"/>
<!-- 彩色日志渲染 -->
<appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
<encoder class="ch.qos.logback.classic.encoder.PatternLayoutEncoder">
<pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} [%highlight(%X{requestId})] [%highlight(%thread)] %-5level %logger{50} - %msg%n</pattern>
<charset>UTF-8</charset>
</encoder>
</appender>
<!-- 滚动文件日志渲染 -->
<appender name="FILE" class="ch.qos.logback.core.rolling.RollingFileAppender">
<!-- 日志文件存储位置 -->
<file>${LOG_PATH}/myPay.log</file>
<!-- 定义滚动策略 -->
<rollingPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedRollingPolicy">
<!-- 按时间和大小滚动日志文件，输出文件名包括日期和索引 -->
<fileNamePattern>${LOG_PATH}/myPay.%d{yyyy-MM-dd}.%i.log</fileNamePattern>
<maxFileSize>${MAX_FILE_SIZE}</maxFileSize>
<maxHistory>${MAX_HISTORY}</maxHistory>
<totalSizeCap>${TOTAL_SIZE_CAP}</totalSizeCap>
</rollingPolicy>
<encoder class="ch.qos.logback.classic.encoder.PatternLayoutEncoder">
<pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} [%X{requestId}] [%thread] %-5level %logger{50} - %msg%n</pattern>
<charset>UTF-8</charset>
</encoder>
</appender>
<!-- 根Logger配置 -->
<root level="INFO">
<appender-ref ref="STDOUT"/>
<appender-ref ref="FILE"/>
</root>
<!-- 添加对 LoggingEventListener 的支持 -->
<appender name="CUSTOM_LISTENER" class="com.yourpackage.LoggingEventListener"/>
<logger name="ROOT" level="INFO" additivity="false">
<appender-ref ref="CUSTOM_LISTENER"/>
</logger>
</configuration>
说明：
%thread：Logback 的一个内置转换词，它会自动获取当前执行日志记录时的线程名。你不需要在代码中额外配置任何东西，SLF4J 会通过 Logback 自动捕获并记录线程名。%X{}：Logback 日志配置中的一个占位符，用于在日志输出时插入一个来自 Mapped Diagnostic Context (MDC) 的值。注意：MDC（Mapped Diagnostic Context）是 SLF4J 和 Logback 提供的一种机制，用于在日志记录中添加和管理上下文信息。线程私有的数据。
appender：负责将日志事件写入特定目标或介质的组件。每个 appender 可以配置为将日志发送到不同的输出位置，比如控制台、文件、数据库、远程服务器等。注意：只要在 logback.xml 中正确配置了
appender标签，并将自定义的AppenderBase实现（如 LoggingEventListener）配置为一个 appender，我们就可以使用 AppenderBase 的append方法来处理和监听日志事件。
按照上面的logback.xml配置，我的日志输出会长下面这样：
2024-08-14 12:34:56.789 [requestId] [thread] INFO com.mypackage.ClassName - This is a log message
2.3 日志拦截
拦截器实现：
import com.alibaba.fastjson.JSONObject;
import lombok.extern.slf4j.Slf4j;
import org.slf4j.MDC;
import org.springframework.stereotype.Component;
import org.springframework.web.servlet.handler.HandlerInterceptorAdapter;
import javax.servlet.http.HttpServletRequest;
import javax.servlet.http.HttpServletResponse;
import java.io.BufferedReader;
import java.io.IOException;
import java.util.UUID;
// 自定义个key值固定前缀
import static xxx.IConst.KEY_PRE;
// 自定义的日志节点常量接口
import xxx.PMCLogNode;
// 自定义的redis工具类
import xxx.RedisClient;
/**
* Description: 日志拦截器
*/
@Slf4j
@Component
public class LogInterceptor extends HandlerInterceptorAdapter {
@Override
public boolean preHandle(HttpServletRequest request, HttpServletResponse response, Object handler) {
String requestId;
/*
每笔订单的第一个流程都是一样的，都是调用这个接口，
所以在调用这个接口的时候给日志生成一个requestId，并存入MDC
然后获取该日志的订单号medOrgOrd，拼接成redis的key
然后将requestId存入缓存，再将requestId存入MDC
*/
if (PMCLogNode.START.equals(request.getRequestURI())) {
requestId = String.valueOf(UUID.randomUUID());
String medOrgOrd = getMedOrgOrd(request);
RedisClient.setString(KEY_PRE + medOrgOrd, requestId, 2 * 60 * 60);
} else {
/*
非初始请求，改从缓存获取requestId
*/
String medOrgOrd = getMedOrgOrd(request);
requestId = RedisClient.getString(KEY_PRE + medOrgOrd);
}
MDC.put("requestId", requestId);
log.info("请求路径为==>{}", request.getRequestURI());
return true;
}
/*
获取请求参数中的订单号medOrgOrd的方法
*/
private String getMedOrgOrd(HttpServletRequest request) {
BufferedReader reader = null;
try {
reader = request.getReader();
} catch (IOException e) {
throw new RuntimeException(e);
}
StringBuilder jsonBuilder = new StringBuilder();
String line;
while (true) {
try {
if ((line = reader.readLine()) == null) break;
} catch (IOException e) {
throw new RuntimeException(e);
}
jsonBuilder.append(line);
}
String json = jsonBuilder.toString();
JSONObject jsonObject = JSONObject.parseObject(json);
return jsonObject.getString("medOrgOrd");
}
}
注册拦截器：
import org.springframework.beans.factory.annotation.Autowired;
import org.springframework.context.annotation.Configuration;
import org.springframework.web.servlet.config.annotation.InterceptorRegistry;
import org.springframework.web.servlet.config.annotation.WebMvcConfigurer;
@Configuration
public class WebMvcConfig implements WebMvcConfigurer {
@Autowired
private LogInterceptor logInterceptor;
@Override
public void addInterceptors(InterceptorRegistry registry) {
// 注册 LogInterceptor，并拦截所有请求路径
registry.addInterceptor(logInterceptor).addPathPatterns("/**");
}
}
2.4 封装请求为HttpServletRequestWrapper
虽然我上面的拦截器里面只调用了request.getRequestURI()获取请求url，并没去使用request.getInputStream()、request.getReader()，按理说我后续还是可以通过@RequestBody等注解来接收参数的，但经过测试，后续还是会报错：java.lang.IllegalStateException: getReader() has already been called for this request。
因此，为了以防万一，还是写个filter将HttpServletRequest封装为HttpServletRequestWrapper，这样就可以多次调用request.getInputStream()、request.getReader()了。
-
CustomHttpServletRequestWrapper继承HttpServletRequestWrapper，并覆盖一些必要的方法。
import javax.servlet.http.HttpServletRequest; import javax.servlet.http.HttpServletRequestWrapper; import java.io.ByteArrayInputStream; import java.io.IOException; import java.io.InputStream; public class CustomHttpServletRequestWrapper extends HttpServletRequestWrapper { // 对比String类型，byte[]更通用，适合处理任何类型的数据，特别是非文本数据。 private byte[] body; public CustomHttpServletRequestWrapper(HttpServletRequest request) throws IOException { super(request); this.body = request.getInputStream().readAllBytes(); // 读取请求体为字节数组 } @Override public InputStream getInputStream() throws IOException { return new ByteArrayInputStream(body); } @Override public BufferedReader getReader() throws IOException { return new BufferedReader(new InputStreamReader(getInputStream(), this.getCharacterEncoding())); } public byte[] getBody() { return this.body; } } -
过滤器，拦截所有请求，将HttpServletRequest封装为HttpServletRequestWrapper。
import XXX.CustomHttpServletRequestWrapper; import lombok.SneakyThrows; import lombok.extern.slf4j.Slf4j; import javax.servlet.*; import javax.servlet.annotation.WebFilter; import javax.servlet.http.HttpServletRequest; /** * description： */ @WebFilter(filterName = "requestFilter", urlPatterns = {"/*"}) @Slf4j public class RequestFilter implements Filter { @Override public void init(FilterConfig filterConfig) { } @Override @SneakyThrows public void doFilter(ServletRequest request, ServletResponse response, FilterChain chain) { ServletRequest requestWrapper = null; if (request instanceof HttpServletRequest) { requestWrapper = new CustomHttpServletRequestWrapper((HttpServletRequest) request); } if (requestWrapper == null) { chain.doFilter(request, response); } else { chain.doFilter(requestWrapper, response); } } @Override public void destroy() { } }@SneakyThrows的作用：Lombok 提供的一个注解，用于简化异常处理。它可以让你在方法中抛出受检异常（checked exception），而无需显式地使用 try-catch 块或者在方法签名中声明 throws。
2.5 AOP
import com.alibaba.fastjson.JSONException;
import com.alibaba.fastjson.JSONObject;
import lombok.extern.slf4j.Slf4j;
import org.aspectj.lang.ProceedingJoinPoint;
import org.aspectj.lang.annotation.Around;
import org.aspectj.lang.annotation.Aspect;
import org.aspectj.lang.annotation.Pointcut;
import org.slf4j.MDC;
import org.springframework.context.annotation.Configuration;
import org.springframework.web.multipart.MultipartFile;
import javax.servlet.ServletRequest;
import javax.servlet.ServletResponse;
import java.util.UUID;
// 自定义的 resultBean
import XXX.ResultBean;
/**
* description：日志生成idAop
*
* @author Li Jianqiao
* @since 2020/11/2 9:13
*/
@Aspect
@Configuration
@Slf4j
public class LogAop {
/**
* 定义切点Pointcut
* 第一个*号：表示返回类型， *号表示所有的类型
* 第二个*号：表示类名，*号表示所有的类
* 第三个*号：表示方法名，*号表示所有的方法
* 后面括弧里面表示方法的参数，两个句点表示任何参数
*/
@Pointcut("execution(* com.mypackage..*(..)) " +
"|| execution(* otherpackage.*.*(..)))
public void executionService() {
// 记录日志方法切点
}
@Around("executionService()")
public Object doAround(ProceedingJoinPoint proceedingJoinPoint) throws Throwable {
Object[] args = proceedingJoinPoint.getArgs();
log.info("====>@Before：请求方法为：[{}.{}]", proceedingJoinPoint.getSignature().getDeclaringTypeName(), proceedingJoinPoint.getSignature().getName());
log.info("====>@Before：请求参数：");
for (Object arg : args) {
if (arg instanceof ServletRequest || arg instanceof ServletResponse || arg instanceof MultipartFile) {
//ServletRequest不能序列化，从入参里排除，否则报异常：java.lang.IllegalStateException: It is illegal to call this method if the current request is not in asynchronous mode (i.e. isAsyncStarted() returns false)
//ServletResponse不能序列化 从入参里排除，否则报异常：java.lang.IllegalStateException: getOutputStream() has already been called for this response
continue;
}
try {
log.info("==>{}", JSONObject.toJSONString(arg));
} catch (JSONException e) {
log.info("==>{}", arg);
}
}
// 开始计时
long begin = System.currentTimeMillis();
// 执行方法
Object result = proceedingJoinPoint.proceed();
// 结束计时
long end = System.currentTimeMillis();
// 耗时
long spendTime = end - begin;
String resultStr = "";
if (result instanceof ResultBean) {
resultStr = ((ResultBean<?>) result).toStringJSON();
} else {
resultStr = JSONObject.toJSONString(result);
}
log.info("<====@After：方法[{}]耗时：{} ms", proceedingJoinPoint.getSignature().getName(), spendTime);
log.info("<====@After：响应参数:");
log.info("<=={}", resultStr);
return result;
}
}
2.6 日志监听
import ch.qos.logback.classic.spi.ILoggingEvent;
import ch.qos.logback.core.AppenderBase;
import lombok.extern.slf4j.Slf4j;
import org.springframework.stereotype.Component;
import javax.annotation.PostConstruct;
import javax.annotation.Resource;
import java.time.LocalDateTime;
import java.util.HashMap;
import java.util.List;
import java.util.Map;
import java.util.Objects;
import java.util.concurrent.*;
import java.util.regex.Matcher;
import java.util.regex.Pattern;
// 节点
import XXX.PMCLogNode;
// 用来存日志的表的dto
import XXX.entity.PaymentLog;
// 日志记录表的service
import XXX.PaymentLogService;
/**
* @desc
*/
@Slf4j
@Component
public class LoggingEventListener extends AppenderBase<ILoggingEvent> {
// 初始化一个线程池
private final ScheduledExecutorService executorService = Executors.newScheduledThreadPool(100);
// 采用 ConcurrentHashMap（线程安全） 来存储日志到内存，以便后续读取
private static final ConcurrentMap<String, StringBuilder> logRecord = new ConcurrentHashMap<>();
@Resource
private PaymentLogService paymentLogService;
private static final Map<String, Integer> pmcLogNodes = new HashMap<>();
// 不同的日志节点，执行时间可能不同，因此要使用不同的等待时间
static {
pmcLogNodes.put(PMCLogNode.GETPAYURL, 1);
pmcLogNodes.put(PMCLogNode.GETMEDICALCONTENTA, 3);
pmcLogNodes.put(PMCLogNode.GETFRONTCONFIG, 1);
pmcLogNodes.put(PMCLogNode.AUTHQUERY, 15);
pmcLogNodes.put(PMCLogNode.UNIFIEDORDER, 15);
pmcLogNodes.put(PMCLogNode.TOPAY, 15);
pmcLogNodes.put(PMCLogNode.QUERYNOTIFYSTATUS, 20);
pmcLogNodes.put(PMCLogNode.NOTIFY, 30);
}
@PostConstruct
public void init() {
((ch.qos.logback.classic.Logger) org.slf4j.LoggerFactory.getLogger("ROOT"))
.addAppender(this);
start();
}
@Override
protected void append(ILoggingEvent eventObject) {
// 获取当前行日志的内容
String message = eventObject.getFormattedMessage();
// 获取线程名
String threadName = eventObject.getThreadName();
// 从MDC获取requestId
String requestId = eventObject.getMDCPropertyMap().get("requestId");
// 用于获取触发日志事件的 Logger 的名称
String loggerName = eventObject.getLoggerName();
String key = requestId + threadName;
logRecord.merge(key, new StringBuilder(loggerName).append("\t -- \t").append(message),
(oldValue, newValue) -> oldValue.append("\n").append(loggerName).append("\t -- \t").append(message));
if (pmcLogNodes.containsKey(message)) {
startLog(threadName, requestId, message);
}
}
private void startLog(String threadName, String requestId, String node) {
Future<?> future = executorService.submit(() -> {
try {
processLogs(threadName, requestId, node);
} catch (Exception ex) {
log.error("处理日志时发生异常: {}", ex.getMessage());
}
});
}
private void processLogs(String threadName, String requestId, String node) {
while (!Thread.currentThread().isInterrupted()) {
// 根据node来判断大概要用多少时间
try {
TimeUnit.SECONDS.sleep(pmcLogNodes.get(node));
String currentKey = requestId + threadName;
String logTxt;
logTxt = Objects.requireNonNull(logRecord.computeIfPresent(currentKey, (k, v) -> {
// 取完数据，就删掉，防止存不下
logRecord.remove(currentKey);
return v;
})).toString();
if (PMCLogNode.GETPAYURL.equals(node)) {
PaymentLog paymentLog = new PaymentLog()
.setLogTxt(logTxt)
.setOutTradeNo(extractValue(logTxt, "medOrgOrd"))
.setAppId(extractValue(logTxt, "appId"))
.setRequestId(requestId)
.setPTime(LocalDateTime.now());
paymentLogService.save(paymentLog);
break;
} else {
List<PaymentLog> paymentLogs = paymentLogService.getPaymentLogsByOutTradeNo(extractValue(logTxt, "medOrgOrd"), requestId);
if (paymentLogs.size() != 1) {
log.error("日志记录异常: 数据库异常");
break;
}
PaymentLog paymentLog = paymentLogs.get(0);
paymentLog.setLogTxt(paymentLog.getLogTxt() + "\n" + logTxt);
paymentLogService.updateById(paymentLog);
break;
}
} catch (InterruptedException e) {
Thread.currentThread().interrupt();
break;
} catch (Exception ex) {
log.error("日志处理过程中发生错误：{}", ex.getMessage());
break;
}
}
}
private static String extractValue(String sb, String key) {
String regex = String.format("\"%s\"\\s*:\\s*\"([^\"]+)\"", key);
Pattern pattern = Pattern.compile(regex);
Matcher matcher = pattern.matcher(sb);
if (matcher.find()) {
return matcher.group(1);
}
return null;
}
public void shutdown() {
executorService.shutdown();
}
}
3. 后记
如果是非外部请求接口打印的日志，会丢失requestId，导致上面的日志监听类无法获取到key，从而存库，这时候就需要在相应的位置根据订单号从缓存获取requestId了，然后MDC.put(“requestId”, requestId)，接着log.info(一个固定的值)，最终在pmcLogNodes.put(一个固定的值, 30);来匹配了。
