Monday, August 9, 2010

Subscription Rejections in Faye

‹prev | My Chain | next›

Last night, I wrote my first faye extension (it was easy!) that prevented subscriptions with wildcards. Tonight I would like to explore a bit of what is going on under the covers.

Wildcard channel subscriptions allow a client to subscribe to the "/foo/bar" channel by subscribing to "/foo/*" or even "/**". I found that my no_wildcards faye extension did indeed prevent messages from being sent back to the wildcard subscriber. The subscription did not fail—no exception was raised—the no_wildcards extension simply rejected the subscription and no further communication took place.

I rather like that behavior. Still, I am curious: does the faye client know that the subscription was rejected?

To investigate, I again start by sniffing packets—this time on the loopback interface (I am localhost only tonight):
cstrom@whitefall:~/repos/my_fab_game$ sudo tcpdump -i lo -X -s0 port 8000
As I mentioned last night, I prefer the -X (hex + ascii) output to the raw output of -w because the latter sometimes messes up my console. The -s0 option indicates no "snap length"—in other words show the entire packet.

I am still using my dirt-simple node.js + faye + extension application from last night:
var faye   = require('faye'),
server = new faye.NodeAdapter({mount: '/faye'}),
puts = require('sys').puts;


var no_wildcards = { ... };

Also, I still have my two node/faye clients for receiving messages:
node> var faye = require("faye");
node> var client = new faye.Client('http://localhost:8000/faye');
node> var wc = client.subscribe('/**', function(message) {puts("[**]: " + message)});
node> var foo_bar = client.subscribe('/foo/bar', function(message) {puts("[foo/bar]: " + message)});
And for sending messages:
node> var faye = require('faye');
node> var client = new faye.Client('http://localhost:8000/faye');
node> client.publish("/foo/bar", "test 01");
What I see in tcpdump when I subscribe to the wildcard channel is:

# The subscription request:
14:19:53.370506 IP whitefall.44758 > whitefall.8000: Flags [P.], seq 1:237, ack 1, win 513, options [nop,nop,TS val 22015347 ecr 22015347], length 236
0x0000: 4500 0120 0018 4000 4006 3bbe 7f00 0001 E.....@.@.;.....
0x0010: 7f00 0001 aed6 1f40 21fa ed66 226a 97d5 .......@!..f"j..
0x0020: 8018 0201 ff14 0000 0101 080a 014f ed73 .............O.s
0x0030: 014f ed73 504f 5354 202f 6661 7965 2048 .O.sPOST./faye.H
0x0040: 5454 502f 312e 310d 0a43 6f6e 7465 6e74 TTP/1.1..Content
0x0050: 2d54 7970 653a 2061 7070 6c69 6361 7469 -Type:.applicati
0x0060: 6f6e 2f6a 736f 6e0d 0a48 6f73 743a 206c on/json..Host:.l
0x0070: 6f63 616c 686f 7374 0d0a 436f 6e74 656e ocalhost..Conten
0x0080: 742d 4c65 6e67 7468 3a20 3132 340d 0a43 t-Length:.124..C
0x0090: 6f6e 6e65 6374 696f 6e3a 2063 6c6f 7365 onnection:.close
0x00a0: 0d0a 0d0a 5b7b 2263 6861 6e6e 656c 223a ....[{"channel":
0x00b0: 222f 6d65 7461 2f73 7562 7363 7269 6265 "/meta/subscribe
0x00c0: 222c 2263 6c69 656e 7449 6422 3a22 3179 ","clientId":"1y
0x00d0: 3762 3931 697a 616c 7370 6b31 786e 7163 7b91izalspk1xnqc
0x00e0: 7070 3930 6d73 3576 222c 2273 7562 7363 pp90ms5v","subsc
0x00f0: 7269 7074 696f 6e22 3a22 2f2a 2a22 2c22 ription":"/**","
0x0100: 6964 223a 2239 3772 7162 6a65 3231 3963 id":"97rqbje219c
0x0110: 316b 3376 7564 7632 3770 6664 6122 7d5d 1k3vudv27pfda"}]


# The denial:
14:19:53.377481 IP whitefall.8000 > whitefall.44758: Flags [P.], seq 1:272, ack 237, win 529, options [nop,nop,TS val 22015349 ecr 22015347], length 271
0x0000: 4500 0143 7aa7 4000 4006 c10b 7f00 0001 E..Cz.@.@.......
0x0010: 7f00 0001 1f40 aed6 226a 97d5 21fa ee52 .....@.."j..!..R
0x0020: 8018 0211 ff37 0000 0101 080a 014f ed75 .....7.......O.u
0x0030: 014f ed73 4854 5450 2f31 2e31 2032 3030 .O.sHTTP/1.1.200
0x0040: 204f 4b0d 0a43 6f6e 7465 6e74 2d54 7970 .OK..Content-Typ
0x0050: 653a 2061 7070 6c69 6361 7469 6f6e 2f6a e:.application/j
0x0060: 736f 6e0d 0a43 6f6e 6e65 6374 696f 6e3a son..Connection:
0x0070: 2063 6c6f 7365 0d0a 5472 616e 7366 6572 .close..Transfer
0x0080: 2d45 6e63 6f64 696e 673a 2063 6875 6e6b -Encoding:.chunk
0x0090: 6564 0d0a 0d0a 6137 0d0a 5b7b 2269 6422 ed....a7..[{"id"
0x00a0: 3a22 3937 7271 626a 6532 3139 6331 6b33 :"97rqbje219c1k3
0x00b0: 7675 6476 3237 7066 6461 222c 2263 6c69 vudv27pfda","cli
0x00c0: 656e 7449 6422 3a22 3179 3762 3931 697a entId":"1y7b91iz
0x00d0: 616c 7370 6b31 786e 7163 7070 3930 6d73 alspk1xnqcpp90ms
0x00e0: 3576 222c 2263 6861 6e6e 656c 223a 222f 5v","channel":"/
0x00f0: 6d65 7461 2f73 7562 7363 7269 6265 222c meta/subscribe",
0x0100: 2265 7272 6f72 223a 2257 696c 6463 6172 "error":"Wildcar
0x0110: 6420 7375 6273 6372 6970 7469 6f6e 7320 d.subscriptions.
0x0120: 6e6f 7420 616c 6c6f 7765 6422 2c22 7375 not.allowed","su
0x0130: 6363 6573 7366 756c 223a 6661 6c73 657d ccessful":false}
0x0140: 5d0d 0a ]..
When I publish messages to channels that would otherwise match the wildcard "/**" subscription, I see no traffic at all. So not only is the subscription being denied, but no subsequent data is sent either. That is all as expected and desired.

The question still remains: the server replies with the error message, but is the failure known by the faye client?

Back in the node session for subscribing to channels, I interrogate the wildcard client's properties:
node> var wc = client.subscribe('/**', function(message) {puts("[**]: " + message)});
node> for (var prop in wc) {puts(prop + ": " + wc[prop])}
_client: [object Object]
_channels: /**
_callback: function (message) {puts("[**]: " + message)}
_scope: undefined
_cancelled: false
initialize: function (client, channels, callback, scope) {
this._client = client;
this._channels = channels;
this._callback = callback;
this._scope = scope;
this._cancelled = false;
cancel: function () {
if (this._cancelled) return;
this._client.unsubscribe(this._channels, this._callback, this._scope);
this._cancelled = true;
unsubscribe: function () {
That looks very much like a successfully subscribed channel. The _channel property includes the wildcard channel ("/**"). The _callback property contains the puts callback that I supplied. It is not cancelled, though that seems a mechanism for stopping the subscription from the client-side, not in response to server side woes. Hrm...

My best bet at this point is the _client property, which has a lot of attributes (and methods):
node> for (var prop in wc._client) {puts(prop + ": " + wc._client[prop])}
_endpoint: http://localhost:8000/faye
_options: [object Object]
_transport: [object Object]
_state: 3
_channels: [object Object]
Brief investigation into that _channels property reveals that the wildcard channel is not included:
node> for (var prop in client._channels._children) {puts(prop + ": " + client._channels._children[prop])}
foo: [object Object]
I suspect the underscores are used as a convention to indicate private methods / properties, so, although I have found one means of verifying unsuccessful subscription, I still hold out hope for another. Among the methods on the _client is, obviously, subscribe():
subscribe: function (channels, callback, scope) {
if (channels instanceof Array)
return Faye.each(channels, function(channel) {
this.subscribe(channel, callback, scope);
}, this);


this.connect(function() {'Client ? attempting to subscribe to ?', this._clientId, channels);

channel: Faye.Channel.SUBSCRIBE,
clientId: this._clientId,
subscription: channels

}, function(response) {
if (!response.successful) return;

var channels = [].concat(response.subscription);'Subscription acknowledged for ? to ?', this._clientId, channels);
this._channels.subscribe(channels, callback, scope);
}, this);

}, this);

return new Faye.Subscription(this, channels, callback, scope);
What I notice there is that, if the response to the subscription request is not successful, then nothing else happens. There is no special error handling, no attribute is set. Nothing.

The last thing I try tonight is setting the log level. There is a special Logging class in faye that controls this. To set the log level at debug, I set the logLevel property in that class to "debug". Then, when I try to subscribe to the wildcard channel, I see lots of feedback:
node> faye.Logging.logLevel = 'debug';
node> var wc = client.subscribe('/**', function(message) {puts("[**]: " + message)});
2010-08-09 21:08:59 [INFO] [Faye.Client] Calling deferred actions for "1ujj1zm11mmj88wxfu0ckdryjw"
2010-08-09 21:08:59 [INFO] [Faye.Client] Client "1ujj1zm11mmj88wxfu0ckdryjw" attempting to subscribe to "/**"
node> 2010-08-09 21:08:59 [DEBUG] [Faye.Transport] Client "1ujj1zm11mmj88wxfu0ckdryjw" sending message to "http://localhost:8000/faye": [{"channel":"/meta/subscribe","clientId":"1ujj1zm11mmj88wxfu0ckdryjw","subscription":"/**","id":"124h5bx14vubfp1kvtij7717qtb"}]
2010-08-09 21:08:59 [DEBUG] [Faye.Transport] Client "1ujj1zm11mmj88wxfu0ckdryjw" received from "http://localhost:8000/faye": [{"id":"124h5bx14vubfp1kvtij7717qtb","clientId":"1ujj1zm11mmj88wxfu0ckdryjw","channel":"/meta/subscribe","error":"Wildcard subscriptions not allowed","successful":false}]
What this tells me is that, if I really care about the unsuccessful response from a subscription, then I need to write a client-side faye extension to match the server-side faye extension. The client is notified of the rejected subscription, but nothing in the core client cares.

Since I already know how to write faye extensions and since I actually like the current behavior, I think I may stop here with my investigation. Tomorrow, unless I come up with a justification for pursuing this further, I think that I will return to testing my (fab) game with faye integration.

Day #190

No comments:

Post a Comment