从源码分析dubbox服务消费端有时找不到提供者原因

问题描述：Dubbox2.8.4版本，用redis作为注册中心时，消费端有时会报提供者不存在的问题。

 

 在排查中，看监控中心有如下日志，通过监控中心的日志可以看出，它会删除过期的key，是不是因为删除过期的key而导致的了？【日志中有：Delete expired key:】

 

[18/04/16 05:47:43:043 CST] DubboRegistryExpireTimer-thread-1  WARN redis.RedisRegistry:  [DUBBO] Delete expired key: /dubbo/xxx.RestPayCallbackChannelService/providers -> value: rest://192.168.1.71:8888/xxx.RestPayCallbackChannelService?accepts=500&anyhost=true&application=jumore-pay-provider&default.service.filter=security&dubbo=2.8.4&generic=false&interface=xxx.RestPayCallbackChannelService&methods=payCallback&organization=jumore&owner=programmer&pid=54132&revision=api&serialization=kryo&server=jetty&side=provider&threads=500&timestamp=1460958038148, expire: Mon Apr 18 17:47:10 CST 2016, now: Mon Apr 18 17:47:43 CST 2016, dubbo version: 2.0.0, current host: 192.168.23.225
[18/04/16 05:47:43:043 CST] DubboRedisSubscribe  INFO redis.RedisRegistry:  [DUBBO] redis event: /dubbo/xxx.RestPayCallbackChannelService/providers = unregister, dubbo version: 2.0.0, current host: 192.168.23.225

  为了考虑性能问题，我需要在提供者方进行timeout处理。所以在使用注解时，我对服务提供方都加入了timeout处理。这个也是dubbo推荐的用法。Provider上尽量多配置Consumer端的属性，让Provider实现者一开始就思考Provider服务特点、服务质量的问题。

 

  类似于这样，我在发布服务时

@Service(protocol = {"dubbo"}, version = 0.0.1, timeout = 3000)
public class PayQueryChannelServiceImpl implements XXXService

     其它的也没有什么特殊处理。

 

  我们首先来说明下，我们在用redis作为注册中心，redis的注册中心类 是：com.alibaba.dubbo.registry.redis.RedisRegistry.  RedisRegistry注册中心在初始化时的一个处理也就是RedisRegistry（Url url）这个构建方法的最后一点：

 

this.expirePeriod = url.getParameter(Constants.SESSION_TIMEOUT_KEY,
            Constants.DEFAULT_SESSION_TIMEOUT);
        this.expireFuture = expireExecutor.scheduleWithFixedDelay(new Runnable() {
            public void run() {
                try {
                    deferExpired(); // 延长过期时间
                } catch (Throwable t) { // 防御性容错
                    logger.error(
                        "Unexpected exception occur at defer expire time, cause: " + t.getMessage(),
                        t);
                }
            }
        }, expirePeriod / 2, expirePeriod / 2, TimeUnit.MILLISECONDS);

 

  通过上面的代码我们可以看出，dubbo服务的每个url在注册到注册中心时，都会开启一个定时任务进行一些操作。定时任务的间隔时间，是通过dubbo服务的url的中的参数session值来规定的，一般这个session值都是在dubbo:register中可以自己定义，如果没有定义，通过上面的程序可以看出，它给的有一个默认的session超时时间为60000，这样我的程序因为没有定义这个session，所以上面的expirePeriod的值为60000

  而定时任务也就是延迟30s后，每隔30s会执行一次。而定时任务中的线程运行时，执行的是deferExpired()这个方法，而这个方法，就是对redis的过期时间进行延长处理。我们可以参看具体的代码实现：

 

 

private void deferExpired() {
        for (Map.Entry<String, JedisPool> entry : jedisPools.entrySet()) {
            JedisPool jedisPool = entry.getValue();
            try {
                Jedis jedis = jedisPool.getResource();
                try {
                    for (URL url : new HashSet<URL>(getRegistered())) {
                        if (url.getParameter(Constants.DYNAMIC_KEY, true)) {
                            String key = toCategoryPath(url);
                            if (jedis.hset(key, url.toFullString(),
                                String.valueOf(System.currentTimeMillis() + expirePeriod)) == 1) {
                                jedis.publish(key, Constants.REGISTER);
                            }
                        }
                    }
                    if (admin) {
                        clean(jedis);
                    }
                    if (!replicate) {
                        break;//  如果服务器端已同步数据，只需写入单台机器
                    }
                } finally {
                    jedisPool.returnResource(jedis);
                }
            } catch (Throwable t) {
                logger.warn("Failed to write provider heartbeat to redis registry. registry: "
                            + entry.getKey() + ", cause: " + t.getMessage(), t);
            }
        }
    }

 

  这个方法中获取所有的redis连接池，因为redis有可能部署多台。Dubbo服务在发布时，可以进行集群的。这里我就不针对这个功能具体介绍了，可以参看dubbo的文档。

然后处理当前jvm中的RedisRegistry类中注册的dubbo服务的url,然后执行

url.getParameter(Constants.DYNAMIC_KEY, true)

 

  因为我在发布服务时，没有设置dynamic属性，所以这会默认是true。然后执行redis的hset命令，来将已经注册的服务的值替换成

String.valueOf(System.currentTimeMillis() + expirePeriod)  

 

   也就是当前时间+过期时间。如果执行hset命令时，插入的这个hash结构是个新值，就会发布redis的register服务。以便其它的订阅者能够知道注册中心有新的服务发布；

其实针对我的问题，上面的代码都不是关键，是关键的是

if (admin) {
          clean(jedis);
}

 

  这里面的代码是，当admin=true时，会进行clean。这里我们先不关心admin的值在什么时候设置成true的，后面再介绍。我们首先看下clean是怎么处理业务的。

 

 

// 监控中心负责删除过期脏数据
    private void clean(Jedis jedis) {
        Set<String> keys = jedis.keys(root + Constants.ANY_VALUE);
        if (keys != null && keys.size() > 0) {
            for (String key : keys) {
                Map<String, String> values = jedis.hgetAll(key);
                if (values != null && values.size() > 0) {
                    boolean delete = false;
                    long now = System.currentTimeMillis();
                    for (Map.Entry<String, String> entry : values.entrySet()) {
                        URL url = URL.valueOf(entry.getKey());
                        if (url.getParameter(Constants.DYNAMIC_KEY, true)) {
                            long expire = Long.parseLong(entry.getValue());
                            if (expire < now) {
                                jedis.hdel(key, entry.getKey());
                                delete = true;
                                if (logger.isWarnEnabled()) {
                                    logger.warn("Delete expired key: " + key + " -> value: "
                                                + entry.getKey() + ", expire: " + new Date(expire)
                                                + ", now: " + new Date(now));
                                }
                            }
                        }
                    }
                    if (delete) {
                        jedis.publish(key, Constants.UNREGISTER);
                    }
                }
            }
        }
    }

 

面主要的功能就是将redis里面的匹配dubbo/*  所有的key的数据取出来。因为dubbo服务在放入到redis时，就是一个hash结构的，具体的结构说明如下：

 

使用Redis的Key/Map结构存储数据。

主Key为服务名和类型。

Map中的Key为URL地址。

Map中的Value为过期时间，用于判断脏数据，脏数据由监控中心删除。(注意：服务器时间必需同步，否则过期检测会不准确)

 

所以上面的程序就是取出map中的value，然后与当前的时间比较是否过期。过期了就执行redis的hdel删除对应的数据。(就是这里会造成有时dubbo的消费端会找不到服务的问题)

 

疑问1：从RedisRegistry中的代码看，它在执行clean之前，会将所有的redis里面的服务的过期时间延长处理，而在clean方法中怎么还是会被删除了？

 

其实不然，在deferExpired()方法中获取url时，是直接调用getRegistered()方法。这也就是说明，当我们所有的服务都是用同一个RedisRegistry类时，getRegistered()方法获取的才是所有的dubbo服务。而实际上是，dubbo在发布服务时，看下debbug类的调用顺序：

 

 

也就是通过RedisRegistryFactory.getRegistry（URL）来进行注册的。而这个对象里面的方法是：

 

public Registry getRegistry(URL url) {
        return new RedisRegistry(url);
}

 

每次都会新new一个对象出来。这样就造成了同一个RedisRegistry类中在调用getRegistered()方法时，不会获取其它的dubbo服务，即使是现一个jvm中，也不会获取。

 

而在redis删除过期的key时，通过前面的clean方法的代码可以看出，它在删除key时，所有的dubbo服务都是从redis中获取到的。这样我们就知道了，并不是在同一个线程里执行的redis过期时间先延长，再进行过期时间判断从redis中删除的。

 

疑问2：那么即使，所有的redis过期时间延长和删除redis不是在同一个线程中执行的，那么它自己在发布服务时，也是会进行new RedisRegistry(url)，然后自己的线程里面会对url的过期时间延长啊，还是不会删除啊？

这个可不是绝对的啊~~。因为针对多线程，而且前面我也说过了，RedisRegistry类的deferExpired()方法是在一个定时任务执行，那么你说会存在这种情况吗？

 

看看下面的日志信息：我将删除同一个redis key的信息摘录出来了：

 

 

Line 57: [18/04/16 04:30:39:039 CST] DubboRegistryExpireTimer-thread-1  WARN redis.RedisRegistry:  [DUBBO] Delete expired key: /dubbo/xxx.member.MemberBindChannelService/providers -> value: dubbo://192.168.1.71:20881/xxx.member.MemberBindChannelService?anyhost=true&application=jumore-pay-provider&default.service.filter=security&dubbo=2.8.4&generic=false&interface=xxx.member.MemberBindChannelService&methods=bindReqParam&organization=jumore&owner=programmer&pid=54132&revision=api&side=provider&timeout=3000&timestamp=1460958037541&version=0.0.1, expire: Mon Apr 18 16:30:08 CST 2016, now: Mon Apr 18 16:30:39 CST 2016, dubbo version: 2.0.0, current host: 192.168.23.225
	Line 136: [18/04/16 04:31:09:009 CST] DubboRegistryExpireTimer-thread-1  WARN redis.RedisRegistry:  [DUBBO] Delete expired key: /dubbo/xxx.member.MemberBindChannelService/providers -> value: dubbo://192.168.1.71:20881/xxx.member.MemberBindChannelService?anyhost=true&application=jumore-pay-provider&default.service.filter=security&dubbo=2.8.4&generic=false&interface=xxx.member.MemberBindChannelService&methods=bindReqParam&organization=jumore&owner=programmer&pid=54132&revision=api&side=provider&timeout=3000&timestamp=1460958037541&version=0.0.1, expire: Mon Apr 18 16:30:38 CST 2016, now: Mon Apr 18 16:31:09 CST 2016, dubbo version: 2.0.0, current host: 192.168.23.225
	Line 205: [18/04/16 04:31:39:039 CST] DubboRegistryExpireTimer-thread-1  WARN redis.RedisRegistry:  [DUBBO] Delete expired key: /dubbo/xxx.member.MemberBindChannelService/providers -> value: dubbo://192.168.1.71:20881/xxx.member.MemberBindChannelService?anyhost=true&application=jumore-pay-provider&default.service.filter=security&dubbo=2.8.4&generic=false&interface=xxx.member.MemberBindChannelService&methods=bindReqParam&organization=jumore&owner=programmer&pid=54132&revision=api&side=provider&timeout=3000&timestamp=1460958037541&version=0.0.1, expire: Mon Apr 18 16:31:08 CST 2016, now: Mon Apr 18 16:31:39 CST 2016, dubbo version: 2.0.0, current host: 192.168.23.225
	Line 273: [18/04/16 04:32:09:009 CST] DubboRegistryExpireTimer-thread-1  WARN redis.RedisRegistry:  [DUBBO] Delete expired key: /dubbo/xxx.member.MemberBindChannelService/providers -> value: dubbo://192.168.1.71:20881/xxx.member.MemberBindChannelService?anyhost=true&application=jumore-pay-provider&default.service.filter=security&dubbo=2.8.4&generic=false&interface=xxx.member.MemberBindChannelService&methods=bindReqParam&organization=jumore&owner=programmer&pid=54132&revision=api&side=provider&timeout=3000&timestamp=1460958037541&version=0.0.1, expire: Mon Apr 18 16:31:38 CST 2016, now: Mon Apr 18 16:32:09 CST 2016, dubbo version: 2.0.0, current host: 192.168.23.225

 

它们中的这些日志信息：

expire: Mon Apr 18 16:30:08 CST 2016, now: Mon Apr 18 16:30:39 CST 2016,
expire: Mon Apr 18 16:30:38 CST 2016, now: Mon Apr 18 16:31:09 CST 2016,
expire: Mon Apr 18 16:31:08 CST 2016, now: Mon Apr 18 16:31:39 CST 2016,
expire: Mon Apr 18 16:31:38 CST 2016, now: Mon Apr 18 16:32:09 CST 2016,

 看看上面的日志已经说明：MemberBindChannelService的url的定时任务在Mon Apr 18 16:30:39 CST 2016时被删除

  这个如果按照前面分析的逻辑key应该删除不了啊？如果过期时间是Mon Apr 18 16:30:08 CST 2016，那它放入这个key的时间应该是Mon Apr 18 16:29:08 CST 2016,而在删除key的时间是Mon Apr 18 16:30:39 CST 2016,在这个期间，放入key的那个线程在Mon Apr 18 16:29:38 CST 2016时应该会将key加上60s,将失效时间变成Mon Apr 18 16:30:38 CST 2016这个时间才对啊？

   为什么了？经过检查，最后发现，是因为我的监控中心服务器与提供服务器的时间不一致。

也就是监控中心服务的时间，比服务提供者服务器的时间快上近一分钟导致的。

 

 

问题3：而为什么启动监控中心时，RedisRegistry对象中的admin属性就会变成true？

这是因为，在启动监控中心时，我们一般都会如下配置：

 

 

通过注册中心发现监控中心服务:
<dubbo:monitor protocol="registry" />
或：
dubbo.properties
dubbo.monitor.protocol=registry

 这样的话，监控中心在启动时就会调用registry名称对应的容器。

 

 

 

 

而这个的具体启动的类我们可以通过监控中心的这个容器配置查看，它里面的内容是：

registry=com.alibaba.dubbo.monitor.simple.RegistryContainer

 

而这个类在启动时，注册的服务url是

 

 

协议是以admin 开始的，注册的interface是*，详细的注册的url是：

 

admin://192.168.23.225?category=providers,consumers&check=false&classifier=*&group=*&interface=*&version=*

 

 

 

 

 

而在调用RedisRegistry 的doSubscribe时，会根据interface是*来将admin的值改在true

 

 下面一篇准备分析服务端设置超时后，客户端不起作用，依然是dubbo默认的超时时间1s