Dubbo + Nacos這么玩就失去高可用的能力了
作者：不焦躁的程序員
本文介紹Dubbo配合Nacos搭建的微服務系統，在Nacos-Server集群重啟時出現的問題。過程中通過種種現象、猜測、翻看源碼、實踐，最終讓Nacos-Server平滑重啟。
我們常用的微服務框架是SpringCloud那一套，在服務遠程調用和注冊中心的選型上也有不少方案。在服務遠程調用上常用的有：Feign、Dubbo等，在注冊中心上常用的有：Nacos、Zookeeper、Consul、Eureka等。我們項目這兩塊的選型是這樣的：RPC調用-Dubbo、注冊中心和配置中心-Nacos。
一、故障開端
項目平穩運行了好幾年，有一天發現Nacos集群的Server內存有點高，所以想升級下機器配置，然后重啟。說干就干，立馬在測試環境的3臺Nacos-Server集群中，任意選了一臺進行停機，暫且叫它Nacos-Server-1吧。接下來就是故障了開端了。
停機之后，測試環境立馬有許多服務的接口調不通，等待許久，故障一直沒恢復。所以又趕緊把Nacos-Server-1啟動起來。要找找原因，否則無法在生產環境重啟Nacos-Server。
我一直的觀點是：出現疑難問題時，首先看異常信息，然后猜測原因，再通過實踐去驗證，最終可以通過源碼再去證實。而不是一上來就看源碼，那樣比醬香配拿鐵更傷頭。
二、、異常信息
當Nacos-server-1停機時，首先在Nacos-Client（即某個微服務應用）看到異常，主要有2個：
- nacos-client與nacos-server心跳異常
- dubbo微服務調用異常
(1) nacos-client與nacos-server心跳異常：
2023-09-06 08:10:09|ERROR|com.alibaba.nacos.client.naming.net.NamingProxy:reqApi|548|com.alibaba.nacos.naming.beat.sender|"request: /nacos/v1/ns/instance/beat failed, servers: [10.20.1.13:8848, 10.20.1.14:8848, 10.20.1.15:8848], code: 500, msg: java.net.SocketTimeoutException: Read timed out"|""
2023-09-06 08:10:09|ERROR|com.alibaba.nacos.client.naming.beat.BeatReactor$BeatTask:run|198|com.alibaba.nacos.naming.beat.sender|"[CLIENT-BEAT] failed to send beat: {"port":0,"ip":"10.21.230.14","weight":1.0,"serviceName":"DEFAULT_GROUP@@consumers:com.cloud.usercenter.api.PartyCompanyMemberApi:1.0:","metadata":{"owner":"ehome-cloud-owner","init":"false","side":"consumer","application.version":"1.0","methods":"queryGroupMemberCount,queryWithValid,query,queryOne,update,insert,queryCount,queryPage,delete,queryList","release":"2.7.8","dubbo":"2.0.2","pid":"6","check":"false","interface":"com.bm001.ehome.cloud.usercenter.api.PartyCompanyMemberApi","version":"1.0","qos.enable":"false","timeout":"20000","revision":"1.2.38-SNAPSHOT","retries":"0","path":"com.bm001.ehome.cloud.usercenter.api.PartyCompanyMemberApi","protocol":"consumer","metadata-type":"remote","application":"xxxx-cloud","sticky":"false","category":"consumers","timestamp":"1693917779436"},"scheduled":false,"period":5000,"stopped":false}, code: 500, msg: failed to req API:/nacos/v1/ns/instance/beat after all servers([10.20.1.13:8848, 10.20.1.14:8848, 10.20.1.15:8848])"|""
2023-09-06 08:10:10|ERROR|com.alibaba.nacos.client.naming.net.NamingProxy:callServer|613|com.alibaba.nacos.naming.beat.sender|"[NA] failed to request"|"com.alibaba.nacos.api.exception.NacosException: java.net.ConnectException: 拒絕連接 (Connection refused)
at com.alibaba.nacos.client.naming.net.NamingProxy.callServer(NamingProxy.java:611)
at com.alibaba.nacos.client.naming.net.NamingProxy.reqApi(NamingProxy.java:524)
at com.alibaba.nacos.client.naming.net.NamingProxy.reqApi(NamingProxy.java:491)
at com.alibaba.nacos.client.naming.net.NamingProxy.sendBeat(NamingProxy.java:426)
at com.alibaba.nacos.client.naming.beat.BeatReactor$BeatTask.run(BeatReactor.java:167)
Caused by: java.io.IOException: Server returned HTTP response code: 502 for URL: http://10.20.1.14:8848/nacos/v1/ns/instance/beat?app=unknown&serviceName=DEFAULT_GROUP%40%40providers%3AChannelOrderExpressApi%3A1.0%3A&namespaceId=dev&port=20880&ip=10.20.0.200
at sun.net.www.protocol.http.HttpURLConnection.getInputStream0(HttpURLConnection.java:1914)
at sun.net.www.protocol.http.HttpURLConnection.getInputStream(HttpURLConnection.java:1512)
at java.net.HttpURLConnection.getResponseCode(HttpURLConnection.java:480)
at com.alibaba.nacos.common.http.client.response.JdkHttpClientResponse.getStatusCode(JdkHttpClientResponse.java:75)
at com.alibaba.nacos.common.http.client.handler.AbstractResponseHandler.handle(AbstractResponseHandler.java:43)
"
(2) dubbo微服務調用異常：
2023-09-06 08:09:38|ERROR|runtimeExceptionHandler|135|http-nio-8080-exec-5|"發生系統異常"|"org.apache.dubbo.rpc.RpcException: No provider available from registry 10.20.1.13:8848,10.20.1.14:8848,10.20.1.15:8848 for service ClueAuntMatchApi:1.0 on consumer 10.21.230.14 use dubbo version 2.7.8, please check status of providers(disabled, not registered or in blacklist).
at org.apache.dubbo.registry.integration.RegistryDirectory.doList(RegistryDirectory.java:599)
at org.apache.dubbo.rpc.cluster.directory.AbstractDirectory.list(AbstractDirectory.java:74)
at org.apache.dubbo.rpc.cluster.support.AbstractClusterInvoker.list(AbstractClusterInvoker.java:292)
at org.apache.dubbo.rpc.cluster.support.AbstractClusterInvoker.invoke(AbstractClusterInvoker.java:257)
at org.apache.dubbo.rpc.cluster.interceptor.ClusterInterceptor.intercept(ClusterInterceptor.java:47)三、根據異常進行猜測
熟悉Dubbo的朋友肯定知道這個錯誤please check status of providers(disabled, not registered or in blacklist).，基本上是代表：Provider下線了 或者 Consumer沒找到Provider。
根據以往使用dubbo + zookeeper的經驗，客戶端應該會拉取注冊中心的Provider的信息，然后本地緩存一份，即使注冊中心掛了，應該也能調用到別的服務。不至于出現完全找不到服務提供者的信息。
當思考不出來時，只能靠異常去猜測原因了。根據以上2個異常開始猜測。
1.猜測1
由于nacos-server-1掛了，導致nacos-client與server的心跳異常，導致本地緩存的provider的元數據被清掉了。有了猜測，趕緊查看nacos-client的源代碼，找到nacos-client 與 nacos-server 心跳的那一段：
繼續往下跟，可以看到這段核心代碼：
public String reqApi(String api, Map<String, String> params, Map<String, String> body, List<String> servers,
String method) throws NacosException {
params.put(CommonParams.NAMESPACE_ID, getNamespaceId());
if (CollectionUtils.isEmpty(servers) && StringUtils.isEmpty(nacosDomain)) {
throw new NacosException(NacosException.INVALID_PARAM, "no server available");
}
NacosException exception = new NacosException();
if (servers != null && !servers.isEmpty()) {
Random random = new Random(System.currentTimeMillis());
int index = random.nextInt(servers.size());
for (int i = 0; i < servers.size(); i++) {
String server = servers.get(index);
try {
return callServer(api, params, body, server, method);
} catch (NacosException e) {
exception = e;
if (NAMING_LOGGER.isDebugEnabled()) {
NAMING_LOGGER.debug("request {} failed.", server, e);
}
}
index = (index + 1) % servers.size();
}
}
if (StringUtils.isNotBlank(nacosDomain)) {
for (int i = 0; i < UtilAndComs.REQUEST_DOMAIN_RETRY_COUNT; i++) {
try {
return callServer(api, params, body, nacosDomain, method);
} catch (NacosException e) {
exception = e;
if (NAMING_LOGGER.isDebugEnabled()) {
NAMING_LOGGER.debug("request {} failed.", nacosDomain, e);
}
}
}
}
NAMING_LOGGER.error("request: {} failed, servers: {}, code: {}, msg: {}", api, servers, exception.getErrCode(),
exception.getErrMsg());
throw new NacosException(exception.getErrCode(),
"failed to req API:" + api + " after all servers(" + servers + ") tried: " + exception.getMessage());
}注意上面的這段代碼：
for (int i = 0; i < servers.size(); i++) {
String server = servers.get(index);
try {
return callServer(api, params, body, server, method);
} catch (NacosException e) {
exception = e;
if (NAMING_LOGGER.isDebugEnabled()) {
NAMING_LOGGER.debug("request {} failed.", server, e);
}
}
index = (index + 1) % servers.size();
}通過以上這一段代碼可以知道，nacos-client與nacos-server集群里的隨機一臺通信，感興趣的朋友可以繼續閱讀源代碼，跟到最后會發現，只要有一次心跳是正常的，那就認為心跳正常。因為我只停了一臺nacos-server，但是與其他兩臺server依舊可以保持心跳，所以整個心跳過程雖然報錯，但是仍然是正常的，所以這個猜測放棄了，繼續猜測。
2.猜測2
既然dubbo與zookeeper是建立長連接進行socket通信，那dubbo與nacos-server可能也是建立了長連接進行socket通信，某個nacos-server掛了之后，可能因為nacos-server沒有zookeeper的選主機制，所以不會自動切換到別的可用的nacos-server去調用。
或者是nacos-server集群選主問題，選主后沒有及時通知到consumer，或者consumer與nacos本身通信機制有問題。總之就是因為某種機制，導致沒有自動切換到可用的nacos-server上，導致獲取不到provider元數據，自然就無法發起調用。
既然有了這個猜想，那就趕緊去證實：
繼續翻看nacos源碼，發現nacos提供了集群節點之間數據一致性保障，使用的是Raft協議（一致性的選主協議，最后在簡單介紹），源代碼如下：
既然有選主協議，那就看看為什么通信還是失敗了呢？繼續從nacos-server的異常信息入手，在nacos-server-1停機時，看到nacos-server的logs下多種異常信息：
在naming-raft.log里，如下異常信息：
java.lang.NullPointerException: null
at com.alibaba.nacos.naming.consistency.persistent.raft.RaftCore.signalDelete(RaftCore.java:275)
at com.alibaba.nacos.naming.consistency.persistent.raft.RaftConsistencyServiceImpl.remove(RaftConsistencyServiceImpl.java:72)
at com.alibaba.nacos.naming.consistency.DelegateConsistencyServiceImpl.remove(DelegateConsistencyServiceImpl.java:53)
at com.alibaba.nacos.naming.core.ServiceManager.easyRemoveService(ServiceManager.java:434)
at com.alibaba.nacos.naming.core.ServiceManager$EmptyServiceAutoClean.lambda$null$1(ServiceManager.java:902)
at java.util.concurrent.ConcurrentHashMap.computeIfPresent(ConcurrentHashMap.java:1769)
at com.alibaba.nacos.naming.core.ServiceManager$EmptyServiceAutoClean.lambda$null$2(ServiceManager.java:891)
at java.util.stream.ForEachOps$ForEachOp$OfRef.accept(ForEachOps.java:183)
at java.util.stream.ReferencePipeline$2$1.accept(ReferencePipeline.java:175)
at java.util.concurrent.ConcurrentHashMap$EntrySpliterator.forEachRemaining(ConcurrentHashMap.java:3606)
at java.util.stream.AbstractPipeline.copyInto(AbstractPipeline.java:482)
at java.util.stream.ForEachOps$ForEachTask.compute(ForEachOps.java:290)
at java.util.concurrent.CountedCompleter.exec(CountedCompleter.java:731)
at java.util.concurrent.ForkJoinTask.doExec(ForkJoinTask.java:289)
at java.util.concurrent.ForkJoinPool.helpComplete(ForkJoinPool.java:1870)
at java.util.concurrent.ForkJoinPool.externalHelpComplete(ForkJoinPool.java:2467)
at java.util.concurrent.ForkJoinTask.externalAwaitDone(ForkJoinTask.java:324)
at java.util.concurrent.ForkJoinTask.doInvoke(ForkJoinTask.java:405)
at java.util.concurrent.ForkJoinTask.invoke(ForkJoinTask.java:734)
at java.util.stream.ForEachOps$ForEachOp.evaluateParallel(ForEachOps.java:159)
at java.util.stream.ForEachOps$ForEachOp$OfRef.evaluateParallel(ForEachOps.java:173)
at java.util.stream.AbstractPipeline.evaluate(AbstractPipeline.java:233)
at java.util.stream.ReferencePipeline.forEach(ReferencePipeline.java:485)
at com.alibaba.nacos.naming.core.ServiceManager$EmptyServiceAutoClean.lambda$run$3(ServiceManager.java:891)
at java.util.concurrent.ConcurrentHashMap.forEach(ConcurrentHashMap.java:1597)
at com.alibaba.nacos.naming.core.ServiceManager$EmptyServiceAutoClean.run(ServiceManager.java:881)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308)
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180)
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
at java.lang.Thread.run(Thread.java:748)
2023-09-07 08:19:25,262 ERROR Raft remove failed.naming-push.log里，如下異常信息：
java.lang.IllegalStateException: unable to find ackEntry for key: 10.21.140.23,43998,31247629183519634, ack json: {"type": "push-ack", "lastRefTime":"31247629183519634", "data":""}
at com.alibaba.nacos.naming.push.PushService$Receiver.run(PushService.java:677)
at java.lang.Thread.run(Thread.java:748)
2023-09-07 08:17:38,533 ERROR [NACOS-PUSH] error while receiving ack datanaming-distro.log里，如下異常信息：
2023-09-07 08:19:39,904 ERROR receive responsible key timestamp of com.alibaba.nacos.naming.iplist.ephemeral.dev-jzj##DEFAULT_GROUP@@providers:com.bm001.league.ordercenter.api.AdCluePoolApi:1.0: from 10.20.1.13:8848將這些異常信息結合起來可以推斷出，在nacos-server-1停機時，nacos-server集群只剩余2臺機器，它們在利用Raft協議進行選主時，出現了異常。導致consumer沒有找到主節點，無法建立正確的通信，所以consumer獲取不到provider的元數據。
繼續證實這個推斷吧！
此時同時把nacos-server-1和nacos-server-2同時停機，只保留1臺nacos-server時，微服務之間調用就正常了。因為單個節點時，選主正常，consumer很快與nacos-server建立了通信。此時再把3臺全部啟動后，也是一切正常。至此可以證實2臺nacos-server確實存在選主問題。
至此問題解決，安心干活兒去了，哈哈！
3.Raft協議
簡單講下Raft協議，Raft協議主要用來滿足微服務CAP理論中的CP，保障集群環境下的數據一致性。在Raft理論中，把每一個集群節點定義了三種狀態，跟zookeeper的ZAB 協議類似：
Follower 追隨者：集群所有節點一開始都是 Follower。
Candidate 候選者：當集群的某個節點開始發起投票選舉 Leader 的時，先給自己投一票，這時就會從 Follower 變成 Candidate。
Leader 領導者：當集群的某個節點獲得大多數節點（超過一半）的投票，那么就會變成 Leader。
四、總結
經過以上的過程，有3點注意：
- nacos-client和nacos-server的心跳只是告訴服務器，我這個客戶端的服務是正常的，同時nacos-server集群之間會異步同步服務信息。但是具體調用時依賴dubbo，dubbo在調用時，是單獨的通道從nacos-server拉取provider的元數據。
- nacos-server重啟時，一定要選在深夜，避開正常流量時間。同時為了保障集群持續可用，集群節點數保持奇數，偶數時會出現選主問題，導致客戶端與服務端無法正常通信，無法發起微服務調用。也就失去了nacos集群的能力了。
- 出現疑難問題時，首先看異常信息，然后猜測原因，再通過實踐去驗證，最終可以通過源碼再去證實。
責任編輯：趙寧寧
來源：
不焦躁的程序員
