面向切面编程-日志切面应用及MDC使用

简介：

　　AOP：面向切面编程，即拓展功能不通过修改源代码实现，采用横向抽取机制，取代了传统的纵向继承体系重复性代码。在运行期通过代理方式向目标类织入增强代码。

　　Aspecj：Aspecj 是一个基于java语言的AOP框架，spring2.0开始，spring AOP引入对Aspect的支持，Aspect扩展了Java语言，提供了一个专门的编译器，在编译时提供横向代码的织入。

　　使用aspectj实现aop有两种方式
　　　　（1）基于aspectj的xml配置
　　　　（2）基于aspectj的注解方式

Spring AOP底层代理机制：

1、JDK动态代理：针对实现了接口的类产生代理

2、CGLib动态代理：针对没有实现接口的类产生代理，应用的是底层的字节码增强技术来生成当前类的子类对象。

面向切面相关术语：

　　JoinPoint（连接点）：能被拦截的点，即类里面可以被增强的方法，这些方法称为连接点，Spring只支持方法类型的连接点。

　　PointCut（切入点）：实际对JoinPoint中拦截的点，即实际增强的方法成为切入点。

　　Advice（通知/增强）：所谓增强是指拦截到JoinPoint之后所要做的事情。（比如扩展的日志功能就是增强），通知分为：

　　　　前置增强@Before：在方法（切入点）之前执行的增强

　　　　后置增强@After：在方法（切入点）之后执行的增强

　　　　异常增强@AfterThrowing：在方法执行出现异常的时候执行的增强

　　　　//最终增强：在后置通知之后执行，无论目标方法是否出现异常，都会执行的增强，好像没有这个

　　　　环绕增强@Around：在方法之前和之后都执行的增强

　　　　返回增强@AfterReturning：在方法正常返回之后执行

　　Aspect（切面）：切入点和增强的结合，即将通知应用到具体方法上的过程

　　Introduction(引介):引介是一种特殊的通知在不修改类代码的前提下, Introduction 可以在运行期为类动态地添加一些方法或 Field.（一般不用）

　　Target（目标对象）：代理的目标对象，即要增强的类

　　Weaving（织入）：是指把增强应用到目标对象来创建新的代理对象的过程

　　Proxy（ 代理） :一个类被 AOP 织入增强后， 就产生一个结果代理类

 　　

实践：

　　导入aop相关的包

<!--注解和aop的jar包-->
<dependency>
  <groupId>org.springframework</groupId>
  <artifactId>spring-aop</artifactId>
  <version>4.2.5.RELEASE</version>
</dependency>
<dependency>
  <groupId>aopalliance</groupId>
  <artifactId>aopalliance</artifactId>
  <version>1.0</version>
</dependency>
<dependency>
  <groupId>org.aspectj</groupId>
  <artifactId>aspectjweaver</artifactId>
  <version>1.8.0</version>
</dependency>
<dependency>
  <groupId>org.springframework</groupId>
  <artifactId>spring-aspects</artifactId>
  <version>4.2.5.RELEASE</version>
</dependency>

Spring核心配置文件导入AOP约束

<?xml version="1.0" encoding="UTF-8"?>
<beans xmlns="http://www.springframework.org/schema/beans"
       xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
       xmlns:context="http://www.springframework.org/schema/context"
       xmlns:aop="http://www.springframework.org/schema/aop"
       xsi:schemaLocation="
        http://www.springframework.org/schema/beans http://www.springframework.org/schema/beans/spring-beans.xsd
        http://www.springframework.org/schema/context http://www.springframework.org/schema/context/spring-context.xsd
        http://www.springframework.org/schema/aop http://www.springframework.org/schema/aop/spring-aop.xsd">
</beans>

通过execution函数，可以定义切点的方法切入
语法：
　　execution(<访问修饰符>?<返回类型><方法名>(<参数>)<异常>)
例如：
1、匹配所有类public方法 execution(public * * (..))
2、匹配指定包下所有类中的方法 execution(* cn.com.yang.dao.*(..)) 不包含子包
execution(* cn.com.yang.dao..*(..)) 包含本包，子孙包下的所有类
3、匹配指定类所有方法 execution(* cn.com.yang.dao.UserDao*(..) )
4、匹配实现特定接口所有类中的方法 execution(* cn.com.yang.dao.GenericDao+.*(..))
5、匹配所有save开头的方法 execution(* save*(..))
6、所有方法 execution(* * . *(..))

基于XML的AOP：

aop增强类：

/**
 * aop增强类
 */
public class MyUserAop {
    //前置通知
    public void before1() {
        System.out.println("前置增强......");
    }
    //后置通知
    public void after1() {
        System.out.println("后置增强......");
    }

    //环绕通知
    public void around1(ProceedingJoinPoint proceedingJoinPoint) throws Throwable {
        //方法之前
        System.out.println("方法之前.....");

        //执行被增强的方法
        proceedingJoinPoint.proceed();

        //方法之后
        System.out.println("方法之后.....");
    }
}

切入点，即实际要增强的方法：

// User实体的add方法
public void add(){
    System.out.println("user的add方法");
}

Spring配置文件中的配置

<!--装配aop增强类-->
<bean id="myUserAop" class="cn.com.yang.common.MyUserAop"/>

<aop:config>
    <!--定义切入点-->
    <aop:pointcut id="pointcut1" expression="execution(* cn.com.yang.modules.base.model.User.add(..))"/>
    <!--定义切面-->
    <aop:aspect ref="myUserAop" order="1">
        <aop:before method="before1" pointcut-ref="pointcut1"/>
        <aop:after method="after1" pointcut-ref="pointcut1"/>
    </aop:aspect>
</aop:config>

输出结果：

　　前置增强......

　　user的add方法

　　后置增强......

基于AspectJ注解的AOP：

1、在Spring核心配置文件中配置，开启AOP扫描

<!--
开启aop扫描
自动为spring容器中那些配置@aspectJ切面的bean创建代理，织入切面。当然，spring
在内部依旧采用AnnotationAwareAspectJAutoProxyCreator进行自动代理的创建工作，但具体实现的细节已经被<aop:aspectj-autoproxy />隐藏起来了
<aop:aspectj-autoproxy />有一个proxy-target-class属性，默认为false，表示使用jdk动态代理织入增强，当配为<aop:aspectj-autoproxy  poxy-target-class="true"/>时，
表示使用CGLib动态代理技术织入增强。不过即使proxy-target-class设置为false，如果目标类没有声明接口，则spring将自动使用CGLib动态代理。
-->
<aop:aspectj-autoproxy/>

<!--aop增强类-->
<bean id="myUserAop" class="cn.com.yang.common.MyUserAop"/>

2、在增强类上面使用注解@Aspect

3、在增强类的方法上使用注解配置切入点表达式

配置之后的增强类：

/**
 * aop增强类
 */
@Aspect
public class MyUserAop {
    //前置通知
    @Before(value = "execution(* cn.com.yang.modules.base.model.User.*(..))")
    public void before1() {
        System.out.println("前置增强......");
    }
    //后置通知
    @After(value = "execution(* cn.com.yang.modules.base.model.User.*(..))")
    public void after1() {
        System.out.println("后置增强......");
    }

    //环绕通知
    @Around(value = "execution(* cn.com.yang.modules.base.model.User.*(..))")
    public void around1(ProceedingJoinPoint proceedingJoinPoint) throws Throwable {
        //方法之前
        System.out.println("方法之前.....");

        //执行被增强的方法
        proceedingJoinPoint.proceed();

        //方法之后
        System.out.println("方法之后.....");
    }
}

执行结果：

　　方法之前.....

　　前置增强......

　　user的add方法

　　方法之后.....

　　后置增强......

AOP应用：

　　在实际的应用中，每个方法内逻辑处理前可能都要打印入参信息，方法执行结束再打印返回结果。那么就可以使用AOP的横向抽取机制，为所有的方法增强前置日志输出和后置日志输出。

下面是一个实际项目中的使用自定义注解和AOP实现的环绕增强打印入参和响应结果日志和在返回结果为sucess的情况下将日志信息入库的例子：

自定义日志注解：

/**
 * 日志注解,不需要入库的则不加本注解(返回值中responseCode为"0000"才会入库)
 * value:需要记录到数据库中的操作信息，如：@Log("删除渠道：{channelId}")，其中channelId为请求参数中的值，
 *      没有占位符则直接记录value值，目前只支持入库传入参数中的值
 * ElementType.METHOD 此注解只可应用在方法上，因为Spring只能对方法增强
 * RetentionPolicy.RUNTIME 此注解在运行期仍保留，所以可在运行期使用代理获取有此注解的方法
 * Documented 此注解包含在JavaDoc中
 */
@Target({ElementType.METHOD})
@Retention(RetentionPolicy.RUNTIME)
@Documented
public @interface Log {
    String value() default "";
}

 注意：若增强的方法位于controller层，那么在springmvc的配置文件中必须加上<aop:aspectj-autoproxy/>配置开启AOP自动自动代理。

　　如果service层或者其他地方也需要增强，那么在Spring的配置文件中也要加上<aop:aspectj-autoproxy/>配置开启AOP自动自动代理。

　　另外，spring的bean扫描和springMvc的bean扫描要分开，分别在各自的配置文件中配置。

日志增强类：

package com.suning.epp.maarms.release.monitor;

import com.alibaba.fastjson.JSON;
import com.alibaba.fastjson.JSONObject;
import com.alibaba.fastjson.serializer.PropertyFilter;
import com.alibaba.fastjson.serializer.SerializerFeature;
import com.suning.epp.maarms.common.constants.Constants;
import com.suning.epp.maarms.common.utils.StringUtil;
import com.suning.epp.maarms.release.service.intf.OperateLogService;
import com.suning.epp.pu.common.aop.lang.CommonResult;
import org.apache.commons.lang3.StringUtils;
import org.aspectj.lang.ProceedingJoinPoint;
import org.aspectj.lang.annotation.Around;
import org.aspectj.lang.annotation.Aspect;
import org.aspectj.lang.annotation.Pointcut;
import org.aspectj.lang.reflect.MethodSignature;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.slf4j.MDC;
import org.springframework.stereotype.Component;
import org.springframework.web.context.request.RequestContextHolder;
import org.springframework.web.context.request.ServletRequestAttributes;

import javax.annotation.Resource;
import javax.servlet.http.HttpServletRequest;
import java.lang.reflect.Method;
import java.util.Arrays;
import java.util.Enumeration;
import java.util.HashMap;
import java.util.Map;
import java.util.regex.Matcher;
import java.util.regex.Pattern;

/**
 * 日志切面,切controller方法，记录方法调用、退出与调用时间，如果有responseCode也会记录调用结果日志，<br/>
 * 如果加了@Log注解，会将操作记录加到数据库
 *
 * @author 17111829
 */
@Aspect
@Component
public class LogAdvice {

    private static final Logger LOGGER = LoggerFactory.getLogger(LogAdvice.class);

    /**
     * 日志文件中配置的线程号占位符
     */
    private static final String STR_INVOKE_NO = "invokeNo";

    private static final Pattern PATTERN = Pattern.compile("\{[^{]*}");

    private static final String LEFT_BRACE = "{";

    /**
     * @Resource 默认按照bean id名称进行注入依赖
     * 日志入库服务
     */
    @Resource
    private OperateLogService operateLogService;

    /**
     * 抽取工作的切入点表达式，切点，所有含有@RequestMapping的方法
     */
    @Pointcut("@annotation(org.springframework.web.bind.annotation.RequestMapping)")
    private void webPointcut() {
        // Do nothing
    }

    /**
     * 在方法执行前后增强
     *
     * @param joinPoint joinPoint
     * @return 方法返回值
     */
    @Around("webPointcut()")
    public Object around(ProceedingJoinPoint joinPoint) {
        MDC.put(STR_INVOKE_NO, StringUtil.getUuid());
        // 记录整个方法的执行用时
        long start = System.currentTimeMillis();
        // 获取当前方法执行的上下文的request
        HttpServletRequest request = ((ServletRequestAttributes) RequestContextHolder.getRequestAttributes())
                .getRequest();
        String requestURI = request.getRequestURI();
        // 获取请求发起操作人
        String userId = request.getRemoteUser();
        // 获取请求参数
        Map<String, Object> paramMap = getRequestParams(request);
        // 不输出map中字段值为null的字段
        String requestParams = JSONObject.toJSONString(paramMap, SerializerFeature.WriteMapNullValue);
        // 打印入参日志
        LOGGER.info("URI：{},用户：{}, 入参：{}", requestURI, userId, requestParams);
        // 获取被增强的方法的相关信息
        MethodSignature ms = (MethodSignature) joinPoint.getSignature();
        // 获取被增强的方法
        Method pointcutMethod = ms.getMethod();
        // @Log注解的value属性值
        String logContent = null;
        // 判断被增强的方法上是否有@Log注解
        if (pointcutMethod.isAnnotationPresent(Log.class)) {
            Log logAnon = pointcutMethod.getAnnotation(Log.class);
            logContent = logAnon.value();
        }

        Object result = null;
        try {
            // 执行被增强的方法并获取方法的返回值
            result = joinPoint.proceed();
            String responseCode = null;
            String resultStr;
            // 如果返回的结果是个字符串
            if (result instanceof String) {
                resultStr = (String) result;
                // 如果有@Log注解并且@Log注解的value不为空
                if (StringUtils.isNotBlank(logContent)) {
                    JSONObject jso = JSON.parseObject(resultStr);
                    responseCode = jso.getString(Constants.RESPONSE_CODE);
                }
                // 方法执行返回的结果不是字符串
            } else {
                // 如果方法的返回值一个分页查询的结果
                if (result instanceof PageResult) {
                    // 分页数据过滤掉 data，不打印日志,SerializerFeature.WriteMapNullValue不输出Map中为null的字段
                    resultStr = JSON.toJSONString(result, dataFilter, SerializerFeature.WriteMapNullValue);
                } else {
                    resultStr = JSON.toJSONString(result, SerializerFeature.WriteMapNullValue);
                }
                // 有@Log注解时，如果返回0000则记录操作日志
                if (StringUtils.isNotBlank(logContent)) {
                    if (result instanceof Map) {
                        responseCode = (String) ((Map) result).get(Constants.RESPONSE_CODE);
                    } else if (result instanceof CommonResult) {
                        responseCode = ((CommonResult) result).getResponseCode();
                    }
                }
            }
            // 返回0000则记录操作日志
            if ("0000".equals(responseCode)) {
                insertOperateLog(logContent, userId, paramMap);
            }

            long end = System.currentTimeMillis();
            long useTime = end - start;
            LOGGER.info("用时：{}ms,返回结果：{}", useTime, resultStr);
　　　　　　// 被增强的方法的异常也再此捕获，因此在代码中将不需要捕获异常信息
        } catch (Throwable throwable) {
            LOGGER.error("发生异常, 异常信息：{}", ExceptionUtil.getAllStackTrace(throwable));
        }
        // 方法执行结束，移除上下文中的线程号
        MDC.remove(STR_INVOKE_NO);
        return result;
    }

    /**
     * 获取请求参数
     *
     * @param request request
     * @return json格式参数
     */
    private Map<String, Object> getRequestParams(HttpServletRequest request) {
        Enumeration pNames = request.getParameterNames();
        Map<String, Object> paramMap = new HashMap<>(6);
        String paramName;
        String[] paramValues;
        while (pNames.hasMoreElements()) {
            paramName = String.valueOf(pNames.nextElement());
            paramValues = request.getParameterValues(paramName);
            if (paramValues != null && paramValues.length == 1) {
                paramMap.put(paramName, paramValues[0]);
            } else {
                paramMap.put(paramName, paramValues);
            }
        }
        return paramMap;
    }

    /**
     * 日志入库
     *
     * @param logContent 操作事件
     */
    private void insertOperateLog(String logContent, String userId, Map<String, Object> paramMap) {
        if (StringUtils.isNotBlank(logContent)) {
            String newLogContent = logContent;
            // 如果有占位符则替换
            if (logContent.contains(LEFT_BRACE) && paramMap != null) {
                newLogContent = replaceParam(logContent, paramMap);
            }
            // 入库，谁干了什么
            operateLogService.insertOperateLog(userId, newLogContent);
        }
    }

    /**
     * 用入参中的值 替换@Log注解中的占位符
     *
     * @param logContent @Log注解中的value值
     * @return 替换后的操作内容
     */
    private String replaceParam(String logContent, Map<String, Object> paramMap) {
        Matcher matcher = PATTERN.matcher(logContent);
        String matchedStr;
        String oldContent;
        Object newContent;
        String newLogContent = logContent;
        while (matcher.find()) {
            matchedStr = matcher.group();
            oldContent = matchedStr.substring(1, matchedStr.length() - 1).trim();
            newContent = paramMap.get(oldContent);
            if (newContent != null) {
                if (newContent instanceof String[]) {
                    newLogContent = newLogContent.replace(matchedStr, Arrays.toString((String[]) newContent));
                } else {
                    newLogContent = newLogContent.replace(matchedStr, newContent.toString());
                }
            }
        }
        return newLogContent;
    }

    /**
     * 字段过滤器，过滤掉data字段不打印
     */
    private PropertyFilter dataFilter = new PropertyFilter() {
        @Override
        public boolean apply(Object object, String name, Object value) {
            // false表示 data字段将被排除在外
            return !"data".equals(name);
        }
    };

}

 为HTTP请求加上线程号方便日志追踪

/**
 * 为每一个的HTTP请求添加线程号
 *
 * @author yangyongjie
 * @date 2019/9/2
 * @desc
 */
@Aspect
@Component
public class LogAspect {

    private static final String STR_THREAD_ID = "threadId";

    @Pointcut(value = "@annotation(org.springframework.web.bind.annotation.RequestMapping)")
    private void webPointcut() {
        // doNothing
    }

    /**
     * 为所有的HTTP请求添加线程号
     *
     * @param joinPoint
     * @throws Throwable
     */
    @Around(value = "webPointcut()")
    public void around(ProceedingJoinPoint joinPoint) throws Throwable {
        // 方法执行前加上线程号
        MDC.put(STR_THREAD_ID, UUID.randomUUID().toString().replaceAll("-", ""));
        // 执行拦截的方法
        joinPoint.proceed();
        // 方法执行结束移除线程号
        MDC.remove(STR_THREAD_ID);
    }
}

同时拦截多个注解的切点：

 @Pointcut(value = "@annotation(org.springframework.web.bind.annotation.RequestMapping)||@annotation(org.springframework.web.bind.annotation.PostMapping)||@annotation(org.springframework.web.bind.annotation.GetMapping)")
    private void webPointcut() {
        // doNothing
    }

其他的一些补充：

1、获取增强的类的全路径
　　　　String targetName = joinPoint.getTarget().getClass().getName();
通过全路径可以获取到被增强的类的Class对象
　　　　Class targetClass=Class.forName(targetName);
获取Spring容器中的对象
　　　　Object obj=ApplicationContext.getBean(targetClass);
被增强类的所有方法
　　　　Method[] method = targetClass.getMethods();
2、获取切点（被增强的方法）
       String methodName = joinPoint.getSignature().getName();
3、获取被增强的方法的入参
       Object[] arguments = joinPoint.getArgs();

MDC

　　MDC(Mapped Diagnostic Contexts)，翻译过来就是：映射的诊断上下文。意思是：在日志中（映射的）请求ID（requestId），可以作为我们定位（诊断）问题的关键字（上下文）。

　　有了MDC工具，只要在接口或切面植入 put 和 remove 代码，就可以在定位问题时，根据映射的唯一 requestID 快速过滤出某次请求的所有日志。

　　slf4j的MDC机制其内部基于ThreadLocal实现，可参见Java基础下的 ThreadLocal这篇博客，https://www.cnblogs.com/yangyongjie/p/10574591.html。所以我们调用 MDC.put()方法传入

　　的请求ID只在当前线程有效。所以，主线程中设置的MDC数据，在其子线程（线程池）中是无法获取的。那么主线程如何将MDC数据传递给子线程？　

　　官方建议

　　　　1、在父线程新建子线程之前调用MDC.getCopyOfContextMap()方法将MDC内容取出来传给子线程

　　　　2、子线程在执行操作前先调用MDC.setContextMap()方法将父线程的MDC内容设置到子线程　

　　　　

示例：

　　使用装饰器模式，对Runnable接口进行一层装饰，在创建MDCRunnable类对Runnable接口进行一层装饰。

在创建MDCRunnable类时保存当前线程的MDC值，再执行run()方法

　　1）：装饰Runnable

import org.slf4j.MDC;

import java.util.Map;

/**
 * 装饰器模式装饰Runnable，传递父线程的线程号
 *
 * @author yangyongjie
 * @date 2020/3/9
 * @desc
 */
public class MDCRunnable implements Runnable {

    private Runnable runnable;

    /**
     * 保存当前主线程的MDC值
     */
    private final Map<String, String> mainMdcMap;

    public MDCRunnable(Runnable runnable) {
        this.runnable = runnable;
        this.mainMdcMap = MDC.getCopyOfContextMap();
    }

    @Override
    public void run() {
        // 将父线程的MDC值赋给子线程
        for (Map.Entry<String, String> entry : mainMdcMap.entrySet()) {
            MDC.put(entry.getKey(), entry.getValue());
        }
        // 执行被装饰的线程run方法
        runnable.run();
        // 执行结束移除MDC值
        for (Map.Entry<String, String> entry : mainMdcMap.entrySet()) {
            MDC.put(entry.getKey(), entry.getValue());
        }
    }

}

　　然后使用MDCRunnable装饰类装饰Runnable

     // 异步线程打印日志，用MDCRunnable装饰Runnable
        new Thread(new MDCRunnable(new Runnable() {
            @Override
            public void run() {
                logger.debug("log in other thread");
            }
        })).start();

        // 异步线程池打印日志，用MDCRunnable装饰Runnable
        EXECUTORS.execute(new MDCRunnable(new Runnable() {
            @Override
            public void run() {
                logger.debug("log in other thread pool");
            }
        }));
        EXECUTOR.shutdown();

　　2）装饰ThreadPoolExecutor线程池

/**
 *  装饰ThreadPoolExecutor，将父线程的MDC内容传给子线程
 * @author yangyongjie
 * @date 2020/3/19
 * @desc
 */
public class MDCThreadPoolExecutor extends ThreadPoolExecutor {

    private static final Logger LOGGER= LoggerFactory.getLogger(MDCThreadPoolExecutor.class);

    public MDCThreadPoolExecutor(int corePoolSize, int maximumPoolSize, long keepAliveTime, TimeUnit unit, BlockingQueue<Runnable> workQueue, ThreadFactory threadFactory, RejectedExecutionHandler handler) {
        super(corePoolSize, maximumPoolSize, keepAliveTime, unit, workQueue, threadFactory, handler);
    }

    @Override
    public void execute(final Runnable runnable) {
        // 获取父线程MDC中的内容，必须在run方法之前，否则等异步线程执行的时候有可能MDC里面的值已经被清空了，这个时候就会返回null
        final Map<String, String> context = MDC.getCopyOfContextMap();
        super.execute(new Runnable() {
            @Override
            public void run() {
                // 将父线程的MDC内容传给子线程
                MDC.setContextMap(context);
                try {
                    // 执行异步操作
                    runnable.run();
                } finally {
                    // 清空MDC内容
                    MDC.clear();
                }
            }
        });
    }
}

　　使用：

        private static final MDCThreadPoolExecutor MDCEXECUTORS=new MDCThreadPoolExecutor(1,10,60,TimeUnit.SECONDS,new LinkedBlockingQueue<Runnable>(600), new CustomThreadFactory("mdcThreadPoolTest"), new RejectedExecutionHandler() {
            @Override
            public void rejectedExecution(Runnable r, ThreadPoolExecutor executor) {
                // 打印日志，并且重启一个线程执行被拒绝的任务
                LOGGER.error("Task：{},rejected from：{}", r.toString(), executor.toString());
                // 直接执行被拒绝的任务，JVM另起线程执行
                r.run();
            }
        });

        LOGGER.info("父线程日志");
        MDCEXECUTORS.execute(new Runnable() {
            @Override
            public void run() {
                LOGGER.info("子线程日志");
            }
        });

　　验证结果父子线程号一致：

[INFO ]2020-03-19 12:42:19.265[main]9454b4b3066c4150b6918cd6ac5584b8[com.xiaomi.mitv.admin.task.AutoRenewCheckTask:76] - 父线程日志
[INFO ]2020-03-19 12:42:21.610[From CustomThreadFactory-mdcThreadPoolTest-worker-1]9454b4b3066c4150b6918cd6ac5584b8[com.xiaomi.mitv.admin.task.AutoRenewCheckTask:80] - 子线程日志