Specifics of Faye WebSocket Communication

[Phrogz]

Summary: I'm trying to understand when (and why) Faye sends certain WebSocket messages, because my custom client is disconnecting and failing to reconnect. 

Details:

As discussed in another thread, I wrote my own QML-based Bayeux client, using WebSockets for communication. It works fine initially, but after receiving about 90 messages (over about 40 seconds) the WebSocket closes on its own, and when I attempt to reconnect (without a handshake) it fails. I've included a copy of the transcript of XHR and WebSocket communication below.

Looking at the WebSocket communication for the Faye JS client (screenshot @ http://phrogz.net/tmp/FayeWebSocket.png) I see three things that surprise me. I'm wondering why they occur, and if I have to mimic them (and if so, what the timing logic is):

1) When the WebSocket first connects, and after receiving 23 messages, the client always sends an empty set of messages, "[]" (and receives an empty response). This is shown with orange arrows in my screenshot.

1a) Is this heartbeat necessary to show the server that the client is still alive?

1b) Is this covered in the Bayeux protocol?

1c) If this is necessary, am I correct that the logic is that a client should always send "[]" after receiving 23 messages?

2) 25 seconds after receiving a message on meta/connect, the server responds with a successful:true message on meta/connect. This is shown with burgundy and blue arrows in my screenshot.

2a) Why does it take so long for the server to acknowledge the connection?

3) Immediately after receiving the meta/connect, the client always responds with a new message on meta/connect. This is shown with blue arrows in my screenshot.

3a) Is this a direct response to the message received, or is this timing because in the initial handshake the server's advice included a 25 second timeout?

3b) If this is not a direct response to the message received, is the logic that the client should always send on meta/connect every <timeout> seconds?

3c) Is this covered in the Bayeux protocol specs?

My continuing thanks for Faye, and advance thanks if you can help with the above questions.

Following is the transcript of communication between MY client (in development) and Faye server, in case it is at all helpful. I've replaced the real client id with "MYID" for simplicity and removed the contents of large data packets unrelated to this question.

http send: [{"channel":"/meta/handshake","supportedConnectionTypes":["websocket","long-polling"],"version":"1.0"}]

http recv: [{"channel":"/meta/handshake","successful":true,"version":"1.0","supportedConnectionTypes":["long-polling","cross-origin-long-polling","callback-polling","websocket","eventsource","in-process"],"clientId":"MYID","advice":{"reconnect":"retry","interval":0,"timeout":25000}}]

WebSocket status: WebSocket.Connecting

WebSocket status: WebSocket.Open

sock send: {"channel":"/meta/connect","connectionType":"websocket","clientId":"MYID"}

sock send: {"channel":"/meta/subscribe","subscription":"/status","clientId":"MYID"}

sock send: {"channel":"/meta/subscribe","subscription":"/next","clientId":"MYID"}

sock send: {"channel":"/meta/subscribe","subscription":"/songdetails","clientId":"MYID"}

sock send: {"channel":"/meta/subscribe","subscription":"/startup-phrogz","clientId":"MYID"}

sock send: {"channel":"/meta/subscribe","subscription":"/user-phrogz","clientId":"MYID"}

sock recv: [{"clientId":"MYID","channel":"/meta/subscribe","successful":true,"subscription":"/status"}]

sock recv: [{"clientId":"MYID","channel":"/meta/subscribe","successful":true,"subscription":"/next"}]

sock recv: [{"clientId":"MYID","channel":"/meta/subscribe","successful":true,"subscription":"/songdetails"}]

sock recv: [{"clientId":"MYID","channel":"/meta/subscribe","successful":true,"subscription":"/startup-phrogz"}]

sock recv: [{"clientId":"MYID","channel":"/meta/subscribe","successful":true,"subscription":"/user-phrogz"}]

sock recv: [{"channel":"/startup-phrogz","data":{...},"id":"cbu"}]

sock recv: [{"channel":"/status","data":{...},"id":"cbv"}]

sock recv: [{"channel":"/status","data":{...},"id":"cbw"}]

sock recv: [{"channel":"/status","data":{...},"id":"cbx"}]

sock recv: [{"channel":"/status","data":{...},"id":"cby"}]

sock recv: [{"channel":"/status","data":{...},"id":"cbz"}]

sock recv: [{"channel":"/status","data":{...},"id":"cc0"}]

sock recv: [{"channel":"/status","data":{...},"id":"cc1"}]

sock recv: [{"channel":"/status","data":{...},"id":"cc2"}]

sock recv: [{"channel":"/status","data":{...},"id":"cc3"}]

sock recv: [{"channel":"/status","data":{...},"id":"cc4"}]

sock recv: [{"channel":"/status","data":{...},"id":"cc5"}]

sock recv: [{"channel":"/status","data":{...},"id":"cc6"}]

sock recv: [{"channel":"/status","data":{...},"id":"cc7"}]

sock recv: [{"channel":"/status","data":{...},"id":"cc8"}]

sock recv: [{"channel":"/status","data":{...},"id":"cc9"}]

sock recv: [{"channel":"/status","data":{...},"id":"cca"}]

sock recv: [{"channel":"/status","data":{...},"id":"ccb"}]

sock recv: [{"channel":"/status","data":{...},"id":"ccc"}]

sock recv: [{"channel":"/status","data":{...},"id":"ccd"}]

sock recv: [{"channel":"/status","data":{...},"id":"cce"}]

sock recv: [{"channel":"/status","data":{...},"id":"ccf"}]

sock recv: [{"channel":"/status","data":{...},"id":"cch"}]

sock recv: [{"channel":"/status","data":{...},"id":"cci"}]

sock recv: [{"channel":"/status","data":{...},"id":"ccj"}]

sock recv: [{"channel":"/status","data":{...},"id":"cck"}]

sock recv: [{"channel":"/status","data":{...},"id":"ccl"}]

sock recv: [{"channel":"/status","data":{...},"id":"ccm"}]

sock recv: [{"channel":"/status","data":{...},"id":"ccn"}]

sock recv: [{"channel":"/status","data":{...},"id":"cco"}]

sock recv: [{"channel":"/status","data":{...},"id":"ccp"}]

sock recv: [{"channel":"/status","data":{...},"id":"ccq"}]

sock recv: [{"channel":"/status","data":{...},"id":"ccr"}]

sock recv: [{"channel":"/status","data":{...},"id":"ccs"}]

sock recv: [{"channel":"/status","data":{...},"id":"cct"}]

sock recv: [{"channel":"/status","data":{...},"id":"ccu"}]

sock recv: [{"channel":"/status","data":{...},"id":"ccv"}]

sock recv: [{"channel":"/status","data":{...},"id":"ccw"}]

sock recv: [{"channel":"/status","data":{...},"id":"ccx"}]

sock recv: [{"channel":"/status","data":{...},"id":"ccy"}]

sock recv: [{"channel":"/status","data":{...},"id":"ccz"}]

sock recv: [{"channel":"/status","data":{...},"id":"cd0"}]

sock recv: [{"channel":"/status","data":{...},"id":"cd1"}]

sock recv: [{"channel":"/status","data":{...},"id":"cd2"}]

sock recv: [{"clientId":"MYID","channel":"/meta/connect","successful":true,"advice":{"reconnect":"retry","interval":0,"timeout":25000}}]

sock recv: [{"channel":"/status","data":{...},"id":"cd3"}]

sock recv: [{"channel":"/status","data":{...},"id":"cd4"}]

sock recv: [{"channel":"/status","data":{...},"id":"cd5"}]

sock recv: [{"channel":"/status","data":{...},"id":"cd6"}]

sock recv: [{"channel":"/status","data":{...},"id":"cd7"}]

sock recv: [{"channel":"/status","data":{...},"id":"cd8"}]

sock recv: [{"channel":"/status","data":{...},"id":"cd9"}]

sock recv: [{"channel":"/status","data":{...},"id":"cda"}]

sock recv: [{"channel":"/status","data":{...},"id":"cdb"}]

sock recv: [{"channel":"/status","data":{...},"id":"cdc"}]

sock recv: [{"channel":"/status","data":{...},"id":"cdd"}]

sock recv: [{"channel":"/status","data":{...},"id":"cde"}]

sock recv: [{"channel":"/status","data":{...},"id":"cdf"}]

sock recv: [{"channel":"/status","data":{...},"id":"cdg"}]

sock recv: [{"channel":"/status","data":{...},"id":"cdh"}]

sock recv: [{"channel":"/status","data":{...},"id":"cdi"}]

sock recv: [{"channel":"/status","data":{...},"id":"cdj"}]

sock recv: [{"channel":"/status","data":{...},"id":"cdk"}]

sock recv: [{"channel":"/status","data":{...},"id":"cdl"}]

sock recv: [{"channel":"/status","data":{...},"id":"cdm"}]

sock recv: [{"channel":"/status","data":{...},"id":"cdn"}]

sock recv: [{"channel":"/status","data":{...},"id":"cdp"}]

sock recv: [{"channel":"/status","data":{...},"id":"cdq"}]

sock recv: [{"channel":"/status","data":{...},"id":"cdr"}]

sock recv: [{"channel":"/status","data":{...},"id":"cds"}]

sock recv: [{"channel":"/status","data":{...},"id":"cdt"}]

sock recv: [{"channel":"/status","data":{...},"id":"cdu"}]

sock recv: [{"channel":"/status","data":{...},"id":"cdv"}]

sock recv: [{"channel":"/status","data":{...},"id":"cdw"}]

sock recv: [{"channel":"/status","data":{...},"id":"cdx"}]

sock recv: [{"channel":"/status","data":{...},"id":"cdy"}]

sock recv: [{"channel":"/status","data":{...},"id":"cdz"}]

sock recv: [{"channel":"/status","data":{...},"id":"ce0"}]

sock recv: [{"channel":"/status","data":{...},"id":"ce1"}]

sock recv: [{"channel":"/status","data":{...},"id":"ce2"}]

sock recv: [{"channel":"/status","data":{...},"id":"ce3"}]

sock recv: [{"channel":"/status","data":{...},"id":"ce4"}]

sock recv: [{"channel":"/status","data":{...},"id":"ce5"}]

sock recv: [{"channel":"/status","data":{...},"id":"ce6"}]

sock recv: [{"channel":"/status","data":{...},"id":"ce7"}]

sock recv: [{"channel":"/status","data":{...},"id":"ce8"}]

sock recv: [{"channel":"/status","data":{...},"id":"ce9"}]

sock recv: [{"channel":"/status","data":{...},"id":"cea"}]

WebSocket status: WebSocket.Closing

WebSocket status: WebSocket.Closed

...attempting to reconnect...

WebSocket status: WebSocket.Connecting

WebSocket status: WebSocket.Open

sock send: {"channel":"/meta/connect","connectionType":"websocket","clientId":"MYID"}

sock recv: [{"channel":"/meta/connect","successful":false,"error":"401:MYID:Unknown client","advice":{"reconnect":"handshake"}}]

[Justin Karneges]

On Sat, Aug 27, 2016 at 12:29 PM, Phrogz <phr...@mac.com> wrote:

1) When the WebSocket first connects, and after receiving 23 messages, the client always sends an empty set of messages, "[]" (and receives an empty response). This is shown with orange arrows in my screenshot.

1a) Is this heartbeat necessary to show the server that the client is still alive?

I believe the reason for sending an empty set of messages is to act as a keep alive so that the connection does not get timed out by intermediaries (for example the client's own NAT router). I don't think the server is supposed to derive any meaning from the payload.
 

1b) Is this covered in the Bayeux protocol?

WebSockets aren't covered in the official Bayeux spec, so what Faye (and others) do with regards to WebSockets is more of a de-facto standard. However, sending an empty set of messages is already allowed by the protocol as a way to send data with no side effects.

1c) If this is necessary, am I correct that the logic is that a client should always send "[]" after receiving 23 messages?

I believe the client should send this as often as it thinks it needs to in order to avoid being timed out by any potential NAT routers or proxies. The Faye client is almost certainly sending it on a timer interval and not relating it to received messages.
 

2) 25 seconds after receiving a message on meta/connect, the server responds with a successful:true message on meta/connect. This is shown with burgundy and blue arrows in my screenshot.

2a) Why does it take so long for the server to acknowledge the connection?

The /meta/connect message is an indication that the client wants to receive messages on a transport, but an immediate response is not required and you should not consider the /meta/connect exchange to be part of connection initialization. E.g. you would not want to display "Connecting to server...." to the user while you are waiting for an ack to /meta/connect. If you've succeeded with /meta/handshake and you've opened a WebSocket connection, then you can consider the client connected to the server.

The reason the server waits a little bit before replying to the connect message is because this is what normally happens with the long-polling transports, and it makes the transport usages symmetrical.

3) Immediately after receiving the meta/connect, the client always responds with a new message on meta/connect. This is shown with blue arrows in my screenshot.

3a) Is this a direct response to the message received, or is this timing because in the initial handshake the server's advice included a 25 second timeout?

Much like the other transports, once a connect request has completed, the client should begin a new one. So in that sense yes, you could say that starting a new connect request is in direct reaction to the previous connect acknowledgement.
 

3c) Is this covered in the Bayeux protocol specs?

As with anything WebSocket-related, this behavior isn't explicitly specified in the official spec, however it is the same behavior as other transports so it is sort of covered.

Justin

[Phrogz]

On Saturday, August 27, 2016 at 2:39:52 PM UTC-6, Justin Karneges wrote:

On Sat, Aug 27, 2016 at 12:29 PM, Phrogz <phr...@mac.com> wrote:

I believe the client should send this as often as it thinks it needs to in order to avoid being timed out by any potential NAT routers or proxies. The Faye client is almost certainly sending it on a timer interval and not relating it to received messages.

Thanks for all your answers. They all make sense, and I've incorporated them into my client[1] to good effect.

Do you have any suggestions for what's an appropriate timeout value? I'm currently using advice.timeout/2 (which may be what the Faye client is using; I couldn't find the appropriate source code line).

[1] https://github.com/Phrogz/rb3jay/blob/master/qt-client/BayeuxClient.qml