[RFC] Pluggable log handler

[jasonpincin]

Would you consider a PR that implemented support for globally defaulting log to something other than process.stderr? The way I’d expect this to work is debug would default to stderr unless process[Symbol.for(‘DEBUG_LOG’)] was set. Of course the local self.log would always take precedence.

The motivation for this feature is to allow an application to redirect all debug output to a logger of its choice, without knowing which all dependencies utilize debug.

I’ve chosen a global Symbol to circumvent the issue of multiple versions of debug in codebase.

Happy to submit this. Thoughts?

[Qix-]

It might be much more practical to just have a top level function on the debug instance. However, it's usually an anti-pattern to modify a package's state in a way that affects other packages.

EventEmitters are a good candidate here, too.

const debug = require('debug');

debug.on('log', msg => writeToSomeStream(msg));

[jasonpincin]

The problem with both of these solutions, is I need to know/iterate all of my dependencies that support debug and set up a listener or call a function on each of their debug instances.

The goal is to re-direct all debug output to a stream other than stdout. An example of why this is useful: to wrap log statements in a structured document so they're coalesced in a log management system, rather than having the messages parsed by line, which makes the debug output completely unreadable in any system other than console or a console redirect.

[Qix-]

Right now it's going to stderr FWIW. Also, why not just use shell redirection?

I still think a top-level function that receives all of the raw output (that defaults to console.error()) would solve your problem.

I also think this is a bit of an anti-pattern, personally.

[jasonpincin]

Yes, stderr, thank you. Shell redirection offers no way to correlate multiple lines. For example, if one debug.log call results in 3 lines being written to stderr, I have no way of correlating them there. If I can redirect in-process, to something like Bunyan, then all three lines are correlated by virtue of the fact that they're in a single structured (JSON) document by the time they reach stderr or stdout.

If I have 3 modules, all using debug, that I authored, and I require them into my application - how do I instruct all three modules to output to my top level function?

I can appreciate that you think it's an anti-pattern; however, all I'm trying to do is control how my application handles debug output. If anything here is an anti-pattern, it's the fact that a dependency is outputting to stderr and there's nothing my application, which should govern all I/O, can do about it.

If this is out-of-scope for debug, that's fine. The reason I opened the issue prior to writing a PR was to suss out the receptiveness.

[Qix-]

You wouldn't, it'd be a top level function that belongs to the module itself, therefore not requiring that you edit the code that uses the module. But as I said before, this is usually an anti-pattern.

[jasonpincin]

Ok; happy to implement this if this is something that you’d consider, but I’m getting the feeling you consider this to be an anti-pattern.

Let me know if you decide otherwise.

[Qix-]

Definitely something I'm considering. I have an idea on how this will happen - stay tuned.

[Qix-]

Within the discussion of #644 the idea of using node -r was brought up. I might be a bit biased, but I think it's a novel way of solving this problem.

Similar to SLF4J, adding log handlers at the end user level is becoming a common theme among use cases (see the closed issues above this comment). I think we should solve it as such.

I think adding a global log handler would be ideal, allowing extensions that use node -r to plug into it before the application is run.

Take the following example implementation:

// debug.js
let handler = (ns, msg) => console.error(`\x1b[2m${ns}\x1b[m`, msg);

const debug = ns => {
	return msg => handler(ns, msg);
};

debug.setHandler = _handler => {
	handler = _handler;
};

module.exports = debug;

// handler.js
const debug = require('./debug');
debug.setHandler((ns, msg) => console.error(JSON.stringify({
	namespace: ns,
	message: msg
})));

// index.js
const debug = require('./debug')('foo:bar');

debug('hello, world!');
debug({foo: 'bar'});

$ node index.js
foo:bar hello, world!
foo:bar { foo: 'bar' }

$ node -r ./handler.js index.js
{"namespace":"foo:bar","message":"hello, world!"}
{"namespace":"foo:bar","message":{"foo":"bar"}}

This solves a lot of the problems, features and pains users have felt for a while. Coupled with #644, this could be a large step forward whilst being backward compatible (with a default compatibility handler for the time being).

Thoughts?

cc @TooTallNate

[jasonpincin]

The node -r option is a nice to have, but orthogonal to the issue raised here and proposed solution. What you’re suggesting would certainly solve the situation we’ve found ourselves in. And would remove some hacky code we’ve had to put in to patch this behavior. 👍

[Qix-]

They would go hand in hand @jasonpincin. :)

[jasonpincin]

Sure. Just saying it’s not a requirement right? My app can internally bind the log handler.

[aurbano]

@Qix- I believe this is relevant here so I'll post it as a comment instead of a new issue (let me know if you'd rather have it as a separate issue though)

I'm trying to stream all debug messages generated in a server via a websocket, is there an elegant way to listen to all messages sent to debug so that I can stream them, but still having them reported in the usual way (stdout)?

[Qix-]

No, not elegant or "correct". That's exactly what this issue would solve.

[aurbano]

@Qix- Thanks for the quick reply! So I guess the only non-hacky way will be to wait for the release of v5, I'll keep an eye on it!

[Qix-]

Yes, sadly :| I have some vacation coming up and hope to knock out a ton of OSS that has built up.

[bodaro]

I too am looking for a similar feature (and for node). Specifically I would like to be able to prepend all debug statements with some process-specific string that can later be used by AWS Cloudwatch Insights to parse log statements based on process-specific information.

For example, I would like to add a unique ID and process name to every debug statement and set this once in my application (not on every file). This makes it easy to filter multiple application's log statements (in AWS Log Insights) so I can see logging for just a a particular run of my process. Typically, an error would be reported by some mechanism (email) and filtering would allow me to see just the log statements that came in the same process just before the error line.

I would like to take this one step further and turn all log statements into a json string. This would give me some well-known structure for all debug statements in my specific application and that json makes it easy to filter in AWS Log Insights.

One thing to note is that I have a require debug in all my source code files and I do not want to modify each and every instance to have this data pre-pended.

[Qix-]

@bodaro This would fit your use-case, but #582 is more what you'd be looking for.

[bodaro]

RE: #582

If using the suggested #582 fix, In order to add a prefix to all log messages that is process specific, could I do something like this to set the ENV programmatically:

process.env.DEBUG_FORMAT=${process.env.PROCESS_UNIQ_ID} %N %m %D

[Qix-]

@bodaro Yep, or just set it directly via DEBUG_FORMAT. Either way.

[Qix-]

Doing a bit of poking around on this today, this appears to be soft-blocked by nodejs/node#40110. Not a deal-breaker but it'll be less than advantageous without allowing users to do this with ESM modules.

The other issue is code-based linkage. If you add a handler via code instead of pre-loading modules, then we'll run into the issue of libraries pre-loading their own handlers and causing unexpected output or mis-routed output (potentially) - something that, given the ubiquity of this package, simply won't do.

There needs to be a way to either prevent or disable added log handlers in application code.

[Qix-]

https://www.npmjs.com/search?q=logging

Not sure what else you'd like from this thread; coming here to complain certainly isn't making this get implemented any faster. You're not "stuck" with this package, you're free to use what you'd like.

I haven't had time to work on this. If my schedule is not fast enough for you, you're welcome to switch to something else.

Locking for now as I don't think there's going to be any more constructive conversation on this topic moving forward until it's implemented.