Skip to content

Lost connection detection not working on delayed connect-Call #1203

@feujun

Description

@feujun

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:

  1. Use this simplelogger-properties-File
  2. Create a simple WebSocketServer like below
  3. Create a simple WebSocketClient like below
  4. Create a main-method like below
  5. 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.

Metadata

Metadata

Assignees

Labels

Projects

No projects

Milestone

Relationships

None yet

Development

No branches or pull requests

Issue actions