Node.js, part 4: the Big Kahuna syslog!

To paraphrase the immortal Samuel Jackson in Pulp Fiction: "Logs! The cornerstone of any nutritious application!". And my Node.js app doesn't have any! As Mr Brando once said "Ah, the horror, the horror!". At the time, he probably didn't worry about log management, but the quote is definitely relevant for that too :D

I'm an old fashioned guy, so the first thing that comes to my mind is : "syslog". We could certainly find fancier ways (yes, I'm looking at you, scala-*), but syslog will do for now.

Once again, I'll use an Ubuntu 12.04 instance in EC2, which happens to have a running rsyslogd :) Let's take a look at the main config file, /etc/rsyslogd.conf.

We'll use UDP to ship our logs. However, because of this unbelievable 2-year old bug, we can't use port 514 (the default port for syslog): we'll use 5140 instead, don't forget to open 5140/UDP in the security group of the EC2 instance!

# provides UDP syslog reception
$ModLoad imudp
$UDPServerRun 5140

Let's now look at the default rules, located in /etc/rsyslog.d/50-default.conf. Let's keep it very simple and make sure we log everything. We'll also add a new template, because the default one misses some useful information, such as priority (duh!).

$template TraditionalFormatWithPRI,"%pri-text%: %timegenerated% %HOSTNAME% %syslogtag%%msg:::drop-last-lf%\n"
*.*    /var/log/messages;TraditionalFormatWithPRI

I hear my sysadmin team booing the ugliness of this setup. Yeah, I love you too, bitchez :-P

Anyway, this should be enough, now we just need to restart rsyslogd:
ubuntu@ip-10-34-245-176:~$ sudo service rsyslog restart

rsyslog stop/waiting

rsyslog start/running, process 4639

Now, let's move back to our Node.js instance and try to talk to our syslog server:
ubuntu@ip-10-37-166-19:~$ echo "<14>Node sez: I see you"|nc -u -v -w0 10.34.245.176 5140

If you tail /var/log/messages on the syslog server, the last line should say:

user.info<14>: Aug  5 14:40:18 Node sez: I see you

OK. Now that we have a running syslog server, how is the Node.js app going to send it data? The good news is that there's a large number of packages to do this. The bad news is, most of them don't seem to work very well... 

Ain2 worked right out of the box. If you're only looking for a syslog module, I would recommend this one. However, I ended up picking winston, an interesting logging framework supporting many different transports  (file, http, several databases, etc) including syslog through the winston-syslog module.

In theory, at least. For the life of me, I couldn't get this thing to work, despite a lot of creative hacking and creative swearing too. Fortunately, winston-syslogUdp works: "It was created when the authors experienced challenges with winston-syslog". Yeah, tell me about it! Good job, guys.

winston requires a newer version of Node.js than the one available in the Ubuntu repo, so let's take care of this upgrade first:
ubuntu@ip-10-37-166-19:~$ sudo add-apt-repository ppa:chris-lea/node.js

ubuntu@ip-10-37-166-19:~$ sudo apt-get update

ubuntu@ip-10-37-166-19:~$ sudo apt-cache show nodejs|grep Version

Version: 0.10.15-1chl1~precise1

Version: 0.6.12~dfsg1-1ubuntu1

ubuntu@ip-10-37-166-19:~$ sudo apt-get install nodejs=0.10.15-1chl1~precise1

ubuntu@ip-10-37-166-19:~$ node -v

v0.10.15

Now, let's update the Node.js packages and install the winston packages:

ubuntu@ip-10-37-166-19:~$ npm update

ubuntu@ip-10-37-166-19:~$ npm install winston winston-syslogudp

After some more hacking and swearing (but no drinking, I promise), I adapted my program to use winston, with the following setup:

• don't log to the console 
• log to a local file
• log to a remote syslog server

Here how you do this, it's really simple:

// Don't log to console

winston.remove(winston.transports.Console);

// Log to local file

winston.add(winston.transports.File, { filename: 'log.txt' });

// Log to remote syslog

winston.add(winston.transports.Syslog, {"host":"10.34.245.176", "port":"5140", "localhost":"10.37.166.19"});

This is quite self-explanatory, as you will see below. However, winston can also do some pretty advanced stuff, I encourage you to read the documentation and go log-crazy ;)

While I was at it, I cleaned the code a little bit and also solved the MongoDB ObjectId validation issue like this. Not sure if it's the canonical way, but it works.
// Check that the ObjectId is valid
try {
    oid = new require('mongodb').ObjectID.createFromHexString(query.id);
}
catch (err) {
    winston.info("Invalid OID, err="+err);
    response.end();
    return;
}

Here's the full code.

var http = require('http'); var url = require('url'); var mc = require('mc'); var winston = require('winston'); require('winston-syslogudp').Syslog; function onRequest(request, response) { // No id parameter --> do nothing // id=0 --> list all documents // id=SOME_OBJECT_ID --> show the 'x' value for this document var query = url.parse(request.url,true).query; winston.info("Request received, id="+query.id); if (query.id == null) { // No id parameter --> do nothing response.end(); return; } if (query.id == "0") { // id=0 --> list all documents collection.find().toArray(function (err, items) { if (err) { winston.error("Could not find all documents, err="+err); response.end(); return; } winston.info("Finding all documents"); response.writeHead(200, {"Content-Type": "text/html"}); response.write("<html>"); for (var i = 0; i < items.length; i++) { response.write(JSON.stringify(items[i])+"<br>"); } response.write("</HTML>"); response.end(); }); } else { // Check that the ObjectId is valid try { oid = new require('mongodb').ObjectID.createFromHexString(query.id); } catch (err) { winston.info("Invalid OID, err="+err); response.end(); return; } // id=SOME_OBJECT_ID --> show the 'x' value for this document // Check the cache first MemcacheClient.get(query.id, function(err, result) { if (!err) { // Key found, display value winston.info("Cache hit, key="+query.id+", value="+result[query.id]); response.writeHead(200, {"Content-Type": "text/html"}); response.write("<html>"); response.write("x="+result[query.id]); response.write("</HTML>"); response.end(); } else { // Key not found, fetch value from DB winston.info("Cache miss, key "+query.id+". Querying..."); collection.findOne({"_id": oid}, function (err, item) { if ((err) || (item == null)) { winston.error("Could not query id "+query.id); response.end(); return; } winston.info("Item found: "+JSON.stringify(item)); // Display value response.writeHead(200, {"Content-Type": "text/html"}); response.write("<html>"); response.write(JSON.stringify(item)); response.write("</HTML>"); response.end(); // Store value in cache with a 60 second TTL MemcacheClient.set(query.id, item.x, { flags: 0, exptime: 60}, function(err, status) { if (!err) { winston.info("Stored key="+query.id+", value="+item.x); } else { winston.error("Couldn't store key="+query.id+", error="+err); } }); }); } }); } } // Program start // Don't log to console winston.remove(winston.transports.Console); // Log to local file winston.add(winston.transports.File, { filename: 'log.txt' }); // Log to remote syslog winston.add(winston.transports.Syslog, {"host":"10.34.245.176", "port":"5140", "localhost":"10.37.166.19"}); winston.info("*** NODE APP STARTED ***"); // Connect to the ElastiCache cluster MemcacheClient = new mc.Client(["memcache.9vficl.0001.euw1.cache.amazonaws.com", "memcache.9vficl.0002.euw1.cache.amazonaws.com"]); MemcacheClient.connect(function() { winston.info("Connected to memcache"); }); // Connect to the MongoDB server hosted at MongoLab var collection; require('mongodb').MongoClient.connect("mongodb://USER:PASSWD@ds051067.mongolab.com:51067/mongolab-test", function(err, db) { if (!err) { winston.info("Connected to database"); collection = db.collection("collection1"); } else { winston.error("Dude, where's my DB?"); process.exit(err); } }); // Start the web server on port 8080 and wait for incoming requests http.createServer(onRequest).listen(8080); winston.info("Web server started");

Let's run this, hit it with some requests and look at the logs :)

ubuntu@ip-10-37-166-19:~$ node www5.js &
ubuntu@ip-10-37-166-19:~$ tail -f log.txt 
{"level":"info","message":"*** NODE APP STARTED ***","timestamp":"2013-08-05T15:07:36.678Z"}
{"level":"info","message":"Web server started","timestamp":"2013-08-05T15:07:36.823Z"}
{"level":"info","message":"Connected to memcache","timestamp":"2013-08-05T15:07:36.850Z"}
{"level":"info","message":"Connected to database","timestamp":"2013-08-05T15:07:36.876Z"}

ubuntu@ip-10-34-245-176:~$ tail -f /var/log/messages 
local0.info<134>: Aug  5 15:07:34 10.37.166.19 {"message":"*** NODE APP STARTED ***"}
local0.info<134>: Aug  5 15:07:34 10.37.166.19 {"message":"Web server started"}
local0.info<134>: Aug  5 15:07:34 10.37.166.19 {"message":"Connected to memcache"}
local0.info<134>: Aug  5 15:07:34 10.37.166.19 {"message":"Connected to database"}

GET http://ec2-54-247-53-161.eu-west-1.compute.amazonaws.com:8080/?id=0
local0.info<134>: Aug  5 15:11:51 10.37.166.19 {"message":"Request received, id=0"}
local0.info<134>: Aug  5 15:11:51 10.37.166.19 {"message":"Finding all documents"}

GET http://ec2-54-247-53-161.eu-west-1.compute.amazonaws.com:8080/?id=51e3ce08915082db3df32bf7
local0.info<134>: Aug  5 15:12:19 10.37.166.19 {"message":"Request received, id=51e3ce08915082db3df32bf7"}
local0.info<134>: Aug  5 15:12:19 10.37.166.19 {"message":"Cache miss, key 51e3ce08915082db3df32bf7. Querying..."}
local0.info<134>: Aug  5 15:12:19 10.37.166.19 {"message":"Item found: {\"_id\":\"51e3ce08915082db3df32bf7\",\"x\":8}"}
local0.info<134>: Aug  5 15:12:19 10.37.166.19 {"message":"Stored key=51e3ce08915082db3df32bf7, value=8"}

The same one, right away:
local0.info<134>: Aug  5 15:12:21 10.37.166.19 {"message":"Request received, id=51e3ce08915082db3df32bf7"}
local0.info<134>: Aug  5 15:12:21 10.37.166.19 {"message":"Cache hit,  key=51e3ce08915082db3df32bf7, value=8"}

The same one, more than 60 seconds later :)
local0.info<134>: Aug  5 15:14:15 10.37.166.19 {"message":"Request received, id=51e3ce08915082db3df32bf7"}
local0.info<134>: Aug  5 15:14:15 10.37.166.19 {"message":"Cache miss, key 51e3ce08915082db3df32bf7. Querying..."}
local0.info<134>: Aug  5 15:14:15 10.37.166.19 {"message":"Item found: {\"_id\":\"51e3ce08915082db3df32bf7\",\"x\":8}"}
local0.info<134>: Aug  5 15:14:15 10.37.166.19 {"message":"Stored key=51e3ce08915082db3df32bf7, value=8"}

Now, let's try a bogus ObjectID:

GET http://ec2-54-247-53-161.eu-west-1.compute.amazonaws.com:8080/?id=666

local0.info<134>: Aug  5 15:17:22 10.37.166.19 {"message":"Request received, id=666"}
local0.info<134>: Aug  5 15:17:22 10.37.166.19 {"message":"Invalid OID, err=Error: Argument passed in must be a single String of 12 bytes or a string of 24 hex characters"}

Woohoo! This doesn't crash the app anymore. By the way, if you use Chrome, you certainly see a lot of annoying lines saying:

local0.info<134>: Aug  5 15:14:15 10.37.166.19 {"message":"Request received, id=undefined"}

You can ignore them: this is just Chrome trying over and over and over again to get the favorite icon (favicon.ico)... This is a known bug.

And so now, our web app haz logz and at 131 lines of code (comments included), it's not bloated either. Pretty amazing.

That's it for today. Keep hacking :)