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.

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:

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:

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:

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:

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:

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:

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:

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:

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:

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.