频繁操作zookeeper节点，客户端收不到监听通知

绝地灬酷狼 2023-05-31 12:12 1阅读 0赞

往往对源码的不甚了解，才会不经意间出现问题。

# 故障现象 #

生产上某个应用有45个节点，每个节点集成有一个zk客户端，即这45个zk客户端监听同一条zk路径。当该zk路径节点的值被更新，这45个节点会收到节点变动的通知，进行相关业务处理。  
某次并行更新6次该zk节点的值（虽然是并行，但是每次setData的时候还是有个时间差，可能比较小）。发现有部分客户端没有通知（因为有些应用节点执行结果不预期）。  
因为是生产上，当时运维重启这45个应用实例节点 获取到监听路径的最新值恢复了。  
后来是查看日志发现，每个节点监听到通知的时候会打印一条日志，则45个节点，监听到6次变动，应当有45\*6=270条日志，实际上可能只100多条，或者200条左右，总有些客户端在某一次监听路径的值变动的时候，没有收到通知。但是最后一两次的通知，全部收到了。

# 本地复现 #

因为是在生产环境，没法直接进行故障复盘。  
zk客户端使用的curator的API封装的，监听器用的DataCache接口。  
我只能本地模拟，在我本机上启动50个zk客户端。zk服务器用的是测试环境，考虑到可能存在网络因素，就不能在本机启动zk服务器来模拟。  
问题是复现了，时间有点久了，过程就不再描述。

# 问题定位 #

通过curator的相关源码跟踪及其它场景的一些模拟，我把问题范围缩小在zookeeper原生客户端、网络、zookeeper服务器这3个方面。  
使用原生的zookeeper客户接口测试，代码很简单，也没什么逻辑：  
![在这里插入图片描述][watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L3g3NjM3OTUxNTE_size_16_color_FFFFFF_t_70]

就是监听到节点变动，获取节点数据、重新注册监听器，打印一行信息，完全没业务逻辑。并且该客户端只启动一个。  
然后再启动一个客户端，循环更新该节点的值5次：  
![在这里插入图片描述][watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L3g3NjM3OTUxNTE_size_16_color_FFFFFF_t_70 1]  
问题出现了，监听客户端偶尔会打印日志不足5条，比如这次：  
![在这里插入图片描述][2019102421495372.png]  
只监听到了3次。  
因为问题定位时间有点紧，还有其它事情要忙，没有其它原因，是真的不想跟源码的。但是目前还不确定是zk客户端代码的原因还是服务器这里有原因。  
没有办法，为了时间原因，这时候我能想到的只有抓包试下了，看下是服务器没发送通知，还是客户端没收到或者是收到了，处理的时候出问题了。  
因为服务器我这边不方便登录，先抓客户端（我本机），本机好抓，用wireshark看起来也方便。  
然后，几次尝试终于出现了一次问题：  
![在这里插入图片描述][20191024215430626.png]  
客户端收到通知不足5条，只收到了0、1、2、4。另一端设置数据的时候，是正常设置的：  
![在这里插入图片描述][watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L3g3NjM3OTUxNTE_size_16_color_FFFFFF_t_70 2]  
下面是抓包的一次分析内容我就说下分析结果：

1.  服务器端实际发来了4条通知
2.  客户端每次收到通知的时候，下次tcp请求是拉取数据（此时请求中会注册监听器的）
3.  tcp拉取数据的请求已发送，但这个时候服务器返回的下一条数据变更的通知
4.  服务器返回上次请求的zk路径的数据。  
    （注意这个顺序）  
    服务器发送通知-》客户端收到通知，请求获取路径节点的值-》服务器返回下一条数据变更通知-》服务器返回上次客户端请求数据的值-》客户端收到了这次的通知，请求这次通知的数据…

p.s. 设置节点的数据客户端也在我本机，上面分析的时候，我是把这个客户端的数据设置的请求报文过滤了。  
问题出现在上面这个顺序，前几条报文都很正常，当客户端收到节点值变更为3的时候，客户端发出了拉取数据报文的请求，然后服务器返回了节点4的数据值。。。最终也没有返回节点值为4的变更通知，客户端本来是在节点值变更3通知的时候，发出的拉取请求却收到的值为4，值3丢失了，并且节点变为4的时候，最终也没有通知过来。  
![在这里插入图片描述][20191024221347615.png]  
（IP不方便展示。虽然是内网）  
上面是抓取的报文：按顺序：

1.  设置数据的zk客户端设置path的值为4
2.  监听变动的zk客户端请求获取path的值（这是节点变更为3的通知，此时它想获取的值是3呀！）
3.  忽略
4.  zk服务器返回监听的zk客户端，Path的值为4。  
    后面的ACK可以忽略了，之后的两条传输报文与此无关，没有其它相关通知和请求了。最终连接断开。

这个时候没有办法了，看来问题在zk服务器这里，只等翻源码了。  
最终从启动类一开始，追踪到WatcheManager类，下面有段核心代码是触发监听的：

public Set<Watcher> triggerWatch(String path, EventType type, Set<Watcher> supress) { 
            WatchedEvent e = new WatchedEvent(type,
                    KeeperState.SyncConnected, path);
            HashSet<Watcher> watchers;
            synchronized (this) { 
                // 这是watchTable变量在前面的声明
    /* private final HashMap<String, HashSet<Watcher>> watchTable = new HashMap<String, HashSet<Watcher>>(); private final HashMap<Watcher, HashSet<String>> watch2Paths = new HashMap<Watcher, HashSet<String>>();*/
    
                // 每个路径注册的监听器在watchTable这个map里放着
                // 这段代码是在同步块内，增加监听器的方法也存在同步操作，并且是和这段代码竞争同把锁
                // 此时监听器先被移除了。
                // 这意味着，新的监听器未注册进来的时候，此时发生节点变动，未注册监听器
                // 的客户端自然不会收到通知
                watchers = watchTable.remove(path);
                if (watchers == null || watchers.isEmpty()) { 
                    if (LOG.isTraceEnabled()) { 
                        ZooTrace.logTraceMessage(LOG,
                                ZooTrace.EVENT_DELIVERY_TRACE_MASK,
                                "No watchers for " + path);
                    }
                    return null;
                }
                for (Watcher w : watchers) { 
                    HashSet<String> paths = watch2Paths.get(w);
                    if (paths != null) { 
                        paths.remove(path);
                    }
                }
            }
            for (Watcher w : watchers) { 
                if (supress != null && supress.contains(w)) { 
                    continue;
                }
                // 通知客户端
                w.process(e);
            }
            return watchers;
        }

看下我上面加的中文注释。  
再加上上面抓的包，可以分析到，服务器端节点值变更为3的通知发给客户端的时候，该客户端的监听器已经被移除了，然后的另个设置数据的客户端设置节点值为4的请求已经发出去了，大约0.05ms后，监听客户端发现获取数据的请求（此时包括注册监听器），但是可能已经晚了，服务器数据变为4，向客户端发送通知的时候，监听器还没注册上（触发监听的增加监听器也存在同步操作的）。  
我计算了下时间，从收到节点变更通知，到注册新监听请求发出，我本机上大概经过了30ms左右。  
从设置节点的值到服务器发送到节点变动耗时在33ms左右，因为没有在服务端抓包还是不好估计传输耗时。  
但是实际生产环境节点压力更大，业务侧的处理能力也不能保证。所以如果是在旧的监听器失效，新的尚未注册的时候，节点变动，自然是不收到通知的。

# 解决办法 #

既然操作频繁导致，数据变量的时候，新的监听器还没注册过来，或许在传输过程中也可能是服务器收到请求了还没注册上。  
那操作避免过于频繁不就好了，给它点时间 。就像我，动态获取应用实例监听点（zk客户端的数目）,并行改为串行，并且适当的计算一个合理的延时（如果有必要，就在两点变动中加上延时，避免客户端监听器来不及注册）

[watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L3g3NjM3OTUxNTE_size_16_color_FFFFFF_t_70]: /images/20230531/1e6ee868e34342519ecf5ed18562b8c9.png
[watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L3g3NjM3OTUxNTE_size_16_color_FFFFFF_t_70 1]: /images/20230531/778b051a413d40a3969168f9d2b95212.png
[2019102421495372.png]: /images/20230531/45a2a0af78f2414aa6c6a12ec77d0317.png
[20191024215430626.png]: /images/20230531/0d72bdc298fc4dd8b0d9230037d29a02.png
[watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L3g3NjM3OTUxNTE_size_16_color_FFFFFF_t_70 2]: /images/20230531/45b5f1bdec0d4d6eb1ea65c832e9027d.png
[20191024221347615.png]: /images/20230531/b0418c8ac32b4ca3831e8fa3a11069a9.png