bunyan-format for node

bunyan-format.js

'use strict';

const util = require('util');
const format = util.format;
const http = require('http');
const chalk = require('chalk');

const stream = require('stream');
const _merge = require('lodash/merge');
const _get = require('lodash/get');

const Writable = stream.Writable;

const COLOR_black = 'black';
const COLOR_red = 'red';
const COLOR_green = 'green';
const COLOR_yellow = 'yellow';
const COLOR_blue = 'blue'; //(On Windows the bright version is used since normal blue is illegible)
const COLOR_magenta = 'magenta';
const COLOR_cyan = 'cyan';
const COLOR_white = 'white';
const COLOR_gray = 'gray'; //("bright black")
const COLOR_redBright = 'redBright';
const COLOR_greenBright = 'greenBright';
const COLOR_yellowBright = 'yellowBright';
const COLOR_blueBright = 'blueBright';
const COLOR_magentaBright = 'magentaBright';
const COLOR_cyanBright = 'cyanBright';
const COLOR_whiteBright = 'whiteBright';

const COLOR_bgRedBright = 'bgRedBright';

let moment;
try {
  moment = require('moment');
} catch (e) {
  moment = null;
}

// Internal debug logging via `console.warn`.
let _selfTrace = function selfTraceNoop() {};
if (process.env.BUNYAN_SELF_TRACE === '1') {
  _selfTrace = function selfTrace() {
    console.warn('[bunyan self-trace] ', arguments);
  };
}

const OM_LONG = 'long';
const OM_JSON = 'json';
const OM_INSPECT = 'inspect';
const OM_SIMPLE = 'simple';
const OM_SHORT = 'short';
const OM_BUNYAN = 'bunyan';

// Levels
const TRACE = 10;
const DEBUG = 20;
const INFO = 30;
const WARN = 40;
const ERROR = 50;
const FATAL = 60;

const levelFromName = {
  trace: TRACE,
  debug: DEBUG,
  info: INFO,
  warn: WARN,
  error: ERROR,
  fatal: FATAL,
};
const nameFromLevel = {};
const upperNameFromLevel = {};
const upperPaddedNameFromLevel = {};
Object.keys(levelFromName).forEach(function(name) {
  const lvl = levelFromName[name];
  nameFromLevel[lvl] = name;
  upperNameFromLevel[lvl] = name.toUpperCase();
  upperPaddedNameFromLevel[lvl] =
    (name.length === 4 ? ' ' : '') + name.toUpperCase();
});

// Display time formats.
const TIME_UTC = 'utc'; // the default, bunyan's native format
const TIME_LOCAL = 'local';

// Timezone formats: output format -> momentjs format string
const TIMEZONE_UTC_FORMATS = {
  long: '[[]YYYY-MM-DD[T]HH:mm:ss.SSS[Z][]]',
  short: 'HH:mm:ss.SSS[Z]',
};
const TIMEZONE_LOCAL_FORMATS = {
  long: '[[]YYYY-MM-DD[T]HH:mm:ss.SSSZ[]]',
  short: 'HH:mm:ss.SSS',
};

function indent(s) {
  return '  ' + s.split(/\r?\n/).join('\n  ');
}

function stylizeWithColor(s, color) {
  if (s == null || s === '') return '';

  return _get(chalk, color, stylizeWithoutColor)(s);
}

function stylizeWithoutColor(str, color) {
  return str;
}

/**
 * Is this a valid Bunyan log record.
 */
function isValidRecord(rec) {
  if (
    rec.v == null ||
    rec.level == null ||
    rec.name == null ||
    rec.hostname == null ||
    rec.pid == null ||
    rec.time == null ||
    rec.msg == null
  ) {
    // Not valid Bunyan log.
    return false;
  } else {
    return true;
  }
}

/**
 * Print out a single result, considering input options.
 */
function formatRecord(rec, opts) {
  const stylize = opts.color ? stylizeWithColor : stylizeWithoutColor;
  let short = false;

  switch (opts.outputMode) {
    case OM_SHORT:
      short = true;
    /* jsl:fall-thru */

    case OM_LONG:
      delete rec.v;

      // Time.
      let time;
      if (!short && opts.timeFormat === TIME_UTC) {
        // Fast default path: We assume the raw `rec.time` is a UTC time
        // in ISO 8601 format (per spec).
        time = '[' + rec.time + ']';
      } else if (!moment && opts.timeFormat === TIME_UTC) {
        // Don't require momentjs install, as long as not using TIME_LOCAL.
        time = rec.time.substr(11);
      } else {
        let tzFormat;
        const moTime = moment(rec.time);
        switch (opts.timeFormat) {
          case TIME_UTC:
            tzFormat = TIMEZONE_UTC_FORMATS[short ? 'short' : 'long'];
            moTime.utc();
            break;
          case TIME_LOCAL:
            tzFormat = TIMEZONE_LOCAL_FORMATS[short ? 'short' : 'long'];
            break;
          default:
            throw new Error('unexpected timeFormat: ' + opts.timeFormat);
        }
        time = moTime.format(tzFormat);
      }
      time = stylize(time, COLOR_gray);
      delete rec.time;

      let nameStr = rec.name;
      delete rec.name;

      if (rec.component) {
        nameStr += '/' + rec.component;
      }
      delete rec.component;

      if (!short) nameStr += '/' + rec.pid;
      delete rec.pid;

      let level = upperPaddedNameFromLevel[rec.level] || 'LVL' + rec.level;
      if (opts.color) {
        level = stylize(level, opts.colorFromLevel[rec.level]);
      }
      delete rec.level;

      let src = '';
      if (rec.src && rec.src.file) {
        const s = rec.src;
        if (s.func) {
          src = format(' (%s:%d in %s)', s.file, s.line, s.func);
        } else {
          src = format(' (%s:%d)', s.file, s.line);
        }
        src = stylize(src, COLOR_green);
      }
      delete rec.src;

      const hostname = rec.hostname;
      delete rec.hostname;

      const extras = [];
      const details = [];

      if (rec.req_id) {
        extras.push('req_id=' + rec.req_id);
      }
      delete rec.req_id;

      if (rec.req && typeof rec.req === 'object') {
        const req = rec.req;
        delete rec.req;
        let headers = req.headers;
        if (!headers) {
          headers = '';
        } else if (typeof headers === 'string') {
          headers = '\n' + headers;
        } else if (typeof headers === 'object') {
          headers =
            '\n' +
            Object.keys(headers)
              .map(function(h) {
                return h + ': ' + headers[h];
              })
              .join('\n');
        }
        let s = format(
          '%s %s HTTP/%s%s',
          req.method,
          req.url,
          req.httpVersion || '1.1',
          headers
        );
        delete req.url;
        delete req.method;
        delete req.httpVersion;
        delete req.headers;
        if (req.body) {
          s +=
            '\n\n' +
            (typeof req.body === 'object'
              ? JSON.stringify(req.body, null, 2)
              : req.body);
          delete req.body;
        }
        if (req.trailers && Object.keys(req.trailers) > 0) {
          s +=
            '\n' +
            Object.keys(req.trailers)
              .map(function(t) {
                return t + ': ' + req.trailers[t];
              })
              .join('\n');
        }
        delete req.trailers;
        details.push(indent(s));
        // E.g. for extra 'foo' field on 'req', add 'req.foo' at
        // top-level. This *does* have the potential to stomp on a
        // literal 'req.foo' key.
        Object.keys(req).forEach(function(k) {
          rec['req.' + k] = req[k];
        });
      }

      if (rec.client_req && typeof rec.client_req === 'object') {
        const client_req = rec.client_req;
        delete rec.client_req;

        const headers = client_req.headers;
        delete client_req.headers;

        let s = format(
          '%s %s HTTP/%s%s',
          client_req.method,
          client_req.url,
          client_req.httpVersion || '1.1',
          headers
            ? '\n' +
                Object.keys(headers)
                  .map(function(h) {
                    return h + ': ' + headers[h];
                  })
                  .join('\n')
            : ''
        );
        delete client_req.method;
        delete client_req.url;
        delete client_req.httpVersion;

        if (client_req.body) {
          s +=
            '\n\n' +
            (typeof client_req.body === 'object'
              ? JSON.stringify(client_req.body, null, 2)
              : client_req.body);
          delete client_req.body;
        }
        // E.g. for extra 'foo' field on 'client_req', add
        // 'client_req.foo' at top-level. This *does* have the potential
        // to stomp on a literal 'client_req.foo' key.
        Object.keys(client_req).forEach(function(k) {
          rec['client_req.' + k] = client_req[k];
        });
        details.push(indent(s));
      }

      if (rec.res && typeof rec.res === 'object') {
        processRes(rec.res, details, rec);
        delete rec.res;
      }
      if (rec.client_res && typeof rec.client_res === 'object') {
        processRes(rec.client_res, details, rec);
        delete rec.client_res;
      }

      if (rec.err && rec.err.stack) {
        const err = rec.err;
        if (typeof err.stack !== 'string') {
          details.push(indent(err.stack.toString()));
        } else {
          details.push(indent(err.stack));
        }
        delete err.message;
        delete err.name;
        delete err.stack;
        // E.g. for extra 'foo' field on 'err', add 'err.foo' at
        // top-level. This *does* have the potential to stomp on a
        // literal 'err.foo' key.
        Object.keys(err).forEach(function(k) {
          rec['err.' + k] = err[k];
        });
        delete rec.err;
      }

      const renderedMsg = renderMsg(rec.msg, rec, stylize);
      let onelineMsg;
      if (rec.msg.indexOf('\n') !== -1) {
        onelineMsg = '';
        details.unshift(indent(stylize(renderedMsg, COLOR_cyan)));
      } else {
        onelineMsg = ' ' + stylize(renderedMsg, COLOR_cyan);
      }
      delete rec.msg;

      const leftover = Object.keys(rec);
      for (let i = 0; i < leftover.length; i++) {
        const key = leftover[i];
        let value = rec[key];
        let stringified = false;
        if (typeof value !== 'string') {
          value = JSON.stringify(value, null, 2);
          stringified = true;
        }
        if (value.indexOf('\n') !== -1 || value.length > 50) {
          details.push(indent(key + ': ' + value));
        } else if (
          !stringified &&
          (value.indexOf(' ') !== -1 || value.length === 0)
        ) {
          extras.push(key + '=' + JSON.stringify(value));
        } else {
          extras.push(key + '=' + value);
        }
      }

      const extrasJoined = stylize(
        extras.length ? ' (' + extras.join(', ') + ')' : '',
        COLOR_gray
      );
      const detailsJoined = stylize(
        details.length ? details.join('\n    --\n') + '\n' : '',
        COLOR_gray
      );
      if (!short)
        return `${time} ${level}: ${nameStr} on ${hostname ||
          '<no-hostname>'}${src}:${onelineMsg}${extrasJoined}\n${detailsJoined}`;
      else
        return `${time} ${level} ${nameStr}:${onelineMsg}${extrasJoined}\n${detailsJoined}`;

    case OM_INSPECT:
      return util.inspect(rec, false, Infinity, true) + '\n';

    case OM_BUNYAN:
      return JSON.stringify(rec, null, 0) + '\n';

    case OM_JSON:
      return JSON.stringify(rec, null, opts.jsonIndent) + '\n';

    case OM_SIMPLE:
      // <http://logging.apache.org/log4j/1.2/apidocs/org/apache/log4j/SimpleLayout.html>
      return format(
        '%s - %s\n',
        upperNameFromLevel[rec.level] || 'LVL' + rec.level,
        rec.msg
      );
    default:
      throw new Error('unknown output mode: ' + opts.outputMode);
  }
}

function processRes(res, details, rec) {
  let s = '';

  /*
   * Handle `res.header` or `res.headers` as either a string or
   * an object of header key/value pairs. Prefer `res.header` if set,
   * because that's what Bunyan's own `res` serializer specifies,
   * because that's the value in Node.js's core HTTP server response
   * implementation that has all the implicit headers.
   *
   * Note: `res.header` (string) typically includes the 'HTTP/1.1 ...'
   * status line.
   */
  const headerTypes = {string: true, object: true};
  let headers;
  let headersStr = '';
  let headersHaveStatusLine = false;
  if (res.header && headerTypes[typeof res.header]) {
    headers = res.header;
    delete res.header;
  } else if (res.headers && headerTypes[typeof res.headers]) {
    headers = res.headers;
    delete res.headers;
  }
  if (headers === undefined) {
    /* pass through */
  } else if (typeof headers === 'string') {
    headersStr = headers.trimRight(); // Trim the CRLF.
    if (headersStr.slice(0, 5) === 'HTTP/') {
      headersHaveStatusLine = true;
    }
  } else {
    headersStr += Object.keys(headers)
      .map(function(h) {
        return h + ': ' + headers[h];
      })
      .join('\n');
  }

  /*
   * Add a 'HTTP/1.1 ...' status line if the headers didn't already
   * include it.
   */
  if (!headersHaveStatusLine && res.statusCode !== undefined) {
    s += format(
      'HTTP/1.1 %s %s\n',
      res.statusCode,
      http.STATUS_CODES[res.statusCode]
    );
  }
  delete res.statusCode;
  s += headersStr;

  if (res.body !== undefined) {
    const body =
      typeof res.body === 'object'
        ? JSON.stringify(res.body, null, 2)
        : res.body;
    if (body.length > 0) {
      s += '\n\n' + body;
    }
    delete res.body;
  } else {
    s = s.trimRight();
  }
  if (res.trailer) {
    s += '\n' + res.trailer;
  }
  delete res.trailer;
  if (s) {
    details.push(indent(s));
  }
  // E.g. for extra 'foo' field on 'res', add 'res.foo' at
  // top-level. This *does* have the potential to stomp on a
  // literal 'res.foo' key.
  Object.keys(res).forEach(function(k) {
    rec['res.' + k] = res[k];
  });
}

const placeholderPattern = /{([@$]?[0-9a-zA-Z_]+)}/g;

function renderMsg(msg, rec, stylize) {
  if (typeof msg !== 'string' || msg === '') {
    return msg;
  }

  return msg.replace(placeholderPattern, (match, token, offset) =>
    renderTokenMatch(match, token, offset, msg, rec, stylize)
  );
}

function renderTokenMatch(match, token, offset, msg, rec, stylize) {
  if (msg[offset - 1] === '{' && msg[offset + match.length] === '}') {
    return token;
  }

  const tokenModifier = msg[offset + 1];
  const jsonEncode = tokenModifier === '@' || tokenModifier === '$';
  const propName = jsonEncode ? token.slice(1) : token;

  let value = rec.hasOwnProperty(propName) ? rec[propName] : undefined;
  if (value === undefined) {
    return `{${propName}}`;
  }

  if (jsonEncode || value === null || value === new Object(value)) {
    value = JSON.stringify(value);
  }

  delete rec[propName];
  return stylize(value, ['underline', COLOR_cyanBright]);
}

module.exports = BunyanFormatWritable;

util.inherits(BunyanFormatWritable, Writable);

/**
 * Creates a writable stream that formats bunyan records written to it.
 *
 * @name BunyanFormatWritable
 * @function
 * @param opts {Object} passed to bunyan format function
 *  - outputMode: short|long|simple|json|bunyan
 *  - color (true): toggles colors in output
 *  - colorFromLevel: allows overriding log level colors
 * @param out [Stream] (process.stdout) writable stream to write
 * @return {WritableStream} that you can pipe bunyan output into
 */
function BunyanFormatWritable(opts, out) {
  if (!(this instanceof BunyanFormatWritable))
    return new BunyanFormatWritable(opts, out);

  opts = opts || {};
  Writable.call(this, opts);

  this.opts = _merge(
    {
      outputMode: 'short',
      timeFormat: TIME_LOCAL,
      color: true,
      colorFromLevel: {
        10: COLOR_gray, // TRACE
        20: COLOR_gray, // DEBUG
        30: COLOR_green, // INFO
        40: COLOR_magenta, // WARN
        50: COLOR_red, // ERROR
        60: [COLOR_whiteBright, COLOR_bgRedBright], // FATAL
      },
    },
    opts
  );
  this.out = out || process.stdout;
  this.stream = this;
}

BunyanFormatWritable.prototype._write = function(chunk, encoding, cb) {
  let s;
  try {
    const rec = JSON.parse(chunk);
    s = formatRecord(rec, this.opts);
  } catch (formatErr) {
    _selfTrace('exception from formatRecord: ', chunk);
  }

  try {
    //console.log(s);
    this.out.write(s);
  } catch (writeErr) {
    _selfTrace('exception from stdout.write: ', writeErr);
    // Handle any exceptions in stdout writing in `stdout.on('error', ...)`.
  }

  cb();
};

bunyan-format.test.js

const bunyan = require('bunyan');
const BunyanFormatWritable = require('./bunyan-format');

function logSomeMessages(log) {
  log.info('starting up');
  log.info(
    {
      hostname: 'danger0.local',
      pid: 76488,
      level: 30,
      res: {
        statusCode: 200,
        headers: {
          Foo: 'bar',
          Date: 'Wed, 02 Aug 2017 22:37:34 GMT',
          Connection: 'keep-alive',
          'Content-Length': 21,
        },
      },
    },
    'response sent'
  );
  log.info({user: 'Alice', other: 'some other info'}, 'Hi, {user}!');
  log.debug('things are heating up', {
    temperature: 80,
    status: {started: 'yes', overheated: 'no'},
  });
  log.warn('getting a bit hot', {temperature: 120});
  log.error(new Error('temperature: 200'), 'OOOOHHH it burns!');
  log.fatal('I died! Do you know what that means???');
}

describe('bunyan-format', () => {
  describe('short mode', () => {
    it('renders', () => {
      const formatOut = BunyanFormatWritable({outputMode: 'short'});
      const log = bunyan.createLogger({
        name: 'te-revival-gateway',
        streams: [
          {
            stream: process.stdout,
          },
          {
            stream: formatOut,
          },
        ],
      });

      logSomeMessages(log);
    });
  });

  describe('long mode', () => {
    it('renders', () => {
      const formatOut = BunyanFormatWritable({outputMode: 'long'});
      const log = bunyan.createLogger({
        name: 'te-revival-gateway',
        streams: [
          {
            stream: process.stdout,
          },
          {
            stream: formatOut,
          },
        ],
      });

      logSomeMessages(log);
    });
  });

  describe('structured logging', () => {
    const formatOut = BunyanFormatWritable({outputMode: 'short'});
    const log = bunyan.createLogger({
      name: 'te-revival-gateway',
      streams: [formatOut],
    });

    it('renders templates containing properties correctly', () => {
      log.info({Message: 'Hello, world!'}, 'string {Message}');
      log.info({Message: 12.345}, 'number {Message}');
      log.info({Message: new Date(1547757317342)}, 'date {Message}');
      log.info({Obj: {Name: 'World'}}, 'obj {Obj}');
      log.info({Array: [42, 45]}, 'array {Array}');
      log.info({Message: null}, 'null {Message}');
      log.info({Message: undefined}, 'undefined {Message}');
    });

    it('renders non message properties', () => {
      log.info({Foo: 42, Bar: 'bar'}, 'Hello from {Bar}!');
    });

    it('does not duplicate properties already rendered in output template', () => {
      log.info({Foo: 42, Bar: 42}, '{Foo} {Properties}');
    });

    it('applies json formatting to message structures when specified', () => {
      log.info({Obj: {Name: 'World'}}, 'json {@Obj}');
      log.info({Obj: null}, 'json null {@Obj}');
      log.info({Obj: undefined}, 'json undefined {@Obj}');
    });

    it('forces toString on structures when specified', () => {
      log.info({Obj: {Name: 'World'}}, 'string {$Obj}');
      log.info({Obj: null}, 'string null {$Obj}');
      log.info({Obj: undefined}, 'string undefined {$Obj}');
    });

    it('escapes double brackets', () => {
      log.info({Message: 'Hello, world!'}, 'escape: {{Message}}');
      log.info({Message: 'Hello, world!'}, 'escape: {{$Message}}');
      log.info({Message: 'Hello, world!'}, 'escape: {{@Message}}');
    });
  });
});

A node-bunyan formatter for the console. Use as a stream destination. Colors are configurable; use the Chalk chained API names in an array.

• started with thlorenz/bunyan-format
• replaced most of it with most recent version of CLI tool from trentm/node-bunyan/bin/bunyan
  • Newer code adds local time formatting and improved res and err processing
• refactored to clean up
• wrote tests in Jest
• replaced console coloring logic with Chalk
• added token formatting based on how Serilog and Seq format strings work
• allowed resulting object to be directly included on the bunyan streams array