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.
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
Last time we walked through a way of managing context through concurrent requests using
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.
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:
The simplest way to achieve that is:
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.
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.
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 —
debug, etc. What it does is wrap those methods into yet another proxy, whose handler is named
logMethodHandler — lines 11–32.
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.
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:
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.