11 ms·

Node.js Logging Made Right

85 points by keenondrums 8y ago

pictur 8y ago
https://github.com/stritti/log4js https://github.com/stritti/log4js
moltar 8y ago
I like the async hook idea. But I’m having a hard time imagining his unit tests would work?
- tytho 8y ago
  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.
lysium 8y ago
Thus is about adding trace ids to the log statement. This is definitely helpful, but from the title I had expected something else.
ex3ndr 8y ago
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 8y ago
  while there is a performance impact, it shouldn‘t be anywhere near 100x. for reference: https://github.com/bmeurer/async-hooks-performance-impact/blob/master/README.md https://github.com/bmeurer/async-hooks-performance-impact/bl...
  - nevir 8y ago
    The implementation for promises is currently a pretty heavy performance hit: https://docs.google.com/document/d/1y4lF-iQhhuSOgzlPIBbfCT4IUpg-in3az5Q87C7aY3Q 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
    - jlogsdon 8y ago
      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 8y ago
        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 8y ago
        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.
        debug-desperado 8y ago
        It’s not just Java, it’s any programmer with proficiency in any other language, including those that are quite proficient at JavaScript. The sentiment after our team wrapped up a recent Node project for a client was basically “the internet keeps lying about the maturity of the node ecosystem”. That was with the latest TypeScript and an architect who was very good. 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.
- lxe 8y ago
  What if you don’t utilize promiseResolved hook? What is the practical performance hit for the rest of the tickobject/tcpwrap/etc hooked resources?
tjelen 8y ago
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.
- cromantin 8y ago
  Yes. This is correct way to do logging. Pass an object with request, user, logger and other attributes around as you process it. This is basically "session"
  - niftylettuce 8y ago
    This is the exact problem I solved with CabinJS; making this simple on both client and server. I've tried nearly every logging service and they continually get one thing or the other wrong (even after my attempts to fix them). https://cabinjs.com https://cabinjs.com
    - simlevesque 8y ago
      Hapi.js does this natively.
      - niftylettuce 8y ago
        No, it does not do it to best standards and simplicity. Hapi itself is also incredibly convoluted and bloated.
- paulddraper 8y ago
  I believe just the opposite. 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.
TheAceOfHearts 8y ago
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.
- dadschool 8y ago
  Agreed, we append a logging function to the request context and inject it where needed. With async/await it actually isnt too unwieldily, though it was a bit more intrusive with promises. I think a lot of guys from multithreaded backgrounds (in my case java) often struggle with this approach because looks like such an anti-pattern for them.
- lxe 8y ago
  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 8y ago
    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
halfmatthalfcat 8y ago
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/
TrickyRick 8y ago
The package he uses (cls-hooked) hasn't been updated for 2 years. Does anyone know any good alternatives?
z3t4 8y ago
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.

85 points by keenondrums 8y ago

pictur 8y ago

https://github.com/stritti/log4js https://github.com/stritti/log4js

moltar 8y ago

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

tytho 8y ago
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.

lysium 8y ago

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

ex3ndr 8y ago

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 8y ago
while there is a performance impact, it shouldn‘t be anywhere near 100x. for reference: https://github.com/bmeurer/async-hooks-performance-impact/blob/master/README.md https://github.com/bmeurer/async-hooks-performance-impact/bl...
- nevir 8y ago
  The implementation for promises is currently a pretty heavy performance hit: https://docs.google.com/document/d/1y4lF-iQhhuSOgzlPIBbfCT4IUpg-in3az5Q87C7aY3Q 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
  - jlogsdon 8y ago
    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 8y ago
      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 8y ago
        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.
      - debug-desperado 8y ago
        It’s not just Java, it’s any programmer with proficiency in any other language, including those that are quite proficient at JavaScript. The sentiment after our team wrapped up a recent Node project for a client was basically “the internet keeps lying about the maturity of the node ecosystem”. That was with the latest TypeScript and an architect who was very good. 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.
lxe 8y ago
What if you don’t utilize promiseResolved hook? What is the practical performance hit for the rest of the tickobject/tcpwrap/etc hooked resources?

tjelen 8y ago

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.

cromantin 8y ago
Yes. This is correct way to do logging. Pass an object with request, user, logger and other attributes around as you process it. This is basically "session"
- niftylettuce 8y ago
  This is the exact problem I solved with CabinJS; making this simple on both client and server. I've tried nearly every logging service and they continually get one thing or the other wrong (even after my attempts to fix them). https://cabinjs.com https://cabinjs.com
  - simlevesque 8y ago
    Hapi.js does this natively.
    - niftylettuce 8y ago
      No, it does not do it to best standards and simplicity. Hapi itself is also incredibly convoluted and bloated.
paulddraper 8y ago
I believe just the opposite. 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.

TheAceOfHearts 8y ago

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.

dadschool 8y ago
Agreed, we append a logging function to the request context and inject it where needed. With async/await it actually isnt too unwieldily, though it was a bit more intrusive with promises. I think a lot of guys from multithreaded backgrounds (in my case java) often struggle with this approach because looks like such an anti-pattern for them.
lxe 8y ago
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 8y ago
  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

halfmatthalfcat 8y ago

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/

TrickyRick 8y ago

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

z3t4 8y ago

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.