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.

[Qix-]

In lieu of having all of the date/time specifiers as individual flags (since that eats up a lot of the available upper/lower alphabet) I propose a slightly less-conventional way of doing it:

DEBUG_FORMAT='%{H:M-Z} %n %m %+'

In this hypothetical:

• %{} is for time formats using the specifiers in the official strftime documentation.
• %n is the namespace
• %m is the message
• %+ is the delta time

I'm not 100% on the latter three, I just wanted to demonstrate how the time specifier (%{}) would look.

[Qix-]

Referring to https://github.com/visionmedia/debug/issues/442#issuecomment-443757866 and #442 in general, asking for a JSON output format:

const debug = require('debug')('rest:debug:myEndpoint', {output: 'JSON'})

Definitely not - the end consumer of the application should have full control over the output format. This would result in many different output formats, which would make this library useless to most people.

DEBUG=*;format:JSON node myScript.js

This would be a breaking change as it's using namespaces for something they aren't designed to do.

---

In reality, you could argue that prefixing J to any one flag would run it through JSON.stringify().

For example, if %m is the message, then %Jm is the message passed through JSON.stringify().

It's not uncommon to prefix flags for extended functionality, so this wouldn't be breaking 'the UNIX way' either.

You'd then have something like the following, giving you guaranteed valid JSON output.

DEBUG_FORMAT='{"message": %Jm, "time": %J{...}, "delta": %J+}'

[Kostanos]

Thank you @Qix- , not sure which would be the best way to fit JSON output to "debug" library, but it definitely will be a great feature add. I'm already having several projects that would have big benefits having logs in json and sure many other people would find it useful too.

[Qix-]

I agree, this should be possible with debug but it isn't.

The biggest problem with this much needed change is that it'll have to be backported for it to be useful at all. :|

[theDanielJLewis]

Please forgive my lack of understanding, but was anything done here?

I, for example, want the non-TTY output to have the same "time since last message" part as the node console gets. But I'm confused by this post. I can't tell if such a feature was added or it's still being discussed.

[Qix-]

It's still being discussed.

[chagris]

Haha woops I didn't expect it to be notified here

Hello! As that commit says, I decided to have a go at trying to implement this -- for now it's incomplete (only works on the node side, doesn't respect DEBUG_HIDE_DATE, doesn't do any date formatting, etc) and I ended up with a few problems. It's also my first attempt at participating to another project, so I don't really know how everything should go (and I'm intimidated), sorry!

The current code is at https://github.com/chagris/debug/tree/format (diff at https://github.com/visionmedia/debug/compare/master...chagris:format ).

What I've tried to do is

• move formatArgs from node.js into common.js's debug() (however I don't know how well it'll work with the browser.js's side)
• add outputFormatters similar to how formatters already exist (but handled in a bit of a hardcoded way for %{DATE} and %J*)
• in debug(), parse DEBUG_FORMAT and output a new array with the original arguments somewhere in the middle
• node.js's formatArgs() is replaced by a generic applyColor()

The problems I've come up with are

• I'm not sure if "hardcoding" how the "output as JSON" %J* and date %{} outputModifiers are handled is the correct way to go
• I don't know how to handle time; the few libs I've seen use strftime's %* delimiters, so I propose formatting time this way (%{%H:%M:%S}), where any delimiter inbetween {} is not handled by debug's outputFormatters. I also don't know which lib would be fine to add as a dependency (browser-wise) -- or if you guys want to implement all this into debug?
• with the way I implemented things (a new array with each of DEBUG_FORMAT's non-delimiters and replaced-by-formatters' element, concatenated with the original args), util.format() automatically adds a space between each elements, which forces a space between each of DEBUG_FORMAT's elements (for example, DEBUG_FORMAT='%n: %m' results in namespace : message instead of namespace: message) (The other way I thought about implementing it is would be to split DEBUG_FORMAT at the %m delimiter, format the "before" and "after" parts into strings, then unshift and push them to the original args. However it also "hardcodes" how the %m delimiter is handled... Maybe there could be a DEBUG_PREFIX and DEBUG_SUFFIX ?)
• Not sure if "hardcoding" how outputFormatters's return values are concatenated into the main args if they're an array is the correct way to go.

I didn't try to add other delimiters than what has been discussed here for now (like the global time diff).

I'd like input on it and would be happy to change / clarify anything. I'm also not sure if I should make a pull request to get all the fancy diff / review tools since my current code is incomplete, or if it'd be better to do the changes on my fork for now?

Thanks for your time!

[Qix-]

@chagris this looks like a great start :) If you open up a PR and tick the box that says "allow maintainers to push commits", I'd be happy to start going through rounds of feedback and guide you through the PR process :)

[chagris]

Maybe to get rid of DEBUG_COLOR there could be a flag prefix similar to %J* for JSON, that'd pass the outputFormatter's output to applyColor() (for example %cn would colorize the namespace, and %Cn would color it and make it bold (on node)?) This'd make an excuse to somewhat standardize "flag prefixes" instead of having that if for %J* -- but I can't really think of more useful prefixes than those. And again, I don't know how feasible coloring would be on the browser side

[Qix-]

I can't either, I think %J* would be a special case (one of the few, if not the only special case).

I think DEBUG_COLOR should also go away, as will DEBUG_HIDE_DATE, of course.

[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?

[Download]

For years now I have been working on and off on a package called ulog, which is actually heavily inspired by debug. In ulog, I wanted to be compatible with debug as much as possible while at the same time supporting log levels and output formatting, so II came up with an extension to debug's configuration mechanism. Here is how you configure formatting in ulog:

log_format=lvl name perf message;my:*=lvl name perf

The lvl, name, perf etc you see in this config string are formats and besides some default formats you can easily add your own custom formats and that system is actually pretty powerful. You can add new custom formats like this:

import ulog from 'ulog'
import formats from 'ulog/mods/formats'
ulog.use({
  use: [ formats ],
  formats: {
    custom: (ctx) => (rec) => (['custom'].concat(rec.message)),
    random: (ctx, rec) => () => Math.random()
  }
})

If you are reconsidering how formatting should work in debug, it might be worthwhile to have a look at how I implemented it.

[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;