util: add debugtest utility

[bmeck]

Checklist

• make -j4 test (UNIX), or vcbuild test (Windows) passes
• tests and/or benchmarks are included
• documentation is changed or added
• commit message follows commit guidelines

Currently we have a debuglog utility to allow logging when debugging. This PR introduces a corollary debugtest utility to see if something is being debugged rather than logging. This would allow people using debuglog style conditional debugging to avoid doing unnecessary work such as creating strings etc. For example:

const debug = debuglog('foo');
debug(`${obj}`);

Would always stringify the object, even if foo is not being debugged. Additionally, it would allow branching to add additional debugging logic that may be undesirable when not debugging. For example:

const debug = debugtest('foo');
class Foo {
  #bar;
  // ...
  get _bar() {
    if (debug) return this.#bar;
  }
  set _bar(v) {
    if (debug) return this.#bar = v;
  }
}

[devsnek]

I feel like we need better namespacing here. Maybe split into util.debug.log and util.debug.test?

[targos]

Is V8 able to completely eliminate the branch when the value is false ?

[bmeck]

@devsnek that would be adding an alias to the existing function and i'm not sure what we get except moving a . around, people could still use util.debuglog and thats what most things that discuss at least in existing refs to this functionality. Can you clarify why adding a namespace would be prudent here?

@targos per my testing, yes. I was using:

node --allow-natives-syntax --code-comments --print-code --print-code-verbose -e 'const test=require("util").debugtest("foo"); function easy_foo() {if (test) return; return [1,'2',null];};%OptimizeFunctionOnNextCall(easy_foo);easy_foo()'

[jasnell]

There are a couple of possible alternative approaches here, since util.debuglog() already does the debug check and returns a non-op function when the category is disabled, we could "simply" build off of that...

const debug = util.debuglog('test');

// What debug log currently does...
debug('how we do it currently');

// Add an additional function off `debug` that invokes the given function
// only if the category is enabled.
debug.do(() => {
  // Do something here
})

And / Or

const debug = util.debuglog('test')

if (debug.enabled) {
  // Do something here
}

Another modification we could make here would be similar to what we did on the C++ level Debug, allow an object to specify it's own stringification logic that is applied only when the debug is active...

const { debuglog } = require('util');
const debug = debuglog('foo');

const obj {
  [debuglog.debug]() { return 'abc'; }
};

debug('something happened: %s', obj);

This would obviously take a bit of work on the internals to account for the symbol but in the default case (debug off) it would not incur any additional cost.

[bmeck]

@jasnell per the alternatives:

• debug.do
  • this seems a -1 to me, but it was my first instinct on how to implement this!
  • always uses a closure/function and must call one. optionally allocating the function isn't possible since it is an input
  • you cannot use control structures inside them (I'm unclear why you would want control structures currently in practical examples, but await does come to mind as potentially being useful).
  • it ~= if (test) fn() so it is a bit higher level than needed
  • things get a bit weird for alternates like o.api = test ? withPrivate : onlyPublic;
  • I'm very unclear on what we would do with the return value of the function, I think having something return undefined when not debugging, but also potentially when debugging sometimes is a smell.
• debug.enabled
  • this seems -0 to me, i'd be fine shipping it but doesn't seem as intuitive
  • it requires the logger be allocated even if you never log anything. perhaps just putting the test results in the cache would be fine to mitigate the concern about running tests multiple times?
  • it seems odd to have to go through a logger if you never want to log things.
• custom stringification
  • I'd be +1 but seems a different feature and would be a different PR
  • this seems to address only the problem of eager operations for logging when debugging, not when you want to do logic when the debugger is enabled.

[BridgeAR]

@jasnell @bmeck it is already possible to use printf like format strings:

const debug = require('util').debuglog('test')

debug('Lazy property inspection: %o', { works: true })
// TEST 123456: Lazy property inspection: { works: true }

If we want to add more powerful lazy evaluations, I'd favor to use debug.do(() => { /* Do something here */ }) as suggested by James.

[jasnell]

The point about having to use ? and graceful fallback makes sense @bmeck ... especially for low cost debug statements we don't want uses to have to incur a cost to check if debug.do exists ;-) ...

Thinking through it more, @devsnek's comment here #33424 (comment) makes a lot of sense ... that is, replacing the debuglog utility with a structured namespace. Something like..

const debug = util.debug('test');

debug('some output: %s', 'a');
debug.do((a) => {/* ... */}, 'a');

if (debug.enabled) {
  /* ... */
}

[bmeck]

I'm not sure on the need for a .do(fn) personally for the reasons listed above. However, if a separate namespace matching:

util.debug: (section: string) => {log(...): typeof debuglog, enabled: boolean};

Is fine I can move the PR to that, I'm not sure I understand the desire for the namespace itself to be a function.

[jasnell]

The namespace being a function just makes the transition from the current model a bit easier in my opinion but it's not critical

[bmeck]

@jasnell If the goal is transition ease; would it make it easier if this was just an alias and we added .enabled as a non-writable to all debuglog functions?

[jasnell]

Yes that works

[bmeck]

Keeping the ENV parsing lazy means debug("foo").enabled would be a getter or a function. Doing so in my testing removes the ability for V8 to properly optimize out conditionals without an intermediary variable to save the boolean. I assume this is alright?

[bmeck]

I've pushed up changes so that util.debug is an alias of util.debuglog and debuglog implementations all have a .enabled getter. The choice of a getter was:

• keeps the environmental check lazy
• to avoid a potential gotcha of if (debuglog('foo').enabled) by not using a method
• to avoid a potential gotcha of if (debuglog('foo').enabled = true) by not having a setter

In both a getter form and a method form V8 does not optimize if (debug.enabled/*()*/) to do dead code elimination on the branch, code must save debug.enabled to a variable prior to the branch to get that optimization.

[bmeck]

#32260 landed an undocumented API change that causes a callback to be fired with the logger or null. I think this PR can be closed and a new one with docs on how to use that API to use the callback to set a boolean can be made instead.

[bmeck]

reopening, i misunderstood how that callback works. made a PR to doc it, but this PR still has utility by avoiding the call to the logger in order to set the boolean.

[bmeck]

rebased due to changes with util.debuglog implementation.

[nodejs-github-bot]

CI: https://ci.nodejs.org/job/node-test-pull-request/32670/

[bmeck]

Landed in 7f5da53c7972

[richardlau]

Landed in 7f5da53c7972

@bmeck I think you've pushed the wrong commits up to master (the ones that were pushed don't appear to have metadata added):

[richardlau]

Looks like @himself65 force pushed them out: https://github.com/orgs/nodejs/teams/collaborators/discussions/105. I'll reopen this one as it will need to be relanded.

[bmeck]

@richardlau i went through git node land so i'm unclear how this occurred, checking my master branch (from which i ran git node land) i also see the correct commit

I'm unclear what to do here to reland since my master matches what i expected and i don't want to repush the wrong commits

[bmeck]

Landed in bcfb176