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