AOP做统一日志处理和日志分类处理

最近自己一直再看现有微服务的日志模块，发现就是使用AOP来做controller层的日志处理，加上项目在进行架构优化，需要将日志分类处理，即第三方和服务内调用的日志单独存储，这个任务被交给我处理，所以自己趁着这个机会来学习一下怎么使用AOP进行日志处理和不同业务的日志如何拆分。

一、AOP做日志统一处理

首先还是创建一个spring boot项目，添加相关的依赖，下面是我项目的pom文件，其实只是添加了Aspect的依赖

<?xml version="1.0" encoding="UTF-8"?>
<project xmlns="http://maven.apache.org/POM/4.0.0" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
         xsi:schemaLocation="http://maven.apache.org/POM/4.0.0 http://maven.apache.org/xsd/maven-4.0.0.xsd">
    <modelVersion>4.0.0</modelVersion>
    <parent>
        <groupId>org.springframework.boot</groupId>
        <artifactId>spring-boot-starter-parent</artifactId>
        <version>2.1.4.RELEASE</version>
        <relativePath/>
    </parent>
    <groupId>com.ypc.logtest</groupId>
    <artifactId>logback</artifactId>
    <version>0.0.1-SNAPSHOT</version>
    <name>logback</name>
    <description>Demo project for Spring Boot</description>

    <properties>
        <java.version>1.8</java.version>
    </properties>

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

        <dependency>
            <groupId>org.projectlombok</groupId>
            <artifactId>lombok</artifactId>
            <optional>true</optional>
        </dependency>
        <dependency>
            <groupId>org.springframework.boot</groupId>
            <artifactId>spring-boot-starter-aop</artifactId>
        </dependency>
        <dependency>
            <groupId>org.springframework.boot</groupId>
            <artifactId>spring-boot-starter-test</artifactId>
            <scope>test</scope>
        </dependency>
    </dependencies>

    <build>
        <plugins>
            <plugin>
                <groupId>org.springframework.boot</groupId>
                <artifactId>spring-boot-maven-plugin</artifactId>
            </plugin>
        </plugins>
    </build>

</project>

接着配置日志切面，日志切面我选择的为环绕增强，当然这个可以根据自己的需求选择，网上的例子也比较多。选择AOP做统一日志好处就是增强的目标类不需要每个都去写相关日志。只需要在切面中记录相关请求就可以了。比如我这个切面会在增强前置记录目标类、执行的方法名称、请求参数名称，最后会记录执行方法的结果，代码如下：

@Slf4j
@Aspect
@Component
public class CustomLogAspect {

    private Gson gson = new Gson();

    @Around("within(com.ypc.logtest.logback.controller..*)")
    public Object around(ProceedingJoinPoint joinPoint) throws Throwable {
        // 目标类的名称
        String className = joinPoint.getTarget().getClass().getName();
        // 方法名称
        String methodName = joinPoint.getSignature().getName();
        // 参数列表
        Parameter[] parameters = ((MethodSignature) joinPoint.getSignature()).getMethod().getParameters();
        Object[] args = joinPoint.getArgs();

        StringBuilder params = new StringBuilder("[");
        for (int i = 0; i < parameters.length; i++) {
            params.append(parameters[i].getName()).append(":").append(args[i]).append("; ");
        }
        if (parameters.length > 0) {
            int length = params.length();
            params.delete(length - 2, length);
        }
        params.append("]");
        log.info(">>>> Target class name={} | method name={} | params={} <<<<",className,methodName,params);
        Object result = null;
        try {
            // 执行方法
            result = joinPoint.proceed();
        } catch (Exception e) {
            // 记录异常日志
            log.error(">>>> Target class name={} | method name={}\n{}\n\t at {} <<<<",className, methodName, e.toString(), e.getStackTrace()[0]);
            throw e;
        }
        // 记录方法结果
        log.info(">>>> Target class name={} | method name={} | results={} <<<<",className, methodName, gson.toJson(result));
        return result;
    }

}

上面代码中@Slf4j就等同于LoggerFactory.getLogger(CustomLogAspect.class);当然如果在idea里面使用log.info等这些方法必须要安装Lombok插件。@Aspect注解就是表明这是一个切面。关于切面这部分学习spring的时候我想都比较熟悉了吧，但是用法我觉得需要多去看下，比如代码里面的within里面表示的是"com.ypc.logtest.logback.controller"包下的所有类的所有方法都会被增强，当然也可以通过其他方式来标记需要增强的目标对象，比如@annotation、target、bean等等。

二、不同业务日志分离

关于适用AOP统一日志处理就先说到这里，实际开发中真的用到再学习也可以。下面主要说下日志分类处理的问题，实际需求是这样的：我们使用spring cloud做微服务，现在的日志全部是统一集中处理的，但是想将第三方相关的日志单独抽取出来，单独存放。也就项目内部服务之间相互调用的日志存放一个文件，和第三方交互的存放一个文件（不管是服务端还是客户端）。但是我就遇到了很棘手的问题，就是怎么将业务区分开的问题，比如我一个服务即有与第三方交互的也有内部调用的，而且可能会调用同一个service的代码，这样我就需要两个单独日志来记录，这个非常的麻烦。举个例子controllerA是供内部服务调用，而controllerB是被第三方调用的，而这两个controller在内部调用了serviceC，根据我们的思路，controllerA和被它调用的serviceC的方法的日志应该存放一个文件，而controllerB和被它调用的serviceC的方法的日志应该存放到另一个文件，但是serviceC的日志目前只有一个，就是LoggerFactory.getLogger(ServiceC.class)，不知道大家有没有发现问题，一个LOGGER实例的输出内容只能添加到一个appender，而现在需要把一个LOGGER添加不同的appender。我暂时还没有和项目架构师确认方案，自己想了几种思路：

方案1、代码进行拆分，即将服务内部调用的service和第三方相关的service代码分离，这意味着同一个service代码可能会被拆成两分，公用部分代码会有一定冗余。然后创建不同包存放从controller层到dao层代码。这个我觉得目前应该算是最好的方法，但是工作量可能会比较大。
方案2、尽量不动现有代码，同样适用切面记录日志，但是有个缺陷就是无法记录方法内部日志，只能像上面的日志切面一样，记录开始、结束以及异常日志，还有就是原有方法的日志依然会输出到现有日志文件。这个方法比较简单，但是感觉不是太好。
方案3、同一个类使用两个不同的日志实例记录相关日志，比如serviceC现在的日志是LoggerFactory.getLogger(ServiceC.class)，我在和第三方代码相关的代码内部使用另一个日志类LoggerFactory.getLogger("third-part-logger")，然后再logback配置文件，添加这个logger即可。这个方法相对也比较简单，但是感觉也不太好。

第一种方法这里就不再讲了，因为相当于将一个服务拆成了不同的包存放，感觉没什么好讲的，主要说下后面两种方法。

---

方案2、

如果还使用切面，那么还需要一个切面，这个切面专门用来记录和第三方交互的日志，在之前我先定义一个注解，以区分和第三方日志相关的方法，只要有该注解的都属于和第三方相关的，注解如下：

@Target(ElementType.METHOD)
@Retention(RetentionPolicy.RUNTIME)
public @interface ThirdPart {
}

下面是logback的配置文件，下面只定义了一个appender，关于logback配置可以网上找资料看一下，实际应用还是很多的，甚至可以自己去实现具体的实现类。

<?xml version="1.0" encoding="UTF-8"?>
<configuration scan="true" scanPeriod="60 seconds">
    <property name="LOG_HOME" value="/home/ypcfly/ypcfly/Log" />
    <!-- 控制台设置 -->
    <appender name="CONSOLE" class="ch.qos.logback.core.ConsoleAppender">
        <encoder>
            <pattern>%d{MM-dd-yyyy HH:mm:ss} %-5level [%thread%X{sourceThread}]%logger{24}-%msg%n</pattern>
        </encoder>
    </appender>
    <!-- INFO -->
    <appender name="FILE" class="ch.qos.logback.core.rolling.RollingFileAppender">
        <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
            <!-- 文件名称 -->
            <fileNamePattern>${LOG_HOME}/log-file.%d{yyyy-MM-dd}.log</fileNamePattern>
            <MaxHistory>30</MaxHistory>
        </rollingPolicy>
        <triggeringPolicy class="ch.qos.logback.core.rolling.SizeBasedTriggeringPolicy">
            <MaxFileSize>50MB</MaxFileSize>
        </triggeringPolicy>
        <encoder>
            <pattern>%d{MM-dd-yyyy HH:mm:ss} %-5level [%thread]%logger{16} - %msg%n</pattern>
        </encoder>
    </appender>

    <root level="INFO">
        <appender-ref ref="CONSOLE"/>
        <appender-ref ref="FILE"/>
    </root>
</configuration>

这样项目的所有日志都会输出到我本地日志文件，先启动然后访问一下第三方交互的controller和服务间调用的controller，目前这两个controller共用一个service，两个代码如下：

@RestController
@RequestMapping("/inner")
public class InnerCallController {

    @Autowired
    private InnerService innerService;

    @Autowired
    private CommonService commonService;

    @GetMapping("/hello")
    public List<LocalDateTime> hello(@RequestParam("id") Long id,@RequestParam("name") String name) {

        return commonService.innerMethod(id,name);
    }

}

@RestController
@RequestMapping("/third")
public class ThirdPartCallController {

    @Autowired
    private ThirdPartCallService thirdPartCallService;

    @Autowired
    private CommonService commonService;

    @PostMapping("/test")
    public List<LocalDateTime> test(@RequestBody CustomDTO customDTO){
        Integer id = customDTO.getId();
        String name = customDTO.getName();
        Integer age = customDTO.getAge();
        return commonService.thirdMethod(id,name,age);
    }

}

然后分别使用rest clien调用这个两个接口，然后我们看下日志输出：

图－1.png

根据图中可以看出切面类输出了用户请求的参数，目标类执行的方法和结果，接下来需要再定义一个appender记录第三方日志，修改logback配置文件，如下：

<?xml version="1.0" encoding="UTF-8"?>
<configuration scan="true" scanPeriod="60 seconds">
    <property name="LOG_HOME" value="/home/ypcfly/ypcfly/Log" />
    <!-- 控制台设置 -->
    <appender name="CONSOLE" class="ch.qos.logback.core.ConsoleAppender">
        <encoder>
            <pattern>%d{MM-dd-yyyy HH:mm:ss} %-5level [%thread%X{sourceThread}]%logger{24}-%msg%n</pattern>
        </encoder>
    </appender>
    <!-- INFO -->
    <appender name="FILE" class="ch.qos.logback.core.rolling.RollingFileAppender">
        <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
            <!-- 文件名称 -->
            <fileNamePattern>${LOG_HOME}/log-file.%d{yyyy-MM-dd}.log</fileNamePattern>
            <MaxHistory>30</MaxHistory>
        </rollingPolicy>
        <triggeringPolicy class="ch.qos.logback.core.rolling.SizeBasedTriggeringPolicy">
            <MaxFileSize>50MB</MaxFileSize>
        </triggeringPolicy>
        <encoder>
            <pattern>%d{MM-dd-yyyy HH:mm:ss} %-5level [%thread]%logger{16} - %msg%n</pattern>
        </encoder>
    </appender>

    <!-- THIRD PART LOG -->
    <appender name="THIRD_FILE" class="ch.qos.logback.core.rolling.RollingFileAppender">
        <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
            <fileNamePattern>${LOG_HOME}/third-part-file.%d{yyyy-MM-dd}.log</fileNamePattern>
            <maxHistory>30</maxHistory>
        </rollingPolicy>
        <triggeringPolicy class="ch.qos.logback.core.rolling.SizeBasedTriggeringPolicy">
            <MaxFileSize>50MB</MaxFileSize>
        </triggeringPolicy>
        <encoder>
            <pattern>%d{MM-dd-yyyy HH:mm:ss} %-5level [%thread]%logger{16} - %msg%n</pattern>
        </encoder>
    </appender>
    <!-- 记录第三方切面日志的logger -->
    <logger name="com.ypc.logtest.logback.aop.ThirdLogAspect" additivity="false" level="INFO">
        <appender-ref ref="THIRD_FILE"/>
    </logger>

    <root level="INFO">
        <appender-ref ref="CONSOLE"/>
        <appender-ref ref="FILE"/>
    </root>
</configuration>

也就是说我们和第三方交互的日志全部由ThirdLogAspect记录，并被写入到THIRD_FILE这个appender里面，该appender配置和FILE一样，只是输出文件名不同而已，这里还是使用共用的service，另外我这里需要两个切面类分别记录第三方和服务内调用日志，切面类分别如下：

// 记录服务内调用的日志切面，即排除掉被我自定义注解@ThirdPart注解的方法。
@Slf4j
@Aspect
@Component
public class CustomLogAspect {

    private Gson gson = new Gson();

    @Around("within(com.ypc.logtest.logback.controller..*) && !@annotation(com.ypc.logtest.logback.aop.ThirdPart)")
    public Object around(ProceedingJoinPoint joinPoint) throws Throwable {
        // 目标类的名称
        String className = joinPoint.getTarget().getClass().getName();
        // 方法名称
        String methodName = joinPoint.getSignature().getName();
        // 参数列表
        Parameter[] parameters = ((MethodSignature) joinPoint.getSignature()).getMethod().getParameters();
        Object[] args = joinPoint.getArgs();

        StringBuilder params = new StringBuilder("[");
        for (int i = 0; i < parameters.length; i++) {
            params.append(parameters[i].getName()).append(":").append(args[i]).append("; ");
        }
        if (parameters.length > 0) {
            int length = params.length();
            params.delete(length - 2, length);
        }
        params.append("]");
        log.info(">>>> Target class name={} | method name={} | params={} <<<<",className,methodName,params);
        Object result = null;
        try {
            // 执行方法
            result = joinPoint.proceed();
        } catch (Exception e) {
            // 记录异常日志
            log.error(">>>> Target class name={} | method name={}\n{}\n\t at {} <<<<",className, methodName, e.toString(), e.getStackTrace()[0]);
            throw e;
        }
        // 记录方法结果
        log.info(">>>> Target class name={} | method name={} | results={} <<<<",className, methodName, gson.toJson(result));
        return result;
    }

}

// 第三方日志切面，包括controller和service，方法上有@ThirdPart注解就行
@Component
@Slf4j
@Aspect
public class ThirdLogAspect {

    private Gson gson = new Gson();

    @Around("@annotation(com.ypc.logtest.logback.aop.ThirdPart)")
    public Object around(ProceedingJoinPoint joinPoint) throws Throwable {

        String className = joinPoint.getTarget().getClass().getName();

        String methodName = joinPoint.getSignature().getName();

        Parameter[] parameters = ((MethodSignature) joinPoint.getSignature()).getMethod().getParameters();
        Object[] args = joinPoint.getArgs();

        StringBuilder params = new StringBuilder("[");
        for (int i = 0; i < parameters.length; i++) {
            params.append(parameters[i].getName()).append(":").append(args[i]).append("; ");
        }
        if (parameters.length > 0) {
            int length = params.length();
            params.delete(length - 2, length);
        }
        params.append("]");

        log.info(">>>> Target class name={} | method name={} | params={} <<<<",className,methodName,params);
        Object result = null;
        try {
            result = joinPoint.proceed();
        } catch (Exception e) {
            log.error(">>>> Target class name={} | method name={}\n{}\n\t at {} <<<<",className, methodName, e.toString(), e.getStackTrace()[0]);
            throw e;
        }
        log.info(">>>> Target class name={} | method name={} | results={} <<<<",className, methodName, gson.toJson(result));
        return result;
    }
}

这两个切面的代码完全相同，只是增强的目标不同而已，我们需要在和第三方交互的方法上都添加自定义的@ThirdPart注解，然后我们再分别用rest client调用这两个接口，然后再分别看下日志输出：

图－2.png

上图是第三方日志的输出日志，但是因为我们使用的环绕增强，因此日志输出基本都是一样的，只能根据目标类来具体区分执行哪个类的哪个方法。
接下来我们看看非第三方的日志输出，即我们的主要日志文件：

图－3.png
我们看到service中和第三方相关方法内部的日志依然会输出到文件中，感觉会显得很突兀。当然服务内调用的日志依然成功输出了。

---

方案3

方案3主要是针对方案2里面第三方日志依然会在非第三方日志文件输出的问题。首先我们需要先修改logback的配置文件，重新添加一个日志实例专门记录第三方相关的日志，然后将这个日志也输出到，修改如下：

<?xml version="1.0" encoding="UTF-8"?>
<configuration scan="true" scanPeriod="60 seconds">
    <property name="LOG_HOME" value="/home/ypcfly/ypcfly/Log" />
    <!-- 控制台设置 -->
    <appender name="CONSOLE" class="ch.qos.logback.core.ConsoleAppender">
        <encoder>
            <pattern>%d{MM-dd-yyyy HH:mm:ss} %-5level [%thread%X{sourceThread}]%logger{24}-%msg%n</pattern>
        </encoder>
    </appender>
    <!-- INFO -->
    <appender name="FILE" class="ch.qos.logback.core.rolling.RollingFileAppender">
        <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
            <!-- 文件名称 -->
            <fileNamePattern>${LOG_HOME}/log-file.%d{yyyy-MM-dd}.log</fileNamePattern>
            <MaxHistory>30</MaxHistory>
        </rollingPolicy>
        <triggeringPolicy class="ch.qos.logback.core.rolling.SizeBasedTriggeringPolicy">
            <MaxFileSize>50MB</MaxFileSize>
        </triggeringPolicy>
        <encoder>
            <pattern>%d{MM-dd-yyyy HH:mm:ss} %-5level [%thread]%logger{16} - %msg%n</pattern>
        </encoder>
    </appender>

    <!-- THIRD PART LOG -->
    <appender name="THIRD_FILE" class="ch.qos.logback.core.rolling.RollingFileAppender">
        <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
            <fileNamePattern>${LOG_HOME}/third-part-file.%d{yyyy-MM-dd}.log</fileNamePattern>
            <maxHistory>30</maxHistory>
        </rollingPolicy>
        <triggeringPolicy class="ch.qos.logback.core.rolling.SizeBasedTriggeringPolicy">
            <MaxFileSize>50MB</MaxFileSize>
        </triggeringPolicy>
        <encoder>
            <pattern>%d{MM-dd-yyyy HH:mm:ss} %-5level [%thread]%logger{16} - %msg%n</pattern>
        </encoder>
    </appender>
    <!-- 记录第三方切面日志的logger -->
    <logger name="com.ypc.logtest.logback.aop.ThirdLogAspect" additivity="false" level="INFO">
        <appender-ref ref="THIRD_FILE"/>
    </logger>
    <!-- 记录第三方service日志 -->
    <logger name="third_part_call_log" additivity="false" level="INFO">
        <appender-ref ref="THIRD_FILE"/>
    </logger>

    <root level="INFO">
        <appender-ref ref="CONSOLE"/>
        <appender-ref ref="FILE"/>
    </root>
</configuration>

接着将service中和第三方交互方法上添加的自定义的注解@ThirdPart去除掉，然后引入logback添加的logger，代码修改如下：

@Service
@Slf4j
public class CommonServiceImpl implements CommonService {

    private static final Logger LOGGER = LoggerFactory.getLogger("third_part_call_log"); 
    
    @Override
    public List<LocalDateTime> innerMethod(Long id, String name) {
        log.info(">>>> common service inner method start <<<<");

        List<LocalDateTime> list = new ArrayList<>();
        list.add(LocalDateTime.now());
        list.add(LocalDateTime.now());
        list.add(LocalDateTime.now());
        list.add(LocalDateTime.now());
        list.add(LocalDateTime.now());

        log.info(">>>> common service inner method end <<<<");
        return list;
    }

    @Override
    public List<LocalDateTime> thirdMethod(Integer id, String name, Integer age) {
        LOGGER.info(">>>> common service start, request params:id={}, name={}, age={} <<<<",id,name,age);
        List<LocalDateTime> list = new ArrayList<>();
        list.add(LocalDateTime.now());
        list.add(LocalDateTime.now().plusDays(1));
        list.add(LocalDateTime.now().plusDays(2));
        list.add(LocalDateTime.now().plusDays(3));

        LOGGER.info(">>>> common service third method end <<<<");
        return list;
    }
}

然后我们启动项目，重新使用rest client调用这两个接口，日志输出如下：

图－4.png
从上图可以看出日志的切面对controller依然有效，而service的日志输出已经是我们自定义的"third_part_call_log"了，这里要想看到具体的类和方法，需要专门在日志中添加，如果方法特别多的话，感觉也挺麻烦的。
图－5.png
这里面我们可以看到service和第三方相关的代码已经没有了，整个日志输出很正常了。其实不管方案2还是3都有个问题，那就是service中共用方法日志的问题，因为只能输出到一个日志文件，所以导致另一个日志文件没有相关日志，所以我觉得最好的还是方案1，但是感觉风险可能会比较大。
上面只是我能想到的几种方案，如果哪位小伙伴有更好的方案也请告知，大家可以交流一下，我们项目具体选择哪种方案还需要项目架构师确认。好了，今天关于使用AOP进行日志统一处理到这里了，代码上传到我的github