node-bunyan-lite/test/serializers.test.js

/*
 * Copyright (c) 2012 Trent Mick. All rights reserved.
 *
 * Test the standard serializers in Bunyan.
 */

var http = require('http');

var bunyan = require('../lib/bunyan');
var verror = require('verror');

// node-tap API
if (require.cache[__dirname + '/tap4nodeunit.js'])
        delete require.cache[__dirname + '/tap4nodeunit.js'];
var tap4nodeunit = require('./tap4nodeunit.js');
var after = tap4nodeunit.after;
var before = tap4nodeunit.before;
var test = tap4nodeunit.test;


function CapturingStream(recs) {
    this.recs = recs;
}
CapturingStream.prototype.write = function (rec) {
    this.recs.push(rec);
}


test('req serializer', function (t) {
    var records = [];
    var log = bunyan.createLogger({
        name: 'serializer-test',
        streams: [
            {
                stream: new CapturingStream(records),
                type: 'raw'
            }
        ],
        serializers: {
            req: bunyan.stdSerializers.req
        }
    });

    // None of these should blow up.
    var bogusReqs = [
        undefined,
        null,
        {},
        1,
        'string',
        [1, 2, 3],
        {'foo':'bar'}
    ];
    for (var i = 0; i < bogusReqs.length; i++) {
        log.info({req: bogusReqs[i]}, 'hi');
        t.equal(records[i].req, bogusReqs[i]);
    }

    // Get http request and response objects to play with and test.
    var theReq, theRes;
    var server = http.createServer(function (req, res) {
        theReq = req;
        theRes = res;
        res.writeHead(200, {'Content-Type': 'text/plain'});
        res.end('Hello World\n');
    })
    server.listen(8765, function () {
        http.get({host: '127.0.0.1', port: 8765, path: '/'}, function (res) {
            res.resume();
            log.info({req: theReq}, 'the request');
            var lastRecord = records[records.length-1];
            t.equal(lastRecord.req.method, 'GET');
            t.equal(lastRecord.req.url, theReq.url);
            t.equal(lastRecord.req.remoteAddress,
                theReq.connection.remoteAddress);
            t.equal(lastRecord.req.remotePort, theReq.connection.remotePort);
            server.close();
            t.end();
        }).on('error', function (err) {
            t.ok(false, 'error requesting to our test server: ' + err);
            server.close();
            t.end();
        });
    });
});


test('res serializer', function (t) {
    var records = [];
    var log = bunyan.createLogger({
        name: 'serializer-test',
        streams: [
            {
                stream: new CapturingStream(records),
                type: 'raw'
            }
        ],
        serializers: {
            res: bunyan.stdSerializers.res
        }
    });

    // None of these should blow up.
    var bogusRess = [
        undefined,
        null,
        {},
        1,
        'string',
        [1, 2, 3],
        {'foo':'bar'}
    ];
    for (var i = 0; i < bogusRess.length; i++) {
        log.info({res: bogusRess[i]}, 'hi');
        t.equal(records[i].res, bogusRess[i]);
    }

    // Get http request and response objects to play with and test.
    var theReq, theRes;
    var server = http.createServer(function (req, res) {
        theReq = req;
        theRes = res;
        res.writeHead(200, {'Content-Type': 'text/plain'});
        res.end('Hello World\n');
    })
    server.listen(8765, function () {
        http.get({host: '127.0.0.1', port: 8765, path: '/'}, function (res) {
            res.resume();
            log.info({res: theRes}, 'the response');
            var lastRecord = records[records.length-1];
            t.equal(lastRecord.res.statusCode, theRes.statusCode);
            t.equal(lastRecord.res.header, theRes._header);
            server.close();
            t.end();
        }).on('error', function (err) {
            t.ok(false, 'error requesting to our test server: ' + err);
            server.close();
            t.end();
        });
    });
});


test('err serializer', function (t) {
    var records = [];
    var log = bunyan.createLogger({
        name: 'serializer-test',
        streams: [
            {
                stream: new CapturingStream(records),
                type: 'raw'
            }
        ],
        serializers: {
            err: bunyan.stdSerializers.err
        }
    });

    // None of these should blow up.
    var bogusErrs = [
        undefined,
        null,
        {},
        1,
        'string',
        [1, 2, 3],
        {'foo':'bar'}
    ];
    for (var i = 0; i < bogusErrs.length; i++) {
        log.info({err: bogusErrs[i]}, 'hi');
        t.equal(records[i].err, bogusErrs[i]);
    }

    var theErr = new TypeError('blah');

    log.info(theErr, 'the error');
    var lastRecord = records[records.length-1];
    t.equal(lastRecord.err.message, theErr.message);
    t.equal(lastRecord.err.name, theErr.name);
    t.equal(lastRecord.err.stack, theErr.stack);
    t.end();
});


test('err serializer: long stack', function (t) {
    var records = [];
    var log = bunyan.createLogger({
        name: 'serializer-test',
        streams: [ {
                stream: new CapturingStream(records),
                type: 'raw'
        } ],
        serializers: {
            err: bunyan.stdSerializers.err
        }
    });

    var topErr, midErr, bottomErr;

    // Just a VError.
    topErr = new verror.VError('top err');
    log.info(topErr, 'the error');
    var lastRecord = records[records.length-1];
    t.equal(lastRecord.err.message, topErr.message, 'Just a VError');
    t.equal(lastRecord.err.name, topErr.name, 'Just a VError');
    t.equal(lastRecord.err.stack, topErr.stack, 'Just a VError');

    // Just a WError.
    topErr = new verror.WError('top err');
    log.info(topErr, 'the error');
    var lastRecord = records[records.length-1];
    t.equal(lastRecord.err.message, topErr.message, 'Just a WError');
    t.equal(lastRecord.err.name, topErr.name, 'Just a WError');
    t.equal(lastRecord.err.stack, topErr.stack, 'Just a WError');

    // WError <- TypeError
    bottomErr = new TypeError('bottom err');
    topErr = new verror.WError(bottomErr, 'top err');
    log.info(topErr, 'the error');
    var lastRecord = records[records.length-1];
    t.equal(lastRecord.err.message, topErr.message, 'WError <- TypeError');
    t.equal(lastRecord.err.name, topErr.name, 'WError <- TypeError');
    var expectedStack = topErr.stack + '\nCaused by: ' + bottomErr.stack;
    t.equal(lastRecord.err.stack, expectedStack, 'WError <- TypeError');

    // WError <- WError
    bottomErr = new verror.WError('bottom err');
    topErr = new verror.WError(bottomErr, 'top err');
    log.info(topErr, 'the error');
    var lastRecord = records[records.length-1];
    t.equal(lastRecord.err.message, topErr.message, 'WError <- WError');
    t.equal(lastRecord.err.name, topErr.name, 'WError <- WError');
    var expectedStack = topErr.stack + '\nCaused by: ' + bottomErr.stack;
    t.equal(lastRecord.err.stack, expectedStack, 'WError <- WError');

    // WError <- WError <- TypeError
    bottomErr = new TypeError('bottom err');
    midErr = new verror.WError(bottomErr, 'mid err');
    topErr = new verror.WError(midErr, 'top err');
    log.info(topErr, 'the error');
    var lastRecord = records[records.length-1];
    t.equal(lastRecord.err.message, topErr.message,
        'WError <- WError <- TypeError');
    t.equal(lastRecord.err.name, topErr.name, 'WError <- WError <- TypeError');
    var expectedStack = (topErr.stack
        + '\nCaused by: ' + midErr.stack
        + '\nCaused by: ' + bottomErr.stack);
    t.equal(lastRecord.err.stack, expectedStack,
            'WError <- WError <- TypeError');

    // WError <- WError <- WError
    bottomErr = new verror.WError('bottom err');
    midErr = new verror.WError(bottomErr, 'mid err');
    topErr = new verror.WError(midErr, 'top err');
    log.info(topErr, 'the error');
    var lastRecord = records[records.length-1];
    t.equal(lastRecord.err.message, topErr.message,
        'WError <- WError <- WError');
    t.equal(lastRecord.err.name, topErr.name, 'WError <- WError <- WError');
    var expectedStack = (topErr.stack
        + '\nCaused by: ' + midErr.stack
        + '\nCaused by: ' + bottomErr.stack);
    t.equal(lastRecord.err.stack, expectedStack, 'WError <- WError <- WError');

    t.end();
});


// Bunyan 0.18.3 introduced a bug where *all* serializers are applied
// even if the log record doesn't have the associated key. That means
// serializers that don't handle an `undefined` value will blow up.
test('do not apply serializers if no record key', function (t) {
    var records = [];
    var log = bunyan.createLogger({
        name: 'serializer-test',
        streams: [ {
                stream: new CapturingStream(records),
                type: 'raw'
        } ],
        serializers: {
            err: bunyan.stdSerializers.err,
            boom: function (value) {
                throw new Error('boom');
            }
        }
    });

    log.info({foo: 'bar'}, 'record one');
    log.info({err: new Error('record two err')}, 'record two');

    t.equal(records[0].boom, undefined);
    t.equal(records[0].foo, 'bar');
    t.equal(records[1].boom, undefined);
    t.equal(records[1].err.message, 'record two err');

    t.end();
});