Customizing output format

[Qix-]

Ref #573, #565, #553, #456, #453, #402, #578, #526, #525, #488

Right now it's very clear that debug takes a subjective stance on its output format. This is unsuitable for a variety of use-cases, especially the disparity between the isatty(2) == 0 and == 1 cases.

Let's figure out how to solve this.

---

My initial knee-jerk idea would be to introduce a DEBUG_FORMAT environment variable. It would accept a string with delimiters similar to date-time or printf formats that indicate different elements of a debug log.

This would also remove the need for a plethora of custom environment variables that have been proposed.

We'd have a default format that would then be the same between interactive/non-interactive TTY sessions (fd 2, as always).

This would look something like

DEBUG_FORMAT="%N %m %D"

Where %N is the namespace (colored if interactive terminal), %m is the message and %D is the time diff - the exact format in the screenshot in the readme.

Of course there would be other delimiters available, and the above doesn't necessarily need to be the default, but it would solve pretty much any use-case imaginable regarding the output format in a non-subjective manner.

---

That's just my personal proposal, but this RFC is after any solution, so if you have a different idea please sound off below.

[joshuamzm]

Definitely, this is the feature I was looking for right now. I've added some kind of event id injector to debug logs but I need to place it right in the middle of date and namespace (for non-TTY).

What would be the impediments to add this feature to debug?

[TooTallNate]

Huge 👍 to this proposal, basically as-is. Env based configuration is the only one that really makes sense to me for this module.

[Qix-]

This could also be a reason to remove all but DEBUG and DEBUG_DEPTH environment variables, too. cc @TooTallNate @thebigredgeek

That'd make it a major change, though.

[SCG82]

Here's how I prepend [ YYYY/MM/DD - HH:mm:ss ] to all debug output lines:

var moment = require('moment');
var debug = require('debug');
debug.formatArgs = formatArgs;
function formatArgs(args) {
    let name = this.namespace;
    let useColors = this.useColors;
    let dateTime = '[' + moment().format('YYYY/MM/DD - HH:mm:ss') + ']';
    if (useColors) {
        let c = this.color;
        let colorCode = '\u001b[3' + (c < 8 ? c : '8;5;' + c);
        let prefix = ' ' + colorCode + ';1m' + name + ' ' + '\u001b[0m';
        args[0] = dateTime + prefix + args[0].split('\n').join('\n' + '                       ' + prefix);
        args.push(colorCode + 'm+' + debug.humanize(this.diff) + '\u001b[0m');
    } else {
        args[0] = dateTime + name + ' ' + args[0].split('\n').join('\n' + '                       ' + name);
    }
}

[Qix-]

Alright, formally accepting this then. No objections for a while.

Further, since this would be a major change (since I think we'd want to clear out DEBUG_HIDE_DATE - as well as include a number of other PRs) - we could backport this to versions 3 and 4 as a minor change (without removing DEBUG_HIDE_DATE).

Then all code would be able to benefit a little bit more, I think.

[mihai-dinu]

How would DEBUG_FORMAT look like for logging the time based on a specific timezone? I'd like to help with implementing this PR (or some parts of it) if I could get some more details of what formats are allowed.

[dbo]

I suggest to add %P to add the process.pid.

[bodaro]

Is a version available in a relatively stable state that supports DEBUG_FORMAT ? I would like to add my own prefix to all statements (across the entire process) to make tracking in AWS LogInsights easier.

I would envision like this at the very beginning of the process:

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

[bodaro]

Here's how I prepend [ YYYY/MM/DD - HH:mm:ss ] to all debug output lines:

var moment = require('moment');
var debug = require('debug');
debug.formatArgs = formatArgs;
function formatArgs(args) {
    let name = this.namespace;
    let useColors = this.useColors;
    let dateTime = '[' + moment().format('YYYY/MM/DD - HH:mm:ss') + ']';
    if (useColors) {
        let c = this.color;
        let colorCode = '\u001b[3' + (c < 8 ? c : '8;5;' + c);
        let prefix = ' ' + colorCode + ';1m' + name + ' ' + '\u001b[0m';
        args[0] = dateTime + prefix + args[0].split('\n').join('\n' + '                       ' + prefix);
        args.push(colorCode + 'm+' + debug.humanize(this.diff) + '\u001b[0m');
    } else {
        args[0] = dateTime + name + ' ' + args[0].split('\n').join('\n' + '                       ' + name);
    }
}

@SCG82 can your code snippet be used to apply to all instances of debug throughout the application?

For example, I would run that code once in my index.js and prepend all debug's output with a reference ID (to be used in log crawlers later).

[SCG82]

@SCG82 can your code snippet be used to apply to all instances of debug throughout the application?

For example, I would run that code once in my index.js and prepend all debug's output with a reference ID (to be used in log crawlers later).

I have all my debug variables in a separate module, debug-vars.js, which I include in all my project's files:

const debug = require('./debug-vars.js');

debug.warning('something went wrong...');

debug-vars.js:

const debug_module = require('debug');

const debug = {
  debug: debug_module('myapp:debug'),
  error: debug_module('myapp:error'),
  info: debug_module('myapp:info'),
  warning: debug_module('myapp:warning')
};

debug_module.formatArgs = formatArgs;

function formatArgs(args) {
  const name = this.namespace;
  const useColors = true;
  const now = new Date();
  const offsetMs = now.getTimezoneOffset() * 60 * 1000;
  const dateLocal = new Date(now.getTime() - offsetMs);
  const space = '                       ';
  const str = dateLocal.toISOString().slice(0, 19).replace(/-/g, '/').replace('T', ' - ');
  const dateTime = '[' + str + ']';
  let prefix = '';
  if (useColors) {
    const c = this.color;
    const colorCode = '\u001b[3' + (c < 8 ? c : '8;5;' + c);
    prefix = ' ' + colorCode + ';1m' + name + ' ' + '\u001b[0m';
    args[0] = dateTime + prefix + args[0].split('\n').join('\n' + space + prefix);
    args.push(colorCode + 'm+' + debug_module.humanize(this.diff) + '\u001b[0m');
  } else {
    prefix = ' ' + name + ' ';
    args[0] = dateTime + prefix + args[0].split('\n').join('\n' + space + prefix);
    args.push(debug_module.humanize(this.diff));
  }
}

module.exports = debug;

[the0neWhoKnocks]

Just curious what sort of progress has been made on this. I see it's on the list for the 5.x milestone. It would be a really nice feature to be able to use.

[Joshfindit]

I'm honestly only in this thread because I want debug to stop automatically returning seconds and instead always return milliseconds.

  ChannelChecker getting channel_id 1656344628 +2ms
  ChannelChecker getting channel_id 891441386 +2ms
  ChannelChecker getting channel_id 2042650534 +1ms
  ChannelChecker getting channel_id 1015526937 +3ms
  ChannelChecker getting channel_id 1649651584 +2s
  ChannelChecker getting channel_id 815734771 +2ms
  ChannelChecker getting channel_id 388112384 +1ms
  ChannelChecker getting channel_id 1290004369 +3ms
  ChannelChecker getting channel_id 1247374628 +1ms
  ChannelChecker getting channel_id 2020239812 +3ms
  ChannelChecker getting channel_id 969553134 +3ms

It's easy to miss that one call took 1000x longer.

[Qix-]

@Joshfindit the problem there is that sometimes events don't happen for hours at a time. Millisecond triviality goes out the window at that scale. Hence why we use ms. But I understand if not everyone wants that behavior.

[Joshfindit]

@Qix- It’s your package, it’s bot for me to tell you what’s right for you or other users, that’s just why I’m here. Custom output will let me accomplish it.

[DimitarNestorov]

I'm honestly only in this thread because I want debug to stop automatically returning seconds and instead always return milliseconds.

Same. Here's a solution:

// JavaScript
debug.humanize = ms => `${ms}ms`;

// TypeScript
function humanize(ms: number): string;
function humanize(ms: string): number;
function humanize(ms: number | string): string | number {
  return `${ms}ms`;
}
debug.humanize = humanize;

[Qix-]

Yep @DimitarNestorov's way is currently the "official" way of doing it and is entirely acceptable.

[ajorpheus]

If you stumble across this issue while trying to enable timestamps for GHA log, here is the good bit:

GitHub Actions now provides timestamps by default with "shift + T" in the logs.

[dmatora]

Here's how I prepend [ YYYY/MM/DD - HH:mm:ss ] to all debug output lines:

var moment = require('moment');
var debug = require('debug');
debug.formatArgs = formatArgs;
function formatArgs(args) {
    let name = this.namespace;
    let useColors = this.useColors;
    let dateTime = '[' + moment().format('YYYY/MM/DD - HH:mm:ss') + ']';
    if (useColors) {
        let c = this.color;
        let colorCode = '\u001b[3' + (c < 8 ? c : '8;5;' + c);
        let prefix = ' ' + colorCode + ';1m' + name + ' ' + '\u001b[0m';
        args[0] = dateTime + prefix + args[0].split('\n').join('\n' + '                       ' + prefix);
        args.push(colorCode + 'm+' + debug.humanize(this.diff) + '\u001b[0m');
    } else {
        args[0] = dateTime + name + ' ' + args[0].split('\n').join('\n' + '                       ' + name);
    }
}

@SCG82 when I try to do that, name and useColors are undefined
doesn't it require debug.formatArgs = formatArgs.bind(debug) or something (which isn't works as well?

[jmrossy]

In case anyone needs to strip the output format down to just the content, this worked for me:

function formatArgs(this: debug.Debugger, args: any[]) {
  args.push(debug.humanize(this.diff));
  args.pop();
}
debug.formatArgs = formatArgs;