Ws: websocket server unable to handle requests immediately after server startup.

[Yrish]

• [x] I've searched for any related issues and avoided creating a duplicate issue.

• [x] I've checked to make sure this is the module with the issue.

Description

Server completes handshake with client websocket before being able to handle messages from client immediately after server startup.

Reproducible in:

version: 5.2.0

Node.js version(s):8.9.4

OS version(s): OSX 10.12.6 (MacOS High Sierra)

Steps to reproduce:

1. mount express-ws on server
2. have client continually try to connect to websocket server while server is starting.

Expected result:

Messages sent by client after handshake are handled by the server immediately after server startup.

Actual result:

Messages sent by client after handshake are never handled by the server (websocket is opened appropriately). The function connectionHandler defined in the app.ws(path, connectionHandler) is never called with the messages.

If client delays the sending of these messages by a small amount of time (around 50 milliseconds on my computer) the server handles the messages appropriately.

Attachments:

---

Server

server sample code

//import ws
const enableWs = require('express-ws')

//lots of extraneous code

//attach ws to server
enableWs(app, server)
app.ws('/ws', webSocketConnectionHandler) //see below

//more extraneous code

//tell the server to listen on port
server.listen(port, ()=> {
  console.log(`server listening on port ${port}`)
});

webSocketConnectionHandler

function wsConnectionHandler(ws, req) {

  //prevent websocket closing from crashing the server
  ws.on('close', () => {})

  //prevent websocket error from crashing the server
  ws.on('error', (error) => {})

  ws.on('message', message => {
    console.log(message) //verifying the message was received
    webSocketMessageHandler(message, getDefaultMessageHandlers(ws, req), ws) //handle message
  })
}

---

Client (not working, but should) - Java

//simplified a lot
class webSocket extends WebSocketClient {

  public webSocket(String url) {
    super(new URI(url), new Draft_6455(), getHeaders(), 0);
  }

  private boolean alreadyConnecting = false;

  //runs once websocket successfully opens (handshake successful)
  public void onOpen(ServerHandshake serverHandshake) {
    this.send("Hello World"); //this message is not handled by the server but should

    Timer timer = new Timer(true);
    timer.schedule(new TimerTask() { // delays sending of message over websocket for 50 milliseconds
        @Override
        public void run() {
            this.send("Hola Teirra"); //this message is handled by the server
            timer.cancel();
        }
    }, 50);
  }

  //once websocket closes or fails to initially connect, keep trying to reconnect until successful
  public void onClose() {
    if (alreadyConnecting) {
      return;
    }

    this.alreadyConnecting = true;

    Timer timer = new Timer(true);
    timer.scheduleAtFixedRate(new TimerTask() { //try to reconnect every second

      @Override
      public void run() {
          try {
              if (this.reconnectBlocking()) {
                  this.alreadyConnecting = false;
                  timer.cancel();
              }
          } catch (InterruptedException e) {
              e.printStackTrace();
          }
        }
    }, 0, 1000);

  }
}

What happens:

The "Hello world" message is sent by the client after handshake completes and websocket successfully opens, however the "Hello world" message is never handled by the server. The "Hola Teirra" message is sent 50 milliseconds after the websocket successfully opens and the message is successfully handled by the server. I have verified that the client successfully sends both messages.

[lpinca]

Can you create a reproducible example that doesn't use express-ws but only ws?

I can't reproduce with the following code which sends data immediately after the client completes the handshake.

const assert = require('assert');
const net = require('net');
const WebSocket = require('ws');

const wss = new WebSocket.Server({ port: 3000 });

wss.on('connection', function (ws) {
  ws.on('message', console.log);
});

wss.on('listening', function () {
  const socket = net.connect(3000, () => {
    let handshake = false;

    socket.write([
      'GET / HTTP/1.1',
      'Upgrade: websocket',
      'Connection: Upgrade',
      'Sec-WebSocket-Key: rfeGe1izPRq2JyonWunAQw==',
      'Sec-WebSocket-Version: 13',
      '',
      ''
    ].join('\r\n'));

    socket.on('data', (data) => {
      if (!handshake) {
        assert.ok(data.equals(Buffer.from([
          'HTTP/1.1 101 Switching Protocols',
          'Upgrade: websocket',
          'Connection: Upgrade',
          'Sec-WebSocket-Accept: prdBmM6el7NzNgJBcdmWum5mTZc=',
          '',
          ''
        ].join('\r\n'))));

        handshake = true;

        //
        // Send a text frame.
        //
        socket.write(Buffer.from('81850000000068656c6c6f', 'hex'));
        return;
      }
    });
  });
});

[dannyharding10]

Hi @lpinca, I'm working with @Yrish on this. Just to confirm, the problem we found is when the server goes down, our client continually tries to reconnect (every 1000 ms in our case). When the server comes back online, the client connects successfully, and immediately sends a message to the server. This message from the client is never seen in the callback in ws.on('message', callback). It seems that the code above would not be attempting to connect a socket immediately after the server is started.

We believe this is some sort of race condition that happens only when the server is starting up. I will try to reproduce without express-ws and respond here, but let me know if you have any other ideas on this!

[lpinca]

It seems that the code above would not be attempting to connect a socket immediately after the server is started.

It actually does that, when the 'listening' event is emitted it means that the server is ready to accept connections, and from the handler of that event a new TCP connection is created.

[dannyharding10]

Got it! Ok I am currently working on reproducing it, I'll try to have that before it's too late where you are 👍

[lpinca]

Maybe the socket, for some reason, is destroyed before the data reaches the server, in this case the client may have tried to send the data but you'll never get it on the server.

[lpinca]

Any update here? Try to use wireshark and see if the ACK for that missing message is received on the client.

[lpinca]

Closing due to inactivity.

[dannyharding10]

hi @lpinca, sorry about the delay! I was unable to duplicate this issue using less code (a very simple server using express-ws and a java client).

I was however able to use wireshark to track down the missing messages, and they are successfully getting through to the server. The server also responds with an ACK for each message sent. The problem I noticed is that it seems the messages from the client are being sent before the message handler is added to the websocket in the server. We send a new connection message from server -> client immediately upon any new connection, before attaching the message handler. In wireshark I see messages from client -> server before I see this new connection message from server -> client.

This makes me think that the error may be with the express-ws library, but I thought I'd share my findings as you have more experience with websockets and may have some insights. Let me know if you have any ideas on this, and I will comment here with anything else I find.

[lpinca]

The problem I noticed is that it seems the messages from the client are being sent before the message handler is added to the websocket in the server.

Does this mean something like this?

wss.on('connection', function (ws) {
  process.nextTick(function () {
    ws.on('message', function () {});
  });
});

If so then yes, you may miss messages if you don't add a listener for the 'message' event immediately after (on the same tick) receiving the 'connection' event.

[dannyharding10]

Our code looks like this, but in wireshark I see the messages from client->server before I see 'Some Message'. This makes me think that the handshake is completed before this connectionHandler function is run.

function wsConnectionHandler(ws, req) {
  ws.send('Some Message')

  //prevent websocket closing from crashing the server
  ws.on('close', () => {})

  //prevent websocket error from crashing the server
  ws.on('error', (error) => {})

  ws.on('message', message => {
    console.log('received message', message)
  })
}

[lpinca]

There might a valid frame(s) sent as the body of the handshake request. That data is received along with request so before the handshake completes and ws does not discard it. The spec says that no data should be exchanged before the handshake but there are a lot of non compliant clients.

[dannyharding10]

I don't follow.. Are you saying that some clients will send data in the initial request? I don't think that our client websocket library is doing that, though it may be possible. I'm going to look more into express-ws to see if the error could be there. I may also look into the express-session-parse example to potentially remove the dependency on express-ws

[lpinca]

Are you saying that some clients will send data in the initial request?

Yes, even the Autobahn|Testsuite does that. You can check if this happens by monkey patching this line. If you enter in the if body then some data was sent along with the upgrade request.

[Workruft]

I have a highly related question to this one, so I'll ask it here. In your examples for WS, I see this kind of code:

const WebSocket = require('ws');

const ws = new WebSocket('ws://www.host.com/path');

ws.on('open', function open() {
  ws.send('something');
});

ws.on('message', function incoming(data) {
  console.log(data);
});

However, this really bothers me, even if it's sort of trivial: Couldn't a connection technically be established before any of the event handler functions are registered?

I'm not really sure how the async nature of Node/JS works here, but it does seem that you can immediately chain .on() calls after creating the new WebSocket. Why aren't the code examples doing this, and why not just have a .startListening() call instead?

[8balloon]

@Workruft the way the nodejs event loop works ensures that this won't happen unless you do something asynchronous before making your ws.on(... calls.

So as long as you aren't making those calls in a callback or after an await statement, you will be fine :)

The connection is established asynchronously, which means it won't be established until all synchronous code that's already been queued up is completed. The ws.on calls are synchronous, so your example is fine, although I can completely understand why you might be confused.

[Workruft]

So basically, .on() calls are only setting up state, nothing actually initiates until the script ends. Makes sense, gotcha, thanks for the explanation.