Node.js

Acking messages with node-amqp

Graham HayLeave a comment

The documentation for node-amqp is pretty good, but I couldn’t find a good example of how to ack messages once some work has been done:

        var queueOpts = {
            durable: true,
            autoDelete: false
        };
        connection.queue('foo.bar', queueOpts, function (queue) {
            var subscriptionOpts = {
                ack: true,
                prefetchCount: 10
            };
            queue.subscribe(subscriptionOpts, function (message, headers, deliveryInfo, ack) {
                doWork(message).then(function() {
                    ack.acknowledge();
                }).fail(function(err) {
                    ack.reject(true);
                });
            });
        });

Remember, this just returns the message to the queue; so you’d probably want to track the number of attempts at processing it, and use a dead letter queue, to avoid poison messages.

Any messages not acked will be requeued when the connection is closed (you can check for them using the management plugin). Bear in mind that using acknowledgements only guarantees at least once delivery, so make sure your handlers are idempotent!

Spin wait in node.js

Graham HayLeave a comment

When writing acceptance tests, you often need to wait for something to happen. The easy thing to do is just wait for a certain period of time before checking, but that can make your tests slower than necessary. The accepted solution is to poll for whatever it is that you’re waiting for.

C# has a handy SpinWait.SpinUntil method, and I found this node module with similar behaviour. I needed it to work with promises though, so I ended up writing my own:

var DEFAULT_TIMEOUT = 5000;

function waitUntil (predicate, done, timeout, started) {
    timeout = defaultParameter(timeout, DEFAULT_TIMEOUT);
    started = defaultParameter(started, Date.now());

    predicate().done(function(res) {
        if (res) {
            return done();
        }

        if ((started + timeout) < Date.now()) {
            throw new Error("timed out");
        }

        setTimeout(function() {
            waitUntil(predicate, done, timeout, started);
        }, 100);
    });
};

function defaultParameter (parameter, defaultValue) {
    if (typeof(parameter) === 'undefined') {
        return defaultValue;
    }
    return parameter;
};

module.exports.waitUntil = waitUntil;

The first argument needs to be a predicate function, that returns a promise; and the second will be called if the first ever succeeds. You can also change the default timeout (5s). Something like this:

SpinWait.waitUntil(function() {
    return getAllTransactions(USER_ID).then(function(data) {
        return data.rows.length > 0;
    });
}, function() {
    getAllTransactions(USER_ID).done(function(data) {
        assert.equal(1, data.rows.length);
        var transaction = data.rows[0];
        assert.equal(1000, transaction.amount);
        done();
    });
});

LogStash & Bunyan, a match made in heaven

Graham Hay4 Comments

Every platform has a plethora of logging libraries; each with their own good points, and bad points. The first node.js library we tried was winston. It had all the usual features: multiple logging levels, different outputs (we actually just use stdout, and the daemon pipes it to a logfile); but in production we wanted to use logstash to aggregate and parse the logs.

Unfortunately winston suffers from a common problem: exception stack traces are split across multiple lines. It should be possible to use the multiline codec to merge the lines, but around this time I ran across bunyan.

The manifesto from Joyent explains the merits of logging in json (or some other machine parseable format), and it’s very easy to configure a logstash file input for a json file just by setting the codec:

input {
    file {
        type => "foo-app"
        path => [ "/var/log/foo-app/*.log" ]
        codec => "json"
    }   
}

Now, when your logs are shipped to the logstash server, each field will be indexed individually without needing to grok any crazy patterns.

It’s also very simple to add fields to the logger at runtime:

var logger = bunyan.createLogger({
    name: name,
    stream: process.stdout,
    level: 'info',
    anExtraField: 'foo'
});

...

logger.fields.anotherExtraField = 'bar';

which will also be searchable in logstash; making it easy to trace a request across multiple services, for example.

UPDATED: to add some sample output

{"name":"foo","hostname":"pikachu","pid":7645,"level":30,"msg":"Listening on port 1234","time":"2014-08-12T16:14:19.667Z","v":0}
{"name":"foo","hostname":"pikachu","pid":7645,"level":30,"msg":"Service started","time":"2014-08-12T16:14:19.673Z","v":0}
{"name":"foo","hostname":"pikachu","pid":7645,"level":30,"msg":"Received request for abc","time":"2014-08-12T16:32:28.600Z","v":0}
{"name":"foo","hostname":"pikachu","pid":7645,"level":50,"msg":"ERROR: bad request","time":"2014-08-12T16:32:28.600Z","v":0}

As the levels are integers (e.g. 30 => INFO), you can ask logstash for all entries where level >= ? (e.g. all ERRORs & FATALs).

Error building node module in a Vagrant box with NFS

Graham HayLeave a comment

I was trying, and failing, to install node-heapdump:

vagrant@debian7:/vagrant$ npm install heapdump
npm WARN package.json execSync@1.0.1-pre No repository field.
npm http GET https://registry.npmjs.org/heapdump
npm http 304 https://registry.npmjs.org/heapdump

> heapdump@0.2.7 install /vagrant/node_modules/heapdump
> node-gyp rebuild

make: Entering directory `/vagrant/node_modules/heapdump/build'
  CXX(target) Release/obj.target/heapdump/src/heapdump.o
  CXX(target) Release/obj.target/heapdump/src/platform-posix.o
  SOLINK_MODULE(target) Release/obj.target/heapdump.node
flock: ./Release/linker.lock: No locks available
make: *** [Release/obj.target/heapdump.node] Error 71
make: Leaving directory `/vagrant/node_modules/heapdump/build'
gyp ERR! build error 
gyp ERR! stack Error: `make` failed with exit code: 2
gyp ERR! stack     at ChildProcess.onExit (/home/vagrant/.nvm/v0.10.26/lib/node_modules/npm/node_modules/node-gyp/lib/build.js:267:23)
gyp ERR! stack     at ChildProcess.EventEmitter.emit (events.js:98:17)
gyp ERR! stack     at Process.ChildProcess._handle.onexit (child_process.js:797:12)
gyp ERR! System Linux 3.2.0-4-686-pae
gyp ERR! command "node" "/home/vagrant/.nvm/v0.10.26/lib/node_modules/npm/node_modules/node-gyp/bin/node-gyp.js" "rebuild"
gyp ERR! cwd /vagrant/node_modules/heapdump
gyp ERR! node -v v0.10.26
gyp ERR! node-gyp -v v0.12.2
gyp ERR! not ok 
npm ERR! heapdump@0.2.7 install: `node-gyp rebuild`
npm ERR! Exit status 1
npm ERR! 
npm ERR! Failed at the heapdump@0.2.7 install script.
npm ERR! This is most likely a problem with the heapdump package,
npm ERR! not with npm itself.
npm ERR! Tell the author that this fails on your system:
npm ERR!     node-gyp rebuild
npm ERR! You can get their info via:
npm ERR!     npm owner ls heapdump
npm ERR! There is likely additional logging output above.

npm ERR! System Linux 3.2.0-4-686-pae
npm ERR! command "/home/vagrant/.nvm/v0.10.26/bin/node" "/home/vagrant/.nvm/v0.10.26/bin/npm" "install" "heapdump"
npm ERR! cwd /vagrant
npm ERR! node -v v0.10.26
npm ERR! npm -v 1.4.3
npm ERR! code ELIFECYCLE
npm ERR! 
npm ERR! Additional logging details can be found in:
npm ERR!     /vagrant/npm-debug.log
npm ERR! not ok code 0

A github issue suggested that cloning the repo, and running node-gyp rebuild, might give a better error. But that succeeded. Searching for the error message: “flock: ./Release/linker.lock: No locks available”, pointed the finger at the share being mounted using NFS. Unfortunately, after much research and fiddling, the best solution I could come up with was to switch the vagrant share back to a VirtualBox one temporarily.

vagrant@debian7:/vagrant$ npm install heapdump
npm WARN package.json execSync@1.0.1-pre No repository field.
npm http GET https://registry.npmjs.org/heapdump
npm http 304 https://registry.npmjs.org/heapdump

> heapdump@0.2.7 install /vagrant/node_modules/heapdump
> node-gyp rebuild

make: Entering directory `/vagrant/node_modules/heapdump/build'
  CXX(target) Release/obj.target/heapdump/src/heapdump.o
  CXX(target) Release/obj.target/heapdump/src/platform-posix.o
  SOLINK_MODULE(target) Release/obj.target/heapdump.node
  SOLINK_MODULE(target) Release/obj.target/heapdump.node: Finished
  COPY Release/heapdump.node
make: Leaving directory `/vagrant/node_modules/heapdump/build'
heapdump@0.2.7 node_modules/heapdump

Success!

FATAL ERROR: JS Allocation failed – process out of memory

Graham HayLeave a comment

We recently started seeing a spate of node processes dying with the unhelpful error:

FATAL ERROR: JS Allocation failed - process out of memory

Unfortunately, there’s no callstack provided. A StackOverflow answer suggested installing the OFE package, which got us a “heapdump” but it still wasn’t obvious what the problem was.

Eventually we spotted a pattern in the logs, and adding more logging led to a reproducible test case. It turned out that the bug was caused by using an array instead of an object (“hashmap”):

var foo = [];
foo[1000000001] = {};
console.log('got here');
console.log(foo);
console.log('boom!');

Accessing the array with a high id caused a huge array to be created, and trying to print that array caused the process to consume all the available memory.

UPDATE: we’re not the only ones to run into this issue.