Node.js Logging Made Right
itnext.io
itnext.io
As other commenters note, using CLS (via async hooks or domains) is often too much magic and can possibly cause leaks or at least it results in program logic that's hard to reason about and hard to test.
Explicitly passing the context is robust but in my experience becomes neglected because of the extra work involved everywhere and so just doesn't happen. (The tracing equivalent of requiring a password so strong that people write it on sticky notes.)
My C++, Python, Ruby, C#, and Java runtimes provides thread local storage without cooperation from every function; I don't see why it's improper for my JS runtime to do the same.
I want my cross-cutting concerns to be as invisible as possible, I definitely do not want them to proliferate through all function calls I make in the app.
I do not believe domains or async hooks is too much magic, and they are pretty sound when used properly. As long as they are used responsibly and in a limited setting it is just the right amount of magic.
Logging should not happen inside libraries or submodules. Libraries should expose errors and exceptions either via throwing or message passing (e.g. dispatching error events). Logging should happen at the top-level of the application from a central place (logging logic should not be scattered all over the source code). The top level application logic should aggregate errors from children components/libraries and decide how to log them. This makes it easy to change the default logger and to customize various aspects of the logging.
When you scatter logging logic everywhere throughout your source code, you break the principle of separation of concerns which is probably the most important principle of software development. Even the term 'cross-cutting concern' implies a violation of separation of concerns (a violation of the cross-cutting kind to be exact). A concern cannot be both separate and cross-cutting.
That's because logging is not a concern of your app -- it's a secondary need that's orthogonal (hence cross-cutting) to its actual concerns, and which is there regardless of the app.
Changing your whole app's structure just so that you collect things to log in a central place (as you propose), would be the real violation of concerns.
Not to mention this way you pass around information that might be useless for the purposes of the app (and is just needed for debugging), that it's enough that separate components know themselves internally.
Maybe it depends on what kind of language/platform you use but if each component is able to dispatch events on itself instead of logging, then that does not require changing the whole app's structure.
The only concern of the top level application logic would be monitoring/reporting so logging fits naturally under that label.
The context pattern exists because go routines don't have parent child relationships.
My initial reaction to this is "just because you can doesn't mean you should". Perhaps that's a bit harsh, but it seems wasteful to be creating these wrappers instead of just adding the desired functionality directly to your favorite logging library. Did you try bringing it up with the people maintaining the wrapped libraries? It's also worth mentioning that async_hooks is considered an experimental API.
The simpler solution is to stick a unique id in the context object of each request, perhaps passing around a request-specific log function as well if needed. You should have access to it from all your call sites so you can pass it in as needed, and there's no need for magic.
A few years before async functions were available you could also achieve the same thing with generators. In fact, the original release of koa used co [0] under the hood.
I'll note my response is written with koa middleware in mind. I haven't kept up much with express, although I think it should be possible to achieve the same thing since they also support async functions.
With koa you can add a middleware that wraps all downstream middleware in a try/catch:
app.use(async (ctx, next) => {
try {
await next()
} catch (error) {
// handle errors
}
})
The promise chaining nature also makes it so that your example handler can catch all downstream errors unlike express where you must call next(err) and handle it in a downstream handler vs koa's upstream middleware pattern (clojure's ring works the same way).
I thank co and early koa for making node bearable for me long before async/await were available.
https://docs.google.com/document/d/1y4lF-iQhhuSOgzlPIBbfCT4I...
The node and v8 teams are working to improve that, but the work hasn't all landed yet
async_hooks are 100% usable in production right now, we use it at my current gig for tracing and its had minimal impact on the services using it.
The event loop model that Node uses is easily replicated in other programming languages. It’s not a sensible default though, blocking code is better for most domains.
Bluebird is bad for measuring async hooks because they have custom scheduler and most of the execution is done in single tick.
Overhead is for each tick, not each promise. If you have ~10 promises per request then you have N overhead if you will have 1000 promises you will get 100N overhead.
Our backend barely survived this after async hooks was just enabled and just disabling them make everything x100 faster.
Not really a long term solution.
We adapted approach with context from golang and now it works really well.
I've used it to do essentially the same thing. Create a new zone for every request that comes in and all async functions within that zone can utilize the id assigned to it's zone for request tracking.