Faye js client doesn't connect properly

[Frank Razenberg]

Hi James and group,

I have a simple setup with the faye server on node, and am using the faye js client. My problem is that the client doesn't seem to connect properly most of the time. I need about 3-4 browser refreshes before I successfully connect to the node server.

The connect code is dirt-simple:

var fayeClient;

$(document).ready(function () { 

fayeClient = new FayeClient("/faye", rctMap);

});

...

        client = new Faye.Client(address);

var initSubscription = client.subscribe("/init", onInit);

initSubscription.callback(function() { 

client.publish("/hello", "hello"); 

});

On the other end I have a subscriber to /hello which sends some initial info on the "/init" channel from which the client unsubscribes. However, this message usually does not arrive.

Relevant log parts are attached, but they don't make much sense to me. Can you see if something's causing problems, or help me debug this issue further?

Thanks,

Frank

[James Coglan]

On 30 August 2012 16:38, Frank Razenberg <zzat...@gmail.com> wrote:

Hi James and group,

I have a simple setup with the faye server on node, and am using the faye js client. My problem is that the client doesn't seem to connect properly most of the time. I need about 3-4 browser refreshes before I successfully connect to the node server.

The connect code is dirt-simple:

var fayeClient;

$(document).ready(function () { 

fayeClient = new FayeClient("/faye", rctMap);

});

...

        client = new Faye.Client(address);

var initSubscription = client.subscribe("/init", onInit);

initSubscription.callback(function() { 

client.publish("/hello", "hello"); 

});

On the other end I have a subscriber to /hello which sends some initial info on the "/init" channel from which the client unsubscribes. However, this message usually does not arrive.

I don't understand what's going on here: you create two clients in the same page -- are they attached to the same server? This will cause problems. As I understand this code: the second client subscribes to /init, and when the subscription is acknowledged, it publishes to /hello.

 

Relevant log parts are attached, but they don't make much sense to me. Can you see if something's causing problems, or help me debug this issue further?

I have annotated the logs by splitting them into chunks and labelling each chunk with what's going on, at a high level:

https://gist.github.com/3534634

Some observations:

The sections I've marked 'Connect cycle' are normal: a client publishes to /meta/connect, and the server responds when there are new messages for the client, or after a timeout, whichever is sooner. This is the long-polling request. On a WebSocket connection, the client simply sends this message periodically as a heartbeat for its clientId; the server can push messages whenever it likes without a pending /meta/connect.

However you have set a very short timeout -- 2 seconds. This is why you're seeing the connection cycle so frequently, and it may cause weird behaviour. It effectively reduces Faye to a polling system. You should still get every message you need, but you've got a lot of data going over the wire that you don't need. Try a longer timeout, like 20 or 60 seconds.

I don't understand the difference between the successful and unsuccessful client logs -- the latter is simply a truncated version of the former. This is what the first one does:

* Handshakes

* Subscribes to /init

* Upgrades transport to WebSocket

* Publishes to /init

<-- Second one stops here

* Receives published message

* Unsubscribes from /init

* Subscribes to /update

* Subscribes to /delete
* Subscribes to /refresh

* Cycles /meta/connect every 2 seconds

The logs in the second case stop where I would expect to see the client receiving the message to /init -- its subscription to that channel is confirmed before the message is published. Is that the end of the logs? Does it continue to cycle /meta/connect without receiving anything? Do you see any errors, e.g. 'Unknown client'?

[James Coglan]

On 30 August 2012 18:47, James Coglan <jco...@gmail.com> wrote:

On 30 August 2012 16:38, Frank Razenberg <zzat...@gmail.com> wrote:

The connect code is dirt-simple:

var fayeClient;

$(document).ready(function () { 

fayeClient = new FayeClient("/faye", rctMap);

});

...

        client = new Faye.Client(address);

var initSubscription = client.subscribe("/init", onInit);

initSubscription.callback(function() { 

client.publish("/hello", "hello"); 

});

* Handshakes

* Subscribes to /init

* Upgrades transport to WebSocket

* Publishes to /init

<-- Second one stops here

* Receives published message

* Unsubscribes from /init

* Subscribes to /update

* Subscribes to /delete
* Subscribes to /refresh

* Cycles /meta/connect every 2 seconds

I should add: I'm not sure the logs correspond to the code, for example there is no record of a publish to /hello in there. Did you mean client.publish('/init', 'hello') ?

[James Coglan]

On 30 August 2012 16:38, Frank Razenberg <zzat...@gmail.com> wrote:

The connect code is dirt-simple:

var fayeClient;

$(document).ready(function () { 

fayeClient = new FayeClient("/faye", rctMap);

});

...

        client = new Faye.Client(address);

var initSubscription = client.subscribe("/init", onInit);

initSubscription.callback(function() { 

client.publish("/hello", "hello"); 

});

I've written a client script that just does this:

var client = new Faye.Client('http://localhost:8000/bayeux');

var initSubscription = client.subscribe("/init", function(m) { console.log(m) });

initSubscription.callback(function() { 

  client.publish("/init", "hello"); 

});

It prints "hello" every time I run the page, on a server with a 2-second timeout.

[James Coglan]

On 30 August 2012 18:47, James Coglan <jco...@gmail.com> wrote:

I have annotated the logs by splitting them into chunks and labelling each chunk with what's going on, at a high level:

https://gist.github.com/3534634

One thing I just realized: your server logs https://gist.github.com/3534634#file_server_logs.js do not show message #4. They show:

1. Handshake

2. Subscribe

3. Connect

5. Connect

6. Connect

7. Connect 

In the client logs https://gist.github.com/3534634#file_successful_client.js, the message published to /init is #4. Seems like your code isn't reaching the client.publish() line, or that message is not being received by the server. Might just be coincidence, though.

[Frank Razenberg]

Hi James,

Thanks for your thorough reply and apologies for my late reply. I dug into this a bit deeper and added some better logs; one where everything goes as expected, and one where some things seems to fail.

> I don't understand what's going on here: you create two clients in the same page

What I called FayeClient (mind the lack of dot) is a small wrapper which contains the subscription/message handling. This class has a Faye.Client member (mind the dot) - so there's really just one connection to the server.

> The logs in the second case stop where I would expect to see the client receiving the message to /init -- its subscription to that channel is confirmed before the message is published. Is that the end of the logs? Does it continue to cycle /meta/connect without receiving anything? Do you see any errors, e.g. 'Unknown client'? 

Yes, that was the end of the log. The /hello" message does not arrive at any of the other clients - but it may have been the case that the C# client did not connect properly either.

For each scenario I think randomly occurs I've added some logs:

- logs_expected.txt contain the server logs of a successfull connect by the C# client. Then I let the JS client connect, and message are exchanged as expected.

- logs_c#_unexpected_client.txt contains the server-side logs of a session where the C# client does not connect properly

- logs_ja_fail.txt contains server-side logs where the C# client connects and subscribes as expected, but the JS client does not.

The observed behavior seems very random, about 1/3 times everything goes as expected. The C# client not connecting properly (about 1 of 5 times) is more rare than the JS client not connecting properly (about 2 out of 3 times). I hope you can make anything out of this :)

Kind regards,

Frank

[James Coglan]

On 1 September 2012 10:32, Frank Razenberg <fr...@zzattack.org> wrote:

The observed behavior seems very random, about 1/3 times everything goes as expected. The C# client not connecting properly (about 1 of 5 times) is more rare than the JS client not connecting properly (about 2 out of 3 times). I hope you can make anything out of this :)

I think the C# client is overloading the server by misbehaving -- it's very weird that the JS client does not get a reply when it publishes to /hello. These logs are suspicious:

2012-09-01 09:47:10 [INFO] [Faye.Server] Processing messages: [{"channel":"/meta/connect","connectionType":"long-polling","id":"3","clientId":"1u0pg2k03kr8m403srfiz1g4yqa5"}] (local: false)

2012-09-01 09:47:10 [INFO] [Faye.Server] Handling message: {"channel":"/meta/connect","connectionType":"long-polling","id":"3","clientId":"1u0pg2k03kr8m403srfiz1g4yqa5"} (local: false)

2012-09-01 09:47:10 [INFO] [Faye.Server] Processing messages: [{"channel":"/meta/connect","connectionType":"long-polling","id":"3","clientId":"1u0pg2k03kr8m403srfiz1g4yqa5"}] (local: false)

2012-09-01 09:47:10 [INFO] [Faye.Server] Handling message: {"channel":"/meta/connect","connectionType":"long-polling","id":"3","clientId":"1u0pg2k03kr8m403srfiz1g4yqa5"} (local: false)

This shows the C# client polling /meta/connect twice in one second, without getting a reply. The timeout seems to be set to 120, and the client should wait until it gets a /meta/connect reply before polling again.

[James Coglan]

On 8 September 2012 16:55, James Coglan <jco...@gmail.com> wrote:

On 1 September 2012 10:32, Frank Razenberg <fr...@zzattack.org> wrote:

The observed behavior seems very random, about 1/3 times everything goes as expected. The C# client not connecting properly (about 1 of 5 times) is more rare than the JS client not connecting properly (about 2 out of 3 times). I hope you can make anything out of this :)

I think the C# client is overloading the server by misbehaving -- it's very weird that the JS client does not get a reply when it publishes to /hello. These logs are suspicious:

Would also like to see debug logs for the server. There's no record of the server receiving the /hello message from the JS client,  but I'm not sure if that's accidental.

You should also check which transport is in use when publishing to /hello -- see client._transport.connectionType. You'll need to use the unminified client from /faye/faye-browser.js for this to work.