我的dubbo應用, 剛開始的時候,啟動一兩個是沒有問題的, 啟動多了就大量出現:
2019-05-08 20:41:24.869 ERROR 2548 --- [TaskScheduler-1] o.s.c.a.nacos.discovery.NacosWatch : Error watching Nacos Service change java.lang.IllegalStateException: failed to req API:/nacos/v1/ns/service/list after all servers([192.168.11.196:8848]) tried: failed to req API:http://192.168.11.196:8848/nacos/v1/ns/service/list. code:500 msg: java.net.BindException: Address already in use: connect at com.alibaba.nacos.client.naming.net.NamingProxy.reqAPI(NamingProxy.java:380) ~[nacos-client-1.0.0.jar:na] at com.alibaba.nacos.client.naming.net.NamingProxy.reqAPI(NamingProxy.java:346) ~[nacos-client-1.0.0.jar:na] at com.alibaba.nacos.client.naming.net.NamingProxy.reqAPI(NamingProxy.java:294) ~[nacos-client-1.0.0.jar:na] at com.alibaba.nacos.client.naming.net.NamingProxy.getServiceList(NamingProxy.java:276) ~[nacos-client-1.0.0.jar:na] at com.alibaba.nacos.client.naming.net.NamingProxy.getServiceList(NamingProxy.java:252) ~[nacos-client-1.0.0.jar:na] at com.alibaba.nacos.client.naming.NacosNamingService.getServicesOfServer(NacosNamingService.java:525) ~[nacos-client-1.0.0.jar:na] at org.springframework.cloud.alibaba.nacos.discovery.NacosWatch.nacosServicesWatch(NacosWatch.java:127) ~[spring-cloud-alibaba-nacos-discovery-0.9.0.RELEASE.jar:0.9.0.RELEASE] at org.springframework.scheduling.support.DelegatingErrorHandlingRunnable.run(DelegatingErrorHandlingRunnable.java:54) ~[spring-context-5.1.5.RELEASE.jar:5.1.5.RELEASE] at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) ~[na:1.8.0_201] at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308) ~[na:1.8.0_201] at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180) ~[na:1.8.0_201] at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294) ~[na:1.8.0_201] at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) ~[na:1.8.0_201] at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) ~[na:1.8.0_201] at java.lang.Thread.run(Thread.java:748) ~[na:1.8.0_201]
可以看到 NamingProxy 的reqAPI 方法返回了錯誤。
根本原因是:
public String callServer(String api, Map<String, String> params, String curServer, String method) throws NacosException { long start = System.currentTimeMillis(); long end = 0L; this.checkSignature(params); List<String> headers = this.builderHeaders(); if (!curServer.contains(":")) { curServer = curServer + ":" + this.serverPort; } String url = HttpClient.getPrefix() + curServer + api; HttpResult result = HttpClient.request(url, headers, params, "UTF-8", method); // 這里 end = System.currentTimeMillis(); MetricsMonitor.getNamingRequestMonitor(method, url, String.valueOf(result.code)).observe((double)(end - start)); if (200 == result.code) { return result.content; } else if (304 == result.code) { return ""; } else { throw new NacosException(500, "failed to req API:" + HttpClient.getPrefix() + curServer + api + ". code:" + result.code + " msg: " + result.content); // 這里!! } }
再進去
public static HttpClient.HttpResult request(String url, List<String> headers, Map<String, String> paramValues, String encoding, String method) { HttpURLConnection conn = null; HttpClient.HttpResult var7; try { String encodedContent = encodingParams(paramValues, encoding); url = url + (StringUtils.isEmpty(encodedContent) ? "" : "?" + encodedContent); conn = (HttpURLConnection)(new URL(url)).openConnection(); setHeaders(conn, headers, encoding); conn.setConnectTimeout(CON_TIME_OUT_MILLIS); conn.setReadTimeout(TIME_OUT_MILLIS); conn.setRequestMethod(method); conn.setDoOutput(true); if ("POST".equals(method) || "PUT".equals(method)) { byte[] b = encodedContent.getBytes(); conn.setRequestProperty("Content-Length", String.valueOf(b.length)); conn.getOutputStream().write(b, 0, b.length); conn.getOutputStream().flush(); conn.getOutputStream().close(); } conn.connect();// 發生錯誤的時候,執行達到這里, 就到了下面的 catch部分。 LogUtils.NAMING_LOGGER.debug("Request from server: " + url); var7 = getResult(conn); return var7; } catch (Exception var13) { try { if (conn != null) { LogUtils.NAMING_LOGGER.warn("failed to request " + conn.getURL() + " from " + InetAddress.getByName(conn.getURL().getHost()).getHostAddress()); } } catch (Exception var12) { LogUtils.NAMING_LOGGER.error("[NA] failed to request ", var12); } LogUtils.NAMING_LOGGER.error("[NA] failed to request ", var13); var7 = new HttpClient.HttpResult(500, var13.toString(), Collections.emptyMap()); } finally { if (conn != null) { conn.disconnect(); } } return var7; }
開始的時候,總是以為是服務端出了什么問題, 應該就是 httpclient 發送GET 請求, 服務端沒有正確響應吧! 於是反復折騰 nacos服務端,還跟進去了其源碼。 后面發現搞錯了方向!
反復折騰,無果。 慢慢的發現, 發生Address already in use: connect錯誤,也不是有規律的,有時候啟動一個應用出錯,有時候不會,有時候需要啟動很多個才會。 而且出現這個錯誤的概率也是不一樣的,有時候一個應用10分鍾 出現 1-2個,有的10分鍾幾十個。
網上搜索一把Address already in use: connect,發現都是 junit相關的錯誤,明顯跟我這個不同(后面才知道, 其實錯誤的原因是一樣的!)。 后面慢慢認識到, com.alibaba.nacos.client.naming.net.HttpClient#request 創建HttpURLConnection 沒有使用連接處, 這樣的問題我之前也遇到過。 如果過多的HttpURLConnection, 可能會導致系統資源不夠用。調試發現 nacos 似乎以非常快的速度調用com.alibaba.nacos.client.naming.net.NamingProxy#callServer(java.lang.String, java.util.Map<java.lang.String,java.lang.String>, java.lang.String, java.lang.String) 方法 。netstat查看服務器,發現大量的
tcp6 0 0 192.168.11.196:49632 192.168.11.196:8848 TIME_WAIT
netstat -na | grep TIME_WAIT | wc -l 返回 28028 , 這肯定是不對的! 太恐怖了有沒有!
[root@localhost logs]# ulimit -a core file size (blocks, -c) 0 data seg size (kbytes, -d) unlimited scheduling priority (-e) 0 file size (blocks, -f) unlimited pending signals (-i) 63250 max locked memory (kbytes, -l) 64 max memory size (kbytes, -m) unlimited open files (-n) 1024 pipe size (512 bytes, -p) 8 POSIX message queues (bytes, -q) 819200 real-time priority (-r) 0 stack size (kbytes, -s) 8192 cpu time (seconds, -t) unlimited max user processes (-u) 63250 virtual memory (kbytes, -v) unlimited file locks (-x) unlimited
修改 ulimit -n 為65535 , 無果。 -n 是用來修改 可打開文件數的,可能不是修改端口數的吧。 搞半天無果。
忽然意識到本機可能也端口不夠用, 果然, netstat查看了一些本機的 端口,發現大量的 端口未釋放,15000 以上的量!
原來不是 nacos 的坑! 而是 我這個客戶端的問題, 我本機(win10)的臨時端口不夠用了!! 難怪nacos的日志找不到錯誤,我本機就 有,原來請求都沒有發送過去!!
linux 默認是可以打開很多端口的,win不是。
據說win 是 1024 -5000, 后面發現這個不對! 那個是之前的win系統,我的win10 不是這樣的,而是:
修改本機
netsh int ipv4 set dynamicport tcp start=20000 num=40000
確定。
netsh int ipv4 show dynamicport tcp 協議 tcp 動態端口范圍 --------------------------------- 啟動端口 : 20000 端口數 : 40000
搞定!
不過,確實跟nacos 有關, 這貨需要打開這么多的端口??? nacos 的坑啊!
wiindows 上容易出現這個問題, linux 一般是不會的:
[root@localhost nacos]# sysctl -a | grep file-max fs.file-max = 1604751 sysctl: reading key "net.ipv6.conf.all.stable_secret" sysctl: reading key "net.ipv6.conf.default.stable_secret" sysctl: reading key "net.ipv6.conf.lo.stable_secret" sysctl: reading key "net.ipv6.conf.p4p1.stable_secret" [root@localhost nacos]# [root@localhost nacos]# sysctl -a | grep ipv4.ip_local_port_range net.ipv4.ip_local_port_range = 32768 60999 sysctl: reading key "net.ipv6.conf.all.stable_secret" sysctl: reading key "net.ipv6.conf.default.stable_secret" sysctl: reading key "net.ipv6.conf.lo.stable_secret" sysctl: reading key "net.ipv6.conf.p4p1.stable_secret" [root@localhost nacos]# ulimit -u 63250 [root@localhost nacos]# netstat -an | wc -l 22136
參考