ZOOKEEPER重连失败BUG踩坑记

Posted 2021-04-13 唯品会质量工程

问题提出

问题第一次被发现是有业务反馈Staging环境新添加的定时任务无法按时调度，通过第一时间查看日志，我们发现错误日志都是和ZOOKEEPER断连相关，且持续在增长。

分析过程

接下来通过一些常规的检查，没有什么特别发现，尝试复现也没有成功，因为与ZK断开重连这个功能平时也是测试比较充分的。从日志看到，持续了10多分钟发现与ZK的会话连接仍然没有成功，这时候我们就想，难道只能祭出重启大法了么？

突然间想到，ZK客户端机制就是不断尝试重连，如果客户端没有异常，有没可能是ZK服务端的问题？查看服务端的日志，发现以前没有见过的错误信息“Len error 1733124”，感觉离胜利又近了一步。

通过搜索ZOOKEEPER源码，发现了这个错误的触发条件。当数据包大小超过了maxBuffer（默认1MB）限制就会导致抛出这个异常。

并未有非法操作，为什么会出现重连失败情况？会不会是组件的BUG? Google搜索Len error果然找到ZOOKEEPER issue.  https://issues.apache.org/jira/browse/ZOOKEEPER-706

考虑到生产环境ZK断开并不罕见，而且数据远远不止1MB，为什么没出现该问题？

通过查找资料和阅读源码找到了原因，ZOOKEEPER客户与服务端的重连并非超时后再尝试重连，而是在心跳断开2/3会话时长后会尝试连接另一个服务器，此时旧的sessionId未过期，客户端会将一次性打包所有的watch发送到服务端，如果全部watch拼接的path大小超过了服务器设置的参数jute.maxbuffer值(默认大小为1M)时，服务器将拒绝连接，而客户端则会一直重试，导致重连不成功。至此，终于真像大白。

One important parameter you should set when creating a session is the session timeout, which is the amount of time the ZOOKEEPER service allows a session before declaring it expired. If the service does not see messages associated to a given session during time T, it declares the session expired. On the client side, if it has heard nothing from the server at 1/3 of T, it sends a heartbeat message to the server. At 2/3 of T, the ZOOKEEPER client starts looking for a different server, and it has another 1/3 of t to find one.

解决方案

通过在测试环境构造条件复现后，最后通过设置服务端参数-Djute.maxbuffer为合适的大小这种workaround的方式来解决该问题。当然还有更彻底的方法也就是升级ZOOKEEPER组件至3.4.8以上的版本。

由于基础架构不止一个产品使用ZOOKEEPER组件，后来也将该问题分享给其它产品团队，至于分享过后引发了另一场血案就是另一个故事了。