Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

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

Closed
feujun opened this issue Dec 7, 2021 · 0 comments · Fixed by #1204
Closed

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

feujun opened this issue Dec 7, 2021 · 0 comments · Fixed by #1204
Assignees
Milestone

Comments

@feujun
Copy link

feujun commented Dec 7, 2021

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.

@marci4 marci4 added this to the Release 1.5.3 milestone Dec 12, 2021
marci4 added a commit to marci4/Java-WebSocket-Dev that referenced this issue Dec 12, 2021
@marci4 marci4 mentioned this issue Dec 12, 2021
8 tasks
@marci4 marci4 self-assigned this Dec 12, 2021
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

Successfully merging a pull request may close this issue.

2 participants