个人在 Spring 应用下切面日志实践分享

本文已参与「新人创作礼」活动，一起开启掘金创作之路。

前言

最近参与了几个项目的开发，感觉日志系统有点杂乱无章：有用 info 的有用 error 的，也有所有信息输出在单一文件里的

也可能是每个人排查错误的方式有差异，我个人比较习惯的一套日志记录的最佳实践原则大体如下：

• info 级别我理解是 提示，标记，通常我习惯拿来输出一些调试过程中的参数、结果、提示语信息，更严格的情况下上述信息也可以调整为 debug 级别
• warn 级别习惯拿来输出一些不影响程序运行但可能有风险或者可能与预期业务运行不同的信息
• error 级别输出确实阻碍系统运行或者业务上错误的结果，比如抛出的异常信息
• 一个全局 info 级别的文件（比如 application.log）来记录程序运行中所有的 info （及以上）信息，该文件的主要用途是个人在非本地环境下调试时，在全局文件下方便查看自己的输出标识（一般调试完后会移除相关输出代码）
• 一个全局 error 级别的文件（比如 error.log）来记录所有程序中的 error 信息，该文件主要是总览所有报错信息，方便快速定位异常、做相关预警操作等
• 个人习惯以层级维度划分日志文件来记录该层级下所有的 info （及以上）信息，比如 controller（web） service 层，这样排查错误更具有针对性，可以层层递推排查问题，该部分的实现通常依托于 Spring AOP

分享一份个人 demo，该 demo 基于 SpringBoot + Logback（默认） 实现，通过 Logback 配置 + Spring AOP 完成日志的记录

logback-spring.xml

先贴一份 logback 配置，相对通用可用作参考，定义了最佳实践中提到一些常规的 Logger 比如 CONSOLE application error controller service，详情如下

<?xml version="1.0" encoding="UTF-8"?>
<configuration>

    <include resource="org/springframework/boot/logging/logback/defaults.xml"/>
    <springProperty scope="context" name="springAppName" source="spring.application.name"/>

    <!-- spring cloud sleuth 下适用 -->
    <property name="PATTERN"
              value="%clr(%d{yyyy-MM-dd HH:mm:ss.SSS}){faint} %clr(${LOG_LEVEL_PATTERN:-%5p}) %clr(${PID:- }){magenta} %clr(---){faint} %clr([%15.15t]){faint} %clr(%-40.40logger{39}){cyan} %clr(:){faint} %m%n${LOG_EXCEPTION_CONVERSION_WORD:-%wEx}"/>

    <appender name="CONSOLE" class="ch.qos.logback.core.ConsoleAppender">
        <encoder>
            <pattern>${PATTERN}</pattern>
            <charset>utf8</charset>
        </encoder>
    </appender>

    <appender name="application"
              class="ch.qos.logback.core.rolling.RollingFileAppender">
        <file>application.log</file>
        <encoder>
            <pattern>${PATTERN}</pattern>
        </encoder>
        <rollingPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedRollingPolicy">
            <fileNamePattern>application.%d{yyyy-MM-dd}.%i.log</fileNamePattern>
            <maxHistory>7</maxHistory>
            <maxFileSize>50MB</maxFileSize>
            <totalSizeCap>10GB</totalSizeCap>
        </rollingPolicy>

        <filter class="ch.qos.logback.classic.filter.ThresholdFilter">
            <level>info</level>
        </filter>
    </appender>

    <appender name="controller"
              class="ch.qos.logback.core.rolling.RollingFileAppender">
        <file>controller.log</file>
        <encoder>
            <pattern>${PATTERN}</pattern>
        </encoder>
        <rollingPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedRollingPolicy">
            <fileNamePattern>controller.%d{yyyy-MM-dd}.%i.log</fileNamePattern>
            <maxHistory>7</maxHistory>
            <maxFileSize>50MB</maxFileSize>
            <totalSizeCap>10GB</totalSizeCap>
        </rollingPolicy>

        <filter class="ch.qos.logback.classic.filter.ThresholdFilter">
            <level>info</level>
        </filter>
    </appender>

    <appender name="service"
              class="ch.qos.logback.core.rolling.RollingFileAppender">
        <file>service.log</file>
        <encoder>
            <pattern>${PATTERN}</pattern>
        </encoder>
        <rollingPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedRollingPolicy">
            <fileNamePattern>service.%d{yyyy-MM-dd}.%i.log</fileNamePattern>
            <maxHistory>7</maxHistory>
            <maxFileSize>50MB</maxFileSize>
            <totalSizeCap>10GB</totalSizeCap>
        </rollingPolicy>

        <filter class="ch.qos.logback.classic.filter.ThresholdFilter">
            <level>info</level>
        </filter>
    </appender>

    <appender name="error"
              class="ch.qos.logback.core.rolling.RollingFileAppender">
        <file>error.log</file>
        <encoder>
            <pattern>${PATTERN}</pattern>
        </encoder>
        <rollingPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedRollingPolicy">
            <fileNamePattern>error.%d{yyyy-MM-dd}.%i.log</fileNamePattern>
            <maxHistory>7</maxHistory>
            <maxFileSize>50MB</maxFileSize>
            <totalSizeCap>10GB</totalSizeCap>
        </rollingPolicy>

        <filter class="ch.qos.logback.classic.filter.ThresholdFilter">
            <level>error</level>
        </filter>
    </appender>

    <root level="info">
        <appender-ref ref="CONSOLE" />
        <appender-ref ref="application"/>
        <appender-ref ref="error"/>
    </root>

    <logger name="application" level="info" additivity="false">
        <appender-ref ref="application"/>
        <appender-ref ref="error"/>
    </logger>
    <logger name="controller" level="info" additivity="false">
        <appender-ref ref="controller"/>
        <appender-ref ref="error"/>
    </logger>
    <logger name="service" level="info" additivity="false">
        <appender-ref ref="service"/>
        <appender-ref ref="error"/>
    </logger>
</configuration>

• PATTERN 适用于引入 spring-cloud-sleuth 的项目，否则日志格式会有点怪异但不影响查看
• application 是默认 Logger，error 记录全局 ERROR 级别信息

LogRecorder

public interface LogRecorder {

    // 获取适合的 logger
    Logger getLogger();

    default void warn(String message) {
        Optional.ofNullable(getLogger())
                .ifPresent(logger -> logger.warn(message));
    }

    default void info(String message) {
        Optional.ofNullable(getLogger())
                .ifPresent(logger -> logger.info(message));
    }

    default void error(String message) {
        Optional.ofNullable(getLogger())
                .ifPresent(logger -> logger.error(message));
    }
}

• 顶层接口，主要提供了 info warn error 方法的常规实现
• getLogger 方法获取适合的 Logger 对象由子类复写

SimpleLogRecorder

@Component
public class SimpleLogRecorder implements LogRecorder {

    public static final String APPLICATION_LOGGER_NAME = "application";

    @Override
    public Logger getLogger() {

        return LoggerFactory.getLogger(APPLICATION_LOGGER_NAME);
    }
}

• 一个通用实现，该类实际就是用来记录全局 info 文件的，默认由 application 记录
• 该类是一个 bean 组件，可直接注入使用

CommonPointcuts

public class CommonPointcuts {

	// web 层，通常为 controller 层
    @Pointcut("execution(* com.example.logapp.controller.*.*(..))")
    public void webLayerPointcut() {

    }

	// 逻辑层，通常即 service 层
    @Pointcut("execution(* com.example.logapp.service.*.*(..))")
    public void serviceLayerPointcut() {

    }
}

切面层基类，维护切面的最佳实践，可用于具体切面通知的 Pointcut 声明

AopLogRecorder

public interface AopLogRecorder extends LogRecorder {

    /**
     * Before 切面，默认记录参数信息
     * @param jp
     */
    default void before(JoinPoint jp) {
        String className = jp.getSignature().getDeclaringTypeName();
        String methodName = jp.getSignature().getName();
        Object[] args = jp.getArgs();
        info(MessageFormat.format(
                "开始调用目标方法 - {0}#{1}，参数为: {2}"
                , className, methodName, JSONObject.toJSONString(args)
        ));
    }

    /**
     * AfterReturning 切面，默认描述返回结果，仅处理 ResponseEntity
     * @param jp
     * @param retVal
     */
    default void afterReturning(JoinPoint jp, ResponseEntity retVal) {
        String className = jp.getSignature().getDeclaringTypeName();
        String methodName = jp.getSignature().getName();
        info(MessageFormat.format(
                "调用目标方法{3} - {0}#{1}，结果为: {2}"
                , className, methodName, JSONObject.toJSONString(retVal)
                , retVal.getSuccessFlag() ? "成功" : "失败"
        ));
    }

    /**
     * AfterThrow 切面，默认记录报错信息
     * @param jp
     * @param e
     */
    default void afterThrow(JoinPoint jp, Throwable e) {
        String className = jp.getSignature().getDeclaringTypeName();
        String methodName = jp.getSignature().getName();
        error(MessageFormat.format(
                "调用目标方法异常 - {0}#{1}，异常信息: {2}"
                , className, methodName, e.getMessage()
        ));
    }

    /**
     * Around 通知，这里会捕获掉异常进行处理，适合 web layer
     * @param pjp
     */
    default Object around(ProceedingJoinPoint pjp) {
        String className = pjp.getSignature().getDeclaringTypeName();
        String methodName = pjp.getSignature().getName();
        Object[] args = pjp.getArgs();

        info(MessageFormat.format(
                "调用目标方法 - {0}#{1}，参数为: {2}"
                , className, methodName, JSONObject.toJSONString(args)
        ));

        Object retVal = null;
        try {
            retVal = pjp.proceed();
        } catch (Throwable e) {
            error(MessageFormat.format(
                    "调用目标方法异常 - {0}#{1}，异常信息: {2}"
                    , className, methodName, e.getMessage()
            ));
            return ResponseEntity.error();
        }

        Optional.ofNullable(retVal)
                .filter(result -> result instanceof ResponseEntity)
                .map(result -> (ResponseEntity) result)
                .ifPresent(t -> info(MessageFormat.format(
                        "调用目标方法{3} - {0}#{1}，结果为: {2}"
                        , className, methodName, JSONObject.toJSONString(t)
                        , t.getSuccessFlag() ? "成功" : "失败"
                )));
        return retVal;
    }
}

• 切面日志基类
• 提供 before afterReturning afterThrow 的默认实现：before 通常记录参数信息、afterReturning 提供记录结果信息、afterThrow 记录报错的异常信息，可由子类选择性的使用，比如 service 层的日志处理
• 提供 around 默认实现，一站式的通用日志处理，同时会包装处理方法执行异常的情况，比如 web 层的日志处理
• 子类可进行选择性的覆盖以实现对应场景功能

WebLayerAopLogRecorder

@Aspect
@Component
public class WebLayerAopLogRecorder implements AopLogRecorder {

    private static final String WEB_LAYER_LOGGER_NAME = "controller";

    @Override
    @Around("com.example.logapp.log.CommonPointcuts.webLayerPointcut()")
    public Object around(ProceedingJoinPoint pjp) {
        return AopLogRecorder.super.around(pjp);
    }

    @Override
    public Logger getLogger() {

        return LoggerFactory.getLogger(WEB_LAYER_LOGGER_NAME);
    }
}

• 最终的日志切面层实现
• 此处是 controller 层的切面，沿用父类定义的 around 切面通知，指定对应的 Pointcut
• getLogger() 方法指定对应的 Logger 为 controller

ServiceLayerAopLogRecorder

@Aspect
@Component
public class ServiceLayerAopLogRecorder implements AopLogRecorder {

    private static final String SERVICE_LAYER_LOGGER_NAME = "service";

    @Override
    @Before("com.example.logapp.log.CommonPointcuts.serviceLayerPointcut()")
    public void before(JoinPoint jp) {
        AopLogRecorder.super.before(jp);
    }

    @Override
    @AfterReturning(
            pointcut = "com.example.logapp.log.CommonPointcuts.serviceLayerPointcut()"
            , returning = "retVal"
    )
    public void afterReturning(JoinPoint jp, ResponseEntity retVal) {
        AopLogRecorder.super.afterReturning(jp, retVal);
    }

    @Override
    @AfterThrowing(
            pointcut = "com.example.logapp.log.CommonPointcuts.serviceLayerPointcut()"
            , throwing = "e"
    )
    public void afterThrow(JoinPoint jp, Throwable e) {
        AopLogRecorder.super.afterThrow(jp, e);
    }

    @Override
    public Logger getLogger() {

        return LoggerFactory.getLogger(SERVICE_LAYER_LOGGER_NAME);
    }
}

• 同上，此处是 service 层的切面日志处理，采用细粒度的切面逻辑分别处理方法执行前后的记录操作
• getLogger() 方法指定对应的 Logger 为 service

SimpleLogRecorder 使用

@Component
public class TestApp {

    @Autowired
    SimpleLogRecorder simpleLogRecorder;

    public String hello(String name) {

        simpleLogRecorder.info(name);
        return "hello " + name;
    }
}

• 上述的场景一般都维护固定的日志信息：比如 入参、返回值 等，但在具体的调试场景中往往需要一些赋值信息的输出才能更好的定位问题
• 此时使用全局的 info 记录即可，在此 demo 中直接注入 SimpleLogRecorder 组件使用即可

总结

本文分享了个人在 Spring 应用下切面日志最佳实践，整合 Spring Cloud Sleuth 后有了 traceId 的协助，更是能在多链路调用中快速定位问题，加快前后端沟通效率