解Bug之路-dubbo應(yīng)用無法重連zookeeper
前言
dubbo是一個成熟且被廣泛運用的框架。饒是如此,在某些極端條件下基于dubbo的應(yīng)用還會出現(xiàn)無法重連zookeeper的問題。由于此問題容易導(dǎo)致比較大的故障，所以筆者費了一番功夫去定位，現(xiàn)將排查過程寫成博文分享出來。
Bug現(xiàn)場
這是一起在測試環(huán)境出現(xiàn)的故障。起因是網(wǎng)工做交換機切換演練，可能由于姿勢不對，使得斷網(wǎng)的時間從預(yù)估的秒級達到了分鐘級。等網(wǎng)絡(luò)恢復(fù)后，測試環(huán)境就炸開了鍋，基本上所有應(yīng)用再也無法提供服務(wù)，在dubbo控制臺上也看不到任何提供者，他們和zk的連接都斷開而且似乎完全沒有重連的跡象。如下圖所示:
無法快速恢復(fù)
為了不影響測試的進度，運維同學緊急進行了重啟，但坑爹的是大部分系統(tǒng)都有啟動依賴，盲目的重啟只會因為xxx provider不存在而無法啟動。只能從最基礎(chǔ)的服務(wù)開始重啟，慢慢恢復(fù)。如下圖所示:
還好只是測試環(huán)境，但為了不讓產(chǎn)線出現(xiàn)這種問題，必須一查到底，把這個Bug揪出來。
著手排查
模擬zookeeper連接斷開
測試環(huán)境的好處是我們可以用各種手段去模擬復(fù)現(xiàn)，而不用和處理產(chǎn)線一樣到處尋找蛛絲馬跡然后進行邏輯推理(推理是一個非常燒腦的過程)。于是筆者聯(lián)系了SA同學，通過iptables進行線下的斷網(wǎng)模擬。命令如下所示:
// 禁用本機和zk三臺機器的流量進出
iptables -A INPUT -s zk-1-ip/32 -j DROP
iptables -A INPUT -s zk-2-ip/32 -j DROP
iptables -A INPUT -s zk-3-ip/32 -j DROP
iptables -A OUTPUT -s zk-1-ip/32 -j DROP
iptables -A OUTPUT -s zk-2-ip/32 -j DROP
iptables -A OUTPUT -s zk-3-ip/32 -j DROP
拓撲圖如下:
發(fā)現(xiàn)在drop對zk的包之后，不管等待多長時間，只要連接一放開，立馬就能重連zk!
看來dubbo對zookeeper的重連還是非?？孔V的。
同時模擬DNS斷開
由于模擬zk斷開不會導(dǎo)致無法重連的現(xiàn)象。于是筆者開始思考，是否交換機異常的時候?qū)е铝怂械陌紵o法發(fā)送/接收,而導(dǎo)致重連出問題的并不是對zookeeper發(fā)起連接。于是筆者看了看配置，是否還有其它和重連有關(guān)聯(lián)的點,仔細觀察下這個配置:
// 這其中有一個不容易注意到的點，就是域名解析也需要網(wǎng)絡(luò)包的交互
dubbo.registry.address=zookeeper://dubbo-1.com?back=dubbo-2.com,dubbo-3.com
難道是DNS訪問不到導(dǎo)致了這一問題？反正測試環(huán)境，繼續(xù)模擬一發(fā)，命令如下所示:
// 禁用本機和zk三臺機器的流量進出
iptables -A INPUT -s zk-1-ip/32 -j DROP
iptables -A INPUT -s zk-2-ip/32 -j DROP
iptables -A INPUT -s zk-3-ip/32 -j DROP
iptables -A OUTPUT -s zk-1-ip/32 -j DROP
iptables -A OUTPUT -s zk-2-ip/32 -j DROP
iptables -A OUTPUT -s zk-3-ip/32 -j DROP
// 禁用本機和DNS兩臺機器的流量進出
iptables -A INPUT -s dns-ip/32 -j DROP
iptables -A INPUT -s dns-ip/32 -j DROP
iptables -A OUTPUT -s dns-ip/32 -j DROP
iptables -A OUTPUT -s dns-ip/32 -j DROP
網(wǎng)絡(luò)拓撲如下:
這次我們在禁用流量后，故意先放開對zk的流量，再放開對DNS的流量，如下圖所示:
看來在dubbo對zookeeper重連過程中，如果DNS也無法響應(yīng)，是會出現(xiàn)網(wǎng)絡(luò)恢復(fù)后也再也無法重連的現(xiàn)象。但是，我們并不能下判斷交換機的故障導(dǎo)致的無法重連肯定是這個Bug引起。需要找到證據(jù)來證明這一點！
它山之石，可以攻玉
有了DNS這個信息后，先google一下，看看能否有其它人遇到過這個坑。于是找到了這個鏈接
https://github.com/sgroschupf/zkclient/issues/23
按照github上的描述，zkclient在UnknownHostException拋出之后再也無法重連zookeeper。不過他是在Kafka中遇到的，但他推斷所有用低版本org.apache.zookeper的都會有這個問題。按照上面給出的Bug Fix鏈接
https://issues.apache.org/jira/browse/ZOOKEEPER-1576
筆者發(fā)現(xiàn)其在3.5.0修復(fù)
于是將對應(yīng)的應(yīng)用的org.apache.zookeeper版本升級到3.5.5版本，重新實驗后，發(fā)現(xiàn)問題解決了!
這里有個小技巧，我們可以通過
zip -d xxx.jar WEB-INF/lib/zookeeper-3.4.8.jar
zip -r 0 xxx.jar WEB-INF/lib/zookeeper-3.5.5.jar
// 以及zip -r 其它zookeeper-3.5.5新依賴的包
使得不用重新編譯打包的方式即可修改應(yīng)用使用的jar包版本,這樣在快速驗證的時候就不需要通知對應(yīng)的開發(fā)修改依賴了。
尋找支持jdk1.6的zookeeper jar包
由于筆者所在的產(chǎn)線環(huán)境有很多老系統(tǒng)用的jdk1.6,而zookeeper-3.5.5之支持1.8及以上版本，所以需要尋找能夠給jdk1.6使用的包。此時，筆者的同事由于負責kafka,其對kafa做過混沌測試，堅信kafka沒有這個問題，于是筆者就用kafka依賴的zookeeper-3.4.13包繼續(xù)進行測試，發(fā)現(xiàn)zookeeper-3.4.13也是okay的，具體代碼改動將會在下面講到。
搜索日志尋找證據(jù)
由于可能是UnknownHostException導(dǎo)致了這一問題，筆者在出問題的應(yīng)用里面尋找，確實發(fā)現(xiàn)了UnknownHostException。日志如下所示:
// 下面過濾了一大堆disconnected連接斷開日志,只列出核心有關(guān)的
2020-03-19 21:06:28.926 [DubboZkclientConnector-EventThread] zookeeper state changed (Disconnected)
2020-03-19 21:06:28.926 [ZkClient-EventThread-101-dubbo.com] Zookeeper失去連接
2020-03-19 21:06:49.758 [DubboZkclientConnector-EventThread] zookeeper state changed (Expired)
2020-03-19 21:06:49:759 [DubboZkclientConnecto-SendThread] Unable to reconnect to ZooKeeper sercice ,session 0xXXXXX has expired
2020-03-19 21:07:29.793 [DubboZkclientConnector-EventThread] ERROR ClientCxnn - Error while calling watcher
java.lang.RuntimeException: Exception while restarting zk client
......
......
Caused by: java.net.UnknownHostException: dubbo-1.com
at...lookupAllHostAddr...
......
at...StaticHostProvier...
......
at...reconnect...[zookeeper-3.4.8.jar:3.4.8--1]
上面日志反應(yīng)出在zookeeper session expired之后重新建立session的過程中如果拋出java.net.UnknownHostException后，zkclient對應(yīng)的線程就再也不會有其它動作。
代碼分析
舊版本代碼邏輯
上面的證據(jù)再配合實驗的結(jié)果基本就能確定這個DNS異常會導(dǎo)致dubbo無法重連zookeeper的現(xiàn)象。于是筆者開發(fā)翻閱代碼,首先我們看下dubbo重連的邏輯:
public class ZkclientZookeeperClient extends AbstractZookeeperClient<IZkChildListener> {
......
public ZkclientZookeeperClient(URL url) {
super(url);
client = new ZkClientWrapper(url.getBackupAddress(), 30000);
client.addListener(new IZkStateListener() {
public void handleStateChanged(KeeperState state) throws Exception {
ZkclientZookeeperClient.this.state = state;
if (state == KeeperState.Disconnected) {
stateChanged(StateListener.DISCONNECTED);
} else if (state == KeeperState.SyncConnected) {
stateChanged(StateListener.CONNECTED);
}
}
// 這邊是session重建的過程
public void handleNewSession() throws Exception {
stateChanged(StateListener.RECONNECTED);
}
});
client.start();
}
......
}
// StateListener.RECONNECTED的處理在zookeeperResigry.java中
public class ZookeeperRegistry extends FailbackRegistry{
......
zkClient.addStateListener(new StateListener() {
// 在收到RECONNECTED事件后，進行recover也就是恢復(fù)的過程
public void stateChanged(int state) {
if (state == RECONNECTED) {
try {
recover();
} catch (Exception e) {
logger.error(e.getMessage(), e);
}
}
}
});
......
}
由上面的代碼我們可以得知，在session expired之后內(nèi)部會重建session，在新建session之后，dubbo的Statelistener會發(fā)送reconnected事件從而執(zhí)行恢復(fù)的過程，如下圖所示:
那么我們看下UnknownHostException拋出后會導(dǎo)致什么現(xiàn)象,代碼如下所示:
public class ZkClient implements Watcher {
......
private void processStateChanged(WatchedEvent event) {
// 這邊對應(yīng)于session expired日志
LOG.info("zookeeper state changed (" + event.getState() + ")");
setCurrentState(event.getState());
if (getShutdownTrigger()) {
return;
}
try {
fireStateChangedEvent(event.getState());
if (event.getState() == KeeperState.Expired) {
// UnknownHostException就是在這拋出。
reconnect();
fireNewSessionEvents();
}
} catch (final Exception e) {
// 這邊對應(yīng)于Error while calling watcher日志
throw new RuntimeException("Exception while restarting zk client", e);
}
}
......
}
異常是在reconnect拋出的，異常拋出后，就不會運行fireNewSessionEvents這個邏輯，也就不會執(zhí)行l(wèi)istener中的handleNewSession邏輯，進而不會recover,從而導(dǎo)致dubbo無法重連！如下圖所示:
新版本如何修復(fù)
由于UnknownHostException是在StaticHostProviver中觸發(fā)，在這邊筆者給出了新舊版本的對應(yīng)代碼，舊版本zookeeper-3.4.8
public final class StaticHostProvider implements HostProvider{
......
public StaticHostProvider(Collection<InetSocketAddress> serverAddresses)
throws UnknownHostException {
for (InetSocketAddress address : serverAddresses) {
InetAddress ia = address.getAddress();
// 這邊沒有抓住UnknownHostException異常
InetAddress resolvedAddresses[] = InetAddress.getAllByName((ia!=null) ? ia.getHostAddress():
address.getHostName());
for (InetAddress resolvedAddress : resolvedAddresses) {
......
if (resolvedAddress.toString().startsWith("/")
&& resolvedAddress.getAddress() != null) {
this.serverAddresses.add(
new InetSocketAddress(InetAddress.getByAddress(
address.getHostName(),
resolvedAddress.getAddress()),
address.getPort()));
} else {
this.serverAddresses.add(new InetSocketAddress(resolvedAddress.getHostAddress(), address.getPort()));
}
}
}
if (this.serverAddresses.isEmpty()) {
throw new IllegalArgumentException(
"A HostProvider may not be empty!");
}
Collections.shuffle(this.serverAddresses);
}
......
}
新版本zookeeper-3.4.13小小的重構(gòu)了一下，將DNS的邏輯放到next函數(shù)里面并抓住了UnknownHostException異常。
public final class StaticHostProvider implements HostProvider{
......
public InetSocketAddress next(long spinDelay) {
currentIndex = ++currentIndex % serverAddresses.size();
if (currentIndex == lastIndex && spinDelay > 0) {
try {
Thread.sleep(spinDelay);
} catch (InterruptedException e) {
LOG.warn("Unexpected exception", e);
}
} else if (lastIndex == -1) {
// We don't want to sleep on the first ever connect attempt.
lastIndex = 0;
}
InetSocketAddress curAddr = serverAddresses.get(currentIndex);
try {
String curHostString = getHostString(curAddr);
List<InetAddress> resolvedAddresses = new ArrayList<InetAddress>(Arrays.asList(this.resolver.getAllByName(curHostString)));
if (resolvedAddresses.isEmpty()) {
return curAddr;
}
Collections.shuffle(resolvedAddresses);
return new InetSocketAddress(resolvedAddresses.get(0), curAddr.getPort());
} catch (UnknownHostException e) {
// 就是這邊抓住了UnknownHostException進而修復(fù)了這一問題
return curAddr;
}
}
......
}
我們可以看到新版zookeeper-3.4.13抓住了這個UnknownHostException進而修復(fù)了這一問題。
BUG觸發(fā)條件復(fù)盤
在與zookeeper服務(wù)連接異常并session expired(默認30s)，DNS緩存也超時(默認30s)同時用的低版本zookeeper jar包就很容易達成上述Bug的情況。而之前測試環(huán)境由于交換機切換的某些原因使得網(wǎng)絡(luò)斷開超過了30s從而誘發(fā)了這一問題。而且不僅僅是Dubbo,任何用zookeeper低版本jar包都有可能出現(xiàn)這個問題！
總結(jié)
海恩法則指出,每一起嚴重事故的背后，必然有29次輕微事故和300起未遂先兆以及1000起事故隱患。所以對測試環(huán)境的任何問題都要引起重視，從而把問題消滅在萌芽階段。
公眾號
關(guān)注筆者公眾號，獲取更多干貨文章: