Showing posts with label Back End Programming. Show all posts

Sunday, November 2, 2014

EcmaScript6 with TypeScript and Grunt.js

ECMAScript 6 is nearly here. In fact I can already taste it and so will you with TypeScript. TypeScript is an open source language and compiler written by Microsoft running on NodeJS. The language is based on the evolving ES6 spec but adds support for types, interfaces that generates JavaScript (ES3 or ES5 dialects based on flag). In fact it's very interesting shift for Microsoft to make something useful for open source community, so before you boo me, have a look at it as it's not so bad.

Introduction

Microsoft has compiled a great video introducing the TypeScript and since one video replaces million words, let's start with it.

Using TypeScript

As TypeScript is built on top of Node.js, installing it will be as easy as breathing.

npm install -g typescript

And compiling the files is done through the tsc command, however this is no way respectable developers work. We'll be using Grunt.js to compile our TypeScript files during the build phase. Let's start with writing something small using the new syntax. As usual all the accompanying code can be found on article's repository. First we'll create Animal class and extend a Lion from it, overriding it's methods.

class Animal {
    constructor(public eats: string) {}

    eat() {
        console.log('Eating ' + this.eats);
    }

    speak() {
        console.log('Animal speaking');
    }
}

///
class Lion extends Animal {
    constructor() {
        super('meat');
    }

    speak() {
        console.log('Lion roars');
        super.speak();
    }
}

Then check our new classes in the HTML file:

<!DOCTYPE html>
<html>
<head>
    <script src="src/Animal.js"></script>
    <script src="src/Lion.js"></script>
    <script>
        var lion = new Lion();
        lion.eat();
        lion.speak();
    </script>
</head>
</html>

Pay attention that we reference the js files and not the ts ones. Now let's move to Grunt.js.

TypeScript and Grunt.js

To make both play together nicely, we'll be needing additional package, called grunt-ts. Since we won't be needing it besides development environment, let's use --save-dev flag to mark our intentions.

npm install grunt-ts --save-dev

Moving on to our gruntfile.js file. I've used as little options as possible to make the example easy to understand. There are a lot of configurations of grunt-ts package, which are thoroughly explained in it's page.

(function () {
    'use strict';
    module.exports = function(grunt) {
        grunt.initConfig({
            ts: {
                dev: {
                    src: ["src/*.ts"]                
                }
            }
        });

        grunt.loadNpmTasks('grunt-ts');
        grunt.registerTask('default', ['ts:dev']);
    };
}());

Once Grunt task is run, four files will be generated including both JavaScript and Map files of our classes. And of course opening our HTML page, will feed the console with following lines:

Eating meat               Animal.ts:5
Lion roars                Lion.ts:8
Animal speaking           Animal.ts:9

Pay attention to where Chrome maps the log calls, which is our original ts files. This will come handy in case of debugging your application, which means you don't really need to open the auto-generated JavaScript files.

Besides support in Visual Studio, TypeScript is also supported in WebStorm and SublimeText. Hope you enjoyed the article and next we'll be talking about CoffeeScript.

Tuesday, September 30, 2014

JavaScript Promise

Nothing weights lighter than a promise

This maybe true regarding to human promises, however in the programming domain, promises are always kept. Following this optimistic note, today we'll be talking about JavaScript promises.

Event Handling Problem

Let's see what promises are good for and their basic capabilities starting with a problem they come to solve. Events are great for things of a repetitive nature like keydown, mousemove etc. With those events you don't really care about what have happened before you attached the listener. On contrary calling services and processing their response is a completely different kind of beast. Have a look at the following function, which reads a json file and returns it's content or an error in case of something goes wrong.

function readJSON(filename, callback) {
 fs.readFile(filename, 'utf8', function (err, res) {
     if (err) {
      return callback(err);
     }
     try {
       res = JSON.parse(res);
     } catch (ex) {
       return callback(ex);
     }
     callback(null, res);
 });
}

As you can see there're a lot of checks for errors inside the callback, which if forgotten or written in an incorrect order may cause it's creator quite a headache. This is where promises shine. JavaScript promises are not just about aggregating callbacks, but actually they are mostly about having a few of the biggest benefits of synchronous functions in async code! Namely, function composition of chainable async invocations and error bubbling; for example if at some point of the async chain of invocation an exception is produced, then the exception bypasses all further invocations until a catch clause can handle it (otherwise we have an uncaught exception that breaks our web app).

What is Promise?

A Promise is an object that is used as a placeholder for the eventual results of a deferred (and possibly asynchronous) computation. A promise can always be situated in one of three different states:

pending - The initial state of a promise.
fulfilled - The state of a promise representing a successful operation.
rejected - The state of a promise representing a failed operation.

Once a promise is fulfilled or rejected, it can never change again. The promises ease significantly the understanding of the program flow and aid in avoiding common pitfalls like error handling. They provide a direct correspondence between synchronous and asynchronous functions. What does this mean? Well, there are two very important aspects of synchronous functions, such as returning values and throwing exceptions. Both of these are essentially about composition. The point of promises is to give us back functional composition and error bubbling in the async world. They do this by saying that your functions should return a promise, which can do one of two things:

Become fulfilled by a value
Become rejected with an exception

Cross Platform Support

Over the years developer community has sprung numerous implementations of Promises. The most notable are Q, When, WinJS and RSVP.js, however since our blog focuses on the latest developments in the JavaScript world, we'll be only covering newest Promise class introduced in EcmaScript 6. You can see the browsers' support for the feature here, and in case you wish of your program to work in other browsers, as usually you can use the polyfill.

EcmaScript 6 Promise

The Promise interface represents a proxy for a value not necessarily known when the promise is created. It allows you to associate handlers to an asynchronous action's eventual success or failure. This lets asynchronous methods return values like synchronous methods: instead of the final value, the asynchronous method returns a promise of having a value at some point in the future. So let's see our previous example using promises.

function readJSONPromise(filename) {
    return new Promise(function (resolve, reject) {
        fs.readFile(filename, 'utf8', function (err, res) {
            if (err) {
                reject(err);
            } else {
                try {
                    res = JSON.parse(res);
                } catch (ex) {
                    reject(ex);
                    return;
                }
                resolve(res);
            }
        });
    });
}

Oddly it seems very similar. So what do we gain? The true power reveals itself when we try to chain the calls.

readJSONPromise('./example.json').then(function onReadFile(res) {
    return res;
}).then(function onProcessFile(response) {
    console.log('response: ' + JSON.stringify(response));
}).catch(function onError(error) {
    console.error('error: ' + error);
});

Once you return the object, you can pass it to other function for further processing. It allows us to apply the concern separation design in an easy and clean way. You can look at the full code in Git repository.

Tuesday, September 23, 2014

Operation Timeout in MongoDB

Today I'd like to talk about a problem every MongoDB developer should be aware of - operation timeout. I have surely risen a lot of eyebrows and a few snide remarks, but let me reassure it's worth reading.

Connection vs Operation Timeout

So where do we start? The main problem with operation timeout in any database, not specifically to MongoDB, is the developer's confusion between connection timeout and operation timeout. So let's clear the air right away by clarifying the difference. Connection timeout is the maximal time you wait until you connect to the database. Whereas operational timeout is the maximal time you wait until a certain operation is performed, usually CRUD. This happens after you're already connected to the database.

Post MongoDB 2.6

If you've just started using MongoDB or had a luck to upgrade your existing instance to the newest version, that being 2.6 at the moment of writing, then you should know there is a build-in support for operation timeout by using $maxTimeMS operator in every request.

 
db.collection.find().maxTimeMS(100)

Akward? Surely, but it does the job pretty well.

Pre MongoDB 2.6

But what happens if you don't have the luxury of upgrading your database instance, either from IT or project constrains. In pre 2.6 world, things get ugly. Naturally we want our operations to be constrained within limited timeline, so that we could properly write error logs and take the effective measures. So how do we do this?

MongoDbManager

I've written a MongoDB wrapper library, which uses JavaScript setTimeout mechanism to tackle the issue. The full code can be found in GitHub. Let's look through the main ideas of the library in depth.

find = function find(obj, callback, logger) {
    var filter = obj.filter, name = obj.name, isOne = obj.isOne,
        isRetrieveId = obj.isRetrieveId, limit = obj.limit,
        projection = obj.projection || {};
    if (!isRetrieveId) {
        projection._id = 0;
    }
    connect(function (err1, db) {
        if (err1) {
            callback(err1);
            return;
        }
        var start = logger.start("get " + name), isSent = false,
            findCallback = function (err, items) {
                logger.end(start);
                if (isSent) {
                    return;
                }
                isSent = true;
                if (err) {
                    callback(err);
                } else {
                    callback(null, items);
                }
            };
        setTimeout(function findTimeoutHanlder() {
            if (isSent) {
                return;
            }
            isSent = true;
            callback(ERRORS.TIMEOUT);
        }, SETTINGS.TIMEOUT);
        if (isRetrieveId) {
            if (isOne) {
                db.collection(name).findOne(filter, projection,
                findCallback);
            } else {
                if (limit) {
                    db.collection(name).find(filter, projection)
                    .limit(limit).toArray(findCallback);
                } else {
                    db.collection(name).find(filter, projection).
                    toArray(findCallback);
                }
            }
        } else {
            if (isOne) {
                db.collection(name).findOne(filter, projection,
                findCallback);
            } else {
                if (limit) {
                    db.collection(name).find(filter, projection).
                    limit(limit).toArray(findCallback);
                } else {
                    db.collection(name).find(filter, projection).
                    toArray(findCallback);
                }
            }
        }
    }, logger);
}

A lot of code :( Let's take step by step or in our case line by line. Firstly we connect to the database by calling connect method. It checks whether there is an open connection and opens one in case there isn't. Then we create a timeout callback, findTimeoutHanlder, and queue it's invocation after SETTINGS.TIMEOUT. Right after this, we query the database with find method. Once the data is retrieved our timeout flag, isSent, is set to true, indicating the response was sent. Once the timeout callback is activated, it checks the value of the flag and in case it isn't set to true, error is returned.

Why is that? Activation of timeout callback means we reached a predefined timeout. If flag is still false, then we haven't still received the data from the database and we should quit. When the data is finally retrieved, we check the flag again. If it was set by timeout callback, then we don't need to do a thing, since the error was already returned.

This simple, yet powerful technique is used throughout the library wrapping other operations like update and insert as well. The code is fully documented and has a few examples, which should aid you with understanding the code within one hour.

If you have any questions or suggestions, please don't hesitate to comment below.

Sunday, August 31, 2014

Automate JavaScript Testing with Grunt.js

So far we've learned how to test your JavaScript code with Jasmine and running them against Node.js and browsers with Karma. We've also got familiar with modular design patterns in JavaScript. And yet, somehow it seems that we're still missing one last puzzle piece connecting all the others, it's called Grunt.js.

What is it?

According to it's site:

In one word: automation. The less work you have to do when performing repetitive tasks like minification, compilation, unit testing, linting, etc, the easier your job becomes. After you've configured it, a task runner can do most of that mundane work for you—and your team—with basically zero effort.

Zero or not, there is a bit of effort in making everything play together, but no worry - we'll figure it out. So what's our plan?

Write classes, which are both usable in Node.js, Require.js and global environment.
Write Jasmine specs to test our code in both Chrome and Firefox
Write Karma and Node.js runners
Write Grunt task to automate the testing

Writing universal JavaScript classes

In the end we'll type one command to test our code from every aspect. Feeling excited? Let's start! All the code can be found in GitHub, to where I copied some code from my project called Raceme.js, JavaScript clustering algorithms framework (some harmless PR :) First one is Vector class, which wraps the JavaScript array with minor functionality:

(function () {
    'use strict';

    var Vector = function Vector(v) {
        var vector = v;

        this.length = function length() {
            return vector.length;
        };

        this.toArray = function toArray() {
            return vector;
        };
    };

    if (typeof define === 'function' && define.amd) {
        // Publish as AMD module
        define(function() {return Vector;});
    } else if (typeof(module) !== 'undefined' && module.exports) {
        // Publish as node.js module
        module.exports = Vector;
    } else {
        // Publish as global (in browsers)
        var Raceme = window.Raceme = window.Raceme || {};
        Raceme.Common = Raceme.Common || {};
        Raceme.Common.Vector = Vector;
    }
}());

Notice the lower part of the code, where we define our class as AMD module using Require.js, CommonJS module for Node.js and global class for window environment. To spice things up, we'll add additional class, PlaneMapper, which will depend on our Vector class. It exposes one method, mapVector, mapping 2-dimensional coordinate point into vector. The problem with writing dependent universal classes is the loading process. As you remember, Require.js and Node.js use different loading methods - asynchronous versus synchronous. loadDependencies method unifies the approaches into one loading process. Pay attention to continuation of declaration logic in line 29; Once we have our PlaneMapper object defined, we finalize the declaration depending upon the method.

(function () {
    'use strict';

    var COMMONJS_TYPE = 2, GLOBAL_TYPE = 3;
    var loadDependencies = function loadDependencies(callback) {
        if (typeof define === 'function' && define.amd) {
            // define AMD module with dependencies
            define(['common/Vector'], callback); // cannot pass env type
        } else if (typeof(module) !== 'undefined' && module.exports) {
            // load CommonJS module
            callback(require('../common/Vector.js'), COMMONJS_TYPE);
        } else {
            // Publish as global (in browsers)
            callback(Raceme.Common.Vector, GLOBAL_TYPE);
        }
    };
    loadDependencies(function (Vector, env) {
        var PlaneMapper = function () {
            var mapVector = function mapVector(node) {
                return new Vector([node.x, node.y]);
            };

            return {
                mapVector: mapVector
            };
        };

        // finalize the declaration
        switch(env) {
            case COMMONJS_TYPE:
                module.exports = PlaneMapper();
                break;
            case GLOBAL_TYPE:
                var Raceme = window.Raceme = window.Raceme || {};
                Raceme.DataMappers = Raceme.DataMappers || {};
                Raceme.DataMappers.PlaneMapper = PlaneMapper();
                break;
            default:
                return PlaneMapper();
        }
    });
}());

Writing universal Jasmine specs

Code is written, time for testing. We'll create two Jasmine specs, each for one of the classes. As in before, we start with Vector class:

(function () {
    'use strict';
    describe('Mappers', function () {
        var loadDependencies = function loadDependencies(callback) {
            if (typeof define === 'function' && define.amd) {
                // load AMD module
                define(['common/Vector'], callback);
            } else if (typeof(module) !== 'undefined' && module.exports) {
                // load CommonJS module
                callback(require('../../src/common/Vector.js'));
            } else {
                // Publish as global (in browsers)
                callback(Raceme.Common.Vector);
            }
        };
        loadDependencies(function (Vector) {
            var vector;
            describe('Vector', function () {
                beforeEach(function() {
                    vector = new Vector([1, 2, 3]);
                });
                it('check length', function () {
                    expect(vector.length()).toEqual(3);
                });

                it('check toArray', function () {
                    expect(vector.toArray()).toEqual([1, 2, 3]);
                });
            });
        });
    });
})();

Nothing new here - we load the Vector class prior to declaring the spec using the same technique. Same with our mapper, besides loading two classes.

(function () {
    'use strict';
    describe('Mappers', function () {
        var loadDependencies = function loadDependencies(callback) {
            if (typeof define === 'function' && define.amd) {
                // load AMD module
                define(['common/Vector', 'dataMappers/PlaneMapper'], callback);
            } else if (typeof(module) !== 'undefined' && module.exports) {
                // load CommonJS module
                callback(require('../../src/common/Vector.js'), 
                    require('../../src/dataMappers/PlaneMapper.js'));
            } else {
                // Publish as global (in browsers)
                callback(Raceme.Common.Vector, Raceme.DataMappers.PlaneMapper);
            }
        };
        loadDependencies(function (Vector, PlaneMapper) {
            var vector;
            describe('PlaneMapper', function () {
                var mapper, node;
                beforeEach(function() {
                    mapper = PlaneMapper;
                    node = {
                        x: 5,
                        y: 10
                    };
                });
                it('check mapping', function () {
                    vector = mapper.mapVector(node);
                    expect(vector.toArray()).toEqual([5, 10]);
                });
            });
        });
    });
})();

Configuring Jasmine spec runners

Testing Node.js modules is easy - just run the jasmine-node command with path to the specs.

jasmine-node test/spec

Moving on to browser testing. We'll start with easier case using global declarations. First we create Karma configuration file, karma.conf.js. The main interest is in files and browsers sections, where we define our source and spec files in correct order and browsers we want to test.

...
files: [      
  'src/common/*.js',
  'src/dataMappers/*.js',
  'test/spec/*Spec.js'
],
...
browsers: ['Chrome', 'Firefox'],
...

Then invoking the tests using karma command.

karma start karma.conf.js

Lastly, let's test our Require.js modules. Since the modules will by loaded by Require.js instead of Karma, a new Karma configuration file is required - karma.conf.require.js. The first difference appears in frameworks section, where we tell Karma to use Require.js framework. This will require installing additional package called karma-requirejs.

...
frameworks: ['jasmine', 'requirejs'],
...
files: [
    {pattern: 'src/common/*.js', included: false},
    {pattern: 'src/dataMappers/*.js', included: false},
    {pattern: 'test/spec/*Spec.js', included: false},
    'test/test-require-main.js'
],
...

Additional difference comes in files section. Here we inform the test runner not to load our source and spec files. So why to list them at all? Listing the files enables us to use them later, during configuration of Require.js in test-require-main.js. Usually Require.js configuration appears in JavaScript file, mentioned in data-main attribute of script tag. However since we don't want to load HTML files, we configure our modules in test-require-main.js.

(function () {
    'use strict';
    var tests = [];
    for (var file in window.__karma__.files) {
        if (window.__karma__.files.hasOwnProperty(file)) {
            if (/Spec\.js$/.test(file)) {
                tests.push(file.replace(/^\/base\//,
                 'http://localhost:9876/base/'));
            }
        }
    }

    requirejs.config({
        // Karma serves files from '/base'
        baseUrl: 'http://localhost:9876/base/src/',

        // ask Require.js to load these files (all our tests)
        deps: tests,

        // start test run, once Require.js is done
        callback: window.__karma__.start
    });
}());

At first we pass through each file listed in the configuration by using window.__karma__.files list and initiate spec files list. While doing so, we adjust the domain of the specs modules to one used by Karma - localhost:9876. It will also be used as a baseUrl attribute in Require.js configuration. Then we integrate Require.js and Karma together by passing Karma's stating method, window.__karma__.start, as a callback in line 21. The heart of the fusing appears in line 18, where we configure to load our specs prior to calling the callback. Once specs are loaded, callback will be invoked starting the testing.

Writing Grunt tasks

As promised, it's time to integrate all parts using Grunt.js. For this to happen, we'll require four packages: grunt, grunt-cli and grunt-karma, grunt-jasmine-node. The first two for running the tasks and the rest are for calling Karma and Node.js runners. Make sure to install the packages locally into project's folder, otherwise it will not work. In fact all the packages should be installed locally, when you work with Grunt.js.

Installing them can be done easily using package.json and bower.json files. Once the files are in place just call appropriate install commands. It will download all the packages automatically into project's folder.

npm install
bower install

If you an eager environmentalist like me, who doesn't wish to store anything, but essential data on your repository, you may use .gitignore file, which tells Git to ignore specified paths.

node_modules/
bower_components/

Grunt tasks are defined using JavaScript code in gruntfile.js.

(function () {
    'use strict';
    module.exports = function(grunt) {
        grunt.initConfig({
            pkg: grunt.file.readJSON('package.json'),
            karma: {
                unit_global: {
                    configFile: 'karma.conf.js'
                },

                unit_requirejs: {
                    configFile: 'karma.conf.require.js'
                }
            },
            jasmine_node: {
                options: {
                    forceExit: true,
                    match: '.',
                    matchall: false,
                    extensions: 'js',
                    specNameMatcher: 'spec'
                },
                all: ['test/spec/']
            }
        });

        grunt.loadNpmTasks('grunt-karma');
        grunt.loadNpmTasks('grunt-jasmine-node');
        grunt.registerTask('default', ['jasmine_node', 
            'karma:unit_global', 'karma:unit_requirejs']);
    };
}());

Not very intimidating, isn't it? Basically what it does is configures our test tasks, loads the required packages and then runs the tasks. Now in details. At first it configures our Karma tasks by specifying two children in karma node: unit_global and unit_requirejs, each states it's configuration file name. Then it configures Node.js runner. Since it doesn't have any configuration file, all the settings are listed here. In the end, it runs the tasks in the order they appear in parameter array of registerTask method. Notice the usage of semicolon, when Karma tasks are specified. It tells Grunt to run specific tasks under karma node.

Tasks names can be changed, both jasmine_node and karma node's names cannot.

Aren't you eager to see the results?

grunt

Grunt will load and run the gruntfile.js file emitting the following result:

Running "jasmine_node:all" (jasmine_node) task
Common
    Vector
        check length
        check toArray
Mappers
    PlaneMapper
        check mapping
Finished in 0.014 seconds
3 tests, 3 assertions, 0 failures

Running "karma:unit_global" (karma) task
INFO [karma]: Karma v0.12.23 server started at http://localhost:9876/
INFO [launcher]: Starting browser Chrome
INFO [launcher]: Starting browser Firefox
INFO [Chrome 36.0.1985]: Connected on socket HrOcIkaJ5aqQG85SOqIS
with id 63263274
Chrome 36.0.1985: Executed 3 of 3 SUCCESS (0.032 secs / 0.005 secs)
INFO [Firefox 31.0.0]: Connected on socket wrrkgK5_skzDJztmOqIT wi
Chrome 36.0.1985: Executed 3 of 3 SUCCESS (0.032 secs / 0.005 secs
Chrome 36.0.1985: Executed 3 of 3 SUCCESS (0.032 secs / 0.005 secs
Chrome 36.0.1985: Executed 3 of 3 SUCCESS (0.032 secs / 0.005 secs
Chrome 36.0.1985: Executed 3 of 3 SUCCESS (0.032 secs / 0.005 secs
Chrome 36.0.1985: Executed 3 of 3 SUCCESS (0.032 secs / 0.005 secs)
Firefox 31.0.0: Executed 3 of 3 SUCCESS (0.026 secs / 0.002 secs)
TOTAL: 6 SUCCESS

Running "karma:unit_requirejs" (karma) task
INFO [karma]: Karma v0.12.23 server started at http://localhost:9876/
INFO [launcher]: Starting browser Chrome
INFO [launcher]: Starting browser Firefox
INFO [Chrome 36.0.1985]: Connected on socket PXxh9c5vacKQovhSOsI2
with id 36823086
Chrome 36.0.1985: Executed 3 of 3 SUCCESS (0.004 secs / 0.002 secs)
INFO [Firefox 31.0.0]: Connected on socket Xu3qldD3wfmNskyOOsI3 wi
Chrome 36.0.1985: Executed 3 of 3 SUCCESS (0.004 secs / 0.002 secs
Chrome 36.0.1985: Executed 3 of 3 SUCCESS (0.004 secs / 0.002 secs
Chrome 36.0.1985: Executed 3 of 3 SUCCESS (0.004 secs / 0.002 secs
Chrome 36.0.1985: Executed 3 of 3 SUCCESS (0.004 secs / 0.002 secs
Chrome 36.0.1985: Executed 3 of 3 SUCCESS (0.004 secs / 0.002 secs)
Firefox 31.0.0: Executed 3 of 3 SUCCESS (0.005 secs / 0.002 secs)
TOTAL: 6 SUCCESS

Done, without errors.

Perfection! But it's only a tip of the iceberg. We'll be talking more about Grunt.js using conditional logic and reporting, so stay tuned ;)

Sunday, August 10, 2014

Logging in Node.js

Once you start developing on Node.js, you'll very soon find out the need for logging. It of course has nothing to do with JavaScript or specifically Node.js, but rather with the need to log activities on production environment, and even on development one for that matter.

console.log

The most rudimentary type of logging you could do is using console.log and console.error methods. This is better than nothing, but hardly the best solution. Basically they work exactly as they do, when you used them in browsers. However since we're in the server dominion now, an interesting aspect is revealed. That is, the console functions are synchronous, when the destination is a terminal or a file (to avoid lost messages in case of premature exit) and asynchronous when it’s a pipe (to avoid blocking for long periods of time). It is fully manual and you'll have to come up with your own format and basically manage everything yourself.

Bunyan

Bunyan library makes its mission to provide structured, machine readable logs as first class citizens. As a result, a log record from Bunyan is one line of JSON.stringify output with some common names for the requisite and common fields for a log record. Use npm manager to install the package. If you're not familiar with the tool, please read the JavaScript Developer Toolkit article first.

npm install bunyan

Winston

Winston is designed to be a simple and universal logging library with support for multiple transports. A transport is essentially a storage device for your logs. Each instance of a winston logger can have multiple transports configured at different levels. For example, one may want error logs to be stored in a persistent remote location (like a database), but all logs output to the console or a local file. To install the library:

npm install winston

Integration

Integrating both libraries is as easy as requiring the modules and using info/error methods just as in console object:

var logger = require('winston');
logger.info('test');

logger = require('bunyan').createLogger({name: 'myapp'});
logger.info('test');

The difference between the libraries can be spotted from the first look at the console output. Bunyan serializes everything using JSON format, whereas Winston uses a readable text format.

info: test
{"name":"myapp","hostname":"CWLP-67","pid":3820,"level":30,"msg":"test",
"time":"2014-08-23T11:11:45.249Z","v":0}

Output destination

But what really makes the Winston shine is the diversity of supported transports, which especially kick in, when your application reaches production environment. Cause you agree that saving logs into terminal is not very useful, when you don't have access to the server or better yet a cluster. What you can do with transports is route your logs to MongoDB for instance or cloud-based service like Loggly. You can read more about the supported transports on the Winston's site. Bunyan also supports different transports, but much more modest. Read about it here.

Session logging

But even this appears to be not sufficient, if you want to take a full advantage out of your logs using analytics and mining. Consider the following Express example. It simulates some error happening after an asynchronous call is completed, just like your service or database request:

(function () {
    'use strict';
    var express = require('express'), app = express(), i = 0,
  init = function init() {
            app.get('/', function (req, res) {
                var logger = require('winston');
                logger.info(new Date() + ' call number: ' + (i++));
                // do some logic
                logger.info(new Date() + ' another log');
                setTimeout(function () {
                    if (Math.random() > 0.2) {
                        logger.error(new Date() + 
                            ' something bad happened');
                    }
                }, Math.round(Math.random() * 10000));
                res.end();
            });

            app.listen('3000', '127.0.0.1');
   };
    init();
}());

Now, try accessing http://localhost:3000 for several times and observe the logs. While they are in place, there is no way of knowing to which call the errors relate:

info: Sat Aug 10 2014 11:33:11 call number: 0
info: Sat Aug 10 2014 11:33:11 another log
info: Sat Aug 10 2014 11:33:12 call number: 1
info: Sat Aug 10 2014 11:33:12 another log
info: Sat Aug 10 2014 11:33:12 call number: 2
info: Sat Aug 10 2014 11:33:12 another log
error: Sat Aug 10 2014 11:33:16 something bad happened
error: Sat Aug 10 2014 11:33:20 something bad happened

You may add some identifier to each log call, but this way is treacherous and when, not if, someone forgets to add the token, you will face the wrath of maintenance God.

To tackle the issue, I've written a wrapper, which works both with Winston and Bunyan and adds the support for session logging. You can find it on GitHub and can use it however you like.

(function () {
    'use strict';
    var express = require('express'), app = express(),
        nconf = require('nconf'), winston = require('winston'),
        i = 0, LogManager = require("./common/LogManager.js"),
  init = function init() {
   var path = require('path');
   nconf.file({
    file : path.resolve(__dirname,  'config.json')
   });

            LogManager.init(nconf.get("logger"), {
                transports: [
                    new (winston.transports.File)({
                        filename: 'common.log'
                    })
                ]
            });

            app.get('/', function (req, res) {
                var logger = LogManager.getInstance(), delta;
                logger.info('call number: ' + (i++));
                // do some logic
                logger.info('another log');
                delta = logger.start('some async method');
                setTimeout(function () {
                    logger.end(delta);
                    if (Math.random() > 0.2) {
                        logger.error('something bad happened');
                    }
                }, Math.round(Math.random() * 10000));
                res.end();
            });

            app.listen('3000', '127.0.0.1');
   };
    init();
}());

Observe the changes. Firstly we configure our LogManager object using nconf to load the configurations from json file. Then we configure it with another transport to output the logs into file. Lastly we create new instance of logger, using getInstance static method, on each GET request to track our requests. The result can be seen below - here the error from 10:25:54.188 can be clearly tracked to request 2, since they share the same token, b9188f46-0def-4c11-ae97-509e6d84bfaa.

info:  d=6abb5532-acf5-4575-8ffb-ff1da549fd74, t=10:25:46.636, i=call number: 0
info:  d=6abb5532-acf5-4575-8ffb-ff1da549fd74, t=10:25:46.639, i=another log
info:  d=2e6d7bf6-8bdc-4b1a-8bee-9bb1eb17a30d, t=10:25:47.086, i=call number: 1
info:  d=2e6d7bf6-8bdc-4b1a-8bee-9bb1eb17a30d, t=10:25:47.086, i=another log
info:  d=b9188f46-0def-4c11-ae97-509e6d84bfaa, t=10:25:47.630, i=call number: 2
info:  d=b9188f46-0def-4c11-ae97-509e6d84bfaa, t=10:25:47.630, i=another log
error:  d=2e6d7bf6-8bdc-4b1a-8bee-9bb1eb17a30d, t=10:25:53.392, e=something bad>
 happened, s=Error
info:  d=2e6d7bf6-8bdc-4b1a-8bee-9bb1eb17a30d, t=10:25:53.392, i=delta of (some
 async method): 6306 ms
    at LogManager.info [as error] (C:\GitHub\LogManager\common\LogManager.js:53:68)
    at null._onTimeout (C:\GitHub\LogManager\server.js:29:32)
    at Timer.listOnTimeout [as ontimeout] (timers.js:110:15)
info:  d=b9188f46-0def-4c11-ae97-509e6d84bfaa, t=10:25:54.188, i=delta of (some
 async method): 6558 ms
error:  d=b9188f46-0def-4c11-ae97-509e6d84bfaa, t=10:25:54.188, e=something bad
 happened, s=Error
    at LogManager.info [as error] (C:\GitHub\LogManager\common\LogManager.js:53:68)
    at null._onTimeout (C:\GitHub\LogManager\server.js:29:32)
    at Timer.listOnTimeout [as ontimeout] (timers.js:110:15)
info:  d=6abb5532-acf5-4575-8ffb-ff1da549fd74, t=10:25:55.546, i=delta of (some
 async method): 8906 ms

I've mentioned already that the library supports both Winston and Bunyan libraries. We do this using the configuration file, config.json, we pass to the logger. We can set here to use either Winston or Bunyan.

{
    "logger": {
        "IS_WINSTON": true,
        "IS_BUNYAN": false,
        "LOG_NAME": "myLog",
        "LONG_STACK": false,
        "STACK_LEVEL": 5
    }
}

Stack Trace

One last thing, I promise :) You see how our error stack trace is appended into log. This happens because we specifically put it there using Error.stack. However what if we wanted to get the whole stack and not just last few calls. To do this you need to set LONG_STACK flag to true and specify the wanted STACK_LEVEL. The feature is implemented using longjohn library and produces much more elaborate log like this:

info:  d=a6786546-2381-41a7-823c-f6ebafea0d06, t=10:50:38.119, i=call number: 0
info:  d=a6786546-2381-41a7-823c-f6ebafea0d06, t=10:50:38.124, i=another log
info:  d=a6786546-2381-41a7-823c-f6ebafea0d06, t=10:50:39.388, i=delta of (some
 async method): 1264 ms
error:  d=a6786546-2381-41a7-823c-f6ebafea0d06, t=10:50:39.388, e=something bad
 happened, s=Error
    at info (C:\GitHub\LogManager\common\LogManager.js:53:68)
    at [object Object]. (C:\GitHub\LogManager\server.js:29:32)
    at listOnTimeout (timers.js:110:15)
---------------------------------------------
    at C:\GitHub\LogManager\server.js:26:17
    at handle (C:\GitHub\LogManager\node_modules\express\lib\router\layer.js:76:5)
    at next (C:\GitHub\LogManager\node_modules\express\lib\router\route.js:100:13)
    at Route.dispatch (C:\GitHub\LogManager\node_modules\express\lib\
router\route.js:81:3)
    at handle (C:\GitHub\LogManager\node_modules\express\lib\router\layer.js:76:5)
    at C:\GitHub\LogManager\node_modules\express\lib\router\index.js:227:24
    at proto.process_params (C:\GitHub\LogManager\node_modules\express\lib\
router\index.js:305:12)
    at C:\GitHub\LogManager\node_modules\express\lib\router\index.js:221:12
---------------------------------------------
    at new Server (http.js:1869:10)
    at exports.createServer (http.js:1899:10)
    at app.listen (C:\GitHub\LogManager\node_modules\express\lib\
application.js:545:21)
    at init (C:\GitHub\LogManager\server.js:35:17)
    at C:\GitHub\LogManager\server.js:37:5
    at Object. (C:\GitHub\LogManager\server.js:38:2)
    at Module._compile (module.js:456:26)
    at Module._extensions..js (module.js:474:10)

Hope you find the library useful and be glad for any contribution.

Sunday, July 20, 2014

Jasmine and Node.js

Following our last article about using Jasmine and Karma together, let's look how we streamline the testing of our server side code written in Node.js. To do this, we'll need to install jasmine-node package.

npm install -g jasmine-node

If you're not familiar with the tool, please read the JavaScript Developer Toolkit before proceeding any further. The installed version will only support Jasmine 1.3 version. In order to add the 2.0 support, you should install the branched version.

npm install -g jasmine-node@2.0.0-beta4

Again as in previous article we'll be using the specs from our previous Jasmine article and the source code can be found in GitHub. After installing the correct version, we'll have to make our Player and Song classes as CommonJS modules. If you don't know how, please read the article about Modular Design Patterns in JavaScript. And of course requiring them in our specs:

...
module.exports = Song;

...
module.exports = Player;

describe("Player", function() {
  var Player = require('../src/Player.js');
  var Song = require('../src/Song.js');
  ...

Everything is ready - let's run the spec. We do this by pointing the path of the spec

jasmine-node spec/

Andddd bummer - we receive an error:

Exception loading helper: c:\GitHub\jsdeepdive-jasmine-and-nodejs\spec\SpecHelper.js
[ReferenceError: beforeEach is not defined]

This happens because customer helpers are not supported :(

Removed Support for Custom Helpers (have to be inside a beforeEach, this is a jasmine change, check out their docs on how to write one)

So let's put our helper inside the spec.

  beforeEach(function() {
    player = new Player();
    song = new Song();

    jasmine.addMatchers({
        toBePlaying: function () {
          return {
            compare: function (actual, expected) {
              var player = actual;

              return {
                pass: player.currentlyPlayingSong ===
                  expected && player.isPlaying
              }
            }
          };
        }
      });
  });

Trying again starts to passing through specs, but fails on the last one:

Failures:
  1) Player #resume should throw an exception if song is already playing
    Message:
      Expected function to throw an Error, but it threw Error: song is already
      playing.
    Stacktrace:
      Error: Expected function to throw an Error, but it threw Error: song is
      already playing.
    at Object. (c:\GitHub\jsdeepdive-jasmine-and-nodejs\spec\PlayerSpec.js:71:10)
Finished in 0.007 seconds
5 Tests, 1 Failures, 0 Skipped

And this is strange, cause we for sure know that example specs should all pass. This happens because of the bug/feature of jasmine-node (don't forget it's still a Beta) and we'll change our code a bit to bypass the problem by using toThrow instead of toThrowError:

expect(function() {
  player.resume();
}).toThrowError("song is already playing");

expect(function() {
  player.resume();
}).toThrow(new Error("song is already playing"));

Hooray - it works now and all the spec pass. Yes it's a bit quirky and yes more work is needed, but it's a progress. Next time I'll show how to use Grunt, which offers a better support for Jasmine 2.0.