Aug 5, 2013

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 5140

If you tail /var/log/messages on the syslog server, the last line should say:<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

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
// Log to local file
winston.add(winston.transports.File, { filename: 'log.txt' });
// Log to remote syslog
winston.add(winston.transports.Syslog, {"host":"", "port":"5140", "localhost":""});

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(;
catch (err) {"Invalid OID, err="+err);

Here's the full code.

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<134>: Aug  5 15:07:34 {"message":"*** NODE APP STARTED ***"}<134>: Aug  5 15:07:34 {"message":"Web server started"}<134>: Aug  5 15:07:34 {"message":"Connected to memcache"}<134>: Aug  5 15:07:34 {"message":"Connected to database"}

GET<134>: Aug  5 15:11:51 {"message":"Request received, id=0"}<134>: Aug  5 15:11:51 {"message":"Finding all documents"}

GET<134>: Aug  5 15:12:19 {"message":"Request received, id=51e3ce08915082db3df32bf7"}<134>: Aug  5 15:12:19 {"message":"Cache miss, key 51e3ce08915082db3df32bf7. Querying..."}<134>: Aug  5 15:12:19 {"message":"Item found: {\"_id\":\"51e3ce08915082db3df32bf7\",\"x\":8}"}<134>: Aug  5 15:12:19 {"message":"Stored key=51e3ce08915082db3df32bf7, value=8"}

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

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

Now, let's try a bogus ObjectID:
GET<134>: Aug  5 15:17:22 {"message":"Request received, id=666"}<134>: Aug  5 15:17:22 {"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:<134>: Aug  5 15:14:15 {"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 :)

No comments:

Post a Comment