Skip to content

Instantly share code, notes, and snippets.

@ngbrown

ngbrown/bunyan-format.js

Last active Jan 17, 2019
Embed
What would you like to do?
bunyan-format for node
'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();
};
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}}');
});
});
});
@ngbrown

This comment has been minimized.

Copy link
Owner Author

@ngbrown ngbrown commented Jan 17, 2019

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
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment