使用Spring AOP 记录Spring MVC请求日志

前言

在一些场景中我们希望能够记录Http的请求地址、请求参数、应答数据、请求处理时间等信息。如果一个接口一个接口的增加日志太过浪费时间，而且容易发生遗漏。那么借助Spring AOP 对接口统一处理，肯定是比较好的方法。

Demo地址

开始之前

在开始之前我们需要先了解下以下知识。

通过上下文获取request和response

代码如下：

private HttpServletRequest getRequest() {
    Optional<RequestAttributes> requestAttributesOptional = Optional.ofNullable(RequestContextHolder.getRequestAttributes());
    if (requestAttributesOptional.isPresent()) {
        var servletRequestAttributes = (ServletRequestAttributes) requestAttributesOptional.get();
        return servletRequestAttributes.getRequest();
    } else {
        throw new LogPointAspectException("Could not get the HttpServletRequest from the spring webmvc context.");
    }
}

private HttpServletResponse getResponse() {
    Optional<RequestAttributes> requestAttributesOptional = Optional.ofNullable(RequestContextHolder.getRequestAttributes());
    if (requestAttributesOptional.isPresent()) {
        var servletRequestAttributes = (ServletRequestAttributes) requestAttributesOptional.get();
        return servletRequestAttributes.getResponse();
    } else {
        throw new LogPointAspectException("Could not get the HttpServletResponse from the spring webmvc context.");
    }
}

之所以能够获取到是因为每次请求都会创建一个线程，Spring把request和response放到了线程的ThreadLocal中。具体细节可查看RequestContextHolder的源码，这不是本文的重点。

Spring AOP的两种配置配置方式

方法一、通过注解配置

@Component
@Aspect
public class RequestAspect {

    @Pointcut("execution(* org.depsea.log..*Controller.*(..))")
    private void pointcut() {
    }
    
    @Around("pointcut()")
    public Object aroundAdvice(ProceedingJoinPoint joinPoint) throws Throwable {
        // before handle
        Object result = null;
        try {
            result = joinPoint.proceed();
        } catch (Throwable ex) {
            // exception handle
            throw ex;
        }
        // after handle
        return result;
    }
}

• @Component：声明为Spring Bean,必须
• @Aspect：AspectJ注解声明支持，Spring仅使用了AspectJ的声明注解，底层代理的实现还是用的JDK动态代理或者cglib来实现。
• @Pointcut：声明切入点
• @Around：声明这是一个环绕通知，使用环绕通知有利于我们计算接口的耗时，以及对异常的记录。

方法二、配置式

核心接口：

• org.aopalliance.aop.Advice
• org.springframework.aop.Advisor

这里我们主要实现 Advice 接口，Advice接口有如下几种：

• org.springframework.aop.MethodBeforeAdvice：在方法开始执行之前织入
• org.springframework.aop.AfterReturningAdvice：在方法返回之后织入
• org.springframework.aop.ThrowsAdvice：在方法发生异常时织入

MethodBeforeAdvice 必定会执行，如果方法没有发生异常，则AfterReturningAdvice执行；如果方法发生异常，则ThrowsAdvice执行。

Advice 主要实现通知处理，是我们需要实现的功能。在Spring中配置如下：

@Configuration
public class ApplicationConfiguration {

    @Bean
    public Advisor requestAdvisor(Advice requestAdvice) {
        var pointcut = new AspectJExpressionPointcut();
        pointcut.setExpression("execution(* org.depsea..*.controller.*.*(..))");
        return new DefaultPointcutAdvisor(pointcut, requestAdvice);
    }

    @Bean
    public Advice requestAdvice(Tracer tracer) {
        var requestAdvice = new RequestAdvice();
        requestAdvice.setTracer(tracer);
        requestAdvice.setApiNameGetter(new Swagger2ApiNameGetterImpl());
        requestAdvice.addPointHandlers(new RequestLogHandler(), new ElasticsearchRequestPointHandler());
        return requestAdvice;
    }
}

本文中采用的是第二种配置方式，目的是为了做成一个框架。可以供多个项目使用，各个项目只需要做简单配置即可实现请求信息的提取以及请求信息的记录。

请求信息提取

RequestPoint

我们定义一个RequestPoint类来存储提取的请求信息。

@Data
public class RequestPoint {

    /**
     * 应用名称
     */
    private String applicationName;

    /**
     * 追踪链路Id
     */
    private String traceId;

    /**
     * 节点id
     */
    private String spanId;

    /**
     * 上级节点ID
     */
    private String parentId;

    /**
     * 模块名称 -- swagger注解中获取
     */
    private String moduleName;

    /**
     * 接口名称 -- swagger 注解中获取
     */
    private String apiName;

    /**
     * http schema, HTTP or HTTPS
     */
    private String schema;

    /**
     * 请求方法
     */
    private String requestMethod;

    /**
     * 请求地址
     */
    private String requestUri;

    /**
     * 本地服务器IP
     */
    private String serverLocalIp;

    /**
     * 接口类的名称
     */
    private String clazz;

    /**
     * 接口方法的名称
     */
    private String methodName;

    /**
     * 请求参数，本来是map但是为了能够在存储到ES中时，不因数据类型和字段发生变更而导致一些错误，所以使用字符串
     */
    private String requestParameterMap;

    /**
     * Spring将请求参数解析后注入到方法参数后的数据
     */
    private String methodParameterMap;

    /**
     * 接口返回的数据
     */
    private String returnValue;

    /**
     * 耗时
     */
    private long timeConsuming;

    /**
     * 是否发生错误
     */
    private boolean error;

    /**
     * 错误消息
     */
    private String errorMessage;

    /**
     * 异常类
     */
    private String exceptionName;

    /**
     * 异常栈
     */
    private String exceptionStack;

    /**
     * 请求完成时间
     */
    private Date timestamp;

    /**
     * Response 状态
     */
    private int responseStatus;

    /**
     * 请求头
     */
    private String requestHeaders;

    /**
     * 应答头
     */
    private String responseHeaders;

    /**
     * cookie 数据
     */
    private String cookies;

    /**
     * 请求接口的用户ID
     */
    private String userId;

    /**
     * 请求接口的用户姓名
     */
    private String name;

}

我们可以提取的信息多达27项，其实还可以更多，比如浏览器信息，甚至可以通过浏览器信息获取到访问的设备类型等，以及用户的操作系统等数据。

扩展点

提供了几个扩展点，如下：

• org.depsea.log.getter.ApiNameGetter

public interface ApiNameGetter {

    /**
     * Get api name from method's annotation. Such as swagger's @ApiOperation
     *
     * @param method Controller Method
     * @return api name
     */
    String getOperationName(Method method);

    /**
     * Get module name from Controller class's annotation. Such as swagger's @Api
     * @param targetClazz Controller Class
     * @return module name
     */
    String getModuleName(Class<?> targetClazz);
}

此扩展点主要用于通过控制层的注解实现获取模块名称及接口名称的功能。

• org.depsea.log.getter.UserGetter

public interface UserGetter {

    /**
     * 获取用户ID
     *
     * @return 用户ID
     */
    String getUserId();

    /**
     * 获取操作员姓名
     *
     * @return 操作员姓名
     */
    String getName();
}

此扩展点用于获取当前登陆的用户信息，可以针对spring security 和 shiro 添加自己的实现。

• org.depsea.log.handler.RequestPointHandler

public interface RequestPointHandler {

    default boolean isAsync() {
        return false;
    }

    /**
     * 处理请求point
     *
     * @param requestPoint 请求point
     */
    void handle(RequestPoint requestPoint);
}

此扩展点用于后请求信息的处理，如果是异步的，则会放到线程池中处理，不影响当前线程。

比如将请求信息打印到控制台，将请求信息保存至数据库或ES或MongoDB中等。

RequestAdvice

此处不列出完整代码，近贴出部分代码，完整代码可以到gitee中查看。

public class RequestAdvice implements AfterReturningAdvice, ThrowsAdvice, MethodBeforeAdvice, ApplicationContextAware {
    /**
     * 线程池，用于执行异步处理
     */
    private final ExecutorService executorService = Executors.newCachedThreadPool();

    /**
     * 是否包含请求头信息
     */
    private boolean includeRequestHeaders = true;

    /**
     * 是否包含应答头信息
     */
    private boolean includeResponseHeaders = true;

    private ApiNameGetter apiNameGetter;

    private UserGetter userGetter;

    /**
     * 需要 spring-cloud-starter-sleuth 支持，用于获取链路追踪信息
     */
    private Tracer tracer;

    /**
     * 用于记录耗时
     */
    private final ThreadLocal<Long> timeConsumingThreadLocal = new ThreadLocal<>();

    /**
     * JSON序列化
     */
    private final ObjectMapper objectMapper = new ObjectMapper();

    /**
     * 请求信息处理
     */
    private List<RequestPointHandler> requestPointHandlers = new ArrayList<>();

    /**
     * Spring 上下文
     */
    private ApplicationContext applicationContext;
}

前置通知

org.springframework.aop.MethodBeforeAdvice 的实现。

@Override
public void before(@NonNull Method method, @NonNull Object[] args, Object target) throws Throwable {
    // record start time
    timeConsumingThreadLocal.set(System.currentTimeMillis());
}

在方法开始时仅记录开始时间。

后置通知

org.springframework.aop.AfterReturningAdvice 的实现

@Override
public void afterReturning(Object returnValue, @NonNull Method method, @NonNull Object[] args, Object target) throws Throwable {
    try {
        var requestPoint = this.createRequestPoint(method, args);
        if (returnValue != null) {
            requestPoint.setReturnValue(this.objectMapper.writeValueAsString(returnValue));
        }
        this.doRequestHandler(requestPoint);
    } catch (Exception ex) {
        log.warn("处理失败：{}", ex.getMessage());
    }
}

异常通知

org.springframework.aop.ThrowsAdvice 的实现。

方法格式：void afterThrowing([Method, args, target], ThrowableSubclass);

示例：

• public void afterThrowing(Exception ex)
• public void afterThrowing(RemoteException)
• public void afterThrowing(Method method, Object[] args, Object target, Exception ex)
• public void afterThrowing(Method method, Object[] args, Object target, ServletException ex)

以上信息从源码注释中查看

public void afterThrowing(Method method, Object[] args, Object target, Exception ex) {
    try {
        var requestPoint = this.createRequestPoint(method, args);
        requestPoint.setError(true);
        requestPoint.setExceptionName(ex.getClass().getName());
        requestPoint.setExceptionStack(ExceptionUtils.getStackTrace(ex));
        requestPoint.setErrorMessage(ex.getMessage());
        this.doRequestHandler(requestPoint);
    } catch (Exception e) {
        log.warn("处理失败：{}", e.getMessage());
    }
}

createRequestPoint

这个方法用于获取请求信息、链路信息、接口信息、用户信息等。

private RequestPoint createRequestPoint(@NonNull Method method, @NonNull Object[] args) throws JsonProcessingException {
    var request = this.getRequest();
    var response = this.getResponse();

    var requestPoint = new RequestPoint();

    if (this.includeRequestHeaders) {
        requestPoint.setRequestHeaders(this.objectMapper.writeValueAsString(this.getRequestHeaders(request)));
    }
    if (this.includeResponseHeaders && response != null) {
        requestPoint.setResponseHeaders(this.objectMapper.writeValueAsString(this.getResponseHeaders(response)));
    }

    if (this.apiNameGetter != null) {
        requestPoint.setModuleName(this.apiNameGetter.getModuleName(method.getDeclaringClass()));
        requestPoint.setApiName(this.apiNameGetter.getOperationName(method));
    }

    if (this.userGetter != null) {
        requestPoint.setUserId(this.userGetter.getUserId());
        requestPoint.setName(this.userGetter.getName());
    }

    requestPoint.setApplicationName(this.getApplicationName());
    requestPoint.setClazz(method.getDeclaringClass().getName());
    requestPoint.setMethodName(method.getName());
    requestPoint.setError(false);
    requestPoint.setTimestamp(new Date());

    if (this.tracer != null) {
        var span = tracer.currentSpan();
        if (span != null) {
            requestPoint.setSpanId(span.context().spanId());
            requestPoint.setTraceId(span.context().traceId());
            requestPoint.setParentId(span.context().parentId());
        }
    }

    requestPoint.setSchema(request.getScheme().toUpperCase());
    requestPoint.setRequestMethod(request.getMethod().toUpperCase());
    requestPoint.setRequestUri(request.getRequestURI());

    Map<String, Object> methodParams = new HashMap<>();
    Parameter[] parameters = method.getParameters();
    for (var i = 0; i < parameters.length; i++) {
        var parameter = parameters[i];
        methodParams.put(parameter.getName(), args[i]);
    }

    requestPoint.setMethodParameterMap(objectMapper.writeValueAsString(methodParams));
    requestPoint.setRequestParameterMap(objectMapper.writeValueAsString(request.getParameterMap()));
    if (response != null) {
        requestPoint.setResponseStatus(response.getStatus());
    }

    long start = this.timeConsumingThreadLocal.get();
    long end = System.currentTimeMillis();
    requestPoint.setTimeConsuming(end - start);
    this.timeConsumingThreadLocal.remove();
    return requestPoint;
}

doRequestHandler

用于对请求信息进行处理

private void doRequestHandler(RequestPoint requestPoint) {
    if (!CollectionUtils.isEmpty(this.requestPointHandlers)) {
        for (RequestPointHandler requestPointHandler : this.requestPointHandlers) {
            try {
                if (requestPointHandler.isAsync()) {
                    this.executorService.submit(() -> requestPointHandler.handle(requestPoint));
                } else {
                    requestPointHandler.handle(requestPoint);
                }
            } catch (Exception ex) {
                log.warn("Execute request point handler [{}] fail. Cause: {}",
                        requestPointHandler.getClass().getName(), ex.getMessage(), ex);
            }
        }
    }
}

RequestPointHandler实现

本文提供一个打印日志的实现，如有其他需求可自行实现。

@Slf4j
public class RequestLogHandler implements RequestPointHandler {

    @Override
    public void handle(RequestPoint requestPoint) {
        log.info("Request Info: {} {} {}", requestPoint.getSchema(), requestPoint.getRequestMethod(), requestPoint.getRequestUri());
        log.info("Controller & Method: {}#{}", requestPoint.getClazz(), requestPoint.getMethodName());
        log.info("Request Parameters: {}", requestPoint.getRequestParameterMap());
        log.info("Method Parameters: {}", requestPoint.getMethodParameterMap());
        if (requestPoint.isError()) {
            log.warn("Request Error: {}", requestPoint.getErrorMessage());
        } else {
            log.info("Return Value：{}", requestPoint.getReturnValue());
        }
        log.info("Time Consuming: {}", requestPoint.getTimeConsuming());
    }
}

效果如下：

...RequestLogHandler   : Request Info: HTTP GET /api/v1/test
...RequestLogHandler   : Controller & Method: org.depsea.log.module.controller.TestController#test
...RequestLogHandler   : Request Parameters: {"name":["zhangsan"]}
...RequestLogHandler   : Method Parameters: {"name":"zhangsan"}
...RequestLogHandler   : Return Value："OK"
...RequestLogHandler   : Time Consuming: 50