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 {

    @Override
    public void init(FilterConfig filterConfig) throws ServletException {

    }

    @Override
    public 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);
        }
    }

    @Override
    public 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;
        }

        @Override
        public BufferedReader getReader() throws IOException {
            return new BufferedReader(new InputStreamReader(getInputStream()));
        }

        @Override
        public ServletInputStream getInputStream() throws IOException {
            // 创建字节数组输入流
            final ByteArrayInputStream bais = new ByteArrayInputStream(mBody.getBytes(StandardCharsets.UTF_8));

            return new ServletInputStream() {
                @Override
                public boolean isFinished() {
                    return false;
                }

                @Override
                public boolean isReady() {
                    return false;
                }

                @Override
                public void setReadListener(ReadListener readListener) {

                }

                @Override
                public 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;
    }

    @Override
    public 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是否合法 TODO
            if(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;
    }

    @Override
    public void postHandle(HttpServletRequest request, HttpServletResponse response, Object handler, ModelAndView modelAndView) throws Exception {
        HandlerInterceptor.super.postHandle(request, response, handler, modelAndView);
    }

    @Override
    public 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)
    @ResponseBody
    public ResultMessage error(Throwable e) {
        e.printStackTrace();
        recordLog(e, e.getMessage());
        return ResultMessage.errorResult(ResponseCodeEnum.SYSTEM_EXCEPTION.getCode(), e.getMessage());
    }

    @ExceptionHandler(BizException.class)
    @ResponseBody
    public 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> {
    @Override
    public boolean supports(MethodParameter returnType, Class<? extends HttpMessageConverter<?>> converterType) {
        return true;
    }

    @Override
    public 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);
    }

}