Fixed-Length Level Logging in Winston

by Michael Scepaniak on November 29, 2015 in software development

Stones

Do you do Node.js development? Do you use winston for logging in your Node application? Are you a stickler for having consistently-aligned content in your log entries? Have you struggled to prevent the log level portion of your log entries from shifting the positioning of your log entry formatting? If so, you might find this helpful.

Note: At the time of this writing, this functionality has been tested/exercised with winston v2.1.1

Suppose we have a Node application that uses winston for logging, with each log entry including timestamp, level, label, and message components. The resultant logs are meant to be human-readable, rather than structured for processing via a CLI tool. Out of the winston box, the log entry components won’t align correctly:

2015-11-28 13:57:58:34 - info: [                index] info message
2015-11-28 13:57:58:34 - verbose: [                index] verbose message
2015-11-28 13:57:58:39 - info: [        my-datasource] MySQL connection pool initialized.
2015-11-28 13:57:58:40 - info: [                index] Server up: http://localhost:3301
2015-11-28 13:57:58:42 - info: [                index] Connected to Mongoose...
2015-11-28 13:57:58:52 - trace: [      loop-controller] trace message
2015-11-28 13:57:58:52 - debug: [      loop-controller] debug message

In these log entries, the message component is the fourth and final component in each log entry (1. timestamp, 2. level, 3. label, and 4. message). However, because the log levels are of varying lengths, the messages are not vertically-aligned, which makes it unnecessarily difficult to visually scan through the log entries.

API Options

The winston API already includes some arguments that would appear to be attempts to address this, but they both come up short. The padLevels arguments tries to determine the longest log level string and pad any shorter log level strings with spaces to arrive at a consistent length. Making use of padLevels improves things:

2015-11-28 13:57:58:34 - info: [                index]    info message
2015-11-28 13:57:58:34 - verbose: [                index] verbose message
2015-11-28 13:57:58:39 - info: [        my-datasource]    MySQL connection pool initialized.
2015-11-28 13:57:58:40 - info: [                index]    Server up: http://localhost:3301
2015-11-28 13:57:58:42 - info: [                index]    Connected to Mongoose...
2015-11-28 13:57:58:52 - trace: [      loop-controller]   trace message
2015-11-28 13:57:58:52 - debug: [      loop-controller]   debug message

All of the messages are aligned as desired. However, the labels are left as-is, unaligned, leaving something to be desired.

The align argument appends a [tab] character to the end of each log level string, which gets us very close to what we want:

2015-11-28 13:57:58:34 - info:     [                index] info message
2015-11-28 13:57:58:34 - verbose:     [                index] verbose message
2015-11-28 13:57:58:39 - info:     [        my-datasource] MySQL connection pool initialized.
2015-11-28 13:57:58:40 - info:     [                index] Server up: http://localhost:3301
2015-11-28 13:57:58:42 - info:     [                index] Connected to Mongoose...
2015-11-28 13:57:58:52 - trace:    [      loop-controller] trace message
2015-11-28 13:57:58:52 - debug:    [      loop-controller] debug message

Unfortunately, this implementation isn’t prepared to handle “exceptionally” long log level strings. As you can see, using “verbose” blows up the alignment in the above example log output. To be fair, this isn’t an unknown issue, as it was brought up when align was first added to the winston API. It’s also worth noting that this argument is only supported in console logging (i.e., not file logging). Bummer.

Custom Formatter

In another discussion regarding log level length normalization in winston, it is suggested that the best way to address this is via a custom formatter. Given the incomplete solutions provided in the API, itself, I tend to agree. So, after a bit of tinkering, I was able to put together a winston formatter that takes the default winston log entry formatting and then modifies it, resulting in perfectly-aligned log entries:

2015-11-28 13:57:58:34 - info : [                index] info message
2015-11-28 13:57:58:34 - verbo: [                index] verbose message
2015-11-28 13:57:58:39 - info : [        my-datasource] MySQL connection pool initialized.
2015-11-28 13:57:58:40 - info : [                index] Server up: http://localhost:3301
2015-11-28 13:57:58:42 - info : [                index] Connected to Mongoose...
2015-11-28 13:57:58:52 - trace: [      loop-controller] trace message
2015-11-28 13:57:58:52 - debug: [      loop-controller] debug message

Simply put, I’m forcing the log level string to conform to a fixed length. In the example above, I’ve chosen to set the level length to 5 characters, causing “verbose” to be truncated. This is by design. If you don’t like that, you can set the length to be longer. Conversely, if you want compact log entries, you can set the level length to be as short as 1 character. Regardless, if you like the look of this, here’s the code. Note that, yes, it does handle colorized log levels. 🙂

/**
 * The fixed (both minimum and maximum) length of the "level" property in each log entry. 
 * Longer values will be truncated, while shorter values will be right-padded with spaces.
 */
var levelLength = 5;

/**
 * Custom log formatter that enforces vertically-aligned log entry components.
 * 
 * @param options - See winston/common.log() for available properties.
 */
var logFormatter = function(options) {
	/* 
	 * The requested level for this log entry, in plain-text. We need to go back to the source 
	 * (options) instead of parsing the output because the output might be colorized (encoded).
	 */
	var levelFull = options.level;
	var levelForDisplay = levelFull;

	// Pad the level.
	if (levelLength > String(levelFull).length) {
		levelForDisplay = levelFull + Array(levelLength - String(levelFull).length + 1).join(' ');
	}
	// And then truncate the level.
	levelForDisplay = levelForDisplay.substring(0, levelLength);

	/**
	 * If the level has been colorized, we need to repeat this colorization of both the search 
	 * and replacement strings.
	 */
	if (options.colorize === 'all' || options.colorize === 'level' || options.colorize === true) {
		levelForDisplay = colors[logColors[levelFull]](levelForDisplay);
		levelFull = colors[logColors[levelFull]](levelFull);
	}

	// Unset the formatter in the options argument so we don't end up in an infinite loop.
	options.formatter = null;

	// Start with winston's default output format.
	var output = winstonCommon.log(options);

	// Perform the actual replacement.
	output = output.replace(levelFull, levelForDisplay);

  	return output;
};

view raw

I hope this helps.

Mike
Want to be notified when new articles are posted?
Enter your email address:

{ 0 comments… add one now }

Leave a Comment

Previous post:

Member of The Internet Defense League