登录注册
最新博客
最新资源下载
躺坑记 —— 第三方包bug引起的站点故障
达芬奇密码2018-08-02 10:29
前两天线上MOOC主站突然出现访问很慢的情况，渐渐地逐步沦陷到无法访问...... 已经有段时间没有遇到这样的问题了一下子没反应过来要怎么处理一下，慌忙中登录到NDP，看到集群中10几个实例处于无响应的状态，连忙用抖动的鼠标选中一半实例重启...（重启大法很奏效！）
1.ZK重连问题
紧接着，先保留下一台，再通过脚本第一时间dump了那台机器情况及实例的现场数据。然后通过哨兵查看web应用最容易出问题的几个指标，tomcat线程池、接口请求情况、JVM相关信息、基础监控等，很快问题定位到了，tomcat线程池爆了……
在思考，为啥都没有报警（这个后边再补充解释一下）？难不成今天有特别活动？然后在查看接口的并发情况后，发现请求限流组件似乎失效了，请求资源被前几个高频接口占用无法释放。
于是从导出实例的堆栈里看到http线程基本被获取被这几个业务的方法的zk所block了，
一开始以为是流量上来某些接口性能差导致雪崩，但进一步分析，发现是使用了zk锁的http接口才会处于WAITING状态，难不成是死锁吗？但这些锁之间似乎都没有很大的联系，觉得应该再多观察一下其他指标才能逼近真相。
于是，接着从应用日志和tomcat的日志中，看到大量zk创建节点失败的异常KeeperErrorCode = ConnectionLoss，
而curator框架不断抛出Background operation retry gave up异常信息，显示一直连接不上zk集群，zk集群不是好好的吗？其他服务接入到该zk集群运行都很正常。
因此，看来得进一步分析这些抛出的异常了
1. 异常KeeperErrorCode = ConnectionLoss到底是怎么导致了？
因为没有发现其他异常情况，感觉只能看下机器的监控情况了，
逐个检查了以下几种可能导致该情况场景：
网络环境连接情况（抖动、连接中断情况超过会话超时时间)，云主机磁盘IO读写延迟导致commit log无法及时写入，客户端GC情况导致的STW导致无法心跳，maxSessionTime是否太短导致（实际设置了60s），zk server的堆设置大小和RAM情况。但对于ZK的集群的监控实在太少了，除了基础的机器监控下，基于上看到的是一个裸跑的ZK集群（错误、GC、健康检查等都没有配置），因此，对zk集群的GC能拿到的数据并不多。
虽然以上数据上显示有波动，但似乎无明显异常，未果。
2. Background operation retry gave up
我们使用了curator客户端做为连接zk server的客户端，设定了一个基于backoff的重连方式，一旦网络断开后，操作会进行基于这种重连方式进行重试，重试到达失败次数后gave up，似乎也没有更多的有效日志得到。
从上面的错误中找不到突破的思路，那么在尝试一直重连zk集群过程中，zk集群的server是否也可能会有一些异常信息呢？于是登录zk集群的某台server重新仔细在查找了下，发现在问题时间段内有一个小的WARN信息很容易被一堆信息掩盖，
解决这类问题最高效的办法就是看看其他人是否已经解决过了，如果没有的话，那就只能依赖监控数据，依赖能收集到的各类错误信息推断，依赖搭建一个debug源码的环境的方式了，不过，我们很快发现其他人也遇到类似的问题，产生的根源是在zk 客户端在重连过程中，因为一次性提交的watcher数量太大，从而使用这个packet的大小超过了server端读取超过最大的设定值
src/java/main/org/apache/zookeeper/server/NIOServerCnxn.java
/** Reads the first 4 bytes of lenBuffer, which could be true length or
* four letter word.
*
* @param k selection key
* @return true if length read, otw false (wasn't really the length)
* @throws IOException if buffer size exceeds maxBuffer size
*/
private boolean readLength(SelectionKey k) throws IOException {
// Read the length, now get the buffer
int len = lenBuffer.getInt();
if (!initialized && checkFourLetterWord(sk, len)) {
return false;
}
if (len < 0 || len > BinaryInputArchive.maxBuffer) {
throw new IOException("Len error " + len);
}
if (!isZKServerRunning()) {
throw new IOException("ZooKeeperServer not running");
}
incomingBuffer = ByteBuffer.allocate(len);
return true;
}
这个长度可通过一个环境变量jute.maxbuffer 进行设置，zk默认大小是1M，这个值对比错误日志1Mb<2568162(2.44M)显然确实小很多，解决方案有两种，一种是长度设置大一点，但存在的问题是设置多大合适呢？设置太大势必会让zk读写性能下降。另一种方式是将限制提交的数据长度，对此，官方做了相关的补丁，将客户端提交的watcher进行了分批处理。那么怎么验证我们所使用的curator和zk 版本就真的存在这个问题呢？我这边做了简单单元测试来重现该问题，大致做法如下：
1. 本地启动zk服务
2. 清空ZKDB数据
3. 创建大量znode数据，并为每个znode设置watch监视
4. 关闭zk服务，再重启观察连接情况
5. 比较设置少量的watcher的情况
//start zk server
startServerInstance();
dropZKDB();
//start client
CuratorFrameworkFactory.Builder builder = CuratorFrameworkFactory.builder().connectString(host + ":" + port).retryPolicy(
new ExponentialBackoffRetry(200, 3)).connectionTimeoutMs(CONNECTION_TIMEOUT).sessionTimeoutMs(60000).namespace(
"zk-demo1");
client = builder.build();
client.start();
//创建1000个节点每个节点都设有watcher
prepareData();
//shutdown zk server
shutdownServerInstance();
awaitDisconnect(CONNECTION_TIMEOUT);
//restart zk server
startServerInstance();
重现结果确实也和预期是一样，如下：
另外，从官网对zk watch的描述也有类似提到这一点，
When a client reconnects, any previously registered watches will be reregistered and triggered if needed。
当然还有一些话题可以进一步探索延伸，这个官网文档就没有太多介绍介绍，如为什么在重连的是要把大量的watch进行重新注册呢？看源码可以看到zk服务端在异常关闭socket时将该对应session对应的znode上的watch及children watch都移除了，因为对于一个断开连接的客户端来说，监视在znode节点的数据变化的watch是怎么都无法通知到该客户端了。
至此，我们只需要升级zk的版本就能解决重连的问题了，但，问题到此还没有完：为什么生产环境会产生那么多watch呢？首次客户端断开又是为什么会断开呢？
2. 过多wacher的根源
首先得分析下应用到底使用了哪些watch，以及应用向整个zk的集群注册了多少watch？
幸运的是，从zookeeper 3.3.0之后就提供了很多方便的问题诊断工具 ②，通过查看客户端及zk server的连接情况可以间接获得相应的session信息
echo cons | nc {zookeeper1 ip} 2181 | grep {clientIP} |awk -F '\\(|\\)' '{print $2}' | awk -F ',' '{print $4}'
因为生产环境我们总共有5台，任何一台上的server都可能被客户端连接，因此，其他的server 都需要查看一下。
通过以上命令查看对应客户端的sessionId，比如我们这里得到的sessionId为：0xb624774d87a00c2，0xb624774d87a00c4，0x9624774d48800e0
为什么会有三个sessionId呢？通过zk提供的命令很快我们可以分析出来，这些session是用于disconf配置推送，curator的zk锁，以及dubbo用于获取注册中心变更的。
但实际上我们是希望想获得单机的watch列表，zk提供了另一个wchc的工具，我们通过获得这些sessinId就能得到这些watcher列表了，如下：
echo wchc | nc 10.172.1.200 2181 | sed -n "/^$arg/,/^0x/p";
0xb624774d87a00c2
/disconf/mooc_0.0.1_online/file/concurrencyControl.xml
0xb624774d87a00c4
/imooc-online/locks_v3/mocUserLessonUnitLearn_4096/1123/_c_8708388e-0a40-4ea9-82aa-9c5cfd41002d-lock-0001329502
/imooc-online/locks_v3/trackMobileLogonLocker_1024/651/_c_c1c6756b-7f76-4e73-9bc3-f9697ed57d5d-lock-0000163994
/imooc-online/locks_v3/mocUserLessonUnitLearn_4096/753/_c_03c07a2a-71ae-4deb-b1b8-9936e133b89f-lock-0001330917
/imooc-online/locks_v3/trackMobileLogonLocker_1024/17/_c_ce3628b2-5438-43f1-aa43-fe9a570150bf-lock-0000164342
/imooc-online/locks_v3/mocUserLessonUnitLearn_4096/3290/_c_70a8efbc-932a-4484-ba28-fc3abc885dfd-lock-0001320518
/imooc-online/locks_v3/mocUserLessonUnitLearn_4096/3075/_c_a9bbd2e1-8535-4bee-b6eb-f976577224b5-lock-0001289817
/imooc-online/locks_v3/mocUserLessonUnitLearn_4096/2094/_c_d4848800-ffc6-4b3a-a3bd-dff9e6adb812-lock-0001306049
/imooc-online/locks_v3/mocUserLessonUnitLearn_4096/2176/_c_cc5234a1-45cf-4290-bea5-1e4589bdeb4f-lock-0001327665
....
0x9624774d48800e0
/dubbo/com.netease.mooc.activity.remote.service.RemoteMocActivityTeamService/configurators
/dubbo/com.netease.mooc.course.remote.service.RemoteMocCourseCategoryService/routers
/dubbo/com.netease.mooc.course.remote.service.RemoteMocCourseService/routers
/dubbo/com.netease.mooc.activity.remote.service.RemoteMocActivityService/routers
/dubbo/com.netease.mooc.activity.remote.service.RemoteMocActivityCounterService/providers
/dubbo/com.netease.edu.biz.message.share.service.Message2AdapterService/configurators
/dubbo/com.netease.mooc.course.manager.MocCourseManager/routers
/dubbo/com.netease.mooc.activity.remote.service.RemoteMocActivityService/providers
/dubbo/com.netease.mooc.attachment.manager.MocTestAnswerAttachmentManager/routers
/dubbo/com.netease.mooc.remote.service.Remote3LevelExtraAddressService/providers
...
以上就是客户端机器完整的watch列表，过程中发现了线上单台机器注册居然能到好几千个watcher，除了300多个是用于dubbo注册中心通知，其余基本上是用于分布式锁，也就是说当下有至少有上千个thread在使用等待zk锁？排查了线上线上tomcat也才设置了200个线程池，而mq后台并发更新视频观看进度的线程也只有20个，似乎还没有达到这个量级，极端情况就算是死锁最多也只有就这些线程池占满的总数，这么多的watcher到底是怎么产生的？有没有可能curator尝试获得锁的过程设置多次watcher操作，使用watcher数量增加？
于是觉得还是有必要写个程序验证一下，测试一下10个线程竞争一个zk锁的watcher 列表情况。
int threadCount = 100;
ExecutorService es = Executors.newFixedThreadPool(threadCount);
for (int i = 0; i < threadCount; i++) {
final InterProcessMutex ipm = new InterProcessMutex(this.client, "/locks");
final int seq = i;
es.submit(new Runnable() {
@Override
public void run() {
boolean acquire = false;
try {
//only one can acquire the locker
acquire = ipm.acquire(20, TimeUnit.SECONDS);
if (acquire) {
LOG.info("i am thread No.:" + seq);
//waiting
TimeUnit.SECONDS.sleep(30);
} else {
LOG.info("acquired failed!, number:" + seq);
}
} catch (Exception e) {
e.printStackTrace();
} finally {
try {
if (acquire) {
LOG.info("i am released, number:" + seq);
ipm.release();
}
} catch (Exception e) {
e.printStackTrace();
}
}
}
});
}
es.shutdown();
while (!es.awaitTermination(1, TimeUnit.SECONDS)) ;
LOG.info("find the list of watchers not removed properly:\n" + FourLetterWordMain.send4LetterWord(host, port, "wchc"));
一测试之后，发现了另一个问题，所有锁都释放了，资源竞争也都结束了，但watcher却很多没有被清理，运行结果如下：
那就奇怪了，要保留那么多的watcher干什么？经过多次测试，发现已然存在，因此，怀疑可能是zk在删除节点的过程清理watcher时没有清理干净。于是debug了zk的代码，在debug过程中，debug到删除节点后又正确了删除了watcher，但发现另一个线程又添加了新的watcher，很快发现有个curator客户端收到watcher通知后，会调用exist()+watcher操作去查看锁是不是真的已经释放了，这时候就会在原来的路径上添加一个watcher。我测试了3.4.5,3.4.11,3.5.3-beta 的zk版本后，发现问题依然存在。因此，通过通过定位问题发现exist()+watcher操作会调用一个statNode方法，而statNode方法内部在addWatch之前并没有判断node是否存在，于是在3.4.11-SNAPSHOT的源码修改了相应的代码：
--- a/src/java/main/org/apache/zookeeper/server/DataTree.java
+++ b/src/java/main/org/apache/zookeeper/server/DataTree.java
@@ -572,15 +572,17 @@ public String getMaxPrefixWithQuota(String path) {
public Stat statNode(String path, Watcher watcher)
throws KeeperException.NoNodeException {
- Stat stat = new Stat();
- DataNode n = nodes.get(path);
- if (watcher != null) {
- dataWatches.addWatch(path, watcher);
- }
- if (n == null) {
- throw new KeeperException.NoNodeException();
- }
synchronized (n) {
+
+ Stat stat = new Stat();
+ DataNode n = nodes.get(path);
+ if (n == null) {
+ throw new KeeperException.NoNodeException();
+ }
+
+ if (watcher != null) {
+ dataWatches.addWatch(path, watcher);
+ }
n.copyStat(stat);
return stat;
}
于是向zookeeper的社区提了个issue看看有没有问题存在，后来经过与zookeeper的开发者沟通后发现其实这是客户端curator框架的bug，主要原因是watcher事实上可以用来监视一个不存在的路径，一旦有新的节点产生，这个watcher的回调就会触发。而curator框架在尝试获取锁的LOOP过程中使用了checkexist()+watcher操作，而不是getData()+watcher的操作，区别在于前者会在一个空的znode的路径上加上watcher，而后者不会，导致后边znode锁被移出后watcher还依然存在，具体可查看：https://issues.apache.org/jira/browse/ZOOKEEPER-3014,https://issues.apache.org/jira/browse/CURATOR-107。升级curator recipes到2.5.0之后的版本后解决了该问题。对于watcher能够监视空路径的说法，我重新翻看了下官方文档说明，好像真没有看到这点说明（不知道其他童靴是否看到这点），这一点确实很难让人想到不是ZK的bug。但不管怎样，总算有个合理的解释了。
3. 经验总结
第一个，这次感到意外其中的一个原因应该属于比较无征兆的，主要是一方面因为ndp上tomcat模板调整后导致原先设置为600的线程池变更为了200，而预警设置为400，最大线程池大小调为200后就基本不会收到这个预警，这个check机制显然是没有做到位；另一方面是某次半夜报警异常太多，然后错误的日志异常配置抑制了报警信息，很明显是异常日志分级没有很好处理，不必要的报警信息就不应该输出，以上两点可以作为典型的反面教材进行学习。
第二个，在出现这个故障后，让我更加关注和重视工程中使用的第三方依赖，原因在于这里边产生的问题的不确定性会更高，相对第一个而言，会让人产生更强的不安全感。所以如果想要保障产品持续稳定可靠运行，软件版本的升级看上去是一个不得不关注的主题。
我觉得从这几点去关注第三方包版本的升级情况：
第一类是安全相关的版本更新，对于安全问题自不必说，涉及到公司资产层面问题，按理应该在第一时间进行解决，但实际情况，往往都是根据严重程度进行处理。如何判断严重程度呢？一般按照report issue的分级可能是一个不错的选择，如critical、major、normal、minor等等。
第二类是质量相关的issue，首先理解这个issue对我们来说严重程度如何，是否可能会有潜在隐患，本文提到的这两个bug应该不会很紧急，可以随着日常迭代版本一起更新，但如果bug是被标注为critical的话，而且实际评估的结果风险确实很高的话，那就应该第一时间上hotfix修复了。
第三类是功能新增或增强改善类的，这些一般都是”如果有的话就更好的“的功能或优化，可以进行多个角度权衡讨论后升级。
希望大家也多发了躺坑记，学习下，我们也可以少走点弯路。
就先说到这里吧。
分享至：
