背景:
????????前端:angular 12,websocket接口由lib.dom.d.ts提供
????????后端:java,websocket接口由jetty 12提供
問題現象:
? ? ? ? 前端連上server后,每隔30s就會斷開,由于長時間空閑,會導致websocket連接斷開,所以前端也發送了ping報文(由于前端接口沒有單獨的ping/ping接口,因此ping報文和普通報文一樣,都是調用的send()方法),每隔30s發一次。當然前端可實現以重連機制,但是這樣就會出現反復重連的情況,會導致界面感知不友好,所以還是得找下根本原因。
前端打印的日志:
后端打印的日志:
onWebSocketClose, statusCode=1005, reason=null
前后端都沒有斷連的具體原因,只有狀態碼,這就很難辦了。?為了省事,我用gpt搜出來的常見狀態碼如下:
從上圖可以看出,不管是1005還是1006,都表示沒有收到關閉幀的異常關閉。
?排查思路:
????????因為客戶端周期性的發送了ping報文,所以先排查下是不是服務端的空閑超時時間太短了導致的?
// 顯式創建 ServerConnector 并設置空閑超時ServerConnector connector = new ServerConnector(server);connector.setPort(port);connector.setIdleTimeout(86400000); // 1 天(毫秒)
上面的代碼就是修改空閑超時時間,先設置為一天,然后重新測試,發現還是不行,前端還是會不斷重連。
????????難道設置的時間沒效果?那就把jetty的日志打開,日志如下:
DEBUG 25-07-25 14:25:59.133 org.eclipse.jetty.websocket.core.server.internal.AbstractHandshaker.upgradeRequest(AbstractHandshaker.java:116) [qtp956673894-39]
session WebSocketCoreSession@1e78624f{SERVER,WebSocketSessionState@78abbc31{CONNECTING,i=NO-OP,o=NO-OP,c=null},[ws://10.10.10.10:8080/mq?token=test,null,false.[permessage-deflate]],af=true,i/o=4096/4096,fs=65536}->JettyWebSocketFrameHandler@6a65aae4[com.nsb.enms.notification.server.WebSocketServer]DEBUG 25-07-25 14:25:59.134 org.eclipse.jetty.io.IdleTimeout.setIdleTimeout(IdleTimeout.java:85) [qtp956673894-39]
Setting idle timeout 86400000 -> 86400000 on SocketChannelEndPoint@202ab0ab[{l=/10.10.10.10:8080,r=/20.20.20.20:45678,OPEN,fill=-,flush=-,to=6/86400000}{io=0/0,kio=0,kro=1}]->[HttpConnection@7fb68543[p=HttpParser{s=END,0 of -1},g=HttpGenerator@7e82a7c8{s=START}]=>HttpChannelState@bd8ef5b{handling=Thread[#39,qtp956673894-39,5,main], handled=false, send=SENDING, completed=false, request=GET@68dd4ee2 http://10.10.10.10:8080/mq?token=test HTTP/1.1}]
從日志上可以看到服務端的設置是生效了的。
????????既然服務端沒問題,那可能是客戶端的空閑超時時間導致的?查了下資料,angular自帶的websocket沒有設置空閑超時時間的方法。那就換個思路,用java寫個客戶端來測試這個問題。
import org.eclipse.jetty.websocket.api.Callback;
import org.eclipse.jetty.websocket.api.Frame;
import org.eclipse.jetty.websocket.api.Session;
import org.eclipse.jetty.websocket.api.annotations.*;
import org.eclipse.jetty.websocket.core.OpCode;import java.nio.ByteBuffer;
import java.util.Scanner;
import java.util.concurrent.CountDownLatch;
import java.util.concurrent.Executors;
import java.util.concurrent.ScheduledExecutorService;
import java.util.concurrent.TimeUnit;@WebSocket
public class ClientSocket {long start;public final CountDownLatch closeLatch = new CountDownLatch(1);private Session session;private ScheduledExecutorService scheduler;@OnWebSocketOpenpublic void onOpen(Session session) {this.session = session;start = System.currentTimeMillis();System.out.println("客戶端:已連接到服務端,URI: " + session.getUpgradeRequest().getRequestURI() + "," + start);// 啟動心跳scheduler = Executors.newSingleThreadScheduledExecutor();// 注意這里設置的間隔時間是31s
// scheduler.scheduleAtFixedRate(this::sendPing, 0, 31, TimeUnit.SECONDS);// 注意這里設置的間隔時間是32s
// scheduler.scheduleAtFixedRate(this::sendMSG, 0, 32, TimeUnit.SECONDS);new Thread(this::readConsoleInput).start();}@OnWebSocketMessagepublic void onMessage(Session session, String message) {System.out.println("客戶端:收到服務端消息: " + message);}@OnWebSocketFramepublic void onFrame(Session session, Frame frame, Callback cb) {System.out.println("客戶端:收到幀,操作碼: " + frame.getOpCode());if (frame.getOpCode() == OpCode.PONG) {System.out.println("客戶端:收到 PONG 幀,負載: " + frame.getPayload());}}@OnWebSocketClosepublic void onClose(Session session, int statusCode, String reason) {this.session = null;System.out.println("客戶端:連接關閉,狀態碼: " + statusCode + ", 原因: " + reason + "," + (System.currentTimeMillis() - start));closeLatch.countDown();}@OnWebSocketErrorpublic void onError(Session session, Throwable throwable) {System.err.println("客戶端:發生錯誤: " + throwable.getMessage() + "," + System.currentTimeMillis());throwable.printStackTrace();}private void readConsoleInput() {Scanner scanner = new Scanner(System.in);System.out.println("請輸入消息(輸入 'ping' 發送 PING 幀,'exit' 退出):");while (session != null && session.isOpen()) {String input = scanner.nextLine();if ("exit".equalsIgnoreCase(input)) {try {session.close(1000, "Client requested closure", Callback.from(() -> {System.out.println("客戶端:消息發送成功: " + input);}, throwable -> {throwable.printStackTrace();}));} catch (Exception e) {e.printStackTrace();}break;} else if ("ping".equalsIgnoreCase(input)) {try {ByteBuffer payload = ByteBuffer.wrap("PingTest".getBytes());session.sendPing(payload, Callback.from(() -> {System.out.println("客戶端:發送 PING 幀成功");}, throwable -> {throwable.printStackTrace();}));} catch (Exception e) {e.printStackTrace();}} else if (!input.trim().isEmpty()) {try {session.sendText(input, Callback.from(() -> {System.out.println("客戶端:消息發送成功: " + input);}, throwable -> {throwable.printStackTrace();}));} catch (Exception e) {e.printStackTrace();}}}scanner.close();}private void sendPing() {if (session != null && session.isOpen()) {try {ByteBuffer payload = ByteBuffer.wrap("PingTest".getBytes());session.sendPing(payload, Callback.from(() -> {System.out.println("客戶端:發送 PING 幀成功");}, throwable -> {throwable.printStackTrace();}));} catch (Exception e) {e.printStackTrace();}}}private void sendMSG() {if (session != null && session.isOpen()) {try {String input = String.valueOf(System.currentTimeMillis());session.sendText(input, Callback.from(() -> {System.out.println("客戶端:消息發送成功: " + input);}, throwable -> {throwable.printStackTrace();}));} catch (Exception e) {e.printStackTrace();}}}
}
注意看,上面的代碼,默認是把這兩行代碼屏蔽了的:
// scheduler.scheduleAtFixedRate(this::sendPing, 0, 31, TimeUnit.SECONDS);
// scheduler.scheduleAtFixedRate(this::sendMSG, 0, 32, TimeUnit.SECONDS);
這兩行代碼表示周期性發送ping/msg,
第一行表示每隔31s發送一次ping報文,
第二行表示每隔32s發送一次msg消息。
以下是調用代碼:
import org.eclipse.jetty.websocket.client.WebSocketClient;import java.net.URI;
import java.time.Duration;
import java.util.concurrent.TimeUnit;public class TestClient {public static void main(String[] args) throws Exception {String serverUri = "ws://10.10.10.10:8080/mq";WebSocketClient client = new WebSocketClient();
// client.setMaxTextMessageSize(65536);try {client.start();System.out.println("WebSocket 客戶端已啟動");ClientSocket wsClient = new ClientSocket();// 設置空閑超時時間,默認注釋該行
// client.setIdleTimeout(Duration.ofSeconds(60));client.connect(wsClient, new URI(serverUri));boolean closed = wsClient.closeLatch.await(5, TimeUnit.MINUTES);if (!closed) {System.out.println("等待連接關閉超時");}} catch (Exception e) {e.printStackTrace();} finally {client.stop();System.out.println("WebSocket 客戶端已停止");}}
}
注意,因為java client支持設置空閑超時時間,所以上面的代碼,默認先注釋掉設置空閑超時時間的代碼。執行上述代碼,等待一會,可以看到如下輸出日志:
WebSocket 客戶端已啟動
客戶端:已連接到服務端,URI: ws://10.10.10.10:8080/mq,1753427445848
請輸入消息(輸入 'ping' 發送 PING 幀,'exit' 退出):
客戶端:消息發送成功: 1753427445852
客戶端:發生錯誤: Connection Idle Timeout,1753427475886
org.eclipse.jetty.websocket.api.exceptions.WebSocketTimeoutException: Connection Idle Timeoutat org.eclipse.jetty.websocket.common.JettyWebSocketFrameHandler.convertCause(JettyWebSocketFrameHandler.java:436)at org.eclipse.jetty.websocket.common.JettyWebSocketFrameHandler.onError(JettyWebSocketFrameHandler.java:240)...
Caused by: org.eclipse.jetty.websocket.core.exception.WebSocketTimeoutException: Connection Idle Timeout... 10 more
Caused by: java.util.concurrent.TimeoutException: Idle timeout expired: 30011/30000 msat org.eclipse.jetty.io.IdleTimeout.checkIdleTimeout(IdleTimeout.java:167)... 7 more
客戶端:連接關閉,狀態碼: 1001, 原因: Connection Idle Timeout,30040
WebSocket 客戶端已停止
從日志上可以得知,關閉原因是:Connection Idle Timeout,30040,說明連接空閑時間超過了30s導致客戶端被關閉。
服務端也是打印的相同的日志:
onWebSocketClose, statusCode=1001, reason=Connection Idle Timeout,
因為服務器端的空閑超時時間設置的1天,由此說明,連接斷開是受客戶端的空閑超時時間影響的,從日志上也可以得出,默認情況下,客戶端的空閑超時時間就是30s。
????????我們前面提到的幾行注釋代碼,就是為了驗證這個30s的問題,接下來,挨個測試下那些被注釋的代碼,看下都有什么輸出的結果。
驗證代碼:
測試1:設置客戶端的超時時間
放開TestClient下的代碼:
client.setIdleTimeout(Duration.ofSeconds(60));
這個表示空閑超時時間為60s后,重新執行測試用例,輸出如下:
WebSocket 客戶端已啟動
客戶端:已連接到服務端,URI: ws://10.10.10.10:8080/mq,1753428684378
請輸入消息(輸入 'ping' 發送 PING 幀,'exit' 退出):
客戶端:發生錯誤: Connection Idle Timeout,1753428744397
...
Caused by: org.eclipse.jetty.websocket.core.exception.WebSocketTimeoutException: Connection Idle Timeout... 10 more
Caused by: java.util.concurrent.TimeoutException: Idle timeout expired: 60005/60000 msat org.eclipse.jetty.io.IdleTimeout.checkIdleTimeout(IdleTimeout.java:167)... 7 more
客戶端:連接關閉,狀態碼: 1001, 原因: Connection Idle Timeout,60020
WebSocket 客戶端已停止
日志顯示60s之后才報超時,說明前面設置的超時代碼生效了。
測試2:周期性發送ping報文
先注釋掉TestClient的60s超時機制,保持默認30s,然后,將ClientSocket下的周期性發送ping報文的代碼打開,間隔為31s。
TestClient.java 修改如下:
// TestClient.java 中注釋該行
// client.setIdleTimeout(Duration.ofSeconds(60));
ClientSocket.java 修改如下:?
// ClientSocket.java 中放開該行,且周期為31s
scheduler.scheduleAtFixedRate(this::sendPing, 0, 31, TimeUnit.SECONDS);
執行結果如下:
WebSocket 客戶端已啟動
客戶端:已連接到服務端,URI: ws://10.10.10.10:8080/mq,1753429262205
請輸入消息(輸入 'ping' 發送 PING 幀,'exit' 退出):
客戶端:發送 PING 幀成功
客戶端:收到幀,操作碼: 10
客戶端:收到 PONG 幀,負載: java.nio.HeapByteBufferR[pos=0 lim=8 cap=8]
客戶端:發生錯誤: Connection Idle Timeout,1753429292256
Connection Idle Timeout... 10 more
Caused by: java.util.concurrent.TimeoutException: Idle timeout expired: 30015/30000 msat org.eclipse.jetty.io.IdleTimeout.checkIdleTimeout(IdleTimeout.java:167)... 7 more
客戶端:連接關閉,狀態碼: 1001, 原因: Connection Idle Timeout,30053
WebSocket 客戶端已停止
日志顯示,問題復現,連接空閑超時超過30s 。
現在修改下ClientSocket.java代碼,將超時時間設置為29s,代碼如下:
// ClientSocket.java 中放開該行,且周期為29s
scheduler.scheduleAtFixedRate(this::sendPing, 0, 29, TimeUnit.SECONDS);
然后執行,輸出的結果就不一樣了:?
WebSocket 客戶端已啟動
客戶端:已連接到服務端,URI: ws://10.10.10.10:8080/mq,1753429377099
請輸入消息(輸入 'ping' 發送 PING 幀,'exit' 退出):
客戶端:發送 PING 幀成功
客戶端:收到幀,操作碼: 10
客戶端:收到 PONG 幀,負載: java.nio.HeapByteBufferR[pos=0 lim=8 cap=8]
客戶端:發送 PING 幀成功
客戶端:收到幀,操作碼: 10
客戶端:收到 PONG 幀,負載: java.nio.HeapByteBufferR[pos=0 lim=8 cap=8]
客戶端:發送 PING 幀成功
客戶端:收到幀,操作碼: 10
客戶端:收到 PONG 幀,負載: java.nio.HeapByteBufferR[pos=0 lim=8 cap=8]
客戶端:發送 PING 幀成功
客戶端:收到幀,操作碼: 10
客戶端:收到 PONG 幀,負載: java.nio.HeapByteBufferR[pos=0 lim=8 cap=8]
客戶端:發送 PING 幀成功
客戶端:收到幀,操作碼: 10
客戶端:收到 PONG 幀,負載: java.nio.HeapByteBufferR[pos=0 lim=8 cap=8]
從上面可以得出結論,只要周期在30s以內發送ping報文,則不會出現超時的問題。
那么,ping報文是否必須發送呢,如果只發送msg呢,是否也能達到相同的效果?
測試3:發送msg報文
修改ClientSocket.java,代碼如下:
// 注釋該行,不發送ping報文
// scheduler.scheduleAtFixedRate(this::sendPing, 0, 29, TimeUnit.SECONDS);// 僅發送msg報文scheduler.scheduleAtFixedRate(this::sendMSG, 0, 32, TimeUnit.SECONDS);
設置發送周期為32s,輸出結果如下:?
WebSocket 客戶端已啟動
客戶端:已連接到服務端,URI: ws://10.10.10.10:8080/mq,1753430236546
請輸入消息(輸入 'ping' 發送 PING 幀,'exit' 退出):
客戶端:消息發送成功: 1753430236548
客戶端:發生錯誤: Connection Idle Timeout,1753430266587
org.eclipse.jetty.websocket.api.exceptions.WebSocketTimeoutException: Connection Idle Timeout...
Caused by: org.eclipse.jetty.websocket.core.exception.WebSocketTimeoutException: Connection Idle Timeout... 10 more
Caused by: java.util.concurrent.TimeoutException: Idle timeout expired: 30011/30000 msat org.eclipse.jetty.io.IdleTimeout.checkIdleTimeout(IdleTimeout.java:167)... 7 more
客戶端:連接關閉,狀態碼: 1001, 原因: Connection Idle Timeout,30042
WebSocket 客戶端已停止
問題同上,因為發送周期為32s,超過了30s,所以會報超時的錯誤。
接下來把發送周期改小為29s,看下是什么情況:
scheduler.scheduleAtFixedRate(this::sendMSG, 0, 29, TimeUnit.SECONDS);
輸出日志:
WebSocket 客戶端已啟動
客戶端:已連接到服務端,URI: ws://100.10.10.10:8080/mq,1753430446727
請輸入消息(輸入 'ping' 發送 PING 幀,'exit' 退出):
客戶端:消息發送成功: 1753430446728
客戶端:消息發送成功: 1753430475742
客戶端:消息發送成功: 1753430504734
客戶端:消息發送成功: 1753430533728
客戶端:消息發送成功: 1753430562739
客戶端:消息發送成功: 1753430591733
客戶端:消息發送成功: 1753430620732
客戶端:消息發送成功: 1753430649737
客戶端:消息發送成功: 1753430678739
周期性地發送msg報文,連接也正常,沒有出現超時的問題。
通過上面幾個日志的對比,可以得出如下結論:
1、驗證了默認30s超時的問題。
2、 只要在30s內周期性地發送報文,無論是ping還是msg,都可以避免超時的問題。
解決方案:
? ? ? ? 經過以上的分析驗證,現在已經明確了,問題就出在客戶端的空閑超時上。解決方案有三種:
????????1、設置客戶端的空閑超時時間為一個很大的數;這個方法不現實,同時,因為angular上沒相應的接口,所以也沒法實現。
????????2、客戶端周期發送ping報文,間隔需要小于客戶端的空閑超時時間;
????????3、客戶端周期發送msg報文,間隔需要小于客戶端的空閑超時時間;實際上,msg報文是根據業務產生的,不具有周期性。java側是將ping報文和msg報文分開的,但angular沒有提供發送ping報文的單獨接口,所以發送ping報文實際也是通過發送msg報文的接口發送出去的。
????????4、服務端周期性的發送ping報文,間隔需要小于客戶端的空閑超時時間;這個方法有個問題,服務端需要對每個新的請求都建一個定時的timer,并在每個請求斷開時,取消對應的timer,這就增加了服務端管理session的復雜度。因此,我不建議采用這種方法。
? ? ? ? 所以,比較好的解決辦法是,angular需要周期性的發送ping報文,間隔時間需要小于空閑超時時間。
????????但在文章開頭,我們已經介紹了,前端實際上是有實現周期發送ping報文的,間隔周期設置的是30s。這個30s,就是問題的根源,因為是超時的臨界值,稍不注意就超時了,可以用前面介紹的java客戶端做測試,將周期改為30s,就會出現超時的情況。
? ? ? ? 基于此,本文提出的問題也好解決,將超時時間改為30s以內即可,為了保險起見可以改為15s。? ? ? ?
? ? ? ? 本以為找到問題的根本原因了,結果經測試,問題并沒有解決,哈哈,😂。沒辦法了,打開前端的debug模式,看到控制臺有很多異常打印:
ERROR SyntaxError: Unexpected token 'p', "ping" is not valid JSONat JSON.parse (<anonymous>)at t.onMessage (main-es2015.d1b55912bea89f3f09c9.js:1:1177790)at ws.onmessage [as __zone_symbol__ON_PROPERTYmessage] (main-es2015.d1b55912bea89f3f09c9.js:1:1177023)
ERROR SyntaxError: Unexpected token 'p', "pong" is not valid JSONat JSON.parse (<anonymous>)at t.onMessage (main-es2015.d1b55912…3f09c9.js:1:1177790)at ws.onmessage [as __zone_symbol__ON_PROPERTYmessage] (main-es2015.d1b55912…3f09c9.js:1:1177023)at WebSocket.S (vendor-es2015.5e60c9…21fe60.js:1:5147553)
?這打印的異常說明處理的數據不是json格式的,因為收到的是ping和pong消息,所以一開始覺得這個錯誤沒啥影響,也就一直沒放在心上。報錯的源碼如下:
protected onMessage(evt) {const msg: Message = JSON.parse(evt.data);const notice = msg.data;const type = msg.type; ...}
按照前面的分析,前端每15s發送一次ping,理論上可以保持連接活躍了,但接近一分鐘的時候還是斷了。經過一番查詢后,還是懷疑這個點,于是加上try/catch試試,不讓其報錯,修改的代碼如下:
protected onMessage(evt) {let msg: any;try {msg = JSON.parse(evt.data);} catch (e) {console.warn('Received non-JSON message from server:', evt.data);return; // 跳過非 JSON 消息,比如ping/pong}...}
然后再測試,發現對了,好吧,問題總算是解決了。?前端我也不熟悉,所以就不總結了,就這樣吧,完結,撒花。