震惊！日志级别居然可能导致Dubbo出现空指针异常

你遇到过Dubbo调用报空指针异常吗？

下面我要介绍的，是一次真实的产线事件。由于各种因素，导致Dubbo多打印了一行日志后，出现空指针异常。希望能帮到苦苦寻找答案的你！

备注：文章所用Dubbo版本为2.6.3

问题复现

Consumer A服务依赖Provider B服务。
Consumer A服务先启动了，此时注册中心无B服务实现，而后Provider B启动。
两个系统均正常启动，但A服务调用B服务时，报空指针异常
报错如下：

[dispatcherServlet] in context with path [] threw exception [Request processing failed; nested exception is java.lang.NullPointerException] with root cause java.lang.NullPointerException: null …

其中，消费者A的Dubbo注入使用了@Reference注解，类似如下代码

@Service public class AuthServiceImpl implements AuthService { 
    @Reference private UserService userService; @Override public String getNameById(String id) { 
    return userService.getNameById(id); } }

出现问题后，我们仔细排查。注意到此处Dubbo服务引用使用的是@Reference注解形式，且未指定check参数（默认为true）。按照常理来说：

如果A依赖的B服务没有启动的话，A服务启动就应当报错，但是启动并没有报错
B服务上线后，按照Dubbo的功能说明，应当可以做到服务自动注入与发现，A服务调用时不应当出现空指针异常

据此推测，可能是@Reference注解+check参数配置原因，导致Dubbo代理没有生成，此时注入的服务为null，因此Dubbo的那一套都失效了。

场景测试

为了判断到底是不是@Reference注解+check配置的原因，我特意做了几个场景测试。包括xml配置和注解配置方式。总结如下：

顺着这种异常的场景代码，进入Dubbo的源码进行debug，经历了一系列坑之后，我终于找到产生的原因。下面从Dubbo源码的角度来分析一下产生的原因。

源码分析

在createProxy方法中，有关check参数解析的代码如下：

Boolean c = check; if (c == null && consumer != null) { 
    c = consumer.isCheck(); } if (c == null) { 
    c = true; // default true } if (c && !invoker.isAvailable()) { 
    throw new IllegalStateException("Failed to check the status of the service " + interfaceName + ". No provider available for the service " + (group == null ? "" : group + "/") + interfaceName + (version == null ? "" : ":" + version) + " from the url " + invoker.getUrl() + " to the consumer " + NetUtils.getLocalHost() + " use dubbo version " + Version.getVersion()); } if (logger.isInfoEnabled()) { 
    logger.info("Refer dubbo service " + interfaceClass.getName() + " from url " + invoker.getUrl()); } // create service proxy return (T) proxyFactory.getProxy(invoker);

可以看到，check参数默认为true。如果服务不可用，会抛出IllegalStateException异常！如果check设置为false，则会跳过校验逻辑，会继续下面的生成代理逻辑。

但是为啥没有调用到呢？

顺着debug调用链路往下看，在Spring启动时，Dubbo注解相关的工作执行代码调用链如下：

com.alibaba.dubbo.config.spring.beans.factory.annotation.ReferenceAnnotationBeanPostProcessor#postProcessPropertyValues
org.springframework.beans.factory.annotation.InjectionMetadata#inject
com.alibaba.dubbo.config.spring.beans.factory.annotation.ReferenceAnnotationBeanPostProcessor.ReferenceFieldElement#inject
com.alibaba.dubbo.config.spring.beans.factory.annotation.ReferenceAnnotationBeanPostProcessor#buildReferenceBean
com.alibaba.dubbo.config.spring.beans.factory.annotation.AbstractAnnotationConfigBeanBuilder#build
com.alibaba.dubbo.config.AbstractConfig#toString
…
com.alibaba.dubbo.config.spring.ReferenceBean#getObject
com.alibaba.dubbo.config.ReferenceConfig#get
com.alibaba.dubbo.config.ReferenceConfig#init
com.alibaba.dubbo.config.ReferenceConfig#createProxy
…

首先，使用了@Reference注解的Bean对象，在Spring启动注入时，会执行com.alibaba.dubbo.config.spring.beans.factory.annotation.ReferenceAnnotationBeanPostProcessor#postProcessPropertyValues方法，进行@Reference字段的注入
然后，执行进入com.alibaba.dubbo.config.spring.beans.factory.annotation.ReferenceAnnotationBeanPostProcessor.ReferenceFieldElement#inject方法，进行referenceBean对象的构建，构建完成后注入到指定的@Reference字段中

 @Override protected void inject(Object bean, String beanName, PropertyValues pvs) throws Throwable { 
    Class<?> referenceClass = field.getType(); // 构建reference对象 referenceBean = buildReferenceBean(reference, referenceClass); ReflectionUtils.makeAccessible(field); // 反射注入值 field.set(bean, referenceBean.getObject()); }

注意在上述反射注入值时，调用了referenceBean的getObject()方法，此方法会依次调用以下链路

com.alibaba.dubbo.config.spring.ReferenceBean#getObject
com.alibaba.dubbo.config.ReferenceConfig#get
com.alibaba.dubbo.config.ReferenceConfig#init
com.alibaba.dubbo.config.ReferenceConfig#createProxy

从而完成ReferenceBean的代理生成和返回，理论上这里应该是check发挥作用（抛异常）的地方，一次正常的调用链路应当如此。

但是回过头来查看我们debug的调用链路，可以发现，referenceBean的getObject()方法好像在奇怪的地方被调用了！！！

com.alibaba.dubbo.config.spring.beans.factory.annotation.ReferenceAnnotationBeanPostProcessor#buildReferenceBean
com.alibaba.dubbo.config.spring.beans.factory.annotation.AbstractAnnotationConfigBeanBuilder#build
com.alibaba.dubbo.config.AbstractConfig#toString

先来看一下调用点，com.alibaba.dubbo.config.spring.beans.factory.annotation.AbstractAnnotationConfigBeanBuilder#build。

 public final B build() throws Exception { 
    checkDependencies(); B bean = doBuild(); configureBean(bean); // 日志级别达到info，就会打印下面的bean，就会调用AbstractConfig的toString方法 if (logger.isInfoEnabled()) { 
    logger.info(bean + " has been built."); } return bean; }

我们进到AbstractConfig的toString方法里看一下:

public String toString() { 
    try { 
    StringBuilder buf = new StringBuilder(); buf.append(" 
    
    ) 
    ; buf 
    . 
    append 
    ( 
    getTagName 
    ( 
    getClass 
    ( 
    ) 
    ) 
    ) 
    ; Method 
    [ 
    ] methods 
    = 
    getClass 
    ( 
    ) 
    . 
    getMethods 
    ( 
    ) 
    ; 
    for 
    (Method method 
    : methods 
    ) 
    { 
      
    try 
    { 
      String name 
    = method 
    . 
    getName 
    ( 
    ) 
    ; 
    if 
    ( 
    (name 
    . 
    startsWith 
    ( 
    "get" 
    ) 
    || name 
    . 
    startsWith 
    ( 
    "is" 
    ) 
    ) 
    && 
    ! 
    "getClass" 
    . 
    equals 
    (name 
    ) 
    && 
    ! 
    "get" 
    . 
    equals 
    (name 
    ) 
    && 
    ! 
    "is" 
    . 
    equals 
    (name 
    ) 
    && Modifier 
    . 
    isPublic 
    (method 
    . 
    getModifiers 
    ( 
    ) 
    ) 
    && method 
    . 
    getParameterTypes 
    ( 
    ) 
    .length 
    == 
    0 
    && 
    isPrimitive 
    (method 
    . 
    getReturnType 
    ( 
    ) 
    ) 
    ) 
    { 
      
    int i 
    = name 
    . 
    startsWith 
    ( 
    "get" 
    ) 
    ? 
    3 
    : 
    2 
    ; String key 
    = name 
    . 
    substring 
    (i 
    , i 
    + 
    1 
    ) 
    . 
    toLowerCase 
    ( 
    ) 
    + name 
    . 
    substring 
    (i 
    + 
    1 
    ) 
    ; 
    // 此处调用了一些类方法 Object value 
    = method 
    . 
    invoke 
    ( 
    this 
    ) 
    ; 
    if 
    (value 
    != null 
    ) 
    { 
      buf 
    . 
    append 
    ( 
    " " 
    ) 
    ; buf 
    . 
    append 
    (key 
    ) 
    ; buf 
    . 
    append 
    ( 
    "=\"" 
    ) 
    ; buf 
    . 
    append 
    (value 
    ) 
    ; buf 
    . 
    append 
    ( 
    "\"" 
    ) 
    ; 
    } 
    } 
    } 
    catch 
    ( 
    Exception e 
    ) 
    { 
      logger 
    . 
    warn 
    (e 
    . 
    getMessage 
    ( 
    ) 
    , e 
    ) 
    ; 
    } 
    } buf 
    . 
    append 
    ( 
    " />" 
    ) 
    ; 
    return buf 
    . 
    toString 
    ( 
    ) 
    ; 
    } 
    catch 
    ( 
    Throwable t 
    ) 
    { 
      logger 
    . 
    warn 
    (t 
    . 
    getMessage 
    ( 
    ) 
    , t 
    ) 
    ; 
    return 
    super 
    . 
    toString 
    ( 
    ) 
    ; 
    } 
    }

哦！看到这里就恍然大悟了。

可能是为了打印日志更详细，AbstractConfig的toString方法里利用反射调用了其相关的一些方法来获取值。而我们的referenceBean是继承自这个AbstractConfig的toString方法的，其getObject方法又正好满足这里的条件，所以就提前被调用了。（注意这里因为check=true，服务不可用而抛出的异常被catch给吃掉了）

现在我们回头看看check字段被解析的方法，它的入口在com.alibaba.dubbo.config.ReferenceConfig#init，该方法对类变量initialized进行了校验。

第一次执行此方法的时候initialized为false，可以进入下面check的解析与服务可用性校验的逻辑
第二次执行时，initialized为true，导致方法执行直接被中断，无法执行到check字段被解析的地方了

private void init() { 
    if (initialized) { 
    return; } initialized = true; ...... }

也就是说，上述的toString方法里先调用了这个方法，所以到真正需要调用这个方法的地方，反而因为已经initialized了，被直接拦截了！真让人哭笑不得~

综合以上因素，可以总结如下：

由于打印日志的需要，提前调用了ReferenceBean的初始化方法，理论上检测服务可用性而抛出的异常，被日志打印的catch捕获了！
由于ReferenceBean初始化进行了次数校验，只有第一次可以进入执行。所以第二次真正应当调用的地方，反而被拦截了

这样，因为一行日志打印，就出现null指针异常了。。。

验证

if (logger.isInfoEnabled()) { 
    logger.info(bean + " has been built."); }

因此只有日志级别达到了info级别，才会打印这个对象。那么如果我调整一下日志，不打印日志，或者打印日志级别为error，会发生什么情况呢？

 <logger name="com.alibaba.dubbo" level="ERROR"></logger>

其他场景说明

为啥XML配置不会出现空指针?

因为XML配置走的调用路径与注解不一样啊，XML配置不会走到方法com.alibaba.dubbo.config.spring.beans.factory.annotation.AbstractAnnotationConfigBeanBuilder#build中哦

为啥注解配置 + check=false 能够正确生成代理？

因为check=false不会检查服务状态，所以toString方法调用时，仍然可以正确完成初始化，也就是说不会影响后面代理的生成逻辑

一些建议

这个bug在2.6.5版本已经修复了，但是许多公司产线上跑着的Dubbo版本，依然低于此版本，所以仍然有出现这个问题的可能。

最好的修复建议是升版本，版本的选择可以参考
dubbo个版本总结与升级建议
如果无法升版本，那么尽量使用xml配置吧
如果依然无法使用xml配置，那么在@Reference注解处加一个 “check=false” 应该是可以的吧
如果依然不行的话，那么你只能通过运维保证，按照服务依赖的顺序来发布了

测试代码

本文所用测试代码点击下载

debug中的坑

下面分享一下在调试过程中遇到的一些坑吧！

在排查这个问题过程中，我发现IDEA调试时，默认是开启toString预览的！也就是说会默认调用对象的toString方法。这对于Dubbo空指针问题的调试，无疑是雪上加霜！调试着，突然就跳去了一个奇怪的地方，着实让人恼火。

好在IDEA提供了关闭的选项，IDEA debug关闭toString预览方法如下

IDEA debug去除toString预览

番外篇

如果你从GitHub上拉取Dubbo 2.6.5版本的代码，可以看到此处的修复代码如下：

public final B build() throws Exception { 
    checkDependencies(); B bean = doBuild(); configureBean(bean); if (logger.isInfoEnabled()) { 
    logger.info("The bean[type:" + bean.getClass().getSimpleName() + "] has been built."); } return bean; }

你看，不再直接打印bean了，而是改为直接展示simpleName了。

如果你细心一点，查看一下提交记录，可以看到此问题是 小马哥 在 2018-10-19 修复的。修复的备注包含了Github issue号
Github问题号
根据这个2657号，去GitHub上Dubbo项目下搜索issue，追踪溯源，你能看到原始的问题：Dubbo use diferent behavior when log’s level greater than info

发布者：全栈程序员-站长，转载请注明出处：https://javaforall.net/222212.html原文链接：https://javaforall.net

震惊！日志级别居然可能导致Dubbo出现空指针异常

问题复现

场景测试

源码分析

验证

其他场景说明

一些建议

测试代码

debug中的坑

番外篇

关于作者

全栈程序员-站长

发表回复

震惊！日志级别居然可能导致Dubbo出现空指针异常

问题复现

场景测试

源码分析

验证

其他场景说明

一些建议

测试代码

debug中的坑

番外篇

关于作者

全栈程序员-站长

相关推荐

360 c语言 笔试,奇虎360校招的笔试真题「建议收藏」

Redis详解（六）——Redis主从同步原理与配置

Zsh 入门(安装及使用)

python3 byte转string[通俗易懂]

牛腩新闻公布系统小结

安装Microsoft .NET Framework 3.5 Service Pack 1回报1603错

发表回复

360 c语言笔试,奇虎360校招的笔试真题「建议收藏」