Debug mixed with console.log

[mjgs]

I use the debug module a lot. It’s great.

One thing I’m finding an issue though is with CLI apps, because these tend to use console.log with something like chalk for colors, and when you set your DEBUG string the output from console.log and debug get mixed together in a way that’s quite unreadable because all the outputs are out of sync.

Is there a way to ensure that output from debug and console .log stay in sync?

[adam-nielsen]

I don't think this is possible because the problem is the terminal sees all the output (including stdout and stderr) mixed together, and it's the one responding to the colour codes.

The only way would be to tell Debug to funnel all its output through the same process the rest of the code is using for coloured output, so that single output function can correctly push and pop the colour state. You can tell Debug to use a different output function (e.g. Debug.log = someOtherFunction;) but implementing that function could be tricky if it doesn't already exist in the colour library you're using.

[mjgs]

Thanks for the reply.

Are you referring to the following section of the docs?

// set all output to go via console.info
// overrides all per-namespace log settings
debug.log = console.info.bind(console);
error('now goes to stdout via console.info');
log('still goes to stdout, but via console.info now');

So I would do something like:

debug.log = console.log.bind(console);

Still a bit confused by all this. I guess I would need to do this in each file I use debug?

Also, surely there’s a reason debug has it’s own output function? Are there downsides to using console.log as the output function rather than the one provided by debug?

[Qix-]

No, both output to stdout. console.error goes to stderr. The reason why they mix is because stdout by default only emits when a newline is printed, whereas stderr emits immediately. Since things are emitted in chunks to avoid having to buffer things in memory (pretty common) you get "mixed" output.

Note that this is only cosmetic. You can redirect streams.

For example if you do

node app.js >/dev/null

you'll see only the output from debug (assuming you haven't overrided the logger function).

[adam-nielsen]

I think you can only solve this if you implement your own output function and have every part of your code use it.

debug.log = console.log.bind(console);

This tells the Debug library to call console.log() to write its output, but instead you would want it to use your custom function instead:

function myPrintFunction(text) { /* do something here */ }
debug.log = myPrintFunction;

This function you write would then manage all the incoming requests for printing text from all parts of your codebase, and output it all in such a way that the colours don't mess up on the terminal. You just have to make sure everything that wants to print text goes via your function - the code above redirects Debug's output to your function, but you'd have to figure out how to do that for everything else your code wants to print too.

Then "all" you have to do is implement myPrintFunction and inside there figure out how to send all the output without the colours all running together.

A simpler solution might be to forget all this stuff for debugging, and just focus on the "real" output your program writes. If you buffer this real output (e.g. into a string) and then when you're done you print it in one single call to process.stdout.write(), starting with a colour-reset command, then it will get written in one block without the risk of anything else appearing in the middle of the output. Because you assume the terminal could be in any state and start with a colour reset command, then it won't matter what colour codes are active on the terminal when you write your text. This probably a lot simpler than trying to coordinate multiple blocks of text being written in a jumbled order, and remembering what colours each one is supposed to be.

[mjgs]

I’m not super concerned about the colors, it’s really a nice to have. What’s more important when I have DEBUG set, is that the console.log and debug output get to the screen in sync.

If the colours disappear from program output when I turn debug on, that’s not the end of the world.

Does that make it any easier?

[ssbarnea]

I endep if on this ticket while trying to redirect node output to a file and discovered that it is broken:

$ DEBUG_FD=4 DEBUG='express:*' node ./out/client/test/mockLightspeedServer/server.js 4> out/log/express.log
/Users/ssbarnea/c/a/vscode-ansible/node_modules/finalhandler/node_modules/debug/src/node.js:173
  switch (tty_wrap.guessHandleType(fd)) {
                   ^

TypeError: tty_wrap.guessHandleType is not a function
    at createWritableStdioStream (/Users/ssbarnea/c/a/vscode-ansible/node_modules/finalhandler/node_modules/debug/src/node.js:173:20)
    at Object.<anonymous> (/Users/ssbarnea/c/a/vscode-ansible/node_modules/finalhandler/node_modules/debug/src/node.js:69:14)
    at Module._compile (node:internal/modules/cjs/loader:1356:14)
    at Module._extensions..js (node:internal/modules/cjs/loader:1414:10)
    at Module.load (node:internal/modules/cjs/loader:1197:32)
    at Module._load (node:internal/modules/cjs/loader:1013:12)
    at Module.require (node:internal/modules/cjs/loader:1225:19)
    at require (node:internal/modules/helpers:177:18)
    at Object.<anonymous> (/Users/ssbarnea/c/a/vscode-ansible/node_modules/finalhandler/node_modules/debug/src/index.js:9:20)
    at Module._compile (node:internal/modules/cjs/loader:1356:14)

Node.js v18.19.1

Apparently DEBUG_FD was removed from current versions of debug but node itself is still using the older ones as otherwise it would not get the error. Also trying to use the undocumented DEBUG_FILE did not had any effects.

I still want to redirect only express logging to another file while keeping the stdout/stderr on console but this not seems to be possible.

[mjgs]

I’m taking another look at this.

If I change debug so it outputs to stdout, do I need to set the log function just in the top level file of my cli program as follows:

// mycliapp/bin/app.js
const debug = require('debug')('mycliapp:bin:app');
debug.log = console.log.bind(console);

const calculate = require(‘../lib/calculate’);

calculate();

// mycliapp/lib/calculate.js
const debug = require('debug')('mycliapp:lib:calculate');

module.exports = function () {
  // calculates here
}

Or do I have to set it in every file?

[adam-nielsen]

You have to set it in every file. I recommend wrapping it anyway, whether you override anything or not:

// mycliapp/debug.js
const debug = require('debug')('mycliapp');
debug.log = console.log.bind(console);
export default debug;

// mycliapp/bin/debug.js
const debug = require('../debug.js').extend('bin')
export default debug;

// mycliapp/bin/app.js
const debug = require('./debug.js').extend('app');

This way you can always just import the debug.js found in the current folder, and it will have the right prefix and output options set.

[Qix-]

See #556 by the way. Aims to solve this at some point.