Skip to content

Messages sent are received "one behind" when using WSS. #270

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

Open
agilezebra opened this issue Jul 4, 2021 · 2 comments · May be fixed by #298
Open

Messages sent are received "one behind" when using WSS. #270

agilezebra opened this issue Jul 4, 2021 · 2 comments · May be fixed by #298

Comments

@agilezebra
Copy link

agilezebra commented Jul 4, 2021

ws4py==0.5.1
CherryPy==18.6.0
Python 3.9.5 / Mac OS 11.4 (M1)

Messages are received as expected when I use WS. If I switch to WSS, messages sent by the client/browser are not received by the server until after a subsequent message is sent by the client (which in turn is also delayed). Once the second message is sent, the first message is received.

I note issue #191 which appears to be similar.

Output from attached test client and server:

WS mode
Chrome console:

on open
sent: one
sent: two
sent: three
Message received:one back
Message received:two back
Message received:three back

Python output:

2021-07-04 19:46:11,986:INFO: Using select as epoll is not available
2021-07-04 19:46:11,986:INFO: [04/Jul/2021:19:46:11] ENGINE Listening for SIGTERM.
2021-07-04 19:46:11,986:INFO: [04/Jul/2021:19:46:11] ENGINE Listening for SIGHUP.
2021-07-04 19:46:11,986:INFO: [04/Jul/2021:19:46:11] ENGINE Listening for SIGUSR1.
2021-07-04 19:46:11,986:INFO: [04/Jul/2021:19:46:11] ENGINE Bus STARTING
2021-07-04 19:46:11,986:INFO: [04/Jul/2021:19:46:11] ENGINE Starting WebSocket processing
2021-07-04 19:46:11,986:INFO: [04/Jul/2021:19:46:11] ENGINE Started monitor thread 'Autoreloader'.
2021-07-04 19:46:12,089:INFO: [04/Jul/2021:19:46:12] ENGINE Serving on http://127.0.0.1:9000
2021-07-04 19:46:12,090:INFO: [04/Jul/2021:19:46:12] ENGINE Bus STARTED
2021-07-04 19:46:24,695:INFO: in /test
2021-07-04 19:46:24,696:INFO: 127.0.0.1 - - [04/Jul/2021:19:46:24] "GET /test HTTP/1.1" 101 - "" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/91.0.4472.114 Safari/537.36"
2021-07-04 19:46:24,696:INFO: Managing websocket [Local => 127.0.0.1:9000 | Remote => 127.0.0.1:61575]
2021-07-04 19:46:24,935:INFO: received_message:one
2021-07-04 19:46:24,936:INFO: received_message:two
2021-07-04 19:46:24,937:INFO: received_message:three

WSS mode
Chrome console:

on open
sent: one
sent: two
sent: three
Message received:one back
Message received:two back

Python output:

2021-07-04 19:49:39,967:INFO: Using select as epoll is not available
2021-07-04 19:49:39,967:INFO: [04/Jul/2021:19:49:39] ENGINE Listening for SIGTERM.
2021-07-04 19:49:39,967:INFO: [04/Jul/2021:19:49:39] ENGINE Listening for SIGHUP.
2021-07-04 19:49:39,967:INFO: [04/Jul/2021:19:49:39] ENGINE Listening for SIGUSR1.
2021-07-04 19:49:39,967:INFO: [04/Jul/2021:19:49:39] ENGINE Bus STARTING
2021-07-04 19:49:39,967:INFO: [04/Jul/2021:19:49:39] ENGINE Starting WebSocket processing
2021-07-04 19:49:39,967:INFO: [04/Jul/2021:19:49:39] ENGINE Started monitor thread 'Autoreloader'.
2021-07-04 19:49:40,073:INFO: [04/Jul/2021:19:49:40] ENGINE Serving on https://127.0.0.1:9000
2021-07-04 19:49:40,073:INFO: [04/Jul/2021:19:49:40] ENGINE Bus STARTED
2021-07-04 19:49:56,428:INFO: in /test
2021-07-04 19:49:56,429:INFO: 127.0.0.1 - - [04/Jul/2021:19:49:56] "GET /test HTTP/1.1" 101 - "" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/91.0.4472.114 Safari/537.36"
2021-07-04 19:49:56,430:INFO: Managing websocket [Local => 127.0.0.1:9000 | Remote => 127.0.0.1:62492]
2021-07-04 19:49:56,641:INFO: received_message:one
2021-07-04 19:49:56,642:INFO: received_message:two

test.html

<!DOCTYPE HTML>

<html>

<head>
    <script type="text/javascript">
        function webSocketTest() {
            if ("WebSocket" in window) {
                var socket = new WebSocket("wss://local.example.com:9000/test");
                //var socket = new WebSocket("ws://local.example.com:9000/test");

                function send(text) {
                    socket.send(text)
                    console.log(`sent: ${text}`)
                }

                socket.onopen = function () {
                    console.log("on open")
                    send("one");
                    send("two");
                    send("three");
                };

                socket.onmessage = function (event) {
                    var received = event.data;
                    console.log(`Message received: ${received}`);
                };
            }
            else {
                console.log("No WebSocket support");
            }
        }
    </script>
</head>

<body>
    <div>
        <input id="run" type="button" value="Upgrade" onclick="webSocketTest();" />
    </div>
</body>

</html>

test.py

#!/usr/bin/env python3

import sys
import logging

import cherrypy
from ws4py.server.cherrypyserver import WebSocketPlugin, WebSocketTool
from ws4py.websocket import WebSocket


class TestWebSocket(WebSocket):
    def received_message(self, message):
        message = message.data.decode('utf8')
        logging.info("received_message:%s", message)
        self.send(f"{message} back")


class Root:
    @cherrypy.expose
    def test(self):
        logging.info("in /test")


def main():
    logging.basicConfig(level=logging.DEBUG, format="%(asctime)s:%(levelname)s: %(message)s")

    config = {
        "global": {
            "server.ssl_module": "builtin",
            "server.ssl_certificate": "/etc/ssl/certs/STAR_example_com.chain.pem",
            "server.ssl_private_key": "/etc/ssl/private/STAR_example_com.key",
            "server.socket_port": 9000,
            "log.screen": False,
        },
        "/test": {
            "tools.websocket.on": True,
            "tools.websocket.handler_cls": TestWebSocket,
        }
    }

    WebSocketPlugin(cherrypy.engine).subscribe()
    cherrypy.tools.websocket = WebSocketTool()
    cherrypy.quickstart(Root(), "/", config=config)


if __name__ == "__main__":
    sys.exit(main())
@derpflanz
Copy link

derpflanz commented Feb 15, 2024

Same problem here. Any feedback on this?

The only workaround I have is to close the WebSocket right after sending.

@mpf82
Copy link

mpf82 commented Apr 17, 2025

The issue still exists with CherryPy 18.10.0 and ws4py 0.6.0

Here's a self-contained test script. You only need to provide your private.pem and public.pem in the same folder as the script.

import logging
import os
import time
from threading import Thread

import cherrypy
import ws4py
from ws4py.client.threadedclient import WebSocketClient
from ws4py.server.cherrypyserver import WebSocketPlugin, WebSocketTool
from ws4py.websocket import WebSocket

logging.basicConfig( level=logging.DEBUG, format="%(asctime)s:%(levelname)s: %(message)s" )
logger = logging.getLogger()

logger.info( f"ws4py version: {ws4py.__version__}" )
logger.info( f"cherrypy version: {cherrypy.__version__}" )

root    = os.path.dirname( os.path.abspath( __file__ ) )
USE_SSL = True
HOST    = "127.0.0.1"
PORT    = 9876
URL     = f"wss://{HOST}:{PORT}/ws" if USE_SSL else f"ws://{HOST}:{PORT}/ws"


class EchoClient( WebSocketClient ):
    def opened( self ):
        self.send( "Let's count!" )
        self.send( 1 )

    def send( self, payload, binary=False ):
        logger.info( f"EchoClient send: {payload}" )
        return super().send( str( payload ), binary )

    def closed( self, code, reason=None ):
        logger.info( ( "Closed down", code, reason ) )

    def received_message( self, m ):
        logger.info( f"EchoClient received_message: {m}" )
        try:
            number = int( str( m ).strip() )
            if number < 10:
                # increase number and send it back
                self.send( number + 1 )
            else:
                self.close( 1000, "Done" )
        except ( TypeError, ValueError ):
            return


class BroadcastWebSocketHandler( WebSocket ):
    def opened( self ):
        logger.info( "WebSocket opened" )
        self.send( "Hello from BroadcastWebSocketHandler" )
        cherrypy.engine.publish( 'websocket-broadcast', "New client connected" )

    def received_message( self, message ):
        logger.info( f"BroadcastWebSocketHandler received_message: {message}" )
        cherrypy.engine.publish( 'websocket-broadcast', str( message ) )


class Root:
    @cherrypy.expose
    def ws( self ):
        pass


def wait_for_cherrypy_engine_started():
    while ( cherrypy.engine.state != cherrypy.engine.states.STARTED ):
        logger.info( "waiting for CherryPy engine to be STARTED" )
        time.sleep( 0.5 )
    logger.info( "CherryPy engine started" )


def run_echo_client():
    wait_for_cherrypy_engine_started()
    try:
        ws = EchoClient( URL )
        ws.connect()
        ws.run_forever()
    except KeyboardInterrupt:
        ws.close()
        logger.info( "KeyboardInterrupt: closing WebSocket client" )
    except Exception:
        logger.exception( "Error in WebSocket client" )


def run_cherrypy_server():
    config = {
        "global" : {
            "server.ssl_module"      : "builtin" if USE_SSL else None,
            "server.ssl_certificate" : os.path.join( root, "public.pem" ) if USE_SSL else None,
            "server.ssl_private_key" : os.path.join( root, "private.pem" ) if USE_SSL else None,
            "server.socket_port"     : PORT,
            "server.socket_host"     : HOST,
            "log.screen"             : False,
            'engine.autoreload.on'   : False,
        },
        "/ws" : {
            "tools.websocket.on"          : True,
            "tools.websocket.handler_cls" : BroadcastWebSocketHandler,
            'tools.websocket.protocols'   : [ 'some-protocol' ],
            'tools.gzip.on'               : False,
            'tools.caching.on'            : False,
            'tools.sessions.on'           : False,
        },
    }

    WebSocketPlugin( cherrypy.engine ).subscribe()
    cherrypy.tools.websocket = WebSocketTool()
    cherrypy.quickstart( Root(), "/", config=config )


def main():
    t = Thread( target=run_echo_client, daemon=True, name="WebSocketClient" )
    t.start()
    run_cherrypy_server()


if __name__ == "__main__":
    main()

Output for USE_SSL = False:

INFO: ws4py version: 0.6.0
INFO: cherrypy version: 18.10.0
INFO: waiting for CherryPy engine to be STARTED
INFO: Using select as epoll is not available
INFO: [17/Apr/2025:14:01:20] ENGINE Listening for SIGTERM.
INFO: [17/Apr/2025:14:01:20] ENGINE Bus STARTING
INFO: [17/Apr/2025:14:01:20] ENGINE Set handler for console events.
INFO: [17/Apr/2025:14:01:20] ENGINE Starting WebSocket processing
INFO: [17/Apr/2025:14:01:20] ENGINE Serving on http://127.0.0.1:9876
INFO: [17/Apr/2025:14:01:20] ENGINE Bus STARTED
INFO: CherryPy engine started
INFO: 127.0.0.1 - - [17/Apr/2025:14:01:20] "GET /ws HTTP/1.1" 101 - "" ""
INFO: Managing websocket [Local => 127.0.0.1:9876 | Remote => 127.0.0.1:52231]
INFO: WebSocket opened
INFO: EchoClient send: Let's count!
INFO: EchoClient send: 1
INFO: EchoClient received_message: Hello from BroadcastWebSocketHandler
INFO: BroadcastWebSocketHandler received_message: Let's count!
INFO: EchoClient received_message: Let's count!
INFO: BroadcastWebSocketHandler received_message: 1
INFO: EchoClient received_message: 1
INFO: EchoClient send: 2
INFO: BroadcastWebSocketHandler received_message: 2
INFO: EchoClient received_message: 2
INFO: EchoClient send: 3
INFO: BroadcastWebSocketHandler received_message: 3
INFO: EchoClient received_message: 3
INFO: EchoClient send: 4
INFO: BroadcastWebSocketHandler received_message: 4
INFO: EchoClient received_message: 4
INFO: EchoClient send: 5
INFO: BroadcastWebSocketHandler received_message: 5
INFO: EchoClient received_message: 5
DEBUG: Closing message received (1000): Done
DEBUG: Closing message received (1000): Done
INFO: Terminating websocket [Local => 127.0.0.1:9876 | Remote => 127.0.0.1:52231]
INFO: ('Closed down', 1000, b'Done')

Output for USE_SSL = True:

INFO: ws4py version: 0.6.0
INFO: cherrypy version: 18.10.0
INFO: waiting for CherryPy engine to be STARTED
INFO: Using select as epoll is not available
INFO: [17/Apr/2025:14:02:51] ENGINE Listening for SIGTERM.
INFO: [17/Apr/2025:14:02:51] ENGINE Bus STARTING
INFO: [17/Apr/2025:14:02:51] ENGINE Set handler for console events.
INFO: [17/Apr/2025:14:02:51] ENGINE Starting WebSocket processing
INFO: [17/Apr/2025:14:02:52] ENGINE Serving on https://127.0.0.1:9876
INFO: [17/Apr/2025:14:02:52] ENGINE Client ('127.0.0.1', 52247) lost — peer dropped the TLS connection suddenly, during handshake: (8, 'EOF occurred in violation of protocol (_ssl.c:992)')
INFO: [17/Apr/2025:14:02:52] ENGINE Bus STARTED
INFO: CherryPy engine started
INFO: 127.0.0.1 - - [17/Apr/2025:14:02:52] "GET /ws HTTP/1.1" 101 - "" ""
INFO: Managing websocket [Local => 127.0.0.1:9876 | Remote => 127.0.0.1:52248]
INFO: WebSocket opened
INFO: EchoClient send: Let's count!
INFO: EchoClient send: 1
INFO: EchoClient received_message: Hello from BroadcastWebSocketHandler
INFO: BroadcastWebSocketHandler received_message: Let's count!
INFO: EchoClient received_message: Let's count!

... and that's it. Since the server does not receive 1, no forth-and-back communication is done.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging a pull request may close this issue.

3 participants