“Trouble parsing json”

We use Bunyan in our node apps, for “structured logging”. The output json string is passed to syslog, by systemd, and then fed into ELK.

{
    "name":"foo-service",
    "hostname":"app-01",
    "pid":30988,
    "ip":"1.19.24.8",
    "requestId":"1c11f448-73f2-4efa-bc63-3de787618d49",
    "level":50,
    "err": {
        "message":"oh noes!"
    }
}

Unfortunately, if that string is longer than 2048 chars (usually a stacktrace, or html returned from a web service instead of json), then the json blob ends up split over 2 lines in syslog.

This causes ELK to barf when attempting to parse the broken lines (assuming you are parsing as json), and means you won’t see those errors in Kibana.

It is possible to detect the error parsing the error, by searching for the string “Trouble parsing json”, but that’s not really a solution.

I would prefer to see a truncated error, than have the current situation, but that means either wrapping or patching Bunyan itself.

Node.js and systemd-notify

Running a nodejs app as a systemd service is pretty simple. But the downside to this approach is that if the app dies straight away (e.g. a config file is malformed), then systemd remains unaware.

An alternative is to switch to using notify:

[Service]
Type=notify
ExecStart=/var/www/app_name/app.js
Restart=always
...

There are various ways to notify systemd that your service is ready; but the simplest is to use systemd-notify, a console wrapper around sd_notify.

this.start = function(port) {
    var deferred = Q.defer();

    server = app.listen(port, '127.0.0.1', function(error) {
        if (error) {
            deferred.reject(new Error(error));
        } else {
            logger.info('Listening on port %d', port);
            exec('systemd-notify --ready');
            deferred.resolve();
        }
        });

        return deferred.promise;
    };
};

If the process that calls systemd-notify is not the one in ExecStart (e.g. you are using cluster), you will also need to set NotifyAccess to “all”.

Now when you use systemctl to start your service, it will wait for the notification before deeming the start process complete.

Managing nodejs dependencies

The easiest way to “deploy” a node app is to clone the git repo on a server, and run npm install. There are a couple of disadvantages though: first, I don’t really like having to install git, and manage credentials for a private repo.

Second, installing the dependencies like that means you may get different versions of the modules you rely on than you were expecting. One of the tenets of a reliable build pipeline is ensuring that builds are repeatable, and that what you deploy matches what you tested.

There are a few alternatives: you could vendor in the node_modules folder, but this dirties the commit history, and increases the size of your repo. You could use npm shrinkwrap, which is the same concept as Bundler’s Gemfile.lock, a list of specific versions to install. This is definitely an improvement, but still leaves the risk of npm i failing during a deployment.

I’d prefer to only install the dependencies once, on the build server. This means I can run the tests, then tar up the folder and upload that to each environment in turn:

npm install
npm test
npm prune --production
npm dedupe
tar -czf app.tar.gz --exclude='*/coverage' app/

After running the tests, we prune the dependencies to remove mocha etc. We then dedupe to try and reduce the number of copies of shared modules, and finally create an archive of the app. This is output as an artifact of the build, and pulled in the by the deploy to staging build, output from that again, and finally pulled in by the deploy to production build.

Arrow functions returning an expression

One of the new features of ES6 that has made it into Node 4 is arrow functions. According to the documentation, there are 2 alternative syntaxes:

(param1, param2, …, paramN) => { statements }
(param1, param2, …, paramN) => expression
         // equivalent to:  => { return expression; }

Using the 2nd version works as expected for primitive values:

> [1,2,3].map(i => i);
[ 1, 2, 3 ]

but not when you return an object:

> [1,2,3].map(i => { id: i });
[ undefined, undefined, undefined ]

As was pointed out to me on SO, it’s impossible to tell the difference between a statement block and an expression consisting of an object literal.

The solution is to wrap the returned object in an extra set of parentheses:

> [1,2,3].map(i => ({ id: i }));
[ {id: 1}, {id: 2}, {id: 3} ]

Zero downtime deployments with node cluster

The easiest way to do zero downtime deployments is using multiple nodes behind a load balancer. Once removed from the rotation, you can fiddle with them to your heart’s content.

If you only have one box to play with, things aren’t so simple. One option is to push the complexity up to whatever you’re using to orchestrate deployments. You could do something like a blue/green deployment, with two full sets of processes behind nginx as a load balancer; but this felt liable to be very fragile.

I next started looking at a process manager, like pm2; but it seemed to offer far too many features I didn’t need, and didn’t play that well with systemd. It was inspiration though, for just going direct to the nodejs cluster API. It’s been available for some time, and is now marked as “stable”.

It allows you to run multiple node processes that share a port, which is also useful if you are running on hardware with multiple CPUs. Using the cluster API allows us to recycle the processes when the code has changed, without dropping any requests:

var cluster = require('cluster');

module.exports = function(start) {
    var env = process.env.NODE_ENV || 'local';
    var cwd = process.cwd();

    var numWorkers = process.env.NUM_WORKERS || 1;

    if (cluster.isMaster) {
        fork();

        cluster.on('exit', function(worker, code, signal) {
            // one for all, let systemd deal with it
            if (code !== 0) {
                process.exit(code);
            }
        });

        process.on('SIGHUP', function() {
            // need to chdir, if the old directory was deleted
            process.chdir(cwd);
            var oldWorkers = Object.keys(cluster.workers);
            // wait until at least one new worker is listening
            // before terminating the old workers
            cluster.once('listening', function(worker, address) {
                kill(oldWorkers);
            });
            fork();
        });
    } else {
        start(env);
    }

    function fork() {
        for (var i = 0; i < numWorkers; i++) {
            cluster.fork();
        }
    }

    function kill(workers) {
        if (workers.length) {
            var id = workers.pop();
            var worker = cluster.workers[id];
            worker.send('shutdown');
            worker.disconnect();
            kill(workers);
        }
    }
};

During a deployment, we simply replace the old code and send a signal to the “master” process (kill -HUP $PID); which causes it to spin up X new workers. As soon as one of those is ready and listening, it terminates the old workers.

Converting complex js objects to xml

The xml node package offers “fast and simple Javascript-based XML generation”.

I had hoped that it would be as simple as:

var xml = require('xml');

var result = xml({
    FOO: {
        BAR: "something"
    }
});

But that only included the top level element:

<FOO />

After some RTFM, and a few false starts, it became clear that you need to represent each child node as an array of key value pairs:

xml({
    FOO: [
        {_attrs: { abra: "cadabra" },
        { BAR: "something" },
        { BAZ: "else" }
    ]
});

Which should result in XML like this:

<FOO abra="cadabra">
    <BAR>something</BAR>
    <BAZ>else</BAZ>
</FOO>

Using bunyan with express

I’ve pontificated previously about the benefits of combining bunyan with logstash, but if your app is using express it can be a little more complicated.

I wanted to add the user id & IP address of a request to all log output involved in that request. Bunyan makes it simple to create a child logger, and add the necessary properties; but due to the way express is architected (and how node works) the only way to access it is to pass it to the handler, and all it’s dependencies:

app.post("/foo", function(req, res) {
    var childLogger = logger.child({
            userId: req.userId, // taken from a header by middleware
            ip: req.ip
        }),
        barService = new BarService(childLogger),
        handler = new Handler(barService, childLogger);
    handler.handle(req, res);
});

Which makes it possible to search the logs for all information relating to a specific user, or IP address.