Latest Tweet

6

Alright, so I’m deploying some new code at PageLever to move our Facebook sync code to node.js. I’ve just slaved over it for a few weeks, creating a queue/worker system (to be publicly released soon) that keeps track of lots of stats and more importantly errors. Very very important to see our errors. Is the problem with us or Facebook?  Have we hit our API limits again?  Did I fat-finger yet another FQL statement?  You know, the vital stuff.

So now I’ve pushed it out there and started up a bunch of workers and I’m monitoring all of them. I start getting a few errors trickling in. No problem, this happens. Let’s check out what they say.

Error: socket hang up
    at Object. (http.js:1124:15)
    at CleartextStream. (http.js:1173:23)
    at CleartextStream.emit (events.js:64:17)
    at Array. (tls.js:792:22)
    at EventEmitter._tickCallback (node.js:190:38)

So that’s really not very helpful. Like not in any way, shape or form. So what to do, what to do… A little googling and I found the awesome long-stack-traces module by Tom Robinson. It’s a very cool bit of code that wraps all async callbacks (even within the core libraries!) with a bit of code to save the current stack trace. I stuck a simple require('long-stack-traces') into an initializer in my code and voila!  Now my stack traces looked more like this.

Error: socket hang up
    at Object. (http.js:1124:15)
    at CleartextStream. (http.js:1173:23)
    at CleartextStream.emit (events.js:64:17)
    at Array. (tls.js:792:22)
    at EventEmitter._tickCallback (node.js:190:38)
---------------------------------------------
    at Facebook._executeRequest (/app/node_modules/facebook.node/node_modules/rest.node/index.js:109:7)
    at Facebook.request (/app/node_modules/facebook.node/node_modules/rest.node/index.js:154:8)
    at Facebook.get (/app/node_modules/facebook.node/node_modules/rest.node/index.js:160:8)
    at Facebook.fql (/app/node_modules/facebook.node/index.js:67:8)
    at PostFetcher.fetch_posts (/app/lib/post_fetcher.coffee:31:21)
    at Object. (/app/lib/register_worker_commands.coffee:58:25)
    at Object. (/app/lib/queue_worker_child.coffee:35:14)
    at EventEmitter. (/app/lib/queue_worker_child.coffee:47:12)
    at QueueWorker.error (/app/lib/queue_worker.coffee:177:15)
    at ChildProcess. (/app/lib/queue_worker.coffee:149:24)
    at ChildProcess. (events.js:156:14)
    at ChildProcess.emit (events.js:88:20)
    at Pipe.onread (child_process.js:102:16)
---------------------------------------------
    at Object. (/app/lib/queue_processor.coffee:62:10)
    at Object. (/app/lib/queue_processor.coffee:73:4)
    at Module._compile (module.js:446:26)
    at Object..coffee (/app/node_modules/caboose/node_modules/coffee-script/lib/coffee-script/coffee-script.js:22:21)
    at Module.load (module.js:353:31)
    at Function._load (module.js:311:12)
    at Module.require (module.js:359:17)
    at Object. (module.js:375:17)

Ooooooooo!!!!  Guess what!  It was an FQL call that hung up on me. No more blaming MongoDB. OK, good.

The Rub

Now we’re golden, right?  Well, not exactly. There seems to be an issue with this implementation of long stack traces. My http server wouldn’t start up. I found this issue that echoed my problem, and hacked in the solution. Yay once again!

Not so fast!  Now when I run my workers, all of my EventEmitter callbacks get called multiple times. Two times. Three times. Four?  Five?  WTF is going on?  OK, more research. Turns out, long-stack-traces doesn’t implement removeListener. Ahhhhhh, I see now. Hmm, the project hasn’t been updated in a year. I could have sent a message to tlrobinson, but you know what, I need this to work today. I’ll just write it.

Introducing longjohn

So I wrote it. It worked. A few days later, I made it a bit neater, exposed some options, published it to npm and posted it on github. Maybe it’ll be useful to you. Maybe not.

Just install longjohn with

$ npm install longjohn

Then somewhere in the initialization of your node app (or just at the top of your script) add

require('longjohn');

Now your stack traces will be nice and long. You say you want to customize something. Want some options? We’ve got options.

Options

The method used to track async callbacks adds some memory overhead if your code looks something like this:

function foo() {
  // do something
  setTimeout(foo, 1000);
}
foo();

You can see that this will wrap every single callback for eternity, keeping around stack traces that node would normally forget about. This is BAAAAD!  To solve this, longjohn will automatically prune the traces kept to the last 10 async callbacks. In order to change this limit, set async_trace_limit.

var longjohn = require('longjohn');
longjohn.async_trace_limit = 5;  // defaults to 10
longjohn.async_trace_limit = -1; //unlimited

Another option is to customize the output for an async callback boundary. By default longjohn will print out a bunch of dashes to represent a callback boundary. Change this by setting empty_frame.

var longjohn = require('longjohn');
longjohn.empty_frame = 'ASYNC CALLBACK';

Nice side-effect

Due to the fact that I’m using the same exact output as long-stack-traces, felixge’s node-stack-trace module can parse the output if you’d like your stack traces in object form. Here’s how to do it.

require('stack-trace').parse(err);

Enjoy!

blog comments powered by Disqus
  1. bankedtrackrollerderby reblogged this from matt-insler
  2. jonbaer reblogged this from matt-insler and added:
    Alright, so I’m deploying some new code at PageLever to move our Facebook sync code to node.js. I’ve just slaved over it...
  3. matt-insler posted this