Java如何实现方法调用日志记录？

1.背景   

SpringBoot项目中，之前都是在controller方法的第一行手动打印 log，return之前再打印返回值。有多个返回点时，就需要出现多少重复代码，过多的非业务代码显得十分凌乱。

本文将采用AOP 配置自定义注解实现 入参、出参的日志打印（方法的入参和返回值都采用 fastjson 序列化）。

2.设计思路

将特定包下所有的controller生成代理类对象，并交由Spring容器管理，并重写invoke方法进行增强(入参、出参的打印).

3.核心代码

3.1 自定义注解

@Target(ElementType.TYPE)
@Retention(RetentionPolicy.RUNTIME)
@Documented
@Import({InteractRecordBeanPostProcessor.class})
public @interface EnableInteractRecord {

    /**
     * app对应controller包名
     */
    String[] basePackages() default {};

    /**
     * 排除某些包
     */
    String[] exclusions() default {};

}

3.2 实现BeanFactoryPostProcessor接口

作用：获取EnableInteractRecord注解对象，用于获取需要创建代理对象的包名，以及需要排除的包名

@Component
public class InteractRecordFactoryPostProcessor implements BeanFactoryPostProcessor {

    private static Logger logger = LoggerFactory.getLogger(InteractRecordFactoryPostProcessor.class);

    private EnableInteractRecord enableInteractRecord;

    @Override
    public void postProcessBeanFactory(ConfigurableListableBeanFactory beanFactory) throws BeansException {
        try {
            String[] names = beanFactory.getBeanNamesForAnnotation(EnableInteractRecord.class);
            for (String name : names) {
                enableInteractRecord = beanFactory.findAnnotationOnBean(name, EnableInteractRecord.class);
                logger.info("开启交互记录 ", enableInteractRecord);
            }
        } catch (Exception e) {
            logger.error("postProcessBeanFactory() Exception ", e);
        }
    }

    public EnableInteractRecord getEnableInteractRecord() {
        return enableInteractRecord;
    }

}

3.3 实现MethodInterceptor编写打印日志逻辑

作用：进行入参、出参打印，包含是否打印逻辑

@Component
public class ControllerMethodInterceptor implements MethodInterceptor {
    private static Logger logger = LoggerFactory.getLogger(ControllerMethodInterceptor.class);
    // 请求开始时间
    ThreadLocal startTime = new ThreadLocal<>();
    private String localIp = "";

    @PostConstruct
    public void init() {
        try {
            localIp = InetAddress.getLocalHost().getHostAddress();
        } catch (UnknownHostException e) {
            logger.error("本地IP初始化失败 : ", e);
        }
    }

    @Override
    public Object invoke(MethodInvocation invocation) {
        pre(invocation);
        Object result;
        try {
            result = invocation.proceed();
            post(invocation, result);
            return result;
        } catch (Throwable ex) {
            logger.error("controller 执行异常: ", ex);
            error(invocation, ex);
        }

        return null;

    }

    public void error(MethodInvocation invocation, Throwable ex) {
        String msgText = ex.getMessage();
        logger.info(startTime.get() + " 异常，请求结束");
        logger.info("RESPONSE : " + msgText);
        logger.info("SPEND TIME : " + (System.currentTimeMillis() - startTime.get()));
    }

    private void pre(MethodInvocation invocation) {
        long now = System.currentTimeMillis();
        startTime.set(now);
        logger.info(now + " 请求开始");
        ServletRequestAttributes attributes = (ServletRequestAttributes) RequestContextHolder.getRequestAttributes();
        HttpServletRequest request = attributes.getRequest();

        logger.info("URL : " + request.getRequestURL().toString());
        logger.info("HTTP_METHOD : " + request.getMethod());
        logger.info("REMOTE_IP : " + getRemoteIp(request));
        logger.info("LOCAL_IP : " + localIp);
        logger.info("METHOD : " + request.getMethod());
        logger.info("CLASS_METHOD : " + getTargetClassName(invocation) + "." + invocation.getMethod().getName());

        // 获取请求头header参数
        Map map = new HashMap();
        Enumeration headerNames = request.getHeaderNames();
        while (headerNames.hasMoreElements()) {
            String key = (String) headerNames.nextElement();
            String value = request.getHeader(key);
            map.put(key, value);
        }
        logger.info("HEADERS : " + JSONObject.toJSONString(map));
        Date createTime = new Date(now);
        // 请求报文
        Object[] args = invocation.getArguments();// 参数
        String msgText = "";
        Annotation[][] annotationss = invocation.getMethod().getParameterAnnotations();

        for (int i = 0; i < args.length; i++) {
            Object arg = args[i];
            if (!(arg instanceof ServletRequest)
                    && !(arg instanceof ServletResponse)
                    && !(arg instanceof Model)) {
                RequestParam rp = null;
                Annotation[] annotations = annotationss[i];
                for (Annotation annotation : annotations) {
                    if (annotation instanceof RequestParam) {
                        rp = (RequestParam) annotation;
                    }
                }
                if (msgText.equals("")) {
                    msgText += (rp != null ? rp.value() + " = " : " ") + JSONObject.toJSONString(arg);
                } else {
                    msgText += "," + (rp != null ? rp.value() + " = " : " ") + JSONObject.toJSONString(arg);
                }
            }
        }
        logger.info("PARAMS : " + msgText);
    }

    private void post(MethodInvocation invocation, Object result) {
        logger.info(startTime.get() + " 请求结束");
        if (!(result instanceof ModelAndView)) {
            String msgText = JSONObject.toJSONString(result);
            logger.info("RESPONSE : " + msgText);
        }
        logger.info("SPEND TIME : " + (System.currentTimeMillis() - startTime.get()));

    }


    private String getRemoteIp(HttpServletRequest request) {
        String remoteIp = null;
        String remoteAddr = request.getRemoteAddr();
        String forwarded = request.getHeader("X-Forwarded-For");
        String realIp = request.getHeader("X-Real-IP");
        if (realIp == null) {
            if (forwarded == null) {
                remoteIp = remoteAddr;
            } else {
                remoteIp = remoteAddr + "/" + forwarded.split(",")[0];
            }
        } else {
            if (realIp.equals(forwarded)) {
                remoteIp = realIp;
            } else {
                if (forwarded != null) {
                    forwarded = forwarded.split(",")[0];
                }
                remoteIp = realIp + "/" + forwarded;
            }
        }
        return remoteIp;
    }

    private String getTargetClassName(MethodInvocation invocation) {
        String targetClassName = "";
        try {
            targetClassName = AopTargetUtils.getTarget(invocation.getThis()).getClass().getName();
        } catch (Exception e) {
            targetClassName = invocation.getThis().getClass().getName();
        }
        return targetClassName;
    }

}

AopTargetUtils：

public class AopTargetUtils {  
  
      
    /** 
     * 获取 目标对象 
     * @param proxy 代理对象 
     * @return  
     * @throws Exception 
     */  
    public static Object getTarget(Object proxy) throws Exception {  
          
        if(!AopUtils.isAopProxy(proxy)) {
            return proxy;//不是代理对象  
        }  
          
        if(AopUtils.isJdkDynamicProxy(proxy)) {
            return getJdkDynamicProxyTargetObject(proxy);  
        } else { //cglib  
            return getCglibProxyTargetObject(proxy);  
        }  
          
          
          
    }  
  
  
    private static Object getCglibProxyTargetObject(Object proxy) throws Exception {  
        Field h = proxy.getClass().getDeclaredField("CGLIB$CALLBACK_0");  
        h.setAccessible(true);
        Object dynamicAdvisedInterceptor = h.get(proxy);  
          
        Field advised = dynamicAdvisedInterceptor.getClass().getDeclaredField("advised");  
        advised.setAccessible(true);  
          
        Object target = ((AdvisedSupport)advised.get(dynamicAdvisedInterceptor)).getTargetSource().getTarget();
          
        return getTarget(target);
    }  
  
  
    private static Object getJdkDynamicProxyTargetObject(Object proxy) throws Exception {  
        Field h = proxy.getClass().getSuperclass().getDeclaredField("h");  
        h.setAccessible(true);  
        AopProxy aopProxy = (AopProxy) h.get(proxy);
          
        Field advised = aopProxy.getClass().getDeclaredField("advised");  
        advised.setAccessible(true);  
          
        Object target = ((AdvisedSupport)advised.get(aopProxy)).getTargetSource().getTarget();
          
        return getTarget(target); 
    }  
      
}

3.4 实现BeanPostProcessor接口

作用：筛选出需要生成代理的类，并生成代理类，返回给Spring容器管理。

public class InteractRecordBeanPostProcessor implements BeanPostProcessor {

    private static Logger logger = LoggerFactory.getLogger(InteractRecordBeanPostProcessor.class);

    @Autowired
    private InteractRecordFactoryPostProcessor interactRecordFactoryPostProcessor;

    @Autowired
    private ControllerMethodInterceptor controllerMethodInterceptor;

    private String BASE_PACKAGES[];//需要拦截的包

    private String EXCLUDING[];// 过滤的包

    //一层目录匹配
    private static final String ONE_REGEX = "[a-zA-Z0-9_]+";

    //多层目录匹配
    private static final String ALL_REGEX = ".*";

    private static final String END_ALL_REGEX = "*";

    @PostConstruct
    public void init() {
        EnableInteractRecord ir = interactRecordFactoryPostProcessor.getEnableInteractRecord();
        BASE_PACKAGES = ir.basePackages();
        EXCLUDING = ir.exclusions();
    }

    @Override
    public Object postProcessAfterInitialization(Object bean, String beanName) throws BeansException {
        try {
            if (interactRecordFactoryPostProcessor.getEnableInteractRecord() != null) {
                // 根据注解配置的包名记录对应的controller层
                if (BASE_PACKAGES != null && BASE_PACKAGES.length > 0) {
                    Object proxyObj = doEnhanceForController(bean);
                    if (proxyObj != null) {
                        return proxyObj;
                    }
                }
            }
        } catch (Exception e) {
            logger.error("postProcessAfterInitialization() Exception ", e);
        }
        return bean;
    }

    @Override
    public Object postProcessBeforeInitialization(Object bean, String beanName) throws BeansException {
        return bean;
    }

    private Object doEnhanceForController(Object bean) {
        String beanPackageName = getBeanPackageName(bean);
        if (StringUtils.isNotBlank(beanPackageName)) {
            for (String basePackage : BASE_PACKAGES) {
                if (matchingPackage(basePackage, beanPackageName)) {
                    if (EXCLUDING != null && EXCLUDING.length > 0) {
                        for (String excluding : EXCLUDING) {
                            if (matchingPackage(excluding, beanPackageName)) {
                                return bean;
                            }
                        }
                    }
                    Object target = null;
                    try {
                        target = AopTargetUtils.getTarget(bean);
                    } catch (Exception e) {
                        logger.error("AopTargetUtils.getTarget() exception", e);
                    }
                    if (target != null) {
                        boolean isController = target.getClass().isAnnotationPresent(Controller.class);
                        boolean isRestController = target.getClass().isAnnotationPresent(RestController.class);
                        if (isController || isRestController) {
                            ProxyFactory proxy = new ProxyFactory();
                            proxy.setTarget(bean);
                            proxy.addAdvice(controllerMethodInterceptor);
                            return proxy.getProxy();
                        }
                    }
                }
            }

        }
        return null;
    }

    private static boolean matchingPackage(String basePackage, String currentPackage) {
        if (StringUtils.isEmpty(basePackage) || StringUtils.isEmpty(currentPackage)) {
            return false;
        }
        if (basePackage.indexOf("*") != -1) {
            String patterns[] = StringUtils.split(basePackage, ".");
            for (int i = 0; i < patterns.length; i++) {
                String patternNode = patterns[i];
                if (patternNode.equals("*")) {
                    patterns[i] = ONE_REGEX;
                }
                if (patternNode.equals("**")) {
                    if (i == patterns.length - 1) {
                        patterns[i] = END_ALL_REGEX;
                    } else {
                        patterns[i] = ALL_REGEX;
                    }
                }
            }
            String basePackageRegex = StringUtils.join(patterns, "\\.");
            Pattern r = Pattern.compile(basePackageRegex);
            Matcher m = r.matcher(currentPackage);
            return m.find();
        } else {
            return basePackage.equals(currentPackage);
        }
    }

    private String getBeanPackageName(Object bean) {
        String beanPackageName = "";
        if (bean != null) {
            Class beanClass = bean.getClass();
            if (beanClass != null) {
                Package beanPackage = beanClass.getPackage();
                if (beanPackage != null) {
                    beanPackageName = beanPackage.getName();
                }
            }
        }
        return beanPackageName;
    }

}

3.5 启动类配置注解

@EnableInteractRecord(basePackages = “com.test.test.controller”,exclusions = “com.test.demo.controller”)

以上即可实现入参、出参日志统一打印，并且可以将特定的controller集中管理，并不进行日志的打印（及不进生成代理类）。

4.出现的问题(及其解决办法)

实际开发中，特定不需要打印日志的接口，无法统一到一个包下。大部分需要打印的接口，和不需要打印的接口，大概率会参杂在同一个controller中，根据以上设计思路，无法进行区分。

解决办法：

自定义排除入参打印注解

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

自定义排除出参打印注解

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

增加逻辑

// 1.在解析requestParam之前进行判断
        Method method = invocation.getMethod();
        Annotation[] declaredAnnotations = method.getDeclaredAnnotations();
        boolean flag = true;
        for (Annotation annotation : declaredAnnotations) {
            if (annotation instanceof ExcludeReqLog) {
                flag = false;
            }
        }
        if (!flag) {
            logger.info("该方法已排除，不打印入参");
            return;
        }
// 2.在解析requestResp之前进行判断
        Method method = invocation.getMethod();
        Annotation[] declaredAnnotations = method.getDeclaredAnnotations();
        boolean flag = true;
        for (Annotation annotation : declaredAnnotations) {
            if (annotation instanceof ExcludeRespLog) {
                flag = false;
            }
        }
        if (!flag) {
            logger.info("该方法已排除，不打印出参");
            return;
        }

使用方法

// 1.不打印入参
    @PostMapping("/uploadImg")
    @ExcludeReqLog
    public Result> uploadIdeaImg(@RequestParam(value = "imgFile", required = false) MultipartFile[] imgFile) {
        return demoService.uploadIdeaImg(imgFile);
    }
//2.不打印出参
    @PostMapping("/uploadImg")
    @ExcludeRespLog 
    public Result> uploadIdeaImg(@RequestParam(value = "imgFile", required = false) MultipartFile[] imgFile) {
        return demoService.uploadIdeaImg(imgFile);
    }