Azure-sdk-for-js: Logging Improvements: A path to structured logging

[jmealo]

It's complex/difficult to set the proper log-levels and namespaces for logging that originates from azure-sdk-for-js modules and Application Insights for inclusion into our application's structured logging. Here's a gist with annotated snippets that gets things working for the most part:
https://gist.github.com/jmealo/ab691efea7c9f8e16cdfd7e39fec888b

Customer Needs:

• Log-levels are determined based on an external developer's perspective consuming that module; rather than that of an internal developer working on the module.
• To allow for grouping log entries together by type, messages should be fixed/static and not contain any dynamic content, the dynamic part of the log entry should go into the structured portion.
• Out of box experience: Reduce overall logging volume by default so that users don't feel compelled to disable it entirely in order to see their own log entries.
• Namespaces: <azure>:<product>:[<functional-area>]:<component> works fine, but it needs to be consistent. Sometimes the log-level is in there and other times it isn't.

Nice to have:

• Performance: Logging isn't free console.error and console.log are blocking. The logger should be cheap/no-op for users who aren't using it. Unless there's a serious reduction in log volume/change in log-level, consider using pino and pino-debug as the default loggers unless the user provides one. It's easy for logging overhead to take the lion's share of available I/O and CPU time if one isn't careful. It would be nice if end-users who want/need their logging to be fast could just plug in fast loggers (or to make them fast by default: async in prod and sync in development as we have in the gist).
• Errors: Ideally the same considerations to internal/external developers applied to logging should apply to error handling.

[chradek]

@jmealo
Thanks for the feedback! @richardpark-msft and I were recently discussing if we could benefit from structured logging so your timing is serendipitous. We've also been concerned that the volume and 'noise' of our logs (thinking specifically of event-hubs and service-bus) are too much to be turned on all the time.

I think I'm in agreement with you on your customer needs section. It's certainly not our intention that the log levels are useful only for internal devs; while the verbose/debug logging admittedly is more useful for us to figure out the cause of an issue, it shouldn't _only_ be useful to us, nor should the other log levels get in the way of external devs.

With regards to why we have the log levels we do today, I believe one of the reasons was to standardize across languages, so setting it to warning in JS would be the same as setting it as warning in .NET. That said, taking another look at what the other language SDKs support, it doesn't look like a clear 1:1 mapping.

I think next steps for us is to take another look at our JS guidelines around logging and also a closer look at the popular loggers used in the JS ecosystem to see how we might converge. I would also love to go through one of our libraries like core-http or core-amqp and see how things would look with structured logging in place.

[jmealo]

@chradek: Looking for a workaround to prevent AQMP buffers from being printed to the terminal. I can't imagine a case when you guys would be using toJSON() on a Buffer... Does this look like a safe way to prevent the AQMP encoded message from getting output?
https://github.com/pinojs/pino/issues/974

[chradek]

Hey @jmealo
We don't call buffer.toJSON() in our libraries, and it doesn't look like rhea-promise or rhea call toJSON() on a buffer either. I think debug ends up using inspect, does pino as well?

If so, you could set the custom inspect symbol on the Buffer prototype so that it just prints something like <Buffer>:

const inspect = Symbol.for("nodejs.util.inspect.custom");
const { Buffer } = require("buffer");
Object.assign(Buffer.prototype, {
  [inspect]() {
    return "<Buffer>";
  }
});

[jmealo]

@chradek: Thanks, that's a really great solution! I gave it a try and unfortunately, Pino doesn't use inspect because they've implemented something quite a bit faster (2-4x faster depending on object complexity) without any known trade-offs. We could definitely solve this in development with a custom pretty-printer; I don't think we're logging buffers in production, I'll know for sure in the next few hours :)

I feel pretty good about the toJSON usage because I can't think of a reason a library author would ever use that in the "happy path".