Javascript, NodeJs

Improve your logging with stack trace

Informative logs playing crucial part in fast debugging, especially when you debug someone else’s code.
Today i wanted to share a nice trick that will help you detect the origin’s of a problem a bit faster.

Let’s say you are debugging a simple flow for a file upload, which was written by someone else or by you couple of months ago, so you don’t remember perfectly where’s what.

You click on the upload button and then bam! you get an error. You are confident that the log is informative enough to explain why,
so you tail -f the log and there you see,

10:56:16 pm – Could not upload file to the file server

Seems clear enough, but now you want to see the piece of code that generated this error.
How would you find it? ctrl+f the entire project folder for the log string? What if the same log exists in multiple files?

Well, obviously you will find it soon enough, but why won’t we try and save us those 30 seconds with logging the function that generated this error.

stack-trace to the rescue

nodeJS have multiple packages to help us easily deal with our stack trace, i personally prefer stack-trace.
Let’s install the package:

npm install stack-trace --save

Now let’s assume we have a common module that holds our logger (IMO it’s better to have a logger in a wrapper module than to directly use it in each module we have, just in case we’ll want to replace it).

Our common module will look like this:

var stackTrace = require('stack-trace');
var moment = require('moment');

var exports = {};

exports.logs = {
    debug: function (text) {

        // get the stack trace
        var trace1 = stackTrace.get()[1];
        var date = moment().format('h:mm:ss a');

        // build the log phrase from the stack trace file name, method and line number
        var trace = {
            level1: date + " - FILE: " + trace1.getFileName().replace(/^.*[\\\/]/, '') + " - METHOD: " + trace1.getMethodName() + " (" + trace1.getLineNumber() + ")"

        // log.debug with whichever library you choose, console is only for simplicity


module.exports = exports;

We have required stack-trace and the moment library (a great library for handling dates in JavaScript, if you are not familiar with it you should check it out). After this, we exposed logs on the module, and logs have method debug. The debug function accepts the string we want to log, then gets the stack trace and the time, and prints it before the actual text. I’ve used console.debug just for simplicity purposes, but you may use any logger you want.

Now lets go back to our file upload example.
Let’s say we handling a request for /file/upload in a route file called file-route.js:

var common = require('../modules/common');

// ... some upload logic 


function error(err) {
    common.logs.debug("Could not upload file to the file server: " + err);

// ... continue

The output to the console will be:

10:56:16 pm – FILE: file-route.js – METHOD: uploadFile(8)
Could not upload file to the file server: METHOD NOT ALLOWED

Which will be much more informative than just a simple

10:56:16 pm – Could not upload file to the file server

3 thoughts on “Improve your logging with stack trace

Leave a Reply

Fill in your details below or click an icon to log in: Logo

You are commenting using your account. Log Out /  Change )

Google+ photo

You are commenting using your Google+ account. Log Out /  Change )

Twitter picture

You are commenting using your Twitter account. Log Out /  Change )

Facebook photo

You are commenting using your Facebook account. Log Out /  Change )

Connecting to %s