Give your logs more context - Part 2

This article was originally published in my personal blog.

Building a contextual logger

This is the continuation of my previous article about logging context. Check it out to better understand the purpose of what we will build.

Give your logs more context - Part 1

Henrique Barcelos ・ Feb 6 '20 ・ 8 min read

#node #logging

TL;DR

The code we are going to build on this story is on my Github. If you just want to check out the final version, you can get it at the master branch.

Intro

Last time we walked through a way of managing context through concurrent requests using pino and cls-hooked. Now let’s build a wrapper around pino that will automatically deal with this for us.

And now, it’s tiiiiiiiime!

What do we want to achieve?

We need to build a logger that will have base “global” context through cls-hooked, but will also allow us to augment such context when actually calling the logger methods.

To improve reusability and interoperability, we want to maintain the original default pino API, so we already have a good set of test cases to cover. Also, we need to provide a way for our application interact with the context.

How will we write our code?

We are going to implement this wrapper TDD style. However the tests we will write are not “unit” tests in a strict sense, because they will include pino itself and make assertions about the generated log data. This is possible because pino accepts a custom WritableStream as its destination.

As testing framework, we will use ava. Keep in mind that while ava transpiles test files by default, it doesn’t do that for the actual code without properly setting babel. To avoid adding more complexity to this solution, all code (including tests) will not use ES modules or any features that are not available in Node.js 10.9.0.

If you want do follow along the implementation, please check out the instructions in the Github repository:

hbarcelos / give-your-logs-more-context

Wrapper on top of pino which provides integration with cls-hooked for better context in log messages

Give your logs more context

This repository is the implementation of the ideas from "Give your logs more context" article series:

• Part 1
• Part 2

Requirements

• Yarn

Setup

If you are following follow the article, after cloning this repository, I checkout the initial tag:

git clone https://github.com/hbarcelos/give-your-logs-more-context
git checkout initial

Each step on the article is a subsequent commit, which you can reference by the commit hash.

The final version is under the final tag, which is also the HEAD of the master branch.

git checkout final
# or...
git checkout master

After choosing what you want to see, run:

yarn install
yarn test

View on GitHub

I tried to make this the sequence as natural as possible, only eliminating some inner loops and struggles that happen in a regular coding session.

Implementation steps

Initial setup

yarn init -y
yarn add pino cls-hooked
yarn add --dev ava

A nice feature of pino accepts a custom WritableStream as its destination. This will make our lives easier when testing our custom logger.

Ensuring methods for log levels

For simplicity, lets stick with pino default log levels: trace, debug, info, warn, error and fatal.

The simplest way to achieve that is:

	const pino = require('pino');
	function createLogger(opts, destination) {
	return pino(opts, destination);
	}
	module.exports = createLogger;

view raw logger.js hosted with ❤ by GitHub

	const test = require('ava');
	const parseJSONStream = require('./utils/parse-json-stream');
	const streamToGenerator = require('./utils/stream-to-generator');
	const createLogger = require('./logger');
	async function testMethod(t, input = {}, expected = {}) {
	const { method } = input;
	const { level } = expected;
	const stream = parseJSONStream();
	const logger = createLogger({ level: 'trace' }, stream);
	const gen = streamToGenerator(stream);
	logger[method]('foo');
	const data = await gen.next().value;
	t.is(data.level, level);
	}
	const loggerMethodUseCases = [
	{ input: { method: 'trace' }, expected: { level: 10 } },
	{ input: { method: 'debug' }, expected: { level: 20 } },
	{ input: { method: 'info' }, expected: { level: 30 } },
	{ input: { method: 'warn' }, expected: { level: 40 } },
	{ input: { method: 'error' }, expected: { level: 50 } },
	{ input: { method: 'fatal' }, expected: { level: 60 } },
	];
	loggerMethodUseCases.forEach(({ input, expected }) => {
	test(
	`Logger methods: ${JSON.stringify(input)} - ${JSON.stringify(expected)}`,
	testMethod,
	input,
	expected
	);
	});

view raw logger.test.js hosted with ❤ by GitHub

	const { Transform } = require('stream');
	const parseJSONStream = () =>
	new Transform({
	objectMode: true,
	transform(chunk, encoding, cb) {
	try {
	const data = JSON.parse(chunk.toString('utf8'));
	return cb(null, data);
	} catch (err) {
	return cb(err);
	}
	},
	});
	module.exports = parseJSONStream;

view raw parse-json-stream.js hosted with ❤ by GitHub

	function* streamToGenerator(stream) {
	while (true) {
	const res = yield Promise.race([
	new Promise(resolve => stream.once('data', resolve)),
	new Promise(resolve => stream.once('end', resolve)),
	new Promise((resolve, reject) => stream.once('end', reject)),
	]);
	if (!res) {
	break;
	}
	}
	}
	module.exports = streamToGenerator;

view raw stream-to-generator.js hosted with ❤ by GitHub

The logger.js is currently just a factory function that return plain pino instances. The logger.test.js file generates one test case for each available method to make sure we don’t break anything later.

parse-json-stream.js is a utility that will parse the log output stream and return plain Javascript objects to make it easier to run assertions against the log output.

stream-to-generator.js is there for convenience: ava doesn’t play well with stream-based APIs. To make tests more concise, we convert the logging stream to a generator that yields promises to the next log entry.

The later two are not important in the context of what we are trying to achieve, they are here only for reference. The remaining snippets won’t include them.

Keeping context on logger method call

Also, notice that pino allow us to pass local context to a log entry by prepending an object to the argument list. This is a behavior we want to keep.

So, lets add a test case that covers this scenario:

	diff --git a/logger.test.js b/logger.test.js
	index 8f89251..a841156 100644
	--- a/logger.test.js
	+++ b/logger.test.js
	@@ -13,3 +13,19 @@ loggerMethodUseCases.forEach(({ input, expected }) => {
	expected
	);
	});
	+
	+test(`Properly logs message with context object`, async t => {
	+ const stream = parseJSONStream();
	+ const gen = streamToGenerator(stream);
	+ const logger = createLogger({}, stream);
	+
	+ const context = { dummy: 'value' };
	+ const message = 'foo';
	+
	+ logger.info(context, message);
	+
	+ const entry = await gen.next().value;
	+
	+ t.deepEqual(entry.dummy, context.dummy);
	+ t.deepEqual(entry.msg, message);
	+});

view raw logger.tests.js.diff hosted with ❤ by GitHub

Since so far we are just creating a pino instance, the test will pass.

Adding CLS awareness

Now we start touching CLS. First we need to create namespace and expose it to the world:

	diff --git a/logger.js b/logger.js
	index f78dff6..dbac73a 100644
	--- a/logger.js
	+++ b/logger.js
	@@ -1,7 +1,11 @@
	const pino = require('pino');
	+const { createNamespace } = require('cls-hooked');
	function createLogger(opts, destination) {
	- return pino(opts, destination);
	+ const baseLogger = pino(opts, destination);
	+ const cls = createNamespace('@@logger');
	+
	+ return Object.assign(baseLogger, { cls });
	}
	module.exports = createLogger;

view raw logger.js.diff hosted with ❤ by GitHub

	diff --git a/logger.test.js b/logger.test.js
	index a841156..7b137e0 100644
	--- a/logger.test.js
	+++ b/logger.test.js
	@@ -29,3 +29,9 @@ test(`Properly logs message with context object`, async t => {
	t.deepEqual(entry.dummy, context.dummy);
	t.deepEqual(entry.msg, message);
	});
	+
	+test(`Exposes a CLS namespace`, t => {
	+ const logger = createLogger();
	+
	+ t.truthy(logger.cls);
	+});

view raw logger.tests.js.diff hosted with ❤ by GitHub

Preventing CLS context sharing between instances

For some reason, we might want to have multiple loggers in a given application. When doing that, it’s important to not mix the namespaces of both. However, the way we implemented above, all instances will have the same namespace '@@logger', which could cause strange behavior laters.

The easiest way to fix this would be to have a counter variable that would increment whenever we call createLogger and append the counter value to the namespace name.

While counters are not the most safe bet to generate unique names, since they are reset when the application restarts, they work in this case because all logger instances would be recreated anyway when the server restarts. Also, this value is not exposed anywhere, it serves only for the purpose of creating different namespaces, so we are fine.

Sometimes less is more!

Here’s what’s changed:

	diff --git a/logger.js b/logger.js
	index dbac73a..3aa3418 100644
	--- a/logger.js
	+++ b/logger.js
	@@ -1,9 +1,13 @@
	const pino = require('pino');
	const { createNamespace } = require('cls-hooked');
	+let counter = 0;
	+
	function createLogger(opts, destination) {
	const baseLogger = pino(opts, destination);
	- const cls = createNamespace('@@logger');
	+ const cls = createNamespace(`@@logger-${counter}`);
	+
	+ counter += 1;
	return Object.assign(baseLogger, { cls });
	}

view raw logger.js.diff hosted with ❤ by GitHub

	diff --git a/logger.test.js b/logger.test.js
	index 7b137e0..45c16ca 100644
	--- a/logger.test.js
	+++ b/logger.test.js
	@@ -35,3 +35,10 @@ test(`Exposes a CLS namespace`, t => {
	t.truthy(logger.cls);
	});
	+
	+test(`2 different loggers don't share the same namespace`, t => {
	+ const logger = createLogger();
	+ const anotherLogger = createLogger();
	+
	+ t.notDeepEqual(logger.cls, anotherLogger.cls);
	+});

view raw logger.test.js.diff hosted with ❤ by GitHub

Applying CLS context to logs

This one is a big leap, so bear with me. First, let’s see the changes in the code, then let’s discuss it:

	diff --git a/logger.js b/logger.js
	index 3aa3418..d19e435 100644
	--- a/logger.js
	+++ b/logger.js
	@@ -1,6 +1,41 @@
	const pino = require('pino');
	const { createNamespace } = require('cls-hooked');
	+const logMethods = ['trace', 'debug', 'info', 'warn', 'error', 'fatal'];
	+
	+const logMethodHandler = {
	+ apply(target, thisArg, argumentList) {
	+ // eslint-disable-next-line camelcase
	+ const { id, _ns_name, ...clsContext } =
	+ ((thisArg || {}).cls || {}).active || {};
	+
	+ const [context, ...rest] = argumentList;
	+
	+ let finalArgList = argumentList;
	+ if (typeof context === 'string') {
	+ // Log was called only with message, no local context
	+ const message = context;
	+ finalArgList = [clsContext, message, ...rest];
	+ } else {
	+ // Log was called local context, so we merge it into clsContext
	+ const fullContext = Object.assign({}, clsContext, context);
	+ finalArgList = [fullContext, ...rest];
	+ }
	+
	+ return target.apply(thisArg, finalArgList);
	+ },
	+};
	+
	+const loggerObjectHandler = {
	+ get(target, prop) {
	+ if (!logMethods.includes(prop)) {
	+ return target[prop];
	+ }
	+
	+ return new Proxy(target[prop], logMethodHandler);
	+ },
	+};
	+
	let counter = 0;
	function createLogger(opts, destination) {
	@@ -9,7 +44,7 @@ function createLogger(opts, destination) {
	counter += 1;
	- return Object.assign(baseLogger, { cls });
	+ return new Proxy(Object.assign(baseLogger, { cls }), loggerObjectHandler);
	}
	module.exports = createLogger;

view raw logger.js.diff hosted with ❤ by GitHub

	diff --git a/logger.test.js b/logger.test.js
	index 45c16ca..155415a 100644
	--- a/logger.test.js
	+++ b/logger.test.js
	@@ -42,3 +42,61 @@ test(`2 different loggers don't share the same namespace`, t => {
	t.notDeepEqual(logger.cls, anotherLogger.cls);
	});
	+
	+test.cb(`Should properly log message with cls context`, t => {
	+ const stream = parseJSONStream();
	+ const gen = streamToGenerator(stream);
	+ const logger = createLogger({}, stream);
	+
	+ const msg = 'foo';
	+ const clsValues = {
	+ dummy: 'value',
	+ another: 'another value',
	+ };
	+
	+ logger.cls.run(() => {
	+ logger.cls.set('dummy', clsValues.dummy);
	+ logger.cls.set('another', clsValues.another);
	+ process.nextTick(async () => {
	+ logger.info(msg);
	+
	+ const entry = await gen.next().value;
	+
	+ t.is(entry.dummy, clsValues.dummy);
	+ t.is(entry.another, clsValues.another);
	+
	+ t.end();
	+ });
	+ });
	+});
	+
	+test.cb(
	+ `Should properly log message with both cls and local context,
	+ And local context should have precedence over cls context`,
	+ t => {
	+ const stream = parseJSONStream();
	+ const gen = streamToGenerator(stream);
	+ const logger = createLogger({}, stream);
	+
	+ const msg = 'foo';
	+ const clsValues = {
	+ dummy: 'value',
	+ precedence: 'will be overwitten',
	+ };
	+
	+ logger.cls.run(() => {
	+ logger.cls.set('dummy', clsValues.dummy);
	+ logger.cls.set('another', clsValues.another);
	+ process.nextTick(async () => {
	+ const localValues = { precedence: 'local' };
	+ logger.info(localValues, msg);
	+
	+ const entry = await gen.next().value;
	+
	+ t.is(entry.precedence, localValues.precedence);
	+
	+ t.end();
	+ });
	+ });
	+ }
	+);

view raw logger.test.js.diff hosted with ❤ by GitHub

Sorry, I couldn’t break this into smaller changes :/

The test code has nothing special about it, just notice that we must run our logging and assertion within the logger.cls.run method callback.

Things start to get interesting on the actual code though. We are leveraging Javascript Proxy to intercept log method calls and patch their arguments.

So, in line 52 we create a proxy for our logger object, whose handler is named a loggerObjectHandler— lines 34–43. The handler defines a get trap, that will intercept only the calls for the log methods — trace, debug, etc. What it does is wrap those methods into yet another proxy, whose handler is named logMethodHandler — lines 11–32.

The loggerMethodHandler gathers the current active context on CLS, excluding some irrelevant properties from it — lines 14–15. Then, based on the current argument list, it checks whether we have or not a local context on the method call. If we don’t, then we simply need to prepend the CLS context to the argument list — lines 20–23. Otherwise, we need to merge the local context into the CLS context — lines 24–28. Finally, we call the original method with the proper arguments — line 30.

Propagating changes to child loggers

A nice feature from pino is that it allows us to create child loggers through the .child() method. A child logger maintains all properties from its parent, but can also accept additional context. So, we need to make our child generation CLS aware too:

	diff --git a/logger.js b/logger.js
	index d19e435..d2740cd 100644
	--- a/logger.js
	+++ b/logger.js
	@@ -1,8 +1,6 @@
	const pino = require('pino');
	const { createNamespace } = require('cls-hooked');
	-const logMethods = ['trace', 'debug', 'info', 'warn', 'error', 'fatal'];
	-
	const logMethodHandler = {
	apply(target, thisArg, argumentList) {
	// eslint-disable-next-line camelcase
	@@ -26,25 +24,47 @@ const logMethodHandler = {
	},
	};
	+const childMethodHandler = {
	+ apply(target, thisArg, argumentList) {
	+ const { cls } = thisArg;
	+
	+ // eslint-disable-next-line no-use-before-define
	+ return createWrapper({ cls }, target.apply(thisArg, argumentList));
	+ },
	+};
	+
	+const logMethods = ['trace', 'debug', 'info', 'warn', 'error', 'fatal'];
	+const childMethod = 'child';
	+
	const loggerObjectHandler = {
	get(target, prop) {
	- if (!logMethods.includes(prop)) {
	- return target[prop];
	+ if (logMethods.includes(prop)) {
	+ return new Proxy(target[prop], logMethodHandler);
	+ }
	+
	+ if (prop === childMethod) {
	+ return new Proxy(target[prop], childMethodHandler);
	}
	- return new Proxy(target[prop], logMethodHandler);
	+ return target[prop];
	},
	};
	+function createWrapper({ cls }, pinoInstance) {
	+ const baseLogger = Object.assign(pinoInstance, { cls });
	+
	+ return new Proxy(baseLogger, loggerObjectHandler);
	+}
	+
	let counter = 0;
	function createLogger(opts, destination) {
	- const baseLogger = pino(opts, destination);
	const cls = createNamespace(`@@logger-${counter}`);
	-
	counter += 1;
	- return new Proxy(Object.assign(baseLogger, { cls }), loggerObjectHandler);
	+ const pinoInstance = pino(opts, destination);
	+
	+ return createWrapper({ cls }, pinoInstance);
	}
	module.exports = createLogger;

view raw logger.js.diff hosted with ❤ by GitHub

	diff --git a/logger.test.js b/logger.test.js
	index 155415a..c1cb970 100644
	--- a/logger.test.js
	+++ b/logger.test.js
	@@ -100,3 +100,69 @@ test.cb(
	});
	}
	);
	+
	+test.cb(`Should properly propagate cls context to child logger`, t => {
	+ const stream = parseJSONStream();
	+ const gen = streamToGenerator(stream);
	+ const logger = createLogger({}, stream);
	+
	+ const msg = 'foo';
	+ const clsValues = {
	+ dummy: 'value',
	+ another: 'another value',
	+ };
	+
	+ const childContext = { foo: 'bar' };
	+ const child = logger.child(childContext);
	+
	+ logger.cls.run(() => {
	+ logger.cls.set('dummy', clsValues.dummy);
	+ logger.cls.set('another', clsValues.another);
	+ process.nextTick(async () => {
	+ child.info(msg);
	+
	+ const entry = await gen.next().value;
	+
	+ t.is(entry.dummy, clsValues.dummy);
	+ t.is(entry.another, clsValues.another);
	+ t.is(entry.foo, childContext.foo);
	+
	+ t.end();
	+ });
	+ });
	+});
	+
	+test.cb(`Should properly propagate cls context to grand child logger`, t => {
	+ const stream = parseJSONStream();
	+ const gen = streamToGenerator(stream);
	+ const logger = createLogger({}, stream);
	+
	+ const msg = 'foo';
	+ const clsValues = {
	+ dummy: 'value',
	+ another: 'another value',
	+ };
	+
	+ const childContext = { foo: 'bar' };
	+ const child = logger.child(childContext);
	+
	+ const grandChildContext = { fizz: 'buzz' };
	+ const grandChild = child.child(grandChildContext);
	+
	+ logger.cls.run(() => {
	+ logger.cls.set('dummy', clsValues.dummy);
	+ logger.cls.set('another', clsValues.another);
	+ process.nextTick(async () => {
	+ grandChild.info(msg);
	+
	+ const entry = await gen.next().value;
	+
	+ t.is(entry.dummy, clsValues.dummy);
	+ t.is(entry.another, clsValues.another);
	+ t.is(entry.foo, childContext.foo);
	+ t.is(entry.fizz, grandChildContext.fizz);
	+
	+ t.end();
	+ });
	+ });
	+});

view raw logger.test.js.diff hosted with ❤ by GitHub

Again, the new tests are self-descriptive. Let’s focus on the implementation. First we extracted the wrapper creation into its own function, named createWrapper — lines 47–52. This allows us to create a wrapper for the child loggers as well.

Next, we define a childMethodHandler which will intercept the calls to .child() — lines 18–25. This handler will call createWrapper on the newly created child logger, passing the CLS context from the parent as a parameter. This will guarantee that parent and children (and children of children) all have the same context.

Lastly, we change the implementation of loggerObjectHandler to include the proxy for the .child() method as well — lines 30–45 — including some internal refactoring on the conditionals.

Further improvements

Seems like our code works so far, but it might not be optimal. An issue that is easy to spot is that we are creating new proxies on the fly for every call on the child and log methods. While this might not be an issue with the former — because we wouldn’t call .child() very often — that’s not true for the latter.

To prevent this problem, we could create the proxies for the desired methods by the time we create the logger itself and put them as properties of the logger object. When we call the methods, the loggerObjectHandler would just check to see if there is a proxy set for the current method. If so, it returns the proxy, otherwise, it returns the original property:

	diff --git a/logger.js b/logger.js
	index d19e435..decb76b 100644
	--- a/logger.js
	+++ b/logger.js
	@@ -1,8 +1,6 @@
	const pino = require('pino');
	const { createNamespace } = require('cls-hooked');
	-const logMethods = ['trace', 'debug', 'info', 'warn', 'error', 'fatal'];
	-
	const logMethodHandler = {
	apply(target, thisArg, argumentList) {
	// eslint-disable-next-line camelcase
	@@ -26,25 +24,59 @@ const logMethodHandler = {
	},
	};
	+const childMethodHandler = {
	+ apply(target, thisArg, argumentList) {
	+ const { cls } = thisArg;
	+
	+ // eslint-disable-next-line no-use-before-define
	+ return createWrapper({ cls }, target.apply(thisArg, argumentList));
	+ },
	+};
	+
	const loggerObjectHandler = {
	get(target, prop) {
	- if (!logMethods.includes(prop)) {
	- return target[prop];
	+ if (target.createProxies && target.createProxies[prop]) {
	+ return target.createProxies[prop];
	}
	- return new Proxy(target[prop], logMethodHandler);
	+ return target[prop];
	},
	};
	+const createProxies = target => ({
	+ trace: new Proxy(target.trace, logMethodHandler),
	+ debug: new Proxy(target.debug, logMethodHandler),
	+ info: new Proxy(target.info, logMethodHandler),
	+ warn: new Proxy(target.warn, logMethodHandler),
	+ error: new Proxy(target.error, logMethodHandler),
	+ fatal: new Proxy(target.fatal, logMethodHandler),
	+ child: new Proxy(target.child, childMethodHandler),
	+});
	+
	+function createWrapper({ cls }, pinoInstance) {
	+ const baseLogger = Object.create(pinoInstance, {
	+ cls: {
	+ value: cls,
	+ },
	+ });
	+ const loggerWithProxies = Object.create(baseLogger, {
	+ proxies: {
	+ value: createProxies(baseLogger),
	+ },
	+ });
	+
	+ return new Proxy(loggerWithProxies, loggerObjectHandler);
	+}
	+
	let counter = 0;
	function createLogger(opts, destination) {
	- const baseLogger = pino(opts, destination);
	const cls = createNamespace(`@@logger-${counter}`);
	-
	counter += 1;
	- return new Proxy(Object.assign(baseLogger, { cls }), loggerObjectHandler);
	+ const pinoInstance = pino(opts, destination);
	+
	+ return createWrapper({ cls }, pinoInstance);
	}

view raw logger.js.diff hosted with ❤ by GitHub

Integrating with our web application

So now we have our logger factory. Now we need to integrate it with our application. From the final example from the previous article, we could refactor to:

	const express = require('express');
	const cuid = require('cuid');
	const createLogger = require('./logger.js');
	const PORT = Number(process.env.PORT) || 8080;
	function clsRequestId(namespace, generateId) {
	return (req, res, next) => {
	const requestId = req.get('X-Request-Id') || generateId();
	res.set('X-Request-Id', requestId);
	namespace.run(() => {
	namespace.set('requestId', requestId);
	next();
	})
	}
	}
	const app = express();
	const logger = createLogger({ level: 'trace' });
	app.use(clsRequestId(logger.cls, cuid));
	app.get('/', async (req, res) => {
	const result = await handler();
	return res.json(result);
	})
	app.listen(PORT, () => {
	logger.info(
	{ endpoint: `http://localhost:${POINT}` },
	'App is running!'
	)
	})
	function delay(timeoutMs) {
	return new Promise(resolve => {
	setTimeout(() => {
	resolve()
	}, timeoutMs);
	})
	}
	function randomInteger(min, max) {
	return Math.floor(Math.random() * (max - min + 1)) + min;
	}
	async function handler() {
	const namespace = getNamespace('logger');
	logger.info({ requestId: namespace.get('requestId') }, 'Before')
	await delay(randomInteger(1000, 10000));
	logger.info({ requestId: namespace.get('requestId') }, 'Middle')
	await delay(randomInteger(1000, 10000));
	logger.info({ requestId: namespace.get('requestId') }, 'After')
	return {};
	}

view raw app.js hosted with ❤ by GitHub

Outro

The code above is pretty much the same I have successfully used in production some times and have saved me and the teams I worked with a lot of time while debugging.

If you have any suggestions that could improve it, you are more than welcome.

---

Did you like what you just read? Buy me a beer with tippin.me.