[NodeJS:bunyan,debug] using debug module to output bunyan logs & avoiding duplicate error output

bunyanDebugRawStreamFactory.js

// core deps
const EOL       = require('os').EOL;

// 3rd party deps
const debug     = require('debug');
const bunyan    = require('bunyan');
const colors    = require('colors/safe');
const lrucache  = require('lru-cache');
const padEnd    = require('lodash/padEnd');

// our deps
const redact_large_msg      = require('./redact_large_msg');

// locals
const trace_output_prop     = Symbol('error_stacktrace_outputted');

// setup ..
colors.setTheme({
    trace : 'blue',
    debug : 'blue',
    info  : 'green',
    warn  : 'yellow',
    error : 'red',
});

// expose the module!
module.exports = (svc_name) => new DebugRawStream(svc_name);

function stackTraceLogged(err)
{
    if (!err || !err.stack)
        return false;

    if (!stackTraceLogged.lrucache)
        stackTraceLogged.lrucache = lrucache({
            max         : 100,
            maxAge      : 10000
        });

    if (err[trace_output_prop])
        return true;

    const got = err.id ? stackTraceLogged.lrucache.get(err.id) : false;

    err[trace_output_prop] = true;

    if (err.id)
        stackTraceLogged.lrucache.set(err.id, true);

    return got;
}

function error_lines(err)
{
    if (!err || !err.stack)
        return '';

    try {
        const instack  = err.stack.split(EOL).slice(1);
        const outstack = [];

        // yeah ... once we see 'at Module.' in a stack trace line it's no longer really meaningful (to me at least!)
        for (let i = 0, l = instack.length; i < l; i += 1)
            if (instack[i].match(/at Module\./))
                break;
            else
                outstack.push(instack[i]);

        if (!outstack.length)
            return;

        return outstack.map(s => '\t - ' + s.trim().replace(/\(([^(]+):(\d+):(\d+)\)$/, (...args) => {
            return '(' + colors.bold(args[1]) + ':' + colors.bold(args[2]) + ':' + colors.bold(args[3]) + ')';
        })).join(EOL);
    } catch (e) {}
}

function request_header_lines(req)
{
    const headers = req && req.headers;

    if (typeof headers !== 'object')
        return;

    return Object.entries(headers).map(v => `\t - ${padEnd(v[0], 24, ' ')} : ${v[1]}`).join(EOL);
}

function gen_msg_str(rec)
{
    const em = rec.err ? rec.err.message + (rec.err.id ? ` (Error.id = ${rec.err.id})` : null) : '';

    if (em)
        return [redact_large_msg(rec.msg), em].filter(v => typeof v === 'string').join(' -> ');

    if (!rec.msg)
        return JSON.stringify(rec);

    const reqid = rec.req_id ? [`(req.id = ${rec.req_id})`] : [];

    if (rec.req)
    if (rec.res)
    if (rec.msg.match(/^handled: \d+$/)) // a hacky/brittle check. meh.
        return ['Response >', rec.req.method, rec.req.url, '=>', 'HTTP', colors.bold(rec.res.statusCode)]
            .concat(rec.latency ? ['in', colors.bold(rec.latency) + 'ms'] : [])
            .concat(reqid)
            .join(' ');

    if (rec.req)
    if (rec.msg === 'req_received')
        return ['Request  >', rec.req.method, rec.req.url, 'FROM', `${rec.req.remoteAddress}:${rec.req.remotePort}`]
            .concat(reqid)
            .join(' ');


    return [rec.msg].concat(reqid).join(' ');
}

class DebugRawStream
{
    constructor(n)
    {
        this.name   = n;
        this.debug  = debug(n);
        this.closed = false;
    }

    write(rec)
    {
        if (!rec || this.closed || !this.debug.enabled)
            return;

        const lvl = bunyan.nameFromLevel[ rec.level ];

        if (!lvl)
            return;

        const LVL = lvl.toUpperCase();

        this.debug((colors[lvl] ? colors.underline(colors[lvl](LVL)) : LVL) + ': ' + gen_msg_str(rec));

        if (rec.req && rec.msg === 'req_received') {
            const header_output = request_header_lines(rec.req);

            if (header_output)                          // eslint-disable-next-line no-console
                console.info(header_output);
        } else if (rec.err) {
            if (!stackTraceLogged(rec.err)) {           // eslint-disable-next-line no-console
                const stacktrace_output = error_lines(rec.err);

                if (stacktrace_output)                  // eslint-disable-next-line no-console
                    console.error(stacktrace_output);
            } else {                                    // eslint-disable-next-line no-console
                console.error(`\t - ${colors.gray('stack-trace already logged, see above.')}`);
            }

            rec.err[trace_output_prop] = true;
        }
    }

    close(done)
    {
        this.closed = true;
        done();
    }
}

bunyanErrSerializer.js

// 3rd party deps
const bunyanErrSerializer   = require('bunyan').stdSerializers.err;
const shortid               = require('shortid');

function errSerializer(e)
{
    if (!e.id)
        e.id = shortid.generate();

    const built = bunyanErrSerializer(e);

    // include out custom error id - mostly so we can avoid duplicate [debug] output in the console!
    if (built)
      built.id = e.id;

    return built;
}
module.exports = errSerializer;

hackDebugModulesWithCustomFormatters.js

/**
 * hack `debug` modules with custom formatters
 * (also a number of ones that exist as duplicates in sub-modules) 
 * due to version conflicts.
 */
module.exports = function()
{
    if (!process.env.DEBUG)
        return;

    const redact_large_msg  = require('./redact_large_msg');

    const custom_formatters = {
        s : v => redact_large_msg(typeof v === 'object' ? v.toString(v) : v),
        h : v => (Buffer.isBuffer(v) ? v.toString('hex') : v),
    };

    [
        // here be hackiness ... lists any known "debug" modules
        'debug',
        'ioredis/node_modules/debug'
    ].forEach(name => {
        try {
            Object.assign(require(name).formatters, custom_formatters);
        } catch (e) {
            // eslint-disable-next-line no-console
            console.log(`FAILED to hack 'debug' module (@ ${name}) formatters`);
        }
    });
};

redact_large_msg.js

// locals
const REDACT_MSG_THRESHOLD  = 1024;
const REDACT_MSG_LENGTH     = 512;

/**
 * take a given message and redacts (truncates) it if large than our threshold,
 * the assumption if that you don't want really long messages. typically this is applied in a logging/debug context
 *
 * @param  {String} msg
 * @return {String}
 */
function redact_large_msg(msg)
{
    if ((typeof msg !== 'string') || msg.length < REDACT_MSG_THRESHOLD)
        return msg || '';

    const len = msg.length;

    return msg.slice(0, REDACT_MSG_LENGTH) + ` ... <REDACTED full-length="${len}">`;
}

module.exports = redact_large_msg;