This article was originally published in my personal blog.
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
And now, it’s tiiiiiiiime!
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.
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:
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:
If you are following follow the article, after cloning this repository, I checkout the
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
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.
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.
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.
Now we start touching CLS. First we need to create namespace and expose it to the world:
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:
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
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
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
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:
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.