-
Notifications
You must be signed in to change notification settings - Fork 2.6k
Closed
Description
Describe the bug
When creating a WebSocketClient and not connecting it immediately, the lost-connection-detection doesn't work properly and the client fails with a missing pong. This only occurs when connecting the client after a delay. At most one "round of pings" is sent before the client closes the connection.
To Reproduce
Steps to reproduce the behavior:
- Use this simplelogger-properties-File
- Create a simple WebSocketServer like below
- Create a simple WebSocketClient like below
- Create a main-method like below
- Run
Server
import java.net.InetSocketAddress;
import org.java_websocket.WebSocket;
import org.java_websocket.handshake.ClientHandshake;
import org.java_websocket.server.WebSocketServer;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
public class Server extends WebSocketServer {
private Logger logger = LoggerFactory.getLogger(Server.class);
public Server(String host, int port) {
super(new InetSocketAddress(host, port));
this.setConnectionLostTimeout(10);
}
@Override
public void onClose(WebSocket conn, int code, String reason, boolean remote) {
logger.info(
"Server.onClose - " +
"conn = " + conn +
", code = " + code +
", reason = " + reason +
", remote = " + remote);
}
@Override
public void onError(WebSocket conn, Exception ex) {
logger.error("Server.onError - " + "conn = " + conn + ", ex = " + ex.getCause());
}
@Override
public void onMessage(WebSocket conn, String message) {
logger.info(conn.getRemoteSocketAddress() + " said: " + message);
}
@Override
public void onOpen(WebSocket conn, ClientHandshake handshake) {
logger.info("Server.onOpen - with " + conn.getRemoteSocketAddress());
}
@Override
public void onStart() {
logger.info("Server.onStart");
logger.info("Listening on " + this.getAddress());
}
}
Client
import java.net.URI;
import org.java_websocket.client.WebSocketClient;
import org.java_websocket.handshake.ServerHandshake;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
public class Client extends WebSocketClient {
private Logger logger = LoggerFactory.getLogger(Client.class);
public Client(URI serverUri) {
super(serverUri);
this.setConnectionLostTimeout(10);
}
@Override
public void onClose(int code, String reason, boolean remote) {
logger.info("Client.onClose - " + "code = " + code + ", reason = " + reason + ", remote = " + remote);
}
@Override
public void onError(Exception ex) {
logger.error("Client.onError - " + "ex = " + ex);
}
@Override
public void onMessage(String message) {
logger.info(getRemoteSocketAddress() + " said: " + message);
}
@Override
public void onOpen(ServerHandshake handshakedata) {
logger.info("Client.onOpen with " + getRemoteSocketAddress());
}
}
Main-Method
import java.net.URI;
import java.util.Timer;
import java.util.TimerTask;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
public class Starter {
private static Logger LOGGER = LoggerFactory.getLogger(Client.class);
public static void main(String[] args) throws InterruptedException {
String hostName = "localhost";
int port = 5008;
Client client = new Client(URI.create("ws://" + hostName + ":" + port));
Server server = new Server(hostName, port);
server.start();
Timer timer = new Timer();
TimerTask task = new TimerTask() {
@Override
public void run() {
LOGGER.info("Connecting now...");
try {
client.connectBlocking();
} catch (InterruptedException e) {
e.printStackTrace();
}
LOGGER.info("Connected successfully");
}
};
timer.schedule(task, 15000);
}
}
Expected behavior
I expect the client to not fail in this case :)
Debug log
LOG
2021-12-07 13:16:05.165 [TRACE] Connection lost timer started
2021-12-07 13:16:05.208 [INFO] Server.onStart
2021-12-07 13:16:05.208 [INFO] Listening on localhost/127.0.0.1:5008
2021-12-07 13:16:19.876 [INFO] Connecting now...
2021-12-07 13:16:19.876 [TRACE] write(153): GET / HTTP/1.1
Connection: Upgrade
Host: localhost:5008
Sec-WebSocket-Key: o2UQnaB+hYeNsbPJmHb33A==
Sec-WebSocket-Version: 13
Upgrade: websocket
2021-12-07 13:16:19.888 [TRACE] process(153): (GET / HTTP/1.1
Connection: Upgrade
Host: localhost:5008
Sec-WebSocket-Key: o2UQnaB+hYeNsbPJmHb33A==
Sec-WebSocket-Version: 13
Upgrade: websocket
)
2021-12-07 13:16:19.888 [TRACE] acceptHandshakeAsServer - Matching extension found: DefaultExtension
2021-12-07 13:16:19.888 [TRACE] acceptHandshake - Matching protocol found:
2021-12-07 13:16:19.903 [TRACE] write(212): HTTP/1.1 101 Web Socket Protocol Handshake
Connection: Upgrade
Date: Tue, 07 Dec 2021 12:16:19 GMT
Sec-WebSocket-Accept: 5GunGz4gMDDQdHm5gIZkNyIuyaE=
Server: TooTallNate Java-WebSocket
Upgrade: websocket
2021-12-07 13:16:19.903 [TRACE] open using draft: Draft_6455 extension: DefaultExtension protocol: max frame size: 2147483647
2021-12-07 13:16:19.903 [TRACE] process(212): (HTTP/1.1 101 Web Socket Protocol Handshake
Connection: Upgrade
Date: Tue, 07 Dec 2021 12:16:19 GMT
Sec-WebSocket-Accept: 5GunGz4gMDDQdHm5gIZkNyIuyaE=
Server: TooTallNate Java-WebSocket
Upgrade: websocket
)
2021-12-07 13:16:19.903 [INFO] Server.onOpen - with /127.0.0.1:52988
2021-12-07 13:16:19.903 [TRACE] acceptHandshakeAsClient - Matching extension found: DefaultExtension
2021-12-07 13:16:19.903 [TRACE] acceptHandshake - Matching protocol found:
2021-12-07 13:16:19.903 [TRACE] open using draft: Draft_6455 extension: DefaultExtension protocol: max frame size: 2147483647
2021-12-07 13:16:19.903 [TRACE] Connection lost timer started
2021-12-07 13:16:19.903 [INFO] Client.onOpen with localhost/127.0.0.1:5008
2021-12-07 13:16:19.903 [INFO] Connected successfully
2021-12-07 13:16:25.218 [TRACE] send frame: Framedata{ opcode:PING, fin:true, rsv1:false, rsv2:false, rsv3:false, payload length:[pos:0, len:0], payload:}
2021-12-07 13:16:25.218 [TRACE] afterEnconding(0):
2021-12-07 13:16:25.218 [TRACE] write(2): �
2021-12-07 13:16:25.218 [TRACE] process(2): (� )
2021-12-07 13:16:25.218 [TRACE] afterDecoding(0):
2021-12-07 13:16:25.218 [TRACE] matched frame: Framedata{ opcode:PING, fin:true, rsv1:false, rsv2:false, rsv3:false, payload length:[pos:0, len:0], payload:}
2021-12-07 13:16:25.218 [TRACE] send frame: Framedata{ opcode:PONG, fin:true, rsv1:false, rsv2:false, rsv3:false, payload length:[pos:0, len:0], payload:}
2021-12-07 13:16:25.218 [TRACE] afterEnconding(0):
2021-12-07 13:16:25.218 [TRACE] write(6): ���bG�
2021-12-07 13:16:25.218 [TRACE] process(6): (���bG�)
2021-12-07 13:16:25.218 [TRACE] afterDecoding(0):
2021-12-07 13:16:25.218 [TRACE] matched frame: Framedata{ opcode:PONG, fin:true, rsv1:false, rsv2:false, rsv3:false, payload length:[pos:0, len:0], payload:}
2021-12-07 13:16:29.929 [TRACE] Closing connection due to no pong received: org.java_websocket.WebSocketImpl@63581375
2021-12-07 13:16:29.929 [TRACE] Connection lost timer stopped
2021-12-07 13:16:29.929 [INFO] Client.onClose - code = 1006, reason = The connection was closed because the other endpoint did not respond with a pong in time. For more information check: https://github.com/TooTallNate/Java-WebSocket/wiki/Lost-connection-detection, remote = false
2021-12-07 13:16:29.929 [INFO] Server.onClose - conn = org.java_websocket.WebSocketImpl@59698028, code = 1006, reason = , remote = true
Environment:
- Version used: Release 1.5.2
- Java versions tried: OpenJDK 8.0.242 and OpenJDK 11.0.6.10 (neither worked)
- Operating System and version: Windows 10 Enterprise 20H2
Additional context
In the Reproduce-Example I set the ConnectionLostTimeout to a lower value than the default 60 seconds so I don't have to wait every time I test it. I think this also works with the default, but then the Timer-Delay would have to be bigger.