# Give your logs more context — Part 2

# Give your logs more context

## 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.


%[https://blog.henriquebarcelos.dev/give-your-logs-more-context-7b43ea6b4ae6]


# TL;DR

The code we are going to build on this story is on my [Github](https://github.com/hbarcelos/give-your-logs-more-context). 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`](https://github.com/pinojs/pino) and [`cls-hooked`](https://github.com/jeff-lewis/cls-hooked]). Now let’s build a wrapper around `pino` that will automatically deal with this for us.

![bruce-buffer.jpeg](https://cdn.hashnode.com/res/hashnode/image/upload/v1580839364396/sXqNF6Lzz.jpeg)

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](https://github.com/pinojs/pino/blob/master/docs/api.md), 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`](https://nodejs.org/api/stream.html#stream_writable_streams) as its destination.

As testing framework, we will use [`ava`](https://github.com/avajs/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:

%[https://github.com/hbarcelos/give-your-logs-more-context]

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

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

A nice feature of `pino` accepts a custom [`WritableStream`](https://nodejs.org/api/stream.html#stream_writable_streams) 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:


%[https://gist.github.com/hbarcelos/62c2e8bf5dfb20806204eef4303d1e59]


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](http://2ality.com/2015/03/es6-generators.html) 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:


%[https://gist.github.com/hbarcelos/f5274dc0233357a1de1d216d5b06eb9b]


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:

%[https://gist.github.com/hbarcelos/44ea8013acefcc36afab34cba1e133c6]

## 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:


%[https://gist.github.com/hbarcelos/a276e1cad0e3813e40536627188b25ba]


## 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:

%[https://gist.github.com/hbarcelos/a351b95fd869240f87cd12d5ad202742#file-logger-js-diff]


![such-wow.jpeg](https://cdn.hashnode.com/res/hashnode/image/upload/v1580839917043/7noJIXQB9.jpeg)

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](https://developer.mozilla.org/en-US/docs/Web/JavaScript/Reference/Global_Objects/Proxy) to intercept log method calls and patch their arguments.

So, in [line 52](https://gist.github.com/hbarcelos/a351b95fd869240f87cd12d5ad202742#file-logger-js-diff-L52) we create a proxy for our logger object, whose handler is named a `loggerObjectHandler`— [lines 34–43](https://gist.github.com/hbarcelos/a351b95fd869240f87cd12d5ad202742#file-logger-js-diff-L34-L43). The handler defines a [`get`](https://developer.mozilla.org/en-US/docs/Web/JavaScript/Reference/Global_Objects/Proxy/handler/get) [trap](https://developer.mozilla.org/en-US/docs/Web/JavaScript/Reference/Global_Objects/Proxy/handler/get), 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](https://gist.github.com/hbarcelos/a351b95fd869240f87cd12d5ad202742#file-logger-js-diff-L11-L32).

The `loggerMethodHandler` gathers the current active context on CLS, excluding some irrelevant properties from it — [lines 14–15](https://gist.github.com/hbarcelos/a351b95fd869240f87cd12d5ad202742#file-logger-js-diff-L14-L15). 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](https://gist.github.com/hbarcelos/a351b95fd869240f87cd12d5ad202742#file-logger-js-diff-L20-L23). Otherwise, we need to merge the local context into the CLS context — [lines 24–28](https://gist.github.com/hbarcelos/a351b95fd869240f87cd12d5ad202742#file-logger-js-diff-L24-L28). Finally, we call the original method with the proper arguments — [line 30](https://gist.github.com/hbarcelos/a351b95fd869240f87cd12d5ad202742#file-logger-js-diff-L30).

## 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:


%[https://gist.github.com/hbarcelos/3c0d258329696e306c10ba3d3451d871]


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](https://gist.github.com/hbarcelos/3c0d258329696e306c10ba3d3451d871#file-logger-js-diff-L47-L52). 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](https://gist.github.com/hbarcelos/3c0d258329696e306c10ba3d3451d871#file-logger-js-diff-L18-L25). 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](https://gist.github.com/hbarcelos/3c0d258329696e306c10ba3d3451d871#file-logger-js-diff-L30-L45) — 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:


%[https://gist.github.com/hbarcelos/3931682d74d7fe2bddf1ba436450832a]


# 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](/give-your-logs-more-context-7b43ea6b4ae6), we could refactor to:


%[https://gist.github.com/hbarcelos/3a2c5ff5c3ddbef84f56a9febb4ccdb6#file-app-js]


# 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.

* * *

![deadpool-thats-all-folks.jpeg](https://cdn.hashnode.com/res/hashnode/image/upload/v1580840219703/NfI1RO7Cs.jpeg)

Did you like what you just read? Buy me a beer with [tippin.me](https://tippin.me/@hbarcelos909).