
Node.js Logging Made Right - keenondrums
https://itnext.io/nodejs-logging-made-right-117a19e8b4ce
======
tjelen
In my experience, it's better to create a "request context" at the beginning
of handling a request and pass it down explicitly to subsequent async calls
that handle the request. I think that this approach is similar to Golang's
"context" package, for example.

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.

~~~
Illniyar
I disagree. Logging is a cross-cutting concern. It is basically the example
used to define what a cross-cutting concern is.

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.

~~~
jondubois
Cross-cutting concerns are an antipattern.

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.

~~~
coldtea
> _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.

~~~
jondubois
>> 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.

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.

------
TheAceOfHearts
I haven't looked into this recently so I don't know if anything has changed,
but when I last looked up Proxy benchmarks I found that it performed very
poorly. Does anyone know if this is no longer the case?

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.

~~~
lxe
You will lose this context when an error is thrown deep in a library somewhere
and your error stack ends up missing most of the useful info. Also how do you
deal with I caught exceptions?

~~~
TheAceOfHearts
This isn't an issue if you're using promises. You can use try/catch from
within async functions and it works exactly as you'd expect.

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
          }
        })
    
    
    

[0] [https://github.com/tj/co](https://github.com/tj/co)

~~~
hombre_fatal
The other main difference between koa and express is that, in express, you
send responses from handlers while in koa, you bubble up a {req,res} context
back to koa which sends it which gives you real middleware since you can still
mutate the response.

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.

------
lysium
Thus is about adding trace ids to the log statement. This is definitely
helpful, but from the title I had expected something else.

------
ex3ndr
Async Hooks? They are insanely slow. If you are using many promises (lie
graphql server) then it will result in x100 performance penalty.

~~~
ch_sm
while there is a performance impact, it shouldn‘t be anywhere near 100x. for
reference: [https://github.com/bmeurer/async-hooks-performance-
impact/bl...](https://github.com/bmeurer/async-hooks-performance-
impact/blob/master/README.md)

~~~
nevir
The implementation for promises is currently a pretty heavy performance hit:

[https://docs.google.com/document/d/1y4lF-
iQhhuSOgzlPIBbfCT4I...](https://docs.google.com/document/d/1y4lF-
iQhhuSOgzlPIBbfCT4IUpg-in3az5Q87C7aY3Q)

The node and v8 teams are working to improve that, but the work hasn't all
landed yet

~~~
jlogsdon
It's not 100x as stated by the OP, but I wouldn't use it (async_hooks) in
situations where performance is actually a concern. I wouldn't use node there
either, but that's besides the point.

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.

~~~
nobleach
I see this "I'd never use node" sentiment quite a bit in the Java community.
I'm always curious for the reason. Is it the JavaScript? or is Node unable to
perform? After reading so many success stories from Netflix and Walmart, I'm
wondering what the missing piece is....

~~~
jlogsdon
Specifically in the area of high CPU load tasks. NodeJS is perfectly fine for
heavily async tasks, especially calling out to external services. When you
have CPU intensive tasks the lack of control over the event loop (task list)
can be painful.

------
halfmatthalfcat
Is Angular's zone.js any different?

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.

[https://github.com/angular/zone.js/](https://github.com/angular/zone.js/)

------
pictur
[https://github.com/stritti/log4js](https://github.com/stritti/log4js)

------
moltar
I like the async hook idea. But I’m having a hard time imagining his unit
tests would work?

~~~
tytho
I worked on a codebase that used the old "domains" this way, and it was very
kludgy. We could get unit tests working, but we essentially mocked calling
that 'set' method before the function we were testing used it. We eventually
ripped it all out in favor of explicitly passing arguments down the async
chain because we found that for some reason those "magic" variables were
leaking across requests. Could have been another factor that caused it, but
the magic was too much for us.

------
z3t4
I just use a incremental counter and closure. For the logging itself you have
to choose between being slow and sync, or fast and async but miss some log
events if you get a crash.

------
TrickyRick
The package he uses (cls-hooked) hasn't been updated for 2 years. Does anyone
know any good alternatives?

