SpringBoot最佳实践之 - 项目中统一记录正常和异常日志

1. 前言

此篇博客是本人在实际项目开发工作中的一些总结和感悟。是在特定需求背景下，针对项目中统一记录日志(包括正常和错误日志)需求的实现方式之一，并不是普适的记录日志的解决方案。所以阅读本篇博客的朋友，可以参考此篇博客中记录日志的方式，可能会对你有些许帮助和启发。

2. 需求描述

项目的大背景是：前后端分离项目，后端框架使用SpringBoot+MyBatis，前端使用Vue。前端调用后端API接口时，需要在请求头中传递一个唯一身份标识（为了让服务端知道此次是谁在调用我的接口）。

        在一次完整的调用中，可能会有两种情况：
        （a）调用过程正常，后端给前端返回想要的数据（通过统一返回对象返回数据）；
        （b）调用过程异常，后端抛出异常，并通过全局异常处理类进行异常处理，然后通过统一返回对象返回异常码和异常消息。

现在的需求是：在情况(a)，即一次请求正常完成，需要在日志中记录本次的请求和响应的相关信息。包括：
1）请求身份唯一标识（我需要知道是哪个人访问了我）；

2）请求的接口名（我需要知道你请求的是哪个接口）；

3）请求的参数（我需要知道你此次请求这个接口传递了哪些参数）；

4）请求的时间（我需要知道你此次请求的开始时间）；

5）响应时间（我需要知道此次请求服务端给客户端响应的时间）；

6）请求处理时间（我需要知道此次请求耗费了多少时间）；

7）响应的结果信息（我需要知道此次请求的响应结果是什么）；

8）请求的客户端IP地址（我需要知道此次请求的客户端IP地址）；

9）此次请求是否成功的标识码（如果是成功日志，则标识位是0；失败日志，标识位是1）。

在情况(b)，即此次请求出现异常，也需要在日志中记录本次的请求和响应信息。包括：

1）请求身份唯一标识（我需要知道是哪个人访问了我）；

2）请求的接口名（我需要知道你请求的是哪个接口）；

3）请求的参数（我需要知道你此次请求这个接口传递了哪些参数）；

4）请求的时间（我需要知道你此次请求的开始时间）；

5）响应时间（我需要知道此次请求服务端给客户端响应的时间）；

6）请求处理时间（我需要知道此次请求耗费了多少时间）；

7）响应的异常信息（我需要知道此次请求的响应的异常信息是什么]）；

8）请求的客户端IP地址（我需要知道此次请求的客户端IP地址）；

9）此次请求是否成功的标识码（如果是成功日志，则标识位是0；失败日志，标识位是1）。

总结需求就一句话：正常和异常请求我都需要记录日志，只不过正常请求后记录的是正常返回的结果信息，而异常请求后记录的是出现异常的原因。

3. 代码实现

3.1 logback日志配置

因为要记录日志，在SpringBoot项目中通常是使用SLF4J作为日志门面，Logback作为底层日志框架实现配合进行日志记录。关于logback的配置信息，可以参考我之前写的一篇博客，你也可以直接把这里的配置信息放到SpringBoot项目的resources目录即可。logback-spring.xml文件的一些记录

3.2 需要的组件

实现此需求，需要如下一些功能组件：过滤器、拦截器、存放日志对象的ThreadLocal、统一返回结果对象、统一异常处理、统一响应结果处理器。此处先简单介绍下各个组件在需求中的作用是什么，主要还是靠理解代码实现逻辑。

1）过滤器：因为需要在请求到达Controller之前获取请求体中的请求参数，而 HttpServletReqeust 获取输入流时仅允许读取一次，如果你直接在拦截器里面获取输入流，拿到里面的请求参数，后续处理过程中就会报java.io.IOException: Stream closed。具体可以参考这篇博文：SpringBoot如何在拦截器中获取@RequestBody参数；

2）拦截器：在请求进来的时候，可以在拦截器里面获取一些请求信息，如此次请求的身份唯一标识、接口名、请求参数、请求时间、客户端ip地址。然后创建日志记录对象并把这些信息设置到日志记录对象中；

3）存放日志对象的ThreadLocal：为了把第 2）步中拦截器里面的日志对象放到ThreadLocal里面，便于后续使用；

4）统一返回结果：SpringBoot的最佳实践之一就是定义全局的统一返回对象，便于和前端联调；

5）统一异常处理：SpringBoot的最佳实践之一就是在业务处理过程中，如果某些条件校验没通过，就直接抛出异常，然后由统一异常处理类进行统一处理，如打印异常堆栈信息，记录异常日志、通过统一返回结果对象给前端封装错误信息并返回；

6）统一响应结果处理器：在给前端响应数据之前，可以对要响应的结果进行拦截并做一些事情，此处主要是为了记录一次正常请求过程中的日志信息。

3.2.1 过滤器 (HttpServletRequestFilter)

package com.shg.component;import cn.hutool.extra.servlet.ServletUtil;
import org.springframework.stereotype.Component;import javax.servlet.Filter;
import javax.servlet.FilterChain;
import javax.servlet.FilterConfig;
import javax.servlet.ReadListener;
import javax.servlet.ServletException;
import javax.servlet.ServletInputStream;
import javax.servlet.ServletRequest;
import javax.servlet.ServletResponse;
import javax.servlet.http.HttpServletRequest;
import javax.servlet.http.HttpServletRequestWrapper;
import java.io.BufferedReader;
import java.io.ByteArrayInputStream;
import java.io.IOException;
import java.io.InputStreamReader;
import java.nio.charset.StandardCharsets;/**** HttpServletRequest 过滤器* 解决: request.getInputStream()只能读取一次的问题* 目标: 流可重复读**/
@Component
public class HttpServletRequestFilter implements Filter {@Overridepublic void init(FilterConfig filterConfig) throws ServletException {}@Overridepublic void doFilter(ServletRequest servletRequest, ServletResponse servletResponse, FilterChain filterChain) throws IOException, ServletException {ServletRequest requestWrapper = null;if (servletRequest instanceof HttpServletRequest) {requestWrapper = new RequestWrapper((HttpServletRequest) servletRequest);}//获取请求中的流，将取出来的字符串，再次转换成流，然后把它放入到新 request对象中.在chain.doFiler方法中传递新的request对象if (null == requestWrapper) {filterChain.doFilter(servletRequest, servletResponse);} else {filterChain.doFilter(requestWrapper, servletResponse);}}@Overridepublic void destroy() {}/**** HttpServletRequest 包装器* 解决: request.getInputStream()只能读取一次的问题* 目标: 流可重复读*/public class RequestWrapper extends HttpServletRequestWrapper {/*** 请求体*/private String mBody;public RequestWrapper(HttpServletRequest request) {super(request);// 将body数据存储起来mBody = getBody(request);}/*** 获取请求体** @param request 请求* @return 请求体*/private String getBody(HttpServletRequest request) {return ServletUtil.getBody(request);}/*** 获取请求体** @return 请求体*/public String getBody() {return mBody;}@Overridepublic BufferedReader getReader() throws IOException {return new BufferedReader(new InputStreamReader(getInputStream()));}@Overridepublic ServletInputStream getInputStream() throws IOException {// 创建字节数组输入流final ByteArrayInputStream bais = new ByteArrayInputStream(mBody.getBytes(StandardCharsets.UTF_8));return new ServletInputStream() {@Overridepublic boolean isFinished() {return false;}@Overridepublic boolean isReady() {return false;}@Overridepublic void setReadListener(ReadListener readListener) {}@Overridepublic int read() throws IOException {return bais.read();}};}}
}

3.2.2 拦截器 (RequestGlobalInterceptor)

package com.shg.component;import cn.hutool.core.date.DatePattern;
import cn.hutool.core.date.DateUtil;
import cn.hutool.core.util.StrUtil;
import cn.hutool.json.JSONUtil;
import com.shg.common.ResponseCodeEnum;
import com.shg.exception.BizException;
import com.shg.model.pojo.RecordLog;
import com.shg.utils.LogUtil;
import lombok.extern.slf4j.Slf4j;
import org.springframework.data.redis.core.StringRedisTemplate;
import org.springframework.stereotype.Component;
import org.springframework.web.servlet.HandlerInterceptor;
import org.springframework.web.servlet.ModelAndView;import javax.servlet.http.HttpServletRequest;
import javax.servlet.http.HttpServletResponse;
import java.util.Date;
import java.util.Objects;@Slf4j
@Component
public class RequestGlobalInterceptor implements HandlerInterceptor {private final StringRedisTemplate stringRedisTemplate;public RequestGlobalInterceptor(StringRedisTemplate stringRedisTemplate) {this.stringRedisTemplate = stringRedisTemplate;}@Overridepublic boolean preHandle(HttpServletRequest request, HttpServletResponse response, Object handler) throws Exception {if ("OPTIONS".equals(request.getMethod())) {return true;}if (request.getRequestURI().contains("/swagger-ui.html") ||request.getRequestURI().contains("/webjars/springfox-swagger-ui") ||request.getRequestURI().contains("swagger") ||request.getRequestURI().contains("webjars") ||request.getRequestURI().contains("images") ||request.getRequestURI().contains("api-docs") ||request.getRequestURI().contains("configuration/ui") ||request.getRequestURI().contains("configuration/security")) {return true;}String appId = null;try {appId = request.getHeader("appId");String appSecret = request.getHeader("appSecret");// 校验appId和appSecret是否合法 TODOif(Objects.isNull(appId)){throw new BizException(ResponseCodeEnum.APP_ID_NOT_PASSED);}} finally {// --- 日志相关 ---// 1. 接口名称String requestURI = request.getRequestURI();String interfaceName;if (requestURI.contains("/api/crypto")) {int startIndex = requestURI.indexOf("/api/crypto");interfaceName = requestURI.substring(startIndex + "/api/crypto/".length());} else {interfaceName = requestURI;}// 2. 请求参数String requestParameter = "";if (request instanceof HttpServletRequestFilter.RequestWrapper) {HttpServletRequestFilter.RequestWrapper repeatedlyRequest = ((HttpServletRequestFilter.RequestWrapper) request);requestParameter = StrUtil.removeAny(StrUtil.removeAllLineBreaks(repeatedlyRequest.getBody()), " ");//log.info("body参数： " + requestParameter);}if (StrUtil.isEmpty(requestParameter)) {requestParameter = JSONUtil.toJsonStr(request.getParameterMap());//log.info("查询字符串参数： " + requestParameter);}// 创建日志对象RecordLog recordLog = new RecordLog();recordLog.setAppId(appId);recordLog.setInterfaceName(interfaceName);recordLog.setArguments(requestParameter);recordLog.setRequestTime(DateUtil.format(new Date(), DatePattern.NORM_DATETIME_MS_PATTERN));recordLog.setServerIp(request.getRemoteAddr());// 把日志对象放到ThreadLocal里面,便于后续使用LogUtil.set(recordLog);}return true;}@Overridepublic void postHandle(HttpServletRequest request, HttpServletResponse response, Object handler, ModelAndView modelAndView) throws Exception {HandlerInterceptor.super.postHandle(request, response, handler, modelAndView);}@Overridepublic void afterCompletion(HttpServletRequest request, HttpServletResponse response, Object handler, Exception ex) throws Exception {LogUtil.remove();}
}

3.2.3 存放日志对象的ThreadLocal (LogUtil)

package com.shg.utils;import com.shg.model.pojo.RecordLog;public class LogUtil {private static final ThreadLocal<RecordLog> appCacheDtoThreadLocal = new ThreadLocal<>();public static void set(RecordLog log) {appCacheDtoThreadLocal.set(log);}public static RecordLog get() {return appCacheDtoThreadLocal.get();}public static void remove() {appCacheDtoThreadLocal.remove();}
}

3.2.4 控制器Controller

package com.shg.controller;import com.shg.common.ResultMessage;
import com.shg.model.vo.RandomRequest;
import org.springframework.web.bind.annotation.GetMapping;
import org.springframework.web.bind.annotation.RequestBody;
import org.springframework.web.bind.annotation.RestController;@RestController
public class TestController {@GetMapping("/test1")public ResultMessage<String> test1(@RequestBody RandomRequest randomRequest) {int i = 1/0;// TODO 调用Service层的业务逻辑return ResultMessage.success("这是测试接口..." +randomRequest.getLength());}
}

3.2.5 统一返回结果对象 (ResultMessage)

package com.shg.common;import com.fasterxml.jackson.annotation.JsonInclude;
import lombok.Data;@Data
@JsonInclude(JsonInclude.Include.NON_NULL)
public class ResultMessage<T> {private Integer code;private String message;private T data;private long timestamp = System.currentTimeMillis();public ResultMessage() {this(ResponseCodeEnum.SUCCESS.getCode(), ResponseCodeEnum.SUCCESS.getMessage(), null);}public ResultMessage(Integer code, String message, T data) {this.code = code;this.message = message;this.data = data;}public static <T> ResultMessage<T> success() {return new ResultMessage<>();}public static <T> ResultMessage<T> success(T data) {ResultMessage<T> resultMessage = new ResultMessage<>();resultMessage.setMessage(ResponseCodeEnum.SUCCESS.getMessage());resultMessage.setData(data);return resultMessage;}public static <T> ResultMessage<T> success(String message, T data) {ResultMessage<T> resultMessage = new ResultMessage<>();resultMessage.setMessage(message);resultMessage.setData(data);return resultMessage;}public static <T> ResultMessage<T> success(String message, boolean success) {ResultMessage<T> resultMessage = new ResultMessage<>();resultMessage.setMessage(message);return resultMessage;}public static <T> ResultMessage<T> errorResult(ResponseCodeEnum responseCodeEnum) {return new ResultMessage<>(responseCodeEnum.getCode(), responseCodeEnum.getMessage(), null);}public static <T> ResultMessage<T> errorResult(Integer code, String message) {return new ResultMessage<>(code, message, null);}public static <T> ResultMessage<T> errorResult(Integer code, String message, T data) {return new ResultMessage<>(code, message, data);}
}

3.2.6 统一异常处理 (GlobalExceptionHandler)

package com.shg.exception;import cn.hutool.core.date.DatePattern;
import cn.hutool.core.date.DateUnit;
import cn.hutool.core.date.DateUtil;
import com.alibaba.fastjson.JSON;
import com.shg.common.ResponseCodeEnum;
import com.shg.common.ResultMessage;
import com.shg.constant.CommonConstant;
import com.shg.model.pojo.RecordLog;
import com.shg.utils.LogUtil;
import lombok.extern.slf4j.Slf4j;
import org.springframework.web.bind.annotation.ControllerAdvice;
import org.springframework.web.bind.annotation.ExceptionHandler;
import org.springframework.web.bind.annotation.ResponseBody;import java.util.Date;
import java.util.Objects;@Slf4j
@ControllerAdvice
public class GlobalExceptionHandler {@ExceptionHandler(Throwable.class)@ResponseBodypublic ResultMessage error(Throwable e) {e.printStackTrace();recordLog(e, e.getMessage());return ResultMessage.errorResult(ResponseCodeEnum.SYSTEM_EXCEPTION.getCode(), e.getMessage());}@ExceptionHandler(BizException.class)@ResponseBodypublic ResultMessage error(BizException e) {recordLog(e, e.getMessage());e.printStackTrace();return ResultMessage.errorResult(e.getCode(), e.getMessage());}private void recordLog(Throwable e, String message) {RecordLog recordLog = LogUtil.get();if (!Objects.isNull(recordLog)) { // 有一种情况是，当请求方法不支持时，经过过滤器进行放行之后，会直接抛出异常，然后就会在这里进行处理了，此时RecordLog还没有对象，所以这里要判断recordLog是否为空String responseTime = DateUtil.format(new Date(), DatePattern.NORM_DATETIME_MS_PATTERN);String requestTime = recordLog.getRequestTime();long costTime = getCostTime(responseTime, requestTime);recordLog.setResponseTime(responseTime);recordLog.setResponseInterval(costTime);recordLog.setMessage(message);recordLog.setResult(CommonConstant.ONE);String myLogJson = JSON.toJSONString(recordLog);log.error("[EX]:" + System.currentTimeMillis() + " " + myLogJson, e);} else {log.error(e.getMessage(), e);}}private long getCostTime(String responseTime, String requestTime) {Date endTime = DateUtil.parse(responseTime);Date startTime = DateUtil.parse(requestTime);return DateUtil.between(endTime, startTime, DateUnit.MS);}
}

package com.shg.common;public enum ResponseCodeEnum {SUCCESS(0, "success"),SYSTEM_EXCEPTION(500, "System internal exception"),APP_ID_NOT_PASSED(1001, "The appId is not passed");private final int code;private final String message;ResponseCodeEnum(int code, String message) {this.code = code;this.message = message;}public int getCode() {return code;}public String getMessage() {return message;}}

3.2.7 统一响应结果处理器 (ResponseBodyAdviceAdapter)

package com.shg.component;import cn.hutool.core.date.DatePattern;
import cn.hutool.core.date.DateUnit;
import cn.hutool.core.date.DateUtil;
import cn.hutool.json.JSONUtil;
import com.alibaba.fastjson.JSON;
import com.shg.common.ResponseCodeEnum;
import com.shg.common.ResultMessage;
import com.shg.constant.CommonConstant;
import com.shg.model.pojo.RecordLog;
import com.shg.utils.LogUtil;
import lombok.extern.slf4j.Slf4j;
import org.springframework.core.MethodParameter;
import org.springframework.http.MediaType;
import org.springframework.http.converter.HttpMessageConverter;
import org.springframework.http.server.ServerHttpRequest;
import org.springframework.http.server.ServerHttpResponse;
import org.springframework.web.bind.annotation.ControllerAdvice;
import org.springframework.web.servlet.mvc.method.annotation.ResponseBodyAdvice;import java.util.Date;
import java.util.Objects;/*** @DESCRIPTION: 在返回结果前进行日志记录* @USER: shg* @DATE: 2024/10/24 22:55*/
@Slf4j
@ControllerAdvice
public class ResponseBodyAdviceAdapter implements ResponseBodyAdvice<Object> {@Overridepublic boolean supports(MethodParameter returnType, Class<? extends HttpMessageConverter<?>> converterType) {return true;}@Overridepublic Object beforeBodyWrite(Object body,MethodParameter returnType,MediaType selectedContentType,Class<? extends HttpMessageConverter<?>> selectedConverterType,ServerHttpRequest request,ServerHttpResponse response) {if (body instanceof ResultMessage) {ResultMessage resultMessage = ((ResultMessage<?>) body);if (resultMessage.getCode() == ResponseCodeEnum.SUCCESS.getCode()) {recordLog(JSONUtil.toJsonStr(resultMessage));}}return body;}private void recordLog(String message) {RecordLog recordLog = LogUtil.get();String responseTime = DateUtil.format(new Date(), DatePattern.NORM_DATETIME_MS_PATTERN);String requestTime = recordLog.getRequestTime();long costTime = getCostTime(responseTime, requestTime);recordLog.setResponseTime(responseTime);recordLog.setResponseInterval(costTime);recordLog.setMessage(message);recordLog.setResult(CommonConstant.ZERO);String myLogJson = JSON.toJSONString(recordLog);if (!Objects.isNull(recordLog.getAppId())) {log.info("[SUCCESS RESULT:]" + myLogJson);}}private long getCostTime(String responseTime, String requestTime) {Date endTime = DateUtil.parse(responseTime);Date startTime = DateUtil.parse(requestTime);return DateUtil.between(endTime, startTime, DateUnit.MS);}}