AOP与日志(上)

作者简介：大家好，我是smart哥，前中兴通讯、美团架构师，现某互联网公司CTO

联系qq：184480602，加我进群，大家一起学习，一起进步，一起对抗互联网寒冬

日志为什么很重要

和我一样，大部分野生程序员对日志的认识总是不够深刻，甚至觉得这玩意可有可无。关于日志，我印象最深的是在软件大道的一场面试。

面试官问了很多Java基础相关的问题，诸如反射、注解、动态代理以及MySQL优化相关的。看我答得还算中规中矩，面试官换了个方向，打算考察我解决问题的能力：

如果现在线上出了一个bug，你要怎么排查呢？

我当时脱口而出：

先看看对应的是哪个接口，然后打个断点观察参数顺便走读一遍代码。

现在想想，当时的自己听到这么简单的问题，觉得捡了一个大便宜，甚至还暗暗佩服自己考虑得很周到：要先推断出对应的接口。

不出所料，听完后面试官微笑地对我说：门口在那边。

我在第一家公司写代码时，从来没看过任何同事打日志，大家都是本地开发时简单粗暴地使用System.out.println()打印想看的信息，或者直接全程断点调试。加上系统本身用户量小，如果本地运行成功，那么线上大概率也不会有什么问题，即使有问题也可以直接本地启动断点排查。

但对于一些稍微有点规模的系统而言，这种方法完全行不通：

• 项目庞大，被拆分成多个服务，出于各方面的原因，本地启动的成本很高或者干脆本地环境无法启动，只能走预发
• 虽然确实可以远程断点调试，但也仅限于预发，线上环境不可能让你去打断点（我理解的远程断点调试其实是将请求转发到你本地）
• 线上数据和本地数据不一致，有时很难复现bug
• 即使可以本地调试，拉取最新master代码、启动项目、构造请求数据、断点走读等一系列操作还是太费事了

较为妥当的解决办法是：打日志、看日志。可以登录服务器看log，或者有些公司的运维会搭建专门的ELK日志系统，可以在页面上选择对应的机器并配合Lucene语句等进行日志查看。

复习AOP

AOP相信大家并不陌生，毕竟Spring除了IOC，最被人津津乐道的就是AOP。要利用AOP完成一个需求，通常包含以下几个部分：

• SpringBoot项目导入spring-boot-starter-aop依赖
• 编写切面类

• • 类上加@Aspect注解，表明这是一个切面类
  • 类上加@Component，把切面交给Spring管理（我们要切的Controller/Service都是Spring容器的，切面要对它们起作用，就必须同样进入容器）
  • 类内部配置切点表达式，比如@Pointcut("execution(* com.bravo.demo.controller.*.*(..))") 表示对com.bravo.demo.controller包下所有方法进行增强
  • 类内部编写增强逻辑，通常使用@Before、@Around声明这是一个增强，不同的注解增强的方式不同，比如@Before前置增强、@Around环绕增强

比如，现在我希望编写一个AOP，计算接口请求的耗时：

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

@Slf4j
@Aspect // 第一步：声明这是一个切面类
public class ApiTimeLogAspect {

    // 第三步：定义切点表达式，明确要对那些方法起作用（比如，只对com.bravo.demo.controller包的方法计算接口耗时）
    @Pointcut("execution(* com.bravo.demo.controller.*.*(..))")
    public void controllerPointcut() {
    }

    // 第四步：1.通过引用切点表达式，明确这个增强的应用规则。 2.编写增强逻辑
    @Around("controllerPointcut()")
    public Object doAround(ProceedingJoinPoint proceedingJoinPoint) throws Throwable {
        // 记录接口执行前的时间戳
        long startTime = System.currentTimeMillis();
        // 实际执行目标方法，类似动态代理的invoke()执行目标方法
        Object result = proceedingJoinPoint.proceed();
        // 计算接口耗时
        log.info("------------ 耗时: {} ms ------------", System.currentTimeMillis() - startTime);
        // 只做增强不做改变，还是要把接口原本的结果返回
        return result;
    }
}

你会发现少了第二步：把切面类交给Spring容器管理。

直接在ApiTimeLogAspect上加@Component是最省事的，但我个人喜欢另外封装一个@EnableXxx注解，单独作为开关：

/**
 * 开启接口耗时计算
 */
@Import(ApiTimeLogAspect.class)
@Retention(RetentionPolicy.RUNTIME)
@Target(ElementType.TYPE)
public @interface EnableApiTimeLog {
}

这个注解最重要的其实是@Import注解，它是Spring定义的注解，由Spring读取并执行：把对应的Bean实例化并加载到容器。所以

• @EnableApiTimeLog（其实核心还是@Import）
• @Import
• @Component

这三种形式本质是一样的，都是要把Bean交给Spring管理。

现在，我把@EnableApiTimeLog加在启动类上，开启AOP：

@EnableApiTimeLog
@MapperScan("com.bravo.demo.dao")
@SpringBootApplication
public class MybatisPlusDemoApplication {

    public static void main(String[] args) {
        SpringApplication.run(MybatisPlusDemoApplication.class, args);
    }

}

AOP打印请求相关日志

一般来说，配合@Slf4j我们会在一些关键代码里打印日志：

@Override
public ApiResultTO<UserVO> getUser(UserDTO userDTO) {
    try {
        userDTO.setUid(AirborneContext.getContext().getUid());
        return userService.getUser(userDTO);
    } catch (Exception e) {
        log.error("getUser接口错误， userDTO:{}，错误信息：{}", JSON.toJSONString(userDTO), JSON.toJSONString(e));
        return ApiResultTO.buildFailed(ErrorCodeEnum.ERR_INTEGRATION_ERROR.getMessage());
    }
}

但这个是局部的、特殊的日志，如果出错的接口刚好没有任何日志，线上出现问题时基本就是“抓瞎”，所以全局的、一般的日志记录很有必要。

通常来说，我们只关心一下几点：

• 接口URL：请求哪个接口
• 类名方法：我应该去哪个类、哪个方法排查
• 请求参数：引发问题的参数是什么（方便复现问题）
• 远程地址（可有可无）
• 接口耗时

ApiLogAspect

/**
 * 参数日志切面，用于打印请求参数、返回值、接口耗时
 */
@Slf4j
@Aspect
public class ApiLogAspect {

    // request获取的方式：1.自动注入 2.通过RequestContextHolder
//    @Autowired
//    private HttpServletRequest request;

    /**
     * SpringMVC自带的jackson，用来输出JSON
     */
    @Autowired
    private ObjectMapper objectMapper;

    /**
     * 如果你拷贝这个切面，只需要修改切点表达式
     */
    @Pointcut("execution(* com.bravo.demo.controller.*.*(..))")
    public void controllerPointcut() {
    }

    @Before("controllerPointcut()")
    public void doBefore(JoinPoint joinPoint) throws JsonProcessingException {

        // 通过Spring提供的请求上下文工具，获取request
        ServletRequestAttributes requestAttributes = (ServletRequestAttributes) RequestContextHolder.getRequestAttributes();
        HttpServletRequest request = requestAttributes.getRequest();
        // signature是方法签名，可以理解为对方法信息的封装
        Signature signature = joinPoint.getSignature();
        String methodName = signature.getName();

        // 根据signature判断当前请求属于哪类操作，前提是工程遵守标准的命名规范
        String operation = "";
        if (methodName.startsWith("list") || methodName.startsWith("query") || methodName.startsWith("get") || methodName.startsWith("select")) {
            operation = "查询";
        } else if (methodName.startsWith("save") || methodName.startsWith("add") || methodName.startsWith("insert")) {
            operation = "新增";
        } else if (methodName.startsWith("delete")) {
            operation = "删除";
        } else if (methodName.startsWith("update") || methodName.startsWith("modify")) {
            operation = "更新";
        }

        Class<?> controllerClazz = signature.getDeclaringType();
        // com.bravo.demo.controller.UserController
        String controllerName = controllerClazz.getName();
        // UserController
        String controllerSimpleName = controllerName.substring(controllerName.lastIndexOf(".") + 1);

        // 打印请求信息
        log.info("------------【{}】{}操作 ------------", controllerSimpleName, operation);
        log.info("接口URL: {} {}", request.getRequestURL().toString(), request.getMethod());
        log.info("类名方法: {}#{}()", controllerName, methodName);
        log.info("远程地址: {}", getClientIp(request));

        // 打印请求参数 TODO 敏感字段排除
        log.info("请求参数: {}", getParamJSon(request, joinPoint));
    }

    @Around("controllerPointcut()")
    public Object doAround(ProceedingJoinPoint proceedingJoinPoint) throws Throwable {
        long startTime = System.currentTimeMillis();
        Object result = proceedingJoinPoint.proceed();
        // TODO 敏感字段排除
        log.info("返回结果: {}", objectMapper.writeValueAsString(result));
        log.info("------------ 耗时: {} ms ------------", System.currentTimeMillis() - startTime);
        return result;
    }

    // --------- private methods ----------

    private String getParamJSon(HttpServletRequest request, JoinPoint joinPoint) throws JsonProcessingException {
        String requestType = request.getMethod();
        if ("GET".equals(requestType)) {
            // 如果是GET请求，直接返回QueryString
            return request.getQueryString();
        }

        // args长什么样呢？类似于Controller方法中的getUser(Long id, HttpServletRequest request)这种，可能有多个参数
        Object[] args = joinPoint.getArgs();
        Object[] arguments = new Object[args.length];

        for (int i = 0; i < args.length; i++) {
            // 只打印客户端传递的参数，排除Spring注入的参数，比如HttpServletRequest
            if (args[i] instanceof ServletRequest
                    || args[i] instanceof ServletResponse
                    || args[i] instanceof MultipartFile) {
                continue;
            }
            arguments[i] = args[i];
        }

        return objectMapper.writeValueAsString(arguments);
    }


    private String getClientIp(HttpServletRequest request) {
        // 一般都会有代理转发，真实的ip会放在X-Forwarded-For
        String xff = request.getHeader("X-Forwarded-For");
        if (xff == null) {
            return request.getRemoteAddr();
        } else {
            return xff.contains(",") ? xff.split(",")[0] : xff;
        }
    }

}

@EnableApiLog

/**
 * 开启参数日志打印
 */
@Import(ApiLogAspect.class)
@Retention(RetentionPolicy.RUNTIME)
@Target(ElementType.TYPE)
public @interface EnableApiLog {
}

启动类开启日志

@EnableApiLog
@MapperScan("com.bravo.demo.dao")
@SpringBootApplication
public class MybatisPlusDemoApplication {

    public static void main(String[] args) {
        SpringApplication.run(MybatisPlusDemoApplication.class, args);
    }

}

测试：

@Slf4j
@Validated
@RestController
public class UserController {

    @GetMapping("getUser")
    public MpUserPojo getUser(@NotNull(message = "id不能为空") Long id) {
        test();
        return null;
    }

    private void test(){
        System.out.println("test");
    }

    @PostMapping("updateBatchUser")
    public Result<Boolean> updateBatchUser(@Validated @RequestBody ValidationList<User> userList) {
        System.out.println(userList);
        return Result.success(null);
    }
}

接口内部调用private方法不会走AOP。

优化

如果你觉得切点表达式细粒度不够，可以试着改成注解的方式。

比如：

/**
 * 在需要记录接口请求信息的类或方法上添加
 */
@Retention(RetentionPolicy.RUNTIME)
@Target({ElementType.TYPE, ElementType.METHOD})
public @interface ApiLog {
}

修改ApiLogAspect的切点表达式：

/**
 * 对所有标记了@ApiLog的方法进行AOP日志记录
 */
@Pointcut("@annotation(com.bravo.demo.aspect.ApiLog)")
public void controllerPointcut() {
}

@Slf4j
@RestController
public class UserController {

    @GetMapping("getUser")
    public MpUserPojo getUser(@NotNull(message = "id不能为空") Long id) {
        test();
        return null;
    }

    private void test() {
        System.out.println("test");
    }

    /**
     * 给需要打印日志的接口方法加@ApiLog
     *
     * @param userList
     * @return
     */
    @ApiLog
    @PostMapping("updateBatchUser")
    public Result<Boolean> updateBatchUser(@Validated @RequestBody ValidationList<User> userList) {
        return Result.success(null);
    }
}

如果你希望更灵活一些，比如在Controller上加@ApiLog对所有方法记录日志的同时，为个别方法增加@IngoreApiLog排除日志，可以这样：

/**
 * 忽略日志
 */
@Retention(RetentionPolicy.RUNTIME)
@Target({ElementType.METHOD})
public @interface IgnoreApiLog {
}

/**
 * 类或方法上有@ApiLog && 没有@IgnoreApiLog
 */
@Pointcut("!@annotation(com.bravo.demo.aspect.IgnoreApiLog) " +
        "&& (@within(com.bravo.demo.aspect.ApiLog) || @annotation(com.bravo.demo.aspect.ApiLog))")
public void controllerPointcut() {
}

/**
 * Controller下所有方法都打印日志
 */
@Slf4j
@ApiLog
@RestController
public class UserController {

    @GetMapping("getUser")
    public MpUserPojo getUser(@NotNull(message = "id不能为空") Long id) {
        test();
        return null;
    }

    private void test() {
        System.out.println("test");
    }

    /**
     * 不打印日志
     *
     * @param userList
     * @return
     */
    @IgnoreApiLog
    @PostMapping("updateBatchUser")
    public Result<Boolean> updateBatchUser(@Validated @RequestBody ValidationList<User> userList) {
        return Result.success(null);
    }
}

作者简介：大家好，我是smart哥，前中兴通讯、美团架构师，现某互联网公司CTO

进群，大家一起学习，一起进步，一起对抗互联网寒冬