一次AOP配错自动创建事务代理的bean引发的疑案

一.案发背景

问题出现在一次发现自己的请求没有被日志记录，发现是AOP中没有配置那个服务，于是在BeanNameAutoProxyCreator是个根据bean名生成自动代理的代理创建器，声明了UrlAuditServiceImpl 这个Bean需要自动生成代理，然后被打日志的拦截器生成代理来打印日志。当时在线下的测试中，自己的接口测试都没有问题，并且也能符合预期的打印出日志，于是自己就将代码合入了主干。当天晚上先回去了，留其他的伙伴们还在奋斗，第二条一来就了解到了他们昨晚通宵上线，排查了一些问题的事情，其中有一个bug就是我这个配置导致的，据说很隐僻，于是我带着好奇心和内疚感对这个问题一探究竟：）

二.现场还原

问过了师傅当时出现问题的情况，知道了是我在AOP里的BeanNameAutoProxyCreator bean名字配错了，导致了其他人的接口报错了，出现了空指针。后来在本地环境改了当时出现问题的配置，并且用postman发出了引起bug的请求，过不奇然，有一个从threadLocal实现的上下文map中取数据出现了空指针。我声明错误的bean和那个出错接口的联系是被调用的关系，我当时想到了可能是AOP嵌套执行了2次导致的，于是立刻debug了一下，还原了步骤:
1. 在RpcContextInteceptor一个集成了MethodInterceptor的自定义日志拦截器中,有给予上下文IP/token/请求来源等逻辑，并且会取上下文的内容，如果没有上下文则新建一个threadLocal的map上下文，这个时候debug一切正常的。
2. 这个时候在业务的主流程中的initCommonContext()，这里会放入一些后面会用到的操作状态枚举。
3. 接着请求进入了validate阶段，这就是在代码的逻辑中调用了UrlAuditServiceImpl 服务的地方，这个地方在BeanNameAutoProxyCreator 声明了要自动生成代理，当然也进入了RpcContextInteceptor的invoke()方法中去，这个时候看threadLocal中的上下文map，也是正常的。
4. 这个时候断点调到了根据上下文取步骤2中initCommonContext()时放置的操作状态，这个时候竟然为null,导致了空指针，很明显刚才有中间的某步对threadLocal里的上下文进行了清理。
5. 于是倒回了前一步，发现在调用完第二次AOP拦截的日志打印方法后，上下文就被清空了，于是开始了研究清空上下文的原因。
6. 这个时候搜索了下，会对操作进行put的地方，发现只有initCommonContext()会做这个操作，而且在这个方法整个调用链路中只执行一次。于是排查了是后面出现了这个上下文里的操作类型属性被put了null元素的可能性。
7. 这个时候就想了下是不是在AOP中有清空的可能，于是在RpcContextInteceptor中搜索了下clear()方法，果然有了收获:

 @Override
    public Object invoke(MethodInvocation methodInvocation) {
    try{
        ...
    } catch (Execption e){
        ...
    }
    } finally {
            // 打印业务日志，一个请求打印一条
            printBizLog();
            try {
                afterRPCInvoke(methodName);
            } catch (Exception e) {
                LOGGER.error("afterRPCInoke error!" + e);
            }
        }
   }

afterRPCInvoke里关键部分:


public void afterRPCInvoke(String methodName) {
...
// 清除threadLocal上线文的逻辑
CommonContextHolder.getEnvstore().remove();
threadLocalCacheProxyImpl.clear();
...
    }

仔细一想，代码里有这样的逻辑是非常合理的。因为每次请求，都会在threadLocal中生成一份上下文，记录下这次请求中的各种业务状态，当请求结束了之后，这些状态不会被再次用到，就应该及时清空，避免对进程的内存有过多的占用，所以释放资源的操作就应该放在finally中取执行。
8. 那么现在问题出现的原因已经十分清晰了:由于BeanNameAutoProxyCreator中配错了bean的名字，导致了一次请求中有两次AOP的代理操作先后对threadLocal上下文的处理。而在这两处AOP的操作之间有一些对上下文状态的初始化数据，由于在嵌套第二次的AOP代理操作的finally清空上下文的操作被处理了，导致请求接下来的步骤中，threadLocal上下文里面已经没有了那些初始化的数据，最后出现了空指针的异常。效果如下图:

    AOP1 beforeRPCInvoke()
        \
        initCommonContext()
            \
            AOP2 beforeRPCInvoke()
            |
            AOP2 afterRPCInvoke() ->  clearCommonContext()
                \
                getCommonContext() ERROR!
    AOP1 afterRPCInvoke()

三.案情小结

通过这个问题的出现和排查结束，我对这个问题有了更多的思考。首先，在代码开发的过程中需要细致，有的时候在程序中会出现失之毫厘差之千里的情况。其次，一定要对AOP代码bean的拦截范围有足够的了解和谨慎，一些看似不相关的操作，但是通过了AOP动态织入的操作，就会引发出意向不到的关联。