Tuesday, August 31, 2010

Express.js Flash

‹prev | My Chain | next›

Bleh. I had planned on playing about with mustache.js in express, but then I remembered, I hate writing HTML. I blame Haml. Instead, I will stick with trying to play with sessions in express.

I do not really need sessions in my (fab) game, but I will try to use flash session messages when the player gets logged out after idling too long. First up, in the jade template, I redirect the player to the /idle_timeout resource when the backend signals that the player is no longer welcome in the game:
      |     var goodbye = function() {
| window.location = window.location.protocol + '//' + window.location.host + '/idle_timeout';
| };
I need to define that resource to set a flash message and then redirect back to the main player board:
app.get('/idle_timeout', function(req, res) {
req.flash('info', 'You were logged out because you weren\'t doing anything.');
res.redirect('/board');
});
When I access this resource, however, I get a sad little stacktrace:
TypeError: Cannot read property 'flash' of undefined
at IncomingMessage.flash (/home/cstrom/.node_libraries/.npm/express/1.0.0rc2/package/lib/express/request.js:152:49)
at Object.<anonymous> (/home/cstrom/repos/my_fab_game/game.js:39:7)
at pass (/home/cstrom/.node_libraries/.npm/connect/0.2.4/package/lib/connect/middleware/router.js:65:27)
at Object.router [as handle] (/home/cstrom/.node_libraries/.npm/connect/0.2.4/package/lib/connect/middleware/router.js:80:10)
at next (/home/cstrom/.node_libraries/.npm/connect/0.2.4/package/lib/connect/index.js:264:23)
at /home/cstrom/.node_libraries/.npm/connect/0.2.4/package/lib/connect/middleware/staticProvider.js:87:21
at node.js:764:9
Hrm... That error is not coming from my (fab) game, it is coming from express. Looking at that method, it seems as though the session is not present:
http.IncomingMessage.prototype.flash = function(type, msg){
var msgs = this.session.flash = this.session.flash || {};
// ....
};
I start acking through the express code for session, when I come across an example app for express sessions. Just what I need. It suggests that I need to add two lines to the createServer call:
// Create the Express server
var app = express.createServer(
express.cookieDecoder(),
express.session()

);
I try adding just the express.session() line, but get warnings about needing the cookieDecoder. Sure enough, once I add that in, flash works. Well, at least it is not crashing.

To get this working, I add an #info div to my jade template:
#info= flash.info
...
But I always see 'undefined' in that div. I think that I am populating it correctly as a local, template variable, but I inspect the flash just to be sure:
app.get('/board', function(req, res) {
puts(inspect(req.flash));
res.render('board', {locals: {flash: req.flash}});
});
In the server output, I see:
[INFO] timeout foo!
[INFO] players.drop_player foo
[Function]
Ah! req.flash() is a function, not an attribute. Easy enough:
app.get('/board', function(req, res) {
puts(inspect(req.flash()));
res.render('board', {locals: {flash: req.flash()}});
});
And now I see the flash message in the server output:
[INFO] timeout foo!
[INFO] players.drop_player foo
{ info: [ 'You were logged out because you weren\'t doing anything.' ] }
Except, in the browser, I still see 'undefined' where the info message should be. Am I invoking the render() method wrong or is something else breaking? I will check the latter first. What is the value of the info attribute?
app.get('/board', function(req, res) {
puts(inspect(req.flash()));
var info = req.flash().info;
puts(inspect(info));
res.render('board', {locals: {flash: flash()}});
});
Now, when my player times out:
[INFO] players.update_player_status: foo
[INFO] timeout foo!
[INFO] players.drop_player foo
{ info: [ 'You were logged out because you weren\'t doing anything.' ] }
undefined
Ah, damn! I've got a Heisenberg thing going on here. Looking at the flash in the first place destroyed it. To get around this, I squirrel away the flash immediately:
app.get('/board', function(req, res) {
var flash = req.flash();
puts(inspect(flash));
var info = flash.info;
puts(inspect(info));
res.render('board', {locals: {flash: flash}});
});
Now, I get the info attribute that I have been expecting:
[INFO] timeout foo!
[INFO] players.drop_player foo
{ info: [ 'You were logged out because you weren\'t doing anything.' ] }
[ 'You were logged out because you weren\'t doing anything.' ]
With that, I finally get the flash warning to show up on the page.

One last thing I need to add is a jade conditional so that the #info div is not displayed unless flash.info is present (it displays undefined otherwise). The conditional:
- if (flash.info)
#info= flash.info

Simple enough.

Well there were certainly a few gotchas in there, at least for this beginner, but I finally got sessions working in express. Tomorrow I plan to head back to faye land to see if I can gracefully handle writes to blocked browsers.


Day #212

Monday, August 30, 2010

How to Crash Faye the Stupid Way

‹prev | My Chain | next›

Yesterday I got my (fab) game to the point that I could briefly lose the backend or DB without any loss of player data and only brief interruption of the action. It was a nice confirmation of the power of node.js and CouchDB.

It was also timely because I am finding that the backend crashes with a faye error when players timeout of the game:
cstrom@whitefall:~/repos/my_fab_game$ ./game.js
[INFO] Starting up...
[INFO] [init_timeouts] bob 1793694
[INFO] players.update_player_status: bob
[INFO] players.update_player_status: bob
[INFO] players.update_player_status: bob
[INFO] timeout bob!
[INFO] players.drop_player bob

net:678
throw new Error('Stream is not writable');
^
Error: Stream is not writable
at Stream._writeOut (net:678:11)
at Stream.write (net:664:17)
at Object.handshake (/home/cstrom/.node_libraries/.npm/faye/0.5.2/package/faye-node.js:1207:14)
at Object.initialize (/home/cstrom/.node_libraries/.npm/faye/0.5.2/package/faye-node.js:1042:19)
at Object.<anonymous> (/home/cstrom/.node_libraries/.npm/faye/0.5.2/package/faye-node.js:149:28)
at Object.handleUpgrade (/home/cstrom/.node_libraries/.npm/faye/0.5.2/package/faye-node.js:1854:18)
at Server.<anonymous> (/home/cstrom/.node_libraries/.npm/faye/0.5.2/package/faye-node.js:1816:52)
at Server.emit (events:43:20)
at Stream.<anonymous> (http:777:14)
at IOWatcher.callback (net:494:29)
The drop player message is being broadcast to all players, including the player that has been idling too long. I suspect that the faye channel in the dropped player's browser is being closed before the backend can finish sending messages. I would like to see if things might be made a bit more graceful.

I could try to track this down in at least two ways: (1) try to reproduce to see if there is a pattern or (2) look at the code to see what is going on in there. I feel lazy when I play with the browser to reproduce, especially when I have a perfectly good stack trace telling me where things are going wrong. Besides, the last time I started playing, I felt ridiculous when no pattern emerged and a cursory code examination made it obvious where the problem was. So I opt for (2) today...

Checking out the handleUpgrade method, I find that the error is originating from the first line (when the websocket is initialized):
handleUpgrade: function(request, socket, head) {
    var socket = new Faye.WebSocket(request, head),
self   = this;

socket.onmessage = function(message) {
try {
var message = JSON.parse(message.data);
self._server.process(message, socket, function(replies) {
socket.send(JSON.stringify(replies));
});
} catch (e) {}
};
}
I also notice that errors generated on the reception of the message are swallowed without note—exceptions when initializing sockets should be similarly non-breaky (though I believe that they ought to be noted, not silently ignored).

Since this is happening under websockets, I wonder if something similar will occur in long-polling. To test this out, I set the player timeout to 10 seconds, then play / idle in Firefox 3 (which does not have websockets). That seems to behave itself in the backend:
[WARN] {"error":"not_found","reason":"deleted"}
[INFO] players.add_player: bob
[WARN] {"error":"not_found","reason":"deleted"}
[INFO] players.update_player_status: bob
[INFO] players.update_player_status: bob
[INFO] players.update_player_status: bob
[INFO] players.update_player_status: bob
[INFO] timeout bob!
[INFO] players.drop_player bob
Aside from needing to ignore warnings from CouchDB about previously deleted players, I look to be good here.

So I try the same thing in Chrome and find... that it works. I allow my player to idle timeout 10+ times and nothing. Gah!

Burned again. I am not sure which approach it best when crashes occur. I ought to start keeping a log to see which is the most likely approach to get quick resolution.

For now, I am stuck with a very hard to reproduce error. While pondering what to do next (simply restarting is starting to look better and better), I end up staring at this for a long time:



Stupid alerts. I really ought to put up a modal or just set a flash message / redirect to the login screen. Distracted from my original train of thought, I click OK and... crash the server.

Again, I think, "stupid alerts". They lock the browser, blocking it from processing events like faye notifications. I suspect that the faye socket timed out in the interim, then tried to reconnect/upgrade. Since the browser was blocking, nothing happened. Clicking OK freed the browser to respond, but the stream was already defunct. Or something like that.

I believe that I will call it a night there. Tomorrow, I will remove the alert dialog. This seems like a good opportunity to play with mustache.js and sessions in express. After that, I will return to this issue of timing out faye sockets. This feels like an edge case (how many people are stupid enough to use alert() dialogs in 2010?). Still, it is fertile ground for learning a bit more about websockets and faye's internals so I will be back.


Day #211

Sunday, August 29, 2010

Surviving Restart

‹prev | My Chain | next›

Today, I would like to see if I can restart my (fab) game without the usual assorted problems. Before the switch to a permanent store (naturally CouchDB) this would have been impossible. At this point, I only need to restore the in-code setTimeouts, which are used to idle timeout players. Every other attribute should already be in CouchDB.

First up, I return the idle timeout epoch milliseconds from the idle_timeout method:
  timeout: 30*60*1000,
timeouts: { },

idle_watch: function(id) {
if (this.timeouts[id])
clearTimeout(this.timeouts[id]);

var self = this;
this.timeouts[id] = setTimeout(function() {
Logger.info("timeout " + id +"!");
self.drop_player(id);
}, self.timeout);

return (new Date((new Date()).getTime() + self.timeout)).getTime();
}
The actual setTimeout is specified in milliseconds that it will run. I hope to use the epoch seconds returned from idle_timeout to re-establish timeouts. The difference between the epoch milliseconds and the current epoch milliseconds is the remaining number of milliseconds in the timeout:
node> new Date((new Date()).getTime() + 30*60*1000).getTime();
1283131853957
node> new Date(1283131853957);
Mon, 30 Aug 2010 01:30:53 GMT
node> 1283131853957 - (new Date).getTime();
1533424
The only time the idle_timeout gets updated is during update_player. That method is also responsible for storing updated player status in the backend. I can use that to store the timeout time:
  update_player_status: function(status) {
var self = this;
this.get(status.id, function(player) {
Logger.debug("[players.update_player_status] " + inspect(player));
if (player) {
Logger.info("players.update_player_status: " + status.id);
player.status = status;
player.timeout = self.idle_watch(status.id);
db.saveDoc(player);

}
else {
Logger.warn("[players.update_player_status] unknown player: " + status.id + "!");
}
});
}
With that being stored in CouchDB:



I can add a bit of code to the players init() method to attempt to restore player timeout:
  init: function() {
var self = this;

// Now, in epoch milliseconds
var now = (new Date()).getTime();

// Grab all players from CouchDB
self.all(function(players) {
players.forEach(function(player){
// Difference between recorded time and now
var timeout = player.timeout - now;

// If time left before timeout, begin the wait again
if (timeout > 0) {
Logger.info("[init_timeouts] " + player._id + " " + timeout);
self.idle_watch(player._id, timeout);
}
// Otherwise drop the player
else {
Logger.info("[init_timeouts] dropping: " + player._id);
self.drop_player(player._id);
}
});
});


// Ensure that the faye server has fully established by waiting
// half a second before subscribing to channels
setTimeout(function(){ self.init_subscriptions(); }, 500);

return self;
}
That seems to work just fine unless a player needs to be deleted. In that can, the drop_player() method needs to broadcast via faye that the player is no longer in the room. The problem is that the faye client is not immediately available.

To get around this, I move the restore-players functionality into an init_players() method to be invoked after the faye client is ready:
  init: function() {
var self = this;

// Ensure that the faye server has fully established by waiting
// half a second before subscribing to channels
setTimeout(function(){
self.init_subscriptions();
self.init_players();
}, 500);

return self;
}
That is all well and good, but does it work?



That is pretty freaking cool! I move my player about in the room a little while, then stop the node.js server with a Ctrl+C. After waiting a few seconds, I restart the server and see that the timeout is restored:
cstrom@whitefall:~/repos/my_fab_game$ ./game.js
[INFO] Starting up...
[INFO] [init_timeouts] bob 1793694
...
Most importantly, I can continue playing as if nothing happened.


Day #210

Saturday, August 28, 2010

More Callbacks with node-couchdb

‹prev | My Chain | next›

Yesterday, I was able to get player updates in my (fab) game stored in a CouchDB backend thanks to node-couchdb. Today, I hope to move the entire store over to CouchDB.

First up, I need to be able to drop players:
  drop_player: function(id) {
Logger.info("players.drop_player " + id);
this.faye.publish("/players/drop", id);

this.get(id, function(player) {
Logger.debug("[players.drop_player] " + inspect(player));
if (player) db.removeDoc(id, player._rev);
});

}
To delete in CouchDB, I need the current revision of the document. I use the get() method from last night to grab the current document, then remove it immediately. I could keep the revision ID in the local store to get around the lookup/then delete. I will worry about doing that when this proves to be a bottleneck.

Up next, I need to rework the idle timeout code a bit. I had been storing the idle timeout directly on the player objects in the local store (this._):
  idle_watch: function(id) {
if (this._[id].idle_timeout) {
clearTimeout(this._[id]].idle_timeout);
}

var self = this;
this._[id].idle_timeout = setTimeout(function() {
Logger.info("timeout " + id +"!");
self.drop_player(id);
}, 30*60*1000);


this._[id].idle_watch_started = "" + (new Date());
}
Since I am no longer storing data locally, I need to create a new local store for these timeouts. Easy enough:
  timeouts: { },

idle_watch: function(id) {
if (this.timeouts[id])
clearTimeout(this.timeouts[id]);

var self = this;
this.timeouts[id] = setTimeout(function() {
Logger.info("timeout " + id +"!");
self.drop_player(id);
}, 30*60*1000);

}
The timeouts are now stored in the timeouts attribute in my players object, which leaves very little still relying on the old local store. After replacing a couple more individual gets from the local store, I am left with only one more local store reference—a lookup of all players in a faye subscription:
     this.faye.subscribe("/players/query", function(q) {
var ret = [];
for (var id in self._) {
ret.push(self._[id].status);
}

self.faye.publish("/players/all", ret);
});
As with everything else in node-couchdb, a lookup of all documents in CouchDB is done via callback:
  all: function(callback) {
return db.allDocs({include_docs:true}, function(err, docs) {
callback(docs.rows.map(function(row) {return row.doc;}));
});
}
I use {include_docs:true} to pull back the player documents rather than just the meta data that is normally returned. Similarly, I map those results to return just the player documents (no meta data). With that, I need to convert the faye subscription to use the callback:
  all: function(callback) {
return db.allDocs({include_docs:true}, function(err, docs) {
callback(docs.rows.map(function(row) {return row.doc;}));
});
}
And finally, I can remove the local store entirely. I am still storing timeouts locally, but that is a code timeout, so there is really no choice in the matter. Now that I think about it, I ought to be able to save the timeout time in the CouchDB store. If I do that, I could restore the software timeout after a server restart. I will pick back up with that tomorrow.


Day #209

Friday, August 27, 2010

Updating CouchDB from Node.js (It's asynchronous)

‹prev | My Chain | next›

Tonight, I would like to explore hooking up the player store in my (fab) game to CouchDB.

First up, I install node-couchdb (it is in npm as couchdb, not node-couchdb):
cstrom@whitefall:~/repos/my_fab_game$ npm install couchdb
npm it worked if it ends with ok
npm cli [ 'install', 'couchdb' ]
npm version 0.1.26
...

npm activate couchdb@1.0.0
npm build Success: couchdb@1.0.0
npm ok
With that, I can declare CouchDB variables in my (fab) game:
var express = require('express'),
http = require('http'),
faye = require('faye'),
puts = require( "sys" ).puts,
p = require( "sys" ).p,
couchdb = require('node-couchdb/lib/couchdb'),
client = couchdb.createClient(5984, 'localhost'),
db = client.db('my-fab-game');


...
When a player first enters the game room, I need to create a new record in the DB. The saveDoc method ought to do the trick:
  add_player: function(player) {
var new_id = player.id;
if (!this.get(new_id)) {
this._[new_id] = {token: player.authToken};
db.saveDoc(new_id, this._[new_id]);
}
delete(player['authToken']);

this.update_player_status(player);
}
Checking in the DB, I see the record created. Easy enough! Now I would like to be able to update that record as the payer moves around the room.

To accomplish this, I need to pull back the record from the DB, modify the data accordingly, then save it back. The getDoc() and saveDoc() methods sound about right:
  get: function(id) {
db.getDoc(id);
},

update_player_status: function(status) {
var player = this.get(status.id);
p(player);
if (player) {
puts("[update_player_status] " + status.id);
player.status = status;
db.saveDoc(player);
this.idle_watch(status.id);
}
else {
puts("[update_player_status] unknown player: " + status.id + "!");
}
}
But nothing happens. The initial record is created, but not updated. And, I'm seeing that "unknown player" message, so nothing is being returned from the get() method.

Ah! Nothing is getting returned because I have no return statement:
  get: function(id) {
return db.getDoc(id);
}
That should fix it. But of course it does not.

What the hell? Why is getDoc() not returning anything? Even in node-repl, there is nothing.

And then, I actually read the documentation.

The getDoc() method, like all methods that retrieve data in node-couchdb, does not return anything. It expects a callback to which it sends both errors and returned data.

I do not care about errors (if the player is not in the room, the message should be ignored), so I log the occurrence and send the response data onto the requesting function via a callback:
  _get: function(id, callback) {
puts("trying to get: " + id);
db.getDoc(id, function(err, res) {
if (err) {
puts(JSON.stringify(er));
}
callback(res);
});
}
Putting this to use in the update_player_status method requires almost no change to the original, other than wrapping it in a callback for the get method:
  update_player_status: function(status) {
var self = this;
this._get(status.id, function(player) {
p(player);
if (player) {
puts("[update_player_status] " + status.id);
player.status = status;
db.saveDoc(player);
self.idle_watch(status.id);
}
else {
puts("[update_player_status] unknown player: " + status.id + "!");
}
});
}
With that, I can move about the room and the player status is updated in CouchDB:



Nice! That is a fine stopping point for now. Tomorrow I will (hopefully) finish adapting the store to CouchDB with a stretch goal of trying to tap into the changes stream.


Day #208

Thursday, August 26, 2010

Jade Templating

‹prev | My Chain | next›

Last night, I got up and running (quite quickly) express, a Sinatra-like framework for node.js. Tonight, I would like to explore one of the templating systems that express supports—jade, which bills itself as a haml (js) successor.

I install jade with npm:
cstrom@whitefall:~/repos/my_fab_game$ npm install jade
npm it worked if it ends with ok
npm cli [ 'install', 'jade' ]
npm version 0.1.26
...

npm linkBin jade ./bin/jade
npm activate jade@0.3.0
npm build Success: jade@0.3.0
npm ok


In my backend server, I set jade as the default templating engine and set it up to respond to the "/board" resource:
app.set('view engine', 'jade');

app.get('/board', function(req, res) {
res.render('board');
});
If I understand the instructions on the express guide, I can put a board.jade file into the views sub-directory. Also, I need to put a layout.jade file in there because I have not supplied layout: false options.

So I have views/board.jade:
h1 Hello World!
...and views/layout.jade:
!!! 5
html(lang="en")
head
title Testing 123
body
div= body
I think that the result of the views/board.jade template will be inserted into views/board.jade, interpolated into the body variable. Checking it out in the browser, I find:



Hrm... that is not quite right. The results of the board.jade template are being escaped before being inserted into layout.jade. Ah! I simply need to prepend an exclamation mark on the body variable to signal that I do not want to escape the HTML:
!!! 5
html(lang="en")
head
title Testing 123
body
div!= body
With that, I get my nice HTML-ified template:



I take a bit of time to get my old, static HTML converted over to jade in the layout:
!!! 5
html(lang="en")
head
title My (fab) Game

link(href="/stylesheets/board.css", media="screen", rel="stylesheet", type="text/css")

script(src="/javascript/jquery-min.js", type="application/javascript")

script(src="/javascript/json2.js", type="application/javascript")

script(type="text/javascript", src="/faye.js")

script(src="/javascript/raphael-min.js", type="application/javascript")
script(src="/javascript/player.js", type="application/javascript")
script(src="/javascript/player_list.js", type="application/javascript")
script(src="/javascript/room.js", type="application/javascript")

:javascript
| var player_list;

| $(function() {
| var kv = location.search.substr(1).split(/=/);
| if (kv[0] == 'player' && kv[1]) {
| $('#login').hide();

| var me = new Player(kv[1], {animate_with: function(avatar){
| var color = ["#ccc", "#c00", "#0c0"][Math.floor(3*Math.random(3))];
| avatar.attr({fill: color});
| } });

| var room = new Room($("#room-container")[0]);
| var goodbye = function() {
| alert("You have been logged out.");
| window.location = window.location.protocol + '//' + window.location.host + window.location.pathname;
| };
| player_list = new PlayerList(me, room, {onComplete: goodbye});
| }
| });

body
div!= body
...And in the board itself:
form#login(method: "get")
label
Name
input(type: "text", name: "player")
input(type: "submit", value: "Play")
#room-container
With that, I can play my (fab) game with express / jade:



Nice! That is a fine stopping point for tonight. Up tomorrow: it's been far too long since I last played with CouchDB.


Day #207

Wednesday, August 25, 2010

Express.js

‹prev | My Chain | next›

At the risk of straying to far on the path of my chain, tonight I would like to play around a bit with express. With the switch to faye, the fab.js backend in my (fab) game is doing little more than serving up static HTML and CSS. If express is as easy as advertised, I ought to be able to swap backends quickly.

First up, I install express via npm:
cstrom@whitefall:~/repos/my_fab_game$ npm install express
npm it worked if it ends with ok
npm cli [ 'install', 'express' ]
npm version 0.1.26
npm config file /home/cstrom/.npmrc
npm config file /home/cstrom/local/etc/npmrc
npm install pkg express
...

npm activate express@1.0.0rc2
npm activate connect@0.2.4
npm build Success: express@1.0.0rc2
npm build Success: connect@0.2.4
npm ok
With express installed, I remove my fab.js code replacing it with express.js code. Since the HTML and CSS is all static, the only "real" work I do is use the built-in express static provider:
var express = require('express'),
http = require('http'),
faye = require('faye'),
puts = require( "sys" ).puts;

// Create the Express server
var app = express.createServer();

// Serve statics from ./public
app.use(express.staticProvider(__dirname + '/public'));


// Server-side extension to lock player messages to client that added
// the player in the first place,
// http://japhr.blogspot.com/2010/08/per-message-authorization-in-faye.html
var serverAuth = {
incoming: function(message, callback) {
// ...
}
};

// Faye nodejs adapter
var bayeux = new faye.NodeAdapter({
mount: '/faye',
timeout: 45
});

// Add the server-side faye extension
bayeux.addExtension(serverAuth);

// Add the faye nodejs faye adapter to the nodejs server
bayeux.attach(app);

// Listen on port 3000
app.listen(3000);
The faye code came directly from the fab.js version of the app, everything else is basic express.js.

And it just works. Me like.


Day #206

Tuesday, August 24, 2010

Fork Faye

‹prev | My Chain | next›

Up tonight, I try to add some error handling to faye channel subscriptions. Yesterday, I isolated the problem in a try-catch blocks in the addListener method:
   request.addListener('response', function(stream) {
response = stream;
Faye.withDataFor(response, function(data) {
try {
self.receive(JSON.parse(data));
} catch (e) {
retry();
}

});
});
The catch block completely ignores any exceptions preferring instead to retry() the original request. A retry sounds like a great idea when there is a problem with the response, but not when there is an error in my code. In my experience, I am far more likely to write bad code than I am to receive a bad response.

I consider throwing the error depending on the type, but opt against that. Blacklisting/whitelisting types are bound to miss something. Instead, I simply add some logging:
    request.addListener('response', function(stream) {
response = stream;
Faye.withDataFor(response, function(data) {
try {
self.receive(JSON.parse(data));
} catch (e) {
var stack = e.stack.split("\n");
self.error(stack[0] + " " + stack[1].replace(/ +/, ''));
self.debug(e.stack);


retry();
}
});
});
I always warn that something has gone wrong. The first two lines include the message itself and the line at which the exception was thrown. If I am at debug loglevel, then I can see the whole stack trace. That seems like a reasonable compromise.

Let's see if it works:
node> var faye = require("faye");
node> var client = new faye.Client("http://localhost:4011/faye");
node> var puts = require("sys").puts;
node> var subscription = client.subscribe("/foo", function(m) {puts("1"); asdf.foo.bar; puts("2");});
node> client.publish("/foo", "test 01")
node> 1
2010-08-24 19:55:13 [ERROR] [Faye.Transport] ReferenceError: asdf is not defined at [object Context]:1:69

Nice!

So far, I have been editing the faye-node.js file directly in my npm library. That is not exactly a recipe for maintainability. So I fork faye and apply the logging change.

To build the library for node, I issue the jake command (it's make for Javascript):
cstrom@whitefall:~/repos/faye$ jake
core src /build/core.js 30 kB
core min /build/core-min.js 15 kB
faye-browser src /build/faye-browser.js 56 kB
faye-browser min /build/faye-browser-min.js 23 kB
faye-node src /build/faye-node.js 57 kB
faye-node min /build/faye-node-min.js 30 kB
/home/cstrom/.rvm/rubies/ruby-1.8.7-p249/lib/ruby/1.8/fileutils.rb:1201:in `stat': No such file or directory - README.txt (Errno::ENOENT)
from /home/cstrom/.rvm/rubies/ruby-1.8.7-p249/lib/ruby/1.8/fileutils.rb:1201:in `lstat'
from /home/cstrom/.rvm/rubies/ruby-1.8.7-p249/lib/ruby/1.8/fileutils.rb:1179:in `stat'
from /home/cstrom/.rvm/rubies/ruby-1.8.7-p249/lib/ruby/1.8/fileutils.rb:1261:in `copy_file'
from /home/cstrom/.rvm/rubies/ruby-1.8.7-p249/lib/ruby/1.8/fileutils.rb:463:in `copy_file'
from /home/cstrom/.rvm/rubies/ruby-1.8.7-p249/lib/ruby/1.8/fileutils.rb:383:in `cp'
from /home/cstrom/.rvm/rubies/ruby-1.8.7-p249/lib/ruby/1.8/fileutils.rb:1396:in `fu_each_src_dest'
from /home/cstrom/.rvm/rubies/ruby-1.8.7-p249/lib/ruby/1.8/fileutils.rb:1412:in `fu_each_src_dest0'
from /home/cstrom/.rvm/rubies/ruby-1.8.7-p249/lib/ruby/1.8/fileutils.rb:1394:in `fu_each_src_dest'
from /home/cstrom/.rvm/rubies/ruby-1.8.7-p249/lib/ruby/1.8/fileutils.rb:382:in `cp'
from /home/cstrom/repos/faye/Jakefile:13
from /home/cstrom/repos/faye/Jakefile:12:in `each'
from /home/cstrom/repos/faye/Jakefile:12
...
Ugh. Before trying to solve this myself, I seem to recall that Isaac Schlueter (the npm guy) had a fork of faye on the github network graph. Sure enough, he does have a fork of faye and seems to have solved this problem.

I adapt the guide on forking and pulling upstream changes to pull in Isaac's changes instead. I add Isaac's repository as a remote repo and fetch it into my local git DB:
cstrom@whitefall:~/repos/faye$ git remote add npm git://github.com/isaacs/faye.git
cstrom@whitefall:~/repos/faye$ git fetch npm
remote: Counting objects: 14, done.
...
Then, I merge in Isaac's changes:
cstrom@whitefall:~/repos/faye$ git merge npm/master
Auto-merging package.json
Merge made by recursive.
Jakefile | 2 +-
Manifest.txt | 2 +-
package.json | 17 +++++++++--------
3 files changed, 11 insertions(+), 10 deletions(-)
Nice! That looks like it will fix my error and, sure enough, it does:
cstrom@whitefall:~/repos/faye$ jake
core src /build/core.js 30 kB
core min /build/core-min.js 15 kB
faye-browser src /build/faye-browser.js UP-TO-DATE
faye-browser min /build/faye-browser-min.js UP-TO-DATE
faye-node src /build/faye-node.js UP-TO-DATE
faye-node min /build/faye-node-min.js 30 kB
To install that with npm, I move into the build directory and use npm install:
cstrom@whitefall:~/repos/faye/build$ npm install .
npm it worked if it ends with ok
npm cli [ 'install', '.' ]
npm version 0.1.26
...
npm build Success: faye@0.5.2
npm ok
With that, I fire node-repl back up and it looks like all is well:
node> var faye = require("faye");
node> var client = new faye.Client("http://localhost:4011/faye");
node> var puts = require("sys").puts;
node> var subscription = client.subscribe("/foo", function(m) {puts("1"); asdf.foo.bar; puts("2");});
node> client.publish("/foo", "test 01")
node> 1
2010-08-24 20:59:13 [ERROR] [Faye.Transport] ReferenceError: asdf is not defined at [object Context]:1:69

Yay!

That is a fine stopping point for tonight. Tomorrow, I hope that I will not require these debugging aids, but I probably will.


Day #205

Monday, August 23, 2010

Isolating the Absence of Errors

‹prev | My Chain | next›

I figured out last night that functions in faye subscriptions are silently swallowing exceptions. I would like to see if there is anything I can do to give voice back to those errors.

But first, I upgrade to node.js 0.2.0 (backing up the previous install):
cstrom@whitefall:~/src$  tar zxf ../Downloads/node-v0.2.0.tar.gz
cstrom@whitefall:~/src$ cd node-v0.2.0/
cstrom@whitefall:~/src/node-v0.2.0$ ./configure --prefix=$HOME/local
cstrom@whitefall:~/src/node-v0.2.0$ mkdir /home/cstrom/local/bin/node.0.1.97
cstrom@whitefall:~/src/node-v0.2.0$ cp -p /home/cstrom/local/bin/node /home/cstrom/local/bin/node.0.1.97/
cstrom@whitefall:~/src/node-v0.2.0$ cp -p /home/cstrom/local/bin/node-repl /home/cstrom/local/bin/node.0.1.97/
cstrom@whitefall:~/src/node-v0.2.0$ cp -p /home/cstrom/local/bin/node-waf /home/cstrom/local/bin/node.0.1.97/
cstrom@whitefall:~/src/node-v0.2.0$ make
cstrom@whitefall:~/src/node-v0.2.0$ make install
cstrom@whitefall:~/src/node-v0.2.0$ node --version
v0.2.0
The only out-of-the-ordinary step in there is supplying a --prefix configure option. That allows me to install the code without root privileges.

With that, I am ready to track down what is happening to those exceptions. I still have my faye server running on 4011. In node-repl, I create a client, then subscribe to a "/foo" channel, supplying a callback that should throw an exception (accessing properties on an undefined variable). Lastly, I publish a message to the "/foo" channel to generate an exception:
node> var faye = require("faye");
node> var client = new faye.Client("http://localhost:4011/faye");
node> var puts = require("sys").puts;
node> client.subscribe("/foo", function(m) { puts("1"); asdf.foo.bar; puts("2"); });
node> client.publish("/foo", "bar");
Sure, enough, when I execute that code, I see output from the first puts, but not the second:
node> 1

Upgrading to the latest node had no effect. I did not really expect it to, but it was worth a shot.

So I start tracking down where the message is published. First I add some print STDERR debug code to Faye.Publisher:
  publishEvent: function() {
var args = Array.prototype.slice.call(arguments),
eventType = args.shift();

if (!this._subscribers || !this._subscribers[eventType]) return;

Faye.each(this._subscribers[eventType], function(listener) {
require("sys").puts("here 1");
listener[0].apply(listener[1], args);
require("sys").puts("here 2");
});
}
Sure enough, I reach the first statement, but not the second when I publish a message:
node> client.publish("/foo", "bar");
node> here 1
1
Ultimately, I work my way back up the stack to Faye.NodeHttpTransport and the request.addListener listener setup method:
    request.addListener('response', function(stream) {
response = stream;
Faye.withDataFor(response, function(data) {
try {
self.receive(JSON.parse(data));
} catch (e) {
require("sys").puts("swallowing nil");

retry();
}
});
});
With that, I see that I have successfully tracked down my exception swallower:
node> client.publish("/foo", "bar");
node> here 1
1
swallowing nil
I suspect that try block is more for handling errors in the JSON data or in the response itself. Certainly it does not expect the listener itself to be bad as it is not defending against my own bad code.

I will stop there for the night and plan to pick up tomorrow attempting to find a way to allow bad code exceptions to bubble up, while still retrying response errors.


Day #204

Sunday, August 22, 2010

Something is Swallowing Errors

‹prev | My Chain | next›

Something in the node.js / fab.js / faye stack in my (fab) game is swallowing errors silently. Tonight I hope to track down the culprit so that I mitigate problems in the future.

So I start with node.js. In node-repl, I create a function designed to cause a stack trace (by accessing properties on an undefined variable), then invoke it:
node> function invalid() { asdf.foo.bar; return 42; }
node> invalid()
ReferenceError: asdf is not defined
at invalid (repl:1:22)
at repl:1:1
at REPLServer.readline (repl:84:17)
at Stream.<anonymous> (repl:47:19)
at Stream.emit (events:25:26)
at IOWatcher.callback (net:378:14)
at node.js:204:9
OK, backtrace. So it is not node.js swallowing errors.

Let's try fab.js. I create a dirt-simple (fab) app that ought to crash in exactly the same way:
  ( /^\/crash_me/ )
( function() {
asdf.foo.bar;
this({body:"foo"})();
} )
Accessing the this resource with curl:
strom@whitefall:~/repos/my_fab_game$ curl -i http://localhost:4011/crash_me
curl: (52) Empty reply from server
...seems to crash the server. Sure enough, checking back in the backend, I find:
cstrom@whitefall:~/repos/my_fab_game$ ./game.js
/home/cstrom/repos/my_fab_game/game.js:61
asdf.foo.bar;
^
ReferenceError: asdf is not defined
at Function.<anonymous> (/home/cstrom/repos/my_fab_game/game.js:61:5)
at /home/cstrom/.node_libraries/fab/apps/fab.path.js:41:21
at Server.<anonymous> (/home/cstrom/.node_libraries/fab/apps/fab.nodejs.js:18:17)
at Server.<anonymous> (/home/cstrom/.node_libraries/.npm/faye/0.5.2/package/faye-node.js:1851:22)
at Server.emit (events:32:26)
at HTTPParser.onIncoming (http:813:10)
at HTTPParser.onHeadersComplete (http:88:31)
at Stream.ondata (http:745:22)
at IOWatcher.callback (net:373:31)
at node.js:204:9
Again, that crashes just like I expect it to.

So was it frustration-induced imagination that errors were being swallowed? Maybe it was caused in faye. I setup a simple subscription that will, again crash, then publish to that channel:
node> var faye = require("faye");
node> var client = new faye.Client("http://localhost:4011/faye");
node> client.subscribe("/foo", function () { puts("here 1"); asdf.foo.bar; puts("here 2"); });
node> client.publish("/foo", "foo");
node> here 1

Ah ha!

I hit my first print STDERR statement, but not my second. This is effectively how I had to debug my faye subscriptions last night—puts output before a line potentially causing a backtrace, then puts immediately after. Eventually, I track down the error.

It is good to know that I need to start with faye (last night, I thought it could be anywhere in my code). Still, it would be nice if I could have a little more help. Will the debug log level in faye help?
node> faye.Logging.logLevel = 'debug';

node> client.publish("/foo", "foo");
2010-08-22 21:14:07 [INFO] [Faye.Client] Calling deferred actions for "xpvtabh47g1a14frlitfwjuo7"
2010-08-22 21:14:07 [INFO] [Faye.Client] Client "xpvtabh47g1a14frlitfwjuo7" queueing published message to "/foo": "foo"
node> 2010-08-22 21:14:07 [DEBUG] [Faye.Transport] Client "xpvtabh47g1a14frlitfwjuo7" sending message to "http://localhost:4011/faye": [{"channel":"/foo","data":"foo","clientId":"xpvtabh47g1a14frlitfwjuo7","id":"1eje88w1kego8iao5wsy2ehkr0"}]
2010-08-22 21:14:07 [DEBUG] [Faye.Transport] Client "xpvtabh47g1a14frlitfwjuo7" received from "http://localhost:4011/faye": [{"id":"1eje88w1kego8iao5wsy2ehkr0","clientId":"xpvtabh47g1a14frlitfwjuo7","channel":"/foo","successful":true}]
2010-08-22 21:14:07 [DEBUG] [Faye.Transport] Client "xpvtabh47g1a14frlitfwjuo7" received from "http://localhost:4011/faye": [{"id":"nmb3fzfima6l1q3nz3jyh9ne4","clientId":"xpvtabh47g1a14frlitfwjuo7","channel":"/meta/connect","successful":true,"advice":{"reconnect":"retry","interval":0,"timeout":45000}},{"channel":"/foo","data":"foo","clientId":"xpvtabh47g1a14frlitfwjuo7","id":"1eje88w1kego8iao5wsy2ehkr0"}]
2010-08-22 21:14:08 [INFO] [Faye.Client] Closed connection for "xpvtabh47g1a14frlitfwjuo7"
2010-08-22 21:14:08 [INFO] [Faye.Client] Client "xpvtabh47g1a14frlitfwjuo7" calling listeners for "/foo" with "foo"
here 1
2010-08-22 21:14:08 [INFO] [Faye.Client] Calling deferred actions for "xpvtabh47g1a14frlitfwjuo7"
2010-08-22 21:14:08 [INFO] [Faye.Client] Initiating connection for "xpvtabh47g1a14frlitfwjuo7"
2010-08-22 21:14:08 [DEBUG] [Faye.Transport] Client "xpvtabh47g1a14frlitfwjuo7" sending message to "http://localhost:4011/faye": [{"channel":"/meta/connect","clientId":"xpvtabh47g1a14frlitfwjuo7","connectionType":"long-polling","id":"9ln0pm1ne24t417ym55kwdhzjl"}]
...
Sadly no. Just a bunch of information about the connection.

So there it is. Faye is swallowing exceptions and not crashing. I appreciate the latter, but the former bit me several times last night. The print STDERR / puts output that I have here is the only thing that saw me through last night. I hope for a better way than this, so I will explore that tomorrow.


Day #203

Saturday, August 21, 2010

Per Message Authorization in Faye

‹prev | My Chain | next›

Tonight, I continue in my attempt to lock down faye messages. I want to ensure that only the original client can sent subsequent updates about players in my (fab) game. With a hack in place allowing me to add server-side faye extensions to the fab.js backend in my (fab) game, I am ready to go. Hopefully...

The other night, before I realized that I realized I needed the faye+fabjs server-side hack, I had made a first attempt at a server-side faye extension that locked messages to clients:
   var serverAuth = {
incoming: function(message, callback) {
// Let non-subscription messages through
if (message.channel !== '/meta/connect')
return callback(message);

// Get subscribed channel and auth token
var subscription = message.subscription,
msgToken = message.ext && message.ext.authToken;

// If the message has a player ID
if (message.id) {

// If the player is already in the room
if (players.get_player(message.id)) {
puts("[token check] " + players.get_player(message.id).token + " " + msgToken);

// If the tokens do not match, stop the message
if (players.get_player(message.id).token != msgToken)
message.error = 'Invalid player auth token';
}
}
// Call the server back now we're done
callback(message);
}
};
Not surprisingly (but still disappointedly), that does not work. There is no failure in the backend, but I see 400 errors in the client. Time to roll up the sleeves.

Print STDERR debugging shows that messages are not getting past the first line in my extension:
        // Let non-subscription messages through
if (message.channel !== '/meta/connect')
return callback(message);
Ah, damn! What was I thinking? I want to ignore all "/meta" channel connections. I have no idea why I tried to secure "/meta/connect" channels (confused while debugging tcpdump output?). No matter, I get that working:
    // Let non-meta messages through
if (message.channel.indexOf('/meta/') === 0)
return callback(message);
Better.

Better, but still not working. Not working, and still no errors in the backend. I should probably turn on debug logging, but I stick with print STDERR debugging:
//...

for (var prop in message) {
puts(" " + prop + ": " + message[prop]);
}
if (message.data.id) {
puts(" checking for player: " + message.data.id);

//...
That first puts message is seen when the player moves about the room. The "checking for player" message is not:
  channel: /players/create
data: [object Object]
clientId: 1ghc65q12m3s078kwna91givtxo
id: wo5i0717pqv49svmkbc1qvhhl
Ah, that id attribute is not the player ID, it is the message ID. That means that what I think of as the message, what will be sent on to connected clients, is in the data attribute:
    // If the message has a player ID
if (message.data.id) {

// If the player is already in the room
if (players.get(message.data.id)) {

// If the tokens do not match, stop the message
if (players.get(message.id).token != msgToken)
message.error = 'Invalid player auth token';
}
}
puts("here!!!!");
// Call the server back now we're done
return callback(message);
Even there, I still have an error where I am trying to retrieve a player based on the message ID instead of the player ID:
        // If the tokens do not match, stop the message
if (players.get(message.player.id).token != msgToken)
message.error = 'Invalid player auth token';
What surprised me about that (and several other) failures is that the game did not crash, but swallowed the errors silently. When I try to lookup a player by the wrong ID, players.get() returns undefined. Accessing the tocken attribute on undefined should throw an error. In fact, the function seems to crash—subsequent print STDERR statements are not executed—but the node.js remains running silently swallowing would be errors. That behavior is something that I need to investigate (tomorrow—could be an old version of node?).

For now, I plow on through a few more silent failure / silly mistakes and eventually get my extension working with:
var serverAuth = {
incoming: function(message, callback) {
// Let non-meta messages through
if (message.channel.indexOf('/meta/') === 0)
return callback(message);

// Get subscribed channel and auth token
var subscription = message.subscription,
msgToken = message.ext && message.ext.authToken;

// If the message has a player ID
if (message.data.id) {

// If the player is already in the room
if (players.get(message.data.id)) {

// If the tokens do not match, stop the message
if (players.get(message.daa.id).token != msgToken) {
puts("rejecting mis-matched token message");
message.error = 'Invalid player auth token';
}
}
else {
message.data.authToken = msgToken;
}
}
// Call the server back now we're done
return callback(message);
}
};
The client-side faye extension that adds the auth token is similar, though it defines an outgoing callback:
  var clientAuth = {
outgoing: function(message, callback) {
// Leave non-data messages alone
if (message.channel.indexOf('/meta/') === 0)
return callback(message);

// Add ext field if it's not present
if (!message.ext) message.ext = {};

// Set the auth token
message.ext.authToken = self.uniq_id;

// Carry on and send the message to the server
return callback(message);
}
};
this.faye.addExtension(clientAuth);
With that, I can no longer move player Fred from Bob's Javascript Console and I get a nice little warning on the server side:



Yay!

It was a little touch and go there for a while. There were times at which I was not even sure it was possible, but I finally got it working. I still have a less-than-ideal hack to add faye server-side extensions in my custom built list_with_faye (fab) app. I doubt that this works if I reload the page. I am still more than a bit concerned about node silently swallowing errors.

But I still call it a night happy.


Day #202

Friday, August 20, 2010

Ugly Hack to Extend Fab.js Faye

‹prev | My Chain | next›

Tonight, I continue my efforts to ensure that player movement messages in my (fab) game can only come from the faye client that originally added the player to the game. In other words, if I enter the room as player Bob, I should not be able to broadcast to the game that player Fred quit.

The trouble facing me is that the faye server is established inside my custom fab.js app, listen_with_faye (a send-up of the built-into-fabjs listen function):
with ( require( "fab" ) )

( fab )

// Listen on the FAB port and establish the faye server
( listen_with_faye, 0xFAB )

...
If the faye server is completely encapsulated in that function, how can I add an extension to it?

Hmmm.... If I export that faye server from the listen_with_faye (fab) app, that ought to do the trick. I export that (using the commonjs convention) in the fab app:
var _faye_server = new faye.NodeAdapter({
mount: '/faye',
timeout: 45
});

exports.faye_server = _faye_server;
Then, in the my (fab) game backend, I import it:
faye_server = require( "fab/apps/fab.nodejs.listen_with_faye" ).faye_server;

var serverTap = {
incoming: function(message, callback) {
puts("here2");
return callback(message);
}
};

faye_server.addExtension(serverTap);
Nice and easy. Except it does not work—there is no output whatsoever from the backend when faye messages are published. Hmmmm...

What if I add my serverTap extension directly in the (fab) app?
exports.app = function( port ) {
var extension;
port.call( function( obj ){ port = obj.body; } );

return function( app ) {
var server = require( "http" )
.createServer( fab.nodejs( app ) );

_faye_server.attach(server);

server.listen(port);

var serverTap = {
incoming: function(message, callback) {
puts("here1");
return callback(message);
}
};
_faye_server.addExtension(serverTap);


return app;
};
};
That works as expected. When faye messages are published, I now see:
here1
here1
here1
here1
here1
After much head scratching, I eventually realize that my import in the backend:
    faye_server = require( "fab/apps/fab.nodejs.listen_with_faye" ).faye_server;
...is pulling in a separate instance of the faye server than is being used to actually connect to the fabjs server.

Ick.

I briefly toy with the idea of fiddling with singletons, but I have no idea if that can work in commonjs land. Besides: singleton.

Instead, I implement a completely different kind of bad hack. Along with the port number, I also allow the faye extension to be supplied in the listen_with_faye app:
exports.app = function( port ) {
var extension;
port.call( function( obj ){
if (typeof obj.body === 'number') {
port = obj.body;
}
else {
port = obj.body.port;
extension = obj.body.extension;
}

} );

return function( app ) {
var server = require( "http" )
.createServer( fab.nodejs( app ) );

_faye_server.attach(server);

server.listen(port);

if (extension) addExtension(extension);

return app;
};
};
Bleck. Well, that is a bit much, but it does work. When I start up my server as:
var serverTap = {
incoming: function(message, callback) {
puts("here2");
return callback(message);
}
};


with ( require( "fab" ) )

( fab )

// Listen on the FAB port and establish the faye server
( listen_with_faye, { port: 0xFAB, extension: serverTap } )

...
Moving around a bit, I find that I am finally hitting my serverTap extension:
cstrom@whitefall:~/repos/my_fab_game$ ./game.js
here2
here2
here2
...
At this point, my brain is pretty well fried, so I am hard pressed to come with a better way to accomplish this. If nothing else, the listen_with_faye (fab) app with an object is serviceable. I may leave this as-is for a bit so that I can get on with the business of securing my messages.

But first, sleep.


Day #201

Thursday, August 19, 2010

Per Message Authorization in Faye (Take 1)

‹prev | My Chain | next›

Currently in my (fab) game, I can use player Bob's Javascript Console to move player Fred:



I would like to ensure that only Fred's browser can move Fred.

Borrowing from the excellent faye documentation, I come up with this extension on the client side:
  this.faye = new Faye.Client('/faye');

var self = this;
var clientAuth = {
outgoing: function(message, callback) {
// Leave non-data messages alone
if (message.channel !== '/meta/connect')
return callback(message);

// Add ext field if it's not present
if (!message.ext) message.ext = {};

// Set the auth token
message.ext.authToken = self.uniq_id;

// Carry on and send the message to the server
return callback(message);
}
};
this.faye.addExtension(clientAuth);
Hopefully that is fairly self-explanatory. If the message is sent on a data channel (i.e. not a subscription channel), then I add the player's unique ID as an authToken message extension.

On the server side, I add code that includes the original authToken to the player store, then check subsequent messages to see if the messages include the same authToken. If not, I add an error to the message, which prevents it from being sent to attached clients:

var self = this;
var serverAuth = {
incoming: function(message, callback) {
// Let non-channel messages through
if (message.channel !== '/meta/connect')
return callback(message);

// Get subscribed channel and auth token
var subscription = message.subscription,
msgToken = message.ext && message.ext.authToken;

if (message.id) {
if (self.get_player(message.id)) {
puts("[token check] " + self.get_player(message.id).token + " " + msgToken);
if (self.get_player(message.id).token != msgToken)
message.error = 'Invalid player auth token';
}
}
// Call the server back now we're done
callback(message);
}
};

this.faye.addExtension(serverAuth);
That does not work. The code does not crash, but nothing changes. Player Bob can still move Fred from the Javascript Console.

It takes me a while to figure this one out, but ultimately, it comes to me: I did not add the serverAuth extension to the server. I added it to a client on the server side! D'oh!

Unfortunately, I do not have an easy answer for this. I am using a custom fab.js app to establish the faye server in my (fab) game:
with ( require( "fab" ) )

( fab )

// Listen on the FAB port and establish the faye server
( listen_with_faye, 0xFAB )


//...
I cannot get access to that server anywhere in the game. At least not as-is. Sigh.

I will circle back to that tomorrow. For now, I would like to make sure that other clients are not able to see faye message extensions—especially authorize tokens. Looking a tcpdump output, I can see the message extension being sent to the server:
21:59:10.137072 IP whitefall.38982 > whitefall.4011: Flags [P.], seq 420:745, ack 199, win 513, options [nop,nop,TS val 44612313 ecr 44612313], length 325
0x0000: 4500 0179 e69c 4000 4006 54e0 7f00 0001 E..y..@.@.T.....
0x0010: 7f00 0001 9846 0fab c5e0 5de9 c64e 7519 .....F....]..Nu.
0x0020: 8018 0201 ff6d 0000 0101 080a 02a8 bad9 .....m..........
0x0030: 02a8 bad9 005b 7b22 6368 616e 6e65 6c22 .....[{"channel"
0x0040: 3a22 2f70 6c61 7965 7273 2f6d 6f76 6522 :"/players/move"
0x0050: 2c22 6461 7461 223a 7b22 6964 223a 2262 ,"data":{"id":"b
0x0060: 6f62 222c 2278 223a 3435 372c 2279 223a ob","x":457,"y":
0x0070: 3230 357d 2c22 636c 6965 6e74 4964 223a 205},"clientId":
0x0080: 2234 766c 3634 7831 3664 6965 346e 3167 "4vl64x16die4n1g
0x0090: 6e73 676b 7871 3732 3872 6a22 2c22 6964 nsgkxq728rj","id
0x00a0: 223a 226a 6b71 3073 6c31 6772 7777 7832 ":"jkq0sl1grwwx2
0x00b0: 7471 3235 6366 7064 3578 3469 227d 2c7b tq25cfpd5x4i"},{
0x00c0: 2263 6861 6e6e 656c 223a 222f 6d65 7461 "channel":"/meta
0x00d0: 2f63 6f6e 6e65 6374 222c 2263 6c69 656e /connect","clien
0x00e0: 7449 6422 3a22 3476 6c36 3478 3136 6469 tId":"4vl64x16di
0x00f0: 6534 6e31 676e 7367 6b78 7137 3238 726a e4n1gnsgkxq728rj
0x0100: 222c 2263 6f6e 6e65 6374 696f 6e54 7970 ","connectionTyp
0x0110: 6522 3a22 7765 6273 6f63 6b65 7422 2c22 e":"websocket","
0x0120: 6964 223a 2231 7461 6a38 7531 6a78 3434 id":"1taj8u1jx44
0x0130: 3434 3135 7339 756d 7875 3736 3871 6b22 4415s9umxu768qk"
0x0140: 2c22 6578 7422 3a7b 2261 7574 6854 6f6b ,"ext":{"authTok
0x0150: 656e 223a 2262 6f62 2d34 3933 3222 7d2c en":"bob-4932"},
0x0160: 2261 6476 6963 6522 3a7b 2274 696d 656f "advice":{"timeo
0x0170: 7574 223a 307d 7d5d ff ut":0}}].
Happily, when I check in the browser, I only see the message, not the extension:



As I have come to expect, faye is doing the right thing on my behalf. This means, I believe, that my overall approach is sound. I just need access to the faye server to add the extension. That will be on tap for tomorrow.


Day #200

Wednesday, August 18, 2010

Preliminary Investigation into Securing Faye Messages

‹prev | My Chain | next›

I am doing some quick investigation of faye messages tonight. I would like to explore the possibility of ensuring that faye messages in my (fab) game describing player activity can only come from the client that originally added the player to the room. Right now there is nothing player Bob from telling the world that player Fred moved to coordinates -100,-100.

My first stopping point in my investigation is tcpdump. Maybe faye is already sending client identifying information along with its messages. Sure enough, it looks as though it is:
cstrom@whitefall:~/repos/my_fab_game$ sudo tcpdump -i lo -X -s 0 port 4011
tcpdump: verbose output suppressed, use -v or -vv for full protocol decode
listening on lo, link-type EN10MB (Ethernet), capture size 65535 bytes
21:35:18.952622 IP whitefall.local.43436 > whitefall.local.4011: Flags [P.], seq 1644034536:1644034678, ack 1642986690, win 770, options [nop,nop,TS val 25728832 ecr 25722550], length 142
0x0000: 4500 00c2 6ec4 4000 4006 46f5 c0a8 0196 E...n.@.@.F.....
0x0010: c0a8 0196 a9ac 0fab 61fd f9e8 61ed fcc2 ........a...a...
0x0020: 8018 0302 8531 0000 0101 080a 0188 9740 .....1.........@
0x0030: 0188 7eb6 005b 7b22 6368 616e 6e65 6c22 ..~..[{"channel"
0x0040: 3a22 2f70 6c61 7965 7273 2f6d 6f76 6522 :"/players/move"
0x0050: 2c22 6461 7461 223a 7b22 6964 223a 2266 ,"data":{"id":"f
0x0060: 7265 6422 2c22 7822 3a32 3833 2c22 7922 red","x":283,"y"
0x0070: 3a32 3030 7d2c 2263 6c69 656e 7449 6422 :200},"clientId"
0x0080: 3a22 3139 3164 7531 6731 7432 6536 6b6d :"191du1g1t2e6km
0x0090: 3132 6233 3678 6f61 3831 3031 3122 2c22 12b36xoa81011","
0x00a0: 6964 223a 226f 3265 7462 6e6f 386a 3469 id":"o2etbno8j4i
0x00b0: 7031 3971 6c7a 6f31 6c6c 7479 6779 227d p19qlzo1lltygy"}
0x00c0: 5dff
I tend to doubt that this client information is sent along with the message for subscribers to use. Before I check, I dig through the faye client object to see where that clientId attribute might be. Unfortunately, I do not find it:



That _0 attribute is completely different than the ID that I saw in the tcpdump output. Even if it were the same, it feels like a private attribute and I see no public methods that would suggest that they describe the client ID.

That seems to be a dead-end. It may seem like sour grapes, but I doubt that the server would have had access to that client ID anyway, so what to try? It is possible to accomplish what I want here?

After digging through the faye site a bit, I rediscover documentation about security code locking down channels with a security code. It occurs to me that I might be able to do something similar, but with messages. A faye extension in the client can calculate a security code when the player first enters the room and embed it in an ext attribute of the message. The server can then extract that ext attribute and check it against the value that it has stored in the local player store. As long as the two match, the server allows the message.

The only thing that might not work there is reloading the page (how to make the code unique to a player, but survive browser reloads? cookies?). I will pursue this more tomorrow.


Day #199

Tuesday, August 17, 2010

Best Bug Finding Technique: Idle a While

‹prev | My Chain | next›

While debugging my (fab) game last night, I found myself with idle timeout issues. It seemed as though things got into an odd state where as soon I entered the room, my player was logged out immediately. It go so bad that as soon as any player timed out, I restarted the game.

To troubleshoot tonight, I set the timeout in the fab.js backend to 30 seconds:
  idle_watch: function(id) {
if (this._[id].idle_timeout) {
clearTimeout(this._[id].idle_timeout);
}

var self = this;
this._[id].idle_timeout = setTimeout(function() {
puts("timeout " + id +"!");
self.drop_player(id);
}, 30*1000);

this._[id].idle_watch_started = "" + (new Date());
}
That idle_watch method seems solid. If player ID is already in the list of players (this._) then I clear the timeout. Next, I set a timeout, 30 seconds now, after which the player is dropped.

So I give it a try. I log in, wait and I get logged out. I log back in, then wait another 30 seconds and I get logged out again. Dang. I hate it when things work (when I do not expect them to).

Next, I try to move around after entering the room. When messages are received on the "/players/move" faye channel, the update_player_status() method is invoked, which updates the idle status:
  update_player_status: function(status) {
if (this._[status.id]) {
puts("[update_player_status] " + status.id);
this._[status.id].status = status;
this.idle_watch(status.id);
}
else {
puts("[update_player_status] unknown player: " + status.id + "!");
}
}
And that works too. If I move around the room for a minute or two, then pause, after 30 seconds, the player is timed out. Logging back in, it just works. Dang.

For a little while, I begin to think that last night's woes were a figment of my imagination. But I did not imagine that frustration. Something is going wrong.

After idling a while myself, it hits me. The difference between what I am doing now and last night is reloading. I was making code changes and reloading the browser to see how they fared. Tonight, I am just waiting, expecting the code to fail. Sure enough, when I log in, wait for 20 seconds then reload, my player is almost immediately logged out.

I did not see it at first, but the problem is in the add_player() method in the backend:
  add_player: function(player) {
var new_id = player.id;
this._[new_id] = {
status: player,
uniq_id: player.uniq_id
};
this.idle_watch(new_id);
}
When the page reloads, a new faye message is broadcast about the same player. That message is picked up in the backend and passed along to add_player(). This method creates a new entry in the running tally of all players (stored in this._). The new entry completely ignores the old entry, including the reference to the old timeout. The reference to the old timeout may be gone, but the old timeout is still about, counting down and eager to drop the player and with no means of stopping it.

Worse of all, after I wipe the old player status + idle timeout away, I start a new idle_watch(). That ensures that, should I log back in, I will be logged out immediately.

Stupid really.

The easy solution here is to check first for a player entry:
  add_player: function(player) {
var new_id = player.id;
if (!this._[new_id])
this._[new_id] = {};
this.update_player_status(player);
}
I also realize that update_player_status() does most of what add_player() had been doing anyway. With that knowledge, I DRY things up and get it working (verified by reloading, moving, reloading, waiting 30 seconds, getting logged out, then logging back in).

I am more than a little abashed at that silly mistake, but I think this resolved it rather nicely.

Up tomorrow, adding a little security to the faye communications so that clients cannot send messages masquerading as other players.


Day #198

Monday, August 16, 2010

Finishing (hopefully) Touches on Collisions with Faye

‹prev | My Chain | next›

I got collision handling in my (fab) game accommodating faye latency. I did so my making my player larger, slower and detecting collisions at the edge of the player in the direction in which the player is moving.

In the end, the players are a tad large (40 pixels wide in a 500 pixel room) and sluggish (requiring 10 seconds from corner to corner). So first up, I put the player on a diet and move them a little faster:
Player.radius = 15;
Player.shadow_distance = Player.radius + 10;
Player.max_walk = Math.sqrt(500*500 + 500*500);
Player.time_to_max_walk = 8 * 1000;
With that, I need to extend the collision point forward a bit—in essence signal a collision before the collision occurs. That will lead to some phantom strikes, but hopefully nothing too bad. Let's try adding about 10%:
    var c_x = avatar.attr("cx") +
$(self.avatar.paper.canvas).parent().offset().left -
$(document).scrollLeft() +
1.1 * self.direction.x * Player.radius;

var c_y = avatar.attr("cy") +
$(self.avatar.paper.canvas).parent().offset().top -
$(document).scrollTop() +
1.1 * self.direction.y * Player.radius;
That seems to work, except when the player is moving downward in the room. In that case, the extended collision point is overlapping with the player's label. To resolve that, I add an attribute to the player object:
Player.prototype.attach_avatar = function(avatar) {
//...
avatar.node.is_player_circle = true;
//...
}
And use that to ensure that the object that raphaël.js is telling me that is in collision is a player circle:
    if (!self.initial_walk &&
!self.mid_bounce &&
c_el.is_player_circle &&
c_el != self.avatar.node) {
self._bounce_away(c_x, c_y);
}
That actually solves a bit of a problem that I have had in the code for a while—how to test for collisions with "collidable" objects. If there need to be more objects that can collide, then I can test for that attribute. Previously, I had been testing there that the colliding object was not the raphaël paper itself. The new condition handles that case nicely as well (the paper does not have that attribute set).

With that, I still have one minor change that still needs to take place: the bounce away from the collision needs to be a bit further than it had been (the radius of a player). Trial and error suggests that the player radius plus 50% should do:
Player.prototype._bounce_away = function(from_x, from_y) {
this.mid_bounce = true;

var x = from_x - 1.5*Player.radius*this.direction.x,
y = from_y - 1.5*Player.radius*this.direction.y;

this.faye.publish('/players/bounce', {id: this.id, x: x, y: y});
};
That gives me fairly decent collisions, well represented in both my browser and in the browser of other players:



I think I will leave well enough alone at this point. The idle timeout seems to be acting up on me again, so I will look into that a bit more tomorrow before moving onto other things.


Day #197

Sunday, August 15, 2010

Mitigating Faye Latency in Games

‹prev | My Chain | next›

Today, I continue exploring ways to mitigate faye latency as it affects my (fab) game. As noted yesterday, there is a 200 millisecond delay between publishing messages to a faye channel and the message reaching a subscribing function. This has almost no effect in my (fab) game other than collision detection:



The collision is seen much earlier in my player's screen than it is seen on the screens of other players. I have already blindly moved code about in a vain attempt to solve the latency issue. Before moving more code about, a look at the problem I am facing.

As mentioned, there is a 200 millisecond latency in faye communication. Looking at the client-side code, I find some more constraints:
Player.radius = 10;
Player.shadow_distance = 20;
Player.max_walk = Math.sqrt(500*500 + 500*500);
Player.time_to_max_walk = 5 * 1000;
From that, I can determine the speed at which my players can move in the room. The max_walk distance evaluates to 707.1 pixels. If the player takes 5 seconds to make that walk, then the speed is 141.2 pixels/second. Thus, during the 200 millisecond latency, the player will travel 28.2 pixels. That is a little more than the diameter of a player. That pretty much explains the delay that I am seeing.

So how can I mitigate the problem? One thing I can do is slow down the players. If I halve the speed at which players move, then players will travel 14 pixels during the faye latency. That still seems too much since the diameter of a player is 20 pixels. Hrm... well, I could double the size of a player as well:
Player.radius = 20;
Player.shadow_distance = 30;
Player.max_walk = Math.sqrt(500*500 + 500*500);
Player.time_to_max_walk = 10 * 1000;
What will that do?



That is still not good enough. The player is almost completely overlapping the other when the bounce is signaled. It is at this point that I realize part of the problem is that I am detecting a collision at the center of my player. If it were possible to detect a collision at the edge in which the player is moving, things might work better. That is, if the player is moving to the right, then I should try detecting collisions at the center x coordinate plus the radius of the player.

As luck would have it, I am already storing the direction in which a player is moving (so that the bounce away can be in the opposite direction). I can use that to detect edge collisions:
    var c_x = avatar.attr("cx") +
$(self.avatar.paper.canvas).parent().offset().left -
$(document).scrollLeft() +
self.direction.x * Player.radius;

var c_y = avatar.attr("cy") +
$(self.avatar.paper.canvas).parent().offset().top -
$(document).scrollTop() +
self.direction.y * Player.radius;
With that my collisions are actually rather good:



That is a fine stopping for tonight. Tomorrow, I will consider alternatives I have not thought up just yet and hopefully drive toward an all-around satisfying solution. But this is pretty close.


Day #196

Saturday, August 14, 2010

Faye Latency

‹prev | My Chain | next›

Tonight, I continue my investigation into latency in faye. This latency manifests itself in my (fab) game collisions:



On my screen, the reaction to a collision is much faster than on the screens of other players. I tried shifting code about to resolve the issue, without luck.

I will use the node-repl to investigate tonight. I establish a faye subscription to a "/test" channel and then send a message on that same channel. When the message is received, I store the time and when the message is sent, I record the time. The difference should be the latency built-in:
node> var faye = require("faye");
node> var client = new faye.Client('http://localhost:4011/faye');
node> var d1, d2;
node> var s = client.subscribe('/test', function(message) {puts(message); d2 = new Date()});
node> client.publish('/test', 'test'); d1 = new Date();
Sat, 14 Aug 2010 08:47:39 GMT
node> d2

Hunh? The variable d2, declared with global scope, should have been set when the subscribed channel received the message. In fact, the puts() statement inside the subscription function proves that the message was received. What gives?

Trying this in a more generic setting, I find that function scope is not able to affect a variable declared outside of it:
node> var foo = "bar";
node> function fn() { foo = "foo"; }
node> foo
'bar'
node> fn();
node> foo
'bar'
That same code works as I expect in the browser:



Dang, looks like different global variable semantics in node-repl. Luckily, a global object will work in node-repl:
node> var faye = require("faye");
node> var client = new faye.Client('http://localhost:4011/faye');
node> var dates={};
node> var s = client.subscribe('/test', function(message) {dates['received'] = new Date()});
node> client.publish('/test', 'test'); dates['sent'] = new Date();
Sat, 14 Aug 2010 08:58:39 GMT
After that, I have both sent and received attributes in my global object:
node> dates
{ sent: Sat, 14 Aug 2010 08:58:39 GMT
, received: Sat, 14 Aug 2010 08:58:40 GMT
}
Those are date values, not strings, so I can do simple arithmetic on them to see how long it takes for the round trip message:
node> dates['received'] - dates['sent']
217
Hmmm... 200 milliseconds. That might account for the delay that I am seeing. To make sure that is not a one time only thing, I run the numbers a few more times:
node> client.publish('/test', 'test'); dates['sent'] = new Date();
Sat, 14 Aug 2010 08:59:27 GMT
node> dates['received'] - dates['sent']
215
node> client.publish('/test', 'test'); dates['sent'] = new Date();
Sat, 14 Aug 2010 08:59:30 GMT
node> dates['received'] - dates['sent']
212
node> client.publish('/test', 'test'); dates['sent'] = new Date();
Sat, 14 Aug 2010 08:59:35 GMT
node> dates['received'] - dates['sent']
211
node> client.publish('/test', 'test'); dates['sent'] = new Date();
Sat, 14 Aug 2010 08:59:40 GMT
node> dates['received'] - dates['sent']
212
node> client.publish('/test', 'test'); dates['sent'] = new Date();
Sat, 14 Aug 2010 08:59:43 GMT
node> dates['received'] - dates['sent']
212
Yup. That's consistently 200+ milliseconds. And that is just on my local machine. What is going to happen when this is happening over Internet connections? I thought I might have to deal with this back when I was passing messages over comet. Now I cannot avoid it if I am going to continue pursuing faye message passing.

And I will get started on mitigating this problem tomorrow.

Day #195