ws4py - send/received_message not working

Question

I'm encountering issues on making a WebSocket Server/Client.

This is my WebSocket Clas:

wslist = []

class LoginLiveWebSocketHandler(WebSocket):  # /live/ws/zones
    loggedon = False

    def opened(self):
        log("Opened!")
        wslist.append(self)

    def received_message(self, m):
        log("Received Message!")
        log(m)
        log(m.data)
        m = str(m.data)
        if not m.startswith("Login: ") & (not self.loggedon):
            return
        if m.startswith("Login: ") & self.loggedon:
            return
        if m.startswith("Login: ") & (not self.loggedon):
            split = m.replace("Login: ", "").split(":")
            try:
                id = split[0]
                key = split[1]
            except KeyError:
                self.send("Login: 0", False)
                return
            try:
                usr = users.getuser(id, key)
                nick = usr["nick"]
                loggedin = True
                token = usr["groupme_token"]
                active = usr["active"]
            except KeyError or TypeError:
                self.send("Login: 0", False)
                return
            if (not loggedin) | (not active) | (not local.token) | (local.user["faction"] != "f"):
                self.send("Login: 0", False)
                return
            self.send("Login: 1", False)
            self.loggedon = True
            return

    def closed(self, code, reason=""):
        log("Closed!")
        wslist.remove(self)

And my JavaScript page (note, not the whole):

function init() {
            showBlocking("Connecting...", "progress-bar-success");
            var wsprotocol = (location.protocol == "https:") ? "wss://" : "ws://";
            var loc = location.pathname;
            loc = loc.replace(/live\u002flive$/i, "");
            var wsurl = wsprotocol + location.host + loc + "/live/ws_zones";
            console.log(wsurl);
            var ws = new WebSocket(wsurl);

            var key = getCookie("key");
            var id = getCookie("id");

            var closed = true;

            ws.onopen = function(evt) {
                console.log("onopen");
                $('#pbheader').text("Logging in...");
                ws.send("Login: " + id + ":" + key);
                closed = false;
            }

            ws.onmessage = function(evt) {
                console.log("OnMessage");
                var channel = evt.data.substring(0, 7);
                var data = evt.data.substr(6);
                if (channel == "Login: ") {
                    if (data == "0") {
                        ws.close();
                        closed = true;
                        alert("Invalid Login, please re-login.");
                        $('#pbheader').text("Invalid Login!");
                        history.back();
                    } else if (data == "1") {
                        hideBlocking();
                    }
                } else if (channel == "ZoneA: ") {
                    // add new thing...
                    // %gridref% %zoneid% %zonename% %faction% %legion% %faceless% %swarm%
                    var datadict = JSON.parse(data);
                    var replitem = itemtemplate.replace("%count%", count).replace("%gridref%", datadict.gridref).replace("%zoneid%", datadict.zoneid).replace("%zonename%", datadict.zonename).replace("%faction%", datadict.faction).replace("%legion%", datadict.legion).replace("%faceless%", datadict.faceless).replace("%swarm%", datadict.swarm);
                    $('#live').prepend(replitem);
                    var curritem = $('#item' + count);
                    setTimeout(function () { fadeoutremove(curritem); }, 60*1000);
                    count = count + 1;
                }
            }

            ws.onclose = function(evt) {
                console.log("Closed");
                closed = true;
            }

            ws.onerror = function(evt) {
                console.log("error");
                closed = true;
            }
        }

        window.addEventListener("load", init, false);

Mounting Service:

log("Starting WebServer (cherrypy)")
cherrypy.server.unsubscribe()
if config.DO_SSL is True:
    server1 = cherrypy._cpserver.Server()
    server1.socket_port = config.LISTEN_PORT_SSL
    server1._socket_host = config.LISTEN
    server1.thread_pool = 30
    server1.ssl_certificate = config.SSL_CERTIFICATE
    server1.ssl_private_key = config.SSL_PRIVATE_KEY
    server1.ssl_certificate_chain = config.SSL_CHAIN
    server1.ssl_module = config.SSL_HANDLER
    server1.subscribe()
server2 = cherrypy._cpserver.Server()
server2.socket_port = config.LISTEN_PORT
server2._socket_host = config.LISTEN
server2.thread_pool = 30
server2.subscribe()

WebSocketPlugin(cherrypy.engine).subscribe()
cherrypy.tools.websocket = WebSocketTool()

cherrypy.tree.mount(APIService.APIService(), "/api", config={"/": {'error_page.404': APIService.ep}})
cherrypy.tree.mount(JSONService.JSONService(), "/json", config={"/": {'error_page.404': JSONService.ep}})
cherrypy.tree.mount(USRAPIService.USRAPIService(), "/usrapi", config={"/": {'error_page.404': USRAPIService.ep}})
cherrypy.tree.mount(USRAPIAdminService.USRAPIAdminService(), "/usrapi/admin", config={
    "/": {'error_page.404': USRAPIService.ep}})
cherrypy.tree.mount(RootService.RootService(), "/", config={"/": {'error_page.404': RootService.ep}})
cherrypy.tree.mount(AdminService.AdminService(), "/admin", config={"/": {'error_page.404': AdminService.ep}})
cherrypy.tree.mount(HelperPanel.HelperPanel(), "/helper", config={"/": {'error_page.404': HelperPanel.ep}})
cherrypy.tree.mount(LiveService.LiveService(), "/live", config={"/": {'error_page.404': LiveService.ep},
                                                                "/ws_zones": {'tools.websocket.on': True,
                                                                              'tools.websocket.handler_cls':
                                                                                  LiveService.LoginLiveWebSocketHandler
                                                                              }})
cherrypy.tree.mount(None, "/static", config={"/": {'error_page.404': AdminService.ep,
                                                   'tools.staticdir.on': True,
                                                   'tools.staticdir.dir':
                                                       os.path.join(__current_dir, "web/static")}})
cherrypy.engine.start()
log("Started WebServer (cherrypy)")

LiveService:

class LiveService(object):

    @cherrypy.expose
    @require(level=0)
    def index(self, user, usrname, usrhelper, usradmin):
        return render("index", usrname, usrhelper, usradmin)

    @cherrypy.expose
    @require(level=4)  # Require login, Groupme, active and faceless
    def live(self, user, usrname, usrhelper, usradmin):
        return render("websocket/zonesdata", usrname, usrhelper, usradmin)

    @cherrypy.expose
    def ws_zones(self):
        log("Handler created: %s" % repr(cherrypy.request.ws_handler))
        cherrypy.request.ws_handler.send(b"Login 0", False)

So, the mounting and starting works, the whole run in production for months now, but the new LiveService with ws is not working. In log, im getting [21/Jul/2015:16:55:28] ENGINE Starting WebSocket processing and Opened Messages, but I never receive or able to send Messages. When I change LiveService.LoginLiveServiceWebSocketHandler to EchoWebSocket he gets Messages and sends them, but on ws_zones handler

cherrypy.request.ws_handler.send(b"Login 0", False)

is not working. wether with the b or not.

Answer 1

Was a bit stupid...

@saaj was right, but the real Problem was that I tried to call function log (which requires str) with m, m.data etc. Doing this with either repr() or removing it, it worked!

Thanks!

Answer 2

Analysis

First thing to say is that you should pay attention to debugging tools that are at you disposal. For instance, when you try you app in Firefox, Firebug (or Web Console) tells you:

Firefox can't establish a connection to the server at ws://127.0.0.1:8080/live/ws_zones.

Chromium console has more useful error message:

WebSocket connection to 'ws://127.0.0.1:8080/live/ws_zones' failed: Error during WebSocket handshake: Invalid status line

Ok, we have a handshake problem.

If you open Wireshark (or another sniffer) you can see that indeed our Login 0 appears before ws4py replies with a handshake response (or maybe there is a race condition).

I can understand your confusion, because in several places ws4py documentation either alludes or directly guides you the wrong way. Let's see:

alludes — you can not send from normal handler.

@cherrypy.expose
def ws(self):
    # you can access the class instance through
    handler = cherrypy.request.ws_handler

guides incorrectly — you can not send from opened hook.

def opened(self):
    """
    Called by the server when the upgrade handshake
    has succeeeded.
    """
    pass

So I think it's either an outdated documentation or a bug.

Solution

For now I suggest you to initiate your communication on client side. If you have some pre-login "chat", you can make a little protocol on top of web sockets (you will end up doing it anyway). Something like this:

#!/usr/bin/env python3


import json

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


class LoginLiveWebSocketHandler(WebSocket):

  wsset = set()
  '''Class level attr, do not rebind'''


  def opened(self):
    '''You can not send yet, because handshake has not been completed.
    Yes, a documentation is not always correct ;-)
    '''

    cherrypy.log('Opened!')
    self.wsset.add(self)

  def closed(self, code, reason = ''):
    cherrypy.log('Closed!')
    self.wsset.remove(self)

  def received_message(self, message):
    cherrypy.log('Received Message!')

    message = json.loads(message.data.decode())
    if message['cmd'] == 'init':
      self.send('Login 0')
    else:
      self.send(message['payload'] + ' pong')


class LiveService(object):

  @cherrypy.expose
  def index(self):
    return '''<!DOCTYPE html>
      <html>
      <body>
        <div id='log'></div>
        <script type='application/javascript'>
          var ws = new WebSocket('ws://127.0.0.1:8080/live/ws_zones');

          ws.onopen = function(event)
          {
            ws.send(JSON.stringify({'cmd': 'init'}));
          };
          ws.onmessage = function(event)
          {
            document.getElementById('log').innerHTML += event.data + '<br/>';
          };

          var handle = setInterval(function()
          {
            if(ws.readyState == WebSocket.CLOSING || ws.readyState == WebSocket.CLOSED)
            {
              clearInterval(handle);
            }
            else
            {
              ws.send(JSON.stringify({'cmd': 'chat', 'payload': 'ping'}));
            }
          }, 1000);
          </script>
      </body>
      </html>
    '''

  @cherrypy.expose
  def ws_zones(self):
    '''You can not send yet, because handshake has not been completed'''
    cherrypy.log('Handler created: %r' % cherrypy.request.ws_handler)



if __name__ == '__main__':
  cherrypy.config.update({
    'server.socket_host' : '127.0.0.1',
    'server.socket_port' : 8080,
    'server.thread_pool' : 8
  })

  cherrypy.tools.websocket = WebSocketTool()
  WebSocketPlugin(cherrypy.engine).subscribe()

  cherrypy.tree.mount(LiveService(), '/live', {
    '/ws_zones' : {
      'tools.websocket.on'          : True,
      'tools.websocket.handler_cls' : LoginLiveWebSocketHandler
    }
  })

  cherrypy.engine.signals.subscribe()
  cherrypy.engine.start()
  cherrypy.engine.block()