前言
dubbo是一個成熟且被廣泛運用的框架。饒是如此,在某些極端條件下基於dubbo的應用還會出現無法重連zookeeper的問題。由於此問題容易導致比較大的故障，所以筆者費了一番功夫去定位，現將排查過程寫成博文分享出來。
Bug現場
這是一起在測試環境出現的故障。起因是網工做交換機切換演練，可能由於姿勢不對，使得斷網的時間從預估的秒級達到了分鐘級。等網路恢復後，測試環境就炸開了鍋，基本上所有應用再也無法提供服務，在dubbo控制檯上也看不到任何提供者，他們和zk的連線都斷開而且似乎完全沒有重連的跡象。如下圖所示:
無法快速恢復
為了不影響測試的進度，運維同學緊急進行了重啟，但坑爹的是大部分系統都有啟動依賴，盲目的重啟只會因為xxx provider不存在而無法啟動。只能從最基礎的服務開始重啟，慢慢恢復。如下圖所示:
還好只是測試環境，但為了不讓產線出現這種問題，必須一查到底，把這個Bug揪出來。
著手排查
模擬zookeeper連線斷開
測試環境的好處是我們可以用各種手段去模擬復現，而不用和處理產線一樣到處尋找蛛絲馬跡然後進行邏輯推理(推理是一個非常燒腦的過程)。於是筆者聯絡了SA同學，通過iptables進行線下的斷網模擬。命令如下所示:
// 禁用本機和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
拓撲圖如下:
發現在drop對zk的包之後，不管等待多長時間，只要連線一放開，立馬就能重連zk!
看來dubbo對zookeeper的重連還是非常靠譜的。
同時模擬DNS斷開
由於模擬zk斷開不會導致無法重連的現象。於是筆者開始思考，是否交換機異常的時候導致了所有的包都無法傳送/接收,而導致重連出問題的並不是對zookeeper發起連線。於是筆者看了看配置，是否還有其它和重連有關聯的點,仔細觀察下這個配置:
// 這其中有一個不容易注意到的點，就是域名解析也需要網路包的互動
dubbo.registry.address=zookeeper://dubbo-1.com?back=dubbo-2.com,dubbo-3.com
難道是DNS訪問不到導致了這一問題？反正測試環境，繼續模擬一發，命令如下所示:
// 禁用本機和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
網路拓撲如下:
這次我們在禁用流量後，故意先放開對zk的流量，再放開對DNS的流量，如下圖所示:
看來在dubbo對zookeeper重連過程中，如果DNS也無法響應，是會出現網路恢復後也再也無法重連的現象。但是，我們並不能下判斷交換機的故障導致的無法重連肯定是這個Bug引起。需要找到證據來證明這一點！
它山之石，可以攻玉
有了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
筆者發現其在3.5.0修復
於是將對應的應用的org.apache.zookeeper版本升級到3.5.5版本，重新實驗後，發現問題解決了!
這裡有個小技巧，我們可以通過
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新依賴的包
使得不用重新編譯打包的方式即可修改應用使用的jar包版本,這樣在快速驗證的時候就不需要通知對應的開發修改依賴了。
尋找支援jdk1.6的zookeeper jar包
由於筆者所在的產線環境有很多老系統用的jdk1.6,而zookeeper-3.5.5之支援1.8及以上版本，所以需要尋找能夠給jdk1.6使用的包。此時，筆者的同事由於負責kafka,其對kafa做過混沌測試，堅信kafka沒有這個問題，於是筆者就用kafka依賴的zookeeper-3.4.13包繼續進行測試，發現zookeeper-3.4.13也是okay的，具體程式碼改動將會在下面講到。
搜尋日誌尋找證據
由於可能是UnknownHostException導致了這一問題，筆者在出問題的應用裡面尋找，確實發現了UnknownHostException。日誌如下所示:
// 下面過濾了一大堆disconnected連線斷開日誌,只列出核心有關的
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]
上面日誌反應出在zookeeper session expired之後重新建立session的過程中如果丟擲java.net.UnknownHostException後，zkclient對應的執行緒就再也不會有其它動作。
程式碼分析
舊版本程式碼邏輯
上面的證據再配合實驗的結果基本就能確定這個DNS異常會導致dubbo無法重連zookeeper的現象。於是筆者開發翻閱程式碼,首先我們看下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也就是恢復的過程
public void stateChanged(int state) {
if (state == RECONNECTED) {
try {
recover();
} catch (Exception e) {
logger.error(e.getMessage(), e);
}
}
}
});
......
}
由上面的程式碼我們可以得知，在session expired之後內部會重建session，在新建session之後，dubbo的Statelistener會傳送reconnected事件從而執行恢復的過程，如下圖所示:
那麼我們看下UnknownHostException丟擲後會導致什麼現象,程式碼如下所示:
public class ZkClient implements Watcher {
......
private void processStateChanged(WatchedEvent event) {
// 這邊對應於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) {
// 這邊對應於Error while calling watcher日誌
throw new RuntimeException("Exception while restarting zk client", e);
}
}
......
}
異常是在reconnect丟擲的，異常丟擲後，就不會執行fireNewSessionEvents這個邏輯，也就不會執行listener中的handleNewSession邏輯，進而不會recover,從而導致dubbo無法重連！如下圖所示:
新版本如何修復
由於UnknownHostException是在StaticHostProviver中觸發，在這邊筆者給出了新舊版本的對應程式碼，舊版本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小小的重構了一下，將DNS的邏輯放到next函式裡面並抓住了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進而修復了這一問題
return curAddr;
}
}
......
}
我們可以看到新版zookeeper-3.4.13抓住了這個UnknownHostException進而修復了這一問題。
BUG觸發條件覆盤
在與zookeeper服務連線異常並session expired(預設30s)，DNS快取也超時(預設30s)同時用的低版本zookeeper jar包就很容易達成上述Bug的情況。而之前測試環境由於交換機切換的某些原因使得網路斷開超過了30s從而誘發了這一問題。而且不僅僅是Dubbo,任何用zookeeper低版本jar包都有可能出現這個問題！
總結
海恩法則指出,每一起嚴重事故的背後，必然有29次輕微事故和300起未遂先兆以及1000起事故隱患。所以對測試環境的任何問題都要引起重視，從而把問題消滅在萌芽階段。
公眾號
關注筆者公眾號，獲取更多幹貨文章:
