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

你可能是被标题吸引过来的,但这确实是一次真实的产线事件。日志级别导致Dubbo出现空指针异常,这个是在查看源码排查问题之后,反推得到的结论。

文章所用Dubbo版本为2.6.3

问题复现

  1. Consumer A服务依赖Provider B服务。
  2. Consumer A先启动了,此时注册中心无B服务实现,而后Provider B启动。
  3. 两个系统均正常启动,但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的调用使用了@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服务启动就应当报错,但是启动并没有
  • Dubbo服务上线后,应当可以自动负载均衡调用,不应当出现空指针异常

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

场景测试

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

若A服务依赖Dubbo服务B,当A服务先于B服务启动,根据配置方式的不同,会有以下几种场景
Dubbo空指针测试结果.png

通过测试结果,可以看到,只有使用注解@Reference进行配置,且check=true场景,不符合我们的预期。
按照官方说明,配置check=true,服务在启动时进行服务可用性的校验。如果服务不可用,应当无法启动才对。

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

源码分析

首先先明确一下,Dubbo中@Reference注解解析的相关代码在ReferenceConfig类中。
调用关系是
com.alibaba.dubbo.config.ReferenceConfig#init --> com.alibaba.dubbo.config.ReferenceConfig#createProxy

在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

...

  1. 使用了@Reference注解的Bean对象,在Spring启动注入时,会执行com.alibaba.dubbo.config.spring.beans.factory.annotation.ReferenceAnnotationBeanPostProcessor#postProcessPropertyValues方法,进行@Reference字段的注入
  2. 然后进入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

这是什么鬼?!
在构建ReferenceBean的时候(buildReferenceBean),referenceBean的getObject()居然被提前执行了?
先来看一下调用点,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;
    }

这个方法看起来平平无奇,为啥会调用到referenceBean的getObject方法呢?
答案就在这里的log上,打印此处的bean(为ReferenceBean类型),会用到这个bean基类(AbstractConfig)的toString方法

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

public String toString() {
        try {
            StringBuilder buf = new StringBuilder();
            buf.append("<dubbo:");
            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(" ></dubbo:");>");
            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这个对象,导致调用父类toString方法,提前完成了init(异常又被toString方法捕获处理了),从而无法正确生成代理,且又能够正常启动。
我们看到,调用生成代码的逻辑中加了判断

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

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

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

修改log4j2.xml中的日志级别为error,重新跑一下上述异常的测试场景,可以发现@Reference注解配置Dubbo的应用已经无法启动了,报错与XML配置场景一致。这说明我们的猜测是正确的!日志级别(小于等于info)居然真的导致Dubbo出现空指针异常!

其他场景说明

  • 为啥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配置,那么在注解处加一个check=false应该是可以的吧
如果依然不加的话,那么你只能通过运维保证,按照服务依赖的顺序来发布了(新加的服务才会有影响)

debug中的坑

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

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

不要勾选复选框
Build,Execution,Deployment -> Debugger -> Data Views -> Java -> Enable 'toString()' object views

IDEA关闭toString预览.png

番外篇

从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 Dubbo空指针问题解决提交备注.png
根据这个2657号,去GitHub上搜索issue,追踪溯源,你能看到原始的问题:Dubbo use diferent behavior when log's level greater than info

原来早就有人发现了相同的问题了。看来下次看到这类问题,还是需要去官方代码库中看看有没有人问过类似的问题,这样可以减少我们很多的时间和精力!

测试代码

点击下载本文测试代码