使用aop实现日志统一管理

前面在介绍aop的时候提到使用aop可以实现统一日志记录，这里就简单通过aop框架实现统一记录日志功能。
为了更加灵活处理，aop拦截时并不是对所有方法都记录日志，我的规划是添加指定标签的方法或类才记录日志，没有添加标签的方法就不记录日志，这样可以让代码更灵活。而且可以在标签中指定日志级别，日志包括方法进入时和退出时都要记录，并且记录方法执行时间，方便做一些统计分析。
按照上面的规划，首先要定义一个标签用于标记哪些方法或类要记录日志，并且标签可以指定日志级别：

import java.lang.annotation.*;

/**
 * 写日志标签
 * @Author xingo
 * @Date 2023/12/13
 */
@Target({ ElementType.METHOD, ElementType.TYPE })
@Retention(RetentionPolicy.RUNTIME)
@Inherited
@Documented
public @interface LogWriter {

    /**
     * 写日志级别：debug、info、warn、error
     * @return
     */
    LogLevel level() default LogLevel.DEBUG;
}

接下来就是要写aop实现类了，首先还是要引入aop的依赖包：

<dependency>
    <groupId>org.springframework.boot</groupId>
    <artifactId>spring-boot-starter-aop</artifactId>
</dependency>

日志拦截类内容：

import lombok.extern.slf4j.Slf4j;
import org.aspectj.lang.JoinPoint;
import org.aspectj.lang.annotation.*;
import org.aspectj.lang.reflect.MethodSignature;
import org.example.pojo.ApiResult;
import org.springframework.aop.aspectj.MethodInvocationProceedingJoinPoint;
import org.springframework.boot.autoconfigure.condition.ConditionalOnWebApplication;
import org.springframework.stereotype.Component;

/**
 * 日志记录切面类
 *
 * @author xingo
 * @date 2023/12/13
 */
@Aspect
@Component
@ConditionalOnWebApplication
@Slf4j
public class LogAspect {

    // 通过环绕通知方式处理
    /**
     * 定义切入点
     */
    @Pointcut("execution(* org.example.controller.*.*(..))")
    public void pointcut1() {

    }

    @Pointcut("execution(* org.example.service.*.*(..))")
    public void pointcut2() {

    }

    /**
     * 请求开始时间
     */
    public static final ThreadLocal<Long> threadStartTime = new ThreadLocal<>();
    /**
     * 记录方法进入和退出次数
     */
    public static final ThreadLocal<Integer> methodCount = new ThreadLocal<>();

    /**
     * 前置通知：执行目标方法之前运行
     * @param jp
     */
    @Before("pointcut1() || pointcut2()")
    public void beforeMethod(JoinPoint jp) {
        threadStartTime.set(System.currentTimeMillis());
        if(methodCount.get() == null) {
            methodCount.set(1);
        } else {
            methodCount.set(methodCount.get() + 1);
        }
        this.writeLogger(jp, "开始", null, null, null);
    }

    /**
     * 返回通知：目标方法正常返回值后运行
     * @param jp
     */
    @AfterReturning(value = "pointcut1() || pointcut2()", returning = "result")
    public void aftherReturn(JoinPoint jp, Object result) {
        long diff = System.currentTimeMillis() - threadStartTime.get();
        if(methodCount.get() == 1) {
            methodCount.remove();
            threadStartTime.remove();
        } else {
            methodCount.set(methodCount.get() - 1);
        }

        this.writeLogger(jp, "结束", diff, null, result);
    }

    /**
     * 异常通知：目标方法出现异常后运行
     * @param jp
     */
    @AfterThrowing(value = "pointcut1() || pointcut2()", throwing = "e")
    public void afterThrowing(JoinPoint jp, Exception e) {
        long diff = System.currentTimeMillis() - threadStartTime.get();
        if(methodCount.get() == 1) {
            methodCount.remove();
            threadStartTime.remove();
        } else {
            methodCount.set(methodCount.get() - 1);
        }
        this.writeLogger(jp, "异常", diff, e, null);
    }

//    /**
//     * 后置通知：目标方法运行结束之后，不管有没有异常
//     * @param jp
//     */
//    @After("execution(* org.example.controller.*.*(..))")
//    public void afterMethod(JoinPoint jp) {
//        long diff = System.currentTimeMillis() - threadStartTime.get();
//        threadStartTime.remove();
//        System.out.println("请求耗时 ====>>> " + diff);
//    }

    /**
     * 记录日志方法
     * @param jp        切入点
     * @param step      步骤
     * @param diff      时间差异
     * @param e         异常
     * @param result    结果
     */
    private void writeLogger(JoinPoint jp, String step, Long diff, Exception e, Object result) {
        // 判断方法或类上面是否有记录日志注解
        MethodInvocationProceedingJoinPoint mjp = (MethodInvocationProceedingJoinPoint) jp;
        MethodSignature signature = (MethodSignature) mjp.getSignature();
        LogWriter logWriter = null;
        if(signature.getMethod().isAnnotationPresent(LogWriter.class)) {
            logWriter = signature.getMethod().getAnnotation(LogWriter.class);
        } else {
            Class<?> clazz = jp.getThis().getClass();
            if(clazz.isAnnotationPresent(LogWriter.class)) {
                logWriter = clazz.getAnnotation(LogWriter.class);
            }
        }

        // 有注解就进行日志记录，记录日志时要区分日志级别
        if(logWriter != null) {
            if(e != null) {
                log.error("{} 异常|参数{}", jp.getSignature().getName(), JacksonUtils.toJSONString(jp.getArgs()), e);
                return;
            }
            String msg = "{} {}|参数 {}{}{}";
            Object[] args = {
                    jp.getSignature().getName(),
                    step,
                    JacksonUtils.toJSONString(jp.getArgs()),
                    result == null ? "" : "|结果 " + JacksonUtils.toJSONString(result),
                    diff == null ? "" : ("|耗时 " + diff + "ms")
            };
            switch (logWriter.level()) {
                case TRACE:
                    log.trace(msg, args);
                    break;
                case DEBUG:
                    log.debug(msg, args);
                    break;
                case INFO:
                    log.info(msg, args);
                    break;
                case WARN:
                    log.warn(msg, args);
                    break;
                case ERROR:
                    log.error(msg, args);
                    break;
            }
        }
    }
}

定义了两个切入点，分别是在controller层和service层都要进行处理，前置通知主要是记录进入方法开始执行的时间，返回通知和异常通知是方法执行完后根据不同情况进行不同的调用。最主要的是写日志内容方法，它里面首先判断方法是否有注解，如果有优先使用方法上的注解；如果没有再判断类上面是否有注解。如果都没有注解，那么就不执行写日志。

下面是我的测试内容，分别用两个数相加和相除来测试。
controller中定义两个接口：

@Autowired
private DemoService demoService;

@LogWriter(level = LogLevel.INFO)
@GetMapping("/demo8")
public ApiResult demo8(Integer a, Double b) throws InterruptedException {
    Map<String, Object> map = new HashMap<>();
    map.put("method", "demo8");
    map.put("sum", demoService.sum(a, b));

    return ApiResult.success(map);
}

@LogWriter
@GetMapping("/demo9")
public ApiResult demo9(Integer a, Integer b) throws InterruptedException {
    Map<String, Object> map = new HashMap<>();
    map.put("method", "demo9");
    map.put("sum", demoService.divide(a, b));

    return ApiResult.success(map);
}

为了模拟多层方法的调用，在service层中执行具体的计算方法：

import org.example.handler.LogWriter;
import org.springframework.boot.logging.LogLevel;
import org.springframework.stereotype.Service;

import java.util.concurrent.TimeUnit;

/**
 * @Author xingo
 * @Date 2023/12/13
 */
@Service
public class DemoService {

    @LogWriter(level = LogLevel.INFO)
    public Double sum(Integer a, Double b) {
        try {
            TimeUnit.MILLISECONDS.sleep(200);
        } catch (InterruptedException e) {
            e.printStackTrace();
        }
        return a + b;
    }

    @LogWriter
    public Integer divide(Integer a, Integer b) {
        try {
            TimeUnit.MILLISECONDS.sleep(200);
        } catch (InterruptedException e) {
            e.printStackTrace();
        }
        return a / b;
    }
}

测试正常执行：

请求方法：http://localhost:8081/demo8?a=100&b=111
日志内容：
2023-12-13 10:43:07.527|http-nio-8081-exec-8|[INFO ]|org.example.handler.LogAspect.writeLogger|demo8 开始|参数 [100,111.0]
2023-12-13 10:43:07.528|http-nio-8081-exec-8|[ERROR]|org.example.handler.LogAspect.writeLogger|sum 开始|参数 [100,111.0]
2023-12-13 10:43:07.729|http-nio-8081-exec-8|[ERROR]|org.example.handler.LogAspect.writeLogger|sum 结束|参数 [100,111.0]|结果 211.0|耗时 201ms
2023-12-13 10:43:07.729|http-nio-8081-exec-8|[INFO ]|org.example.handler.LogAspect.writeLogger|demo8 结束|参数 [100,111.0]|结果 {"code":200,"data":{"method":"demo8","sum":211.0},"message":"success","time":"0","success":true}|耗时 201ms


请求方法：http://localhost:8081/demo9?a=100&b=100
日志内容：
2023-12-13 10:54:04.862|http-nio-8081-exec-1|[DEBUG]|org.example.handler.LogAspect.writeLogger|demo9 开始|参数 [100,100]
2023-12-13 10:54:04.871|http-nio-8081-exec-1|[DEBUG]|org.example.handler.LogAspect.writeLogger|divide 开始|参数 [100,100]
2023-12-13 10:54:05.075|http-nio-8081-exec-1|[DEBUG]|org.example.handler.LogAspect.writeLogger|divide 结束|参数 [100,100]|结果 1|耗时 204ms
2023-12-13 10:54:05.097|http-nio-8081-exec-1|[DEBUG]|org.example.handler.LogAspect.writeLogger|demo9 结束|参数 [100,100]|结果 {"code":200,"data":{"method":"demo9","sum":1},"message":"success","time":"0","success":true}|耗时 205ms

测试发生异常时：

请求方法：http://localhost:8081/demo9?a=100&b=0
日志内容：
2023-12-13 10:58:42.708|http-nio-8081-exec-1|[DEBUG]|org.example.handler.LogAspect.writeLogger|demo9 开始|参数 [100,0]
2023-12-13 10:58:42.716|http-nio-8081-exec-1|[DEBUG]|org.example.handler.LogAspect.writeLogger|divide 开始|参数 [100,0]
2023-12-13 10:58:42.923|http-nio-8081-exec-1|[ERROR]|org.example.handler.LogAspect.writeLogger|divide 异常|参数[100,0]
java.lang.ArithmeticException: / by zero
	at org.example.service.DemoService.divide(DemoService.java:33)
	at org.example.service.DemoService$$FastClassBySpringCGLIB$$66398aeb.invoke(<generated>)
	at org.springframework.cglib.proxy.MethodProxy.invoke(MethodProxy.java:218)
	at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.invokeJoinpoint(CglibAopProxy.java:793)
	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:163)
	at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.proceed(CglibAopProxy.java:763)
	at org.springframework.aop.aspectj.AspectJAfterThrowingAdvice.invoke(AspectJAfterThrowingAdvice.java:64)
	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186)
	at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.proceed(CglibAopProxy.java:763)
	at org.springframework.aop.framework.adapter.AfterReturningAdviceInterceptor.invoke(AfterReturningAdviceInterceptor.java:57)
	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186)
	at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.proceed(CglibAopProxy.java:763)
	at org.springframework.aop.framework.adapter.MethodBeforeAdviceInterceptor.invoke(MethodBeforeAdviceInterceptor.java:58)
	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186)
	at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.proceed(CglibAopProxy.java:763)
	at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:97)
	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186)
	at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.proceed(CglibAopProxy.java:763)
	at org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:708)
	at org.example.service.DemoService$$EnhancerBySpringCGLIB$$3977f776.divide(<generated>)
	at org.example.controller.DemoController.demo9(DemoController.java:114)
	at org.example.controller.DemoController$$FastClassBySpringCGLIB$$e30db683.invoke(<generated>)
	at org.springframework.cglib.proxy.MethodProxy.invoke(MethodProxy.java:218)
	at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.invokeJoinpoint(CglibAopProxy.java:793)
	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:163)
	at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.proceed(CglibAopProxy.java:763)
	at org.springframework.aop.aspectj.AspectJAfterThrowingAdvice.invoke(AspectJAfterThrowingAdvice.java:64)
	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186)
	at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.proceed(CglibAopProxy.java:763)
	at org.springframework.aop.framework.adapter.AfterReturningAdviceInterceptor.invoke(AfterReturningAdviceInterceptor.java:57)
	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186)
	at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.proceed(CglibAopProxy.java:763)
	at org.springframework.aop.framework.adapter.MethodBeforeAdviceInterceptor.invoke(MethodBeforeAdviceInterceptor.java:58)
	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186)
	at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.proceed(CglibAopProxy.java:763)
	at org.springframework.aop.aspectj.MethodInvocationProceedingJoinPoint.proceed(MethodInvocationProceedingJoinPoint.java:89)
	at org.example.handler.AopAspect.doAround(AopAspect.java:40)
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:498)
	at org.springframework.aop.aspectj.AbstractAspectJAdvice.invokeAdviceMethodWithGivenArgs(AbstractAspectJAdvice.java:634)
	at org.springframework.aop.aspectj.AbstractAspectJAdvice.invokeAdviceMethod(AbstractAspectJAdvice.java:624)
	at org.springframework.aop.aspectj.AspectJAroundAdvice.invoke(AspectJAroundAdvice.java:72)
	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186)
	at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.proceed(CglibAopProxy.java:763)
	at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:97)
	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186)
	at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.proceed(CglibAopProxy.java:763)
	at org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:708)
	at org.example.controller.DemoController$$EnhancerBySpringCGLIB$$b559dc28.demo9(<generated>)
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:498)
	at org.springframework.web.method.support.InvocableHandlerMethod.doInvoke(InvocableHandlerMethod.java:205)
	at org.springframework.web.method.support.InvocableHandlerMethod.invokeForRequest(InvocableHandlerMethod.java:150)
	..........
2023-12-13 10:58:42.924|http-nio-8081-exec-1|[ERROR]|org.example.handler.LogAspect.writeLogger|demo9 异常|参数[100,0]
java.lang.ArithmeticException: / by zero
	at org.example.service.DemoService.divide(DemoService.java:33)
	at org.example.service.DemoService$$FastClassBySpringCGLIB$$66398aeb.invoke(<generated>)
	at org.springframework.cglib.proxy.MethodProxy.invoke(MethodProxy.java:218)
	at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.invokeJoinpoint(CglibAopProxy.java:793)
	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:163)
	at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.proceed(CglibAopProxy.java:763)
	at org.springframework.aop.aspectj.AspectJAfterThrowingAdvice.invoke(AspectJAfterThrowingAdvice.java:64)
	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186)
	at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.proceed(CglibAopProxy.java:763)
	at org.springframework.aop.framework.adapter.AfterReturningAdviceInterceptor.invoke(AfterReturningAdviceInterceptor.java:57)
	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186)
	at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.proceed(CglibAopProxy.java:763)
	at org.springframework.aop.framework.adapter.MethodBeforeAdviceInterceptor.invoke(MethodBeforeAdviceInterceptor.java:58)
	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186)
	at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.proceed(CglibAopProxy.java:763)
	at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:97)
	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186)
	at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.proceed(CglibAopProxy.java:763)
	at org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:708)
	at org.example.service.DemoService$$EnhancerBySpringCGLIB$$3977f776.divide(<generated>)
	at org.example.controller.DemoController.demo9(DemoController.java:114)
	at org.example.controller.DemoController$$FastClassBySpringCGLIB$$e30db683.invoke(<generated>)
	at org.springframework.cglib.proxy.MethodProxy.invoke(MethodProxy.java:218)
	..........

通过在日志中记录发生异常的完整堆栈信息和方法入参，可以很方便的定位问题发生的原因。
上面这种通过aop记录日志的方式是通用的，只是在方法进入和返回时记录日志，如果要在方法内部代码执行时记录日志，还是要在代码中写入日志。这里也说明了aop是为了解决通用场景下的重复工作，特殊需求还是要单独处理。
虽然这种方式简化了重复代码的编写，但是却带来了额外的性能开销，所以在项目中要根据情况选择使用。