Node: List of tests where console.log|error can be replaced with debug

[HarshithaKP]

This issue is to track all the test files that have console.log|error that can be replaced with debug statements. The consideration is that only informative messages can be replaced, not the one that influence the test logic itself.
A good candidate for a future code & learn. Recommend one per person, doing more does not add value.
Refs: https://github.com/nodejs/node/pull/32588#issuecomment-607476500

Checklist for reference

test/parallel

• [ ] test-cluster-setup-master-cumulative.js
• [ ] test-cluster-setup-master-multiple.js
• [ ] test-cluster-worker-wait-server-close.js
• [ ] test-code-cache.js
• [ ] test-crypto.js
• [ ] test-dgram-close.js
• [ ] test-domain-http-server.js
• [ ] test-domain-stack.js
• [ ] test-event-emitter-listeners-side-effects.js
• [ ] test-event-emitter-subclass.js
• [ ] test-exception-handler2.js

[I am still building the list]

[HarshithaKP]

Can someone label this as "good-first-issue"?

[gireeshpunathil]

/cc @nodejs/testing

[Himself65]

I think const debug = require('util').debuglog('test') can be extracted to the `common' module if we really do this

using

const common = require('common')

common.debug('xxx')

[Trott]

The console.log() statements in test-cli-eval.js are part of the test and changing them to debug will make the test fail, as it should. Those statement should be left alone. That test should not be on the list, I don't think.

[Trott]

Same for test-cli-node-options.js. Shouldn't be changed.

[Trott]

By the way, there are (at the time of this writing) still 8 open code-and-learn PRs that can be helped to a conclusion.

[daemon1024]

Can I work on this issue ?

From what I understand, I just need to replace console.log/error(message) with debug(message) across the listed tests.

[HarshithaKP]

@daemon1024, yes please; but would suggest to pick up only (any) one item.

[agustindaguerre]

I would like to work on this issue as well, may I take test-cluster-setup-master-multiple.js ?

[daemon1024]

@daemon1024, yes please;

Great @HarshithaKP

but would suggest to pick up only (any) one item.

Sure. I will start with working on test-domain-http-server.js

[addaleax]

Not to bring anybody down, but … can we spell out what the motivation for this is? All I can see coming out as a result of this is that some tests become harder to debug when they fail in CI.

[daemon1024]

can we spell out what the motivation for this is? All I can see coming out as a result of this is that some tests become harder to debug when they fail in CI.

@addaleax as mentioned in the reference comment .

The idea is to separate output that is considered part of the test itself from informational/debug output. The rationale is to make the intent of the output clear and to avoid cases where the debug output itself may alter the outcome of the test

Should clarify things up.

[Trott]

The idea is to separate output that is considered part of the test itself from informational/debug output. The rationale is to make the intent of the output clear and to avoid cases where the debug output itself may alter the outcome of the test

Should clarify things up.

Yeah, here's the thing. That's a problem that comes up infrequently. It happens. I've been bit by it. But the problem of a test intermittently timing out in CI and there not being enough information to figure out what's going on? Happens a lot. Way more often than console.log() messing up a test with timing, and so on. And it often happens that the test only times out once in 100 runs or 1000 runs. And often the stress test job can't reproduce it because it only happens under certain conditions on a certain machine, but that's not obvious at the outset.

I will take some extra information that confuses me a little bit once in a long while over spending hours trying to reproduce a test failure so I can debug it.

I'm not opposed to this. I'm not going to block it. But I am, sorry to say, unenthusiastic.

[Himself65]

we could enable debug option when test fail and rerun it then output the error log in CI. I think it’s not a big problem.

what's more, we can make the logs usually look very clear if do this

[addaleax]

@himself65 That’s true, but what if the test doesn’t fail then? As Rich said, we do have an actual problem with tests failing in CI that are not easily reproducible and don’t provide sufficient debugging information. We do not commonly run into trouble because a test has too many logging statements.

[Trott]

we could enable debug option when test fail and rerun it then output the error log in CI. I think it’s not a big problem.

Well, sure, if the failure can be easily reproduced. Which it cannot in many cases.

[Trott]

I will say that I have seen a case where a test fails, but then starts passing as soon as a console.log() is added because is affected timing. This does suggest that console.log() may be masking bugs. I don't believe there's a lot of evidence that this is a frequent problem. But since it is something that can happen, that would be a reason for wanting to do this.

FWIW, for me, that's the most compelling reason to do this.

[jasnell]

The other motivation is that separating the two makes it very clear what is part of the test vs. what is debug output. Consider something like...

if (isMainThread) {
  const w = new Worker(__filename);
  let data = '';
  w.stdout.setEncoding('utf8');
  w.stdout.on('data', (chunk) => data += chunk);
  w.on('exit', () = {
    debug('test');
    assert.strictEqual('test', data);
  });
} else {
  console.log('test');
  debug('testing');
}

vs.

if (isMainThread) {
  const w = new Worker(__filename);
  let data = '';
  w.stdout.setEncoding('utf8');
  w.stdout.on('data', (chunk) => data += chunk);
  w.on('exit', () = {
    console.error('test')
    assert.strictEqual('test', data);
  });
} else {
  console.log('test');
  console.error('testing');
}

They end up doing exactly the same thing when NODE_DEBUG=test is enabled but visually it is extremely simple to distinguish what is part of the test vs. what is debug information for the test itself.

[jasnell]

@addaleax:

... tests failing in CI that are not easily reproducible and don’t provide sufficient debugging information

Yep, and most of the time the current console.log() statements in those tests don't really help much anyway. That said, it is trivial to add a NODE_DEBUG=test to the default test-ci* targets in Makefile

[addaleax]

Yep, and most of the time the current console.log() statements in those tests don't really help much anyway.

Tbh, that sounds like a reason to add more of them to me, especially for the ones that do tend to be more flaky.

That said, it is trivial to add a NODE_DEBUG=test to the default test-ci* targets in Makefile

Fwiw, in the example above, enabling debugging would make the test fail. And, again, sometimes it’s hard to reproduce a failure, even with repeating a test.

[jasnell]

Certainly no one is arguing that we shouldn't have debug statements in the tests ;-) ... just the opposite! We need to get a whole lot better at having useful debug statements in the tests... no part of this change is advocating against having those statements.

And yes, it is possible that enabling the debug statements by default in CI could make those rare test where the timing is an issue fail (which is status quo for where we are today) but in those cases, it is far easier to temporarily disable the debuglog() with a single environment variable change than it is to suppress console.log() statements...

That is, if I suspect that the debug output could be throwing off the test I could simply unset the NODE_DEBUG variable and run the test again. If I know that all of the console.log() or console.error() or console.whatever statements I see in the test are actually important parts of the test, then that provides additional context. Further, having gone through and debugged a number of these timing related issues during test development, the fact that I could easily switch the debug stuff on and off has allowed me to identify the source of the problems easier.

[jasnell]

The other possibility here is to prioritize these changes for tests where timing is most likely to be an issue... most often from what I've seen: tests involving networking

[jasnell]

PR to enable NODE_DEBUG=test by default for ci: https://github.com/nodejs/node/pull/32696

[Trott]

PR to enable NODE_DEBUG=test by default for ci: #32696

Still turning all this over in my mind, but my immediate reaction to that suggestion is 👍 and that it will go a long way towards addressing the arguments against doing this at this time. I honestly don't know why I've been assuming that such a change should wait until more tests are changed over to debug().

[HarshithaKP]

I started this issue based on a clarification I sought in https://github.com/nodejs/node/pull/32588#issuecomment-607062444 , assuming it is an improvement for the CI and an opportunity for new contributors. Looks like these still need to be discussed. Should we remove the label for the time being until a decision is made?

[jasnell]

Likely good to remove the label.

[addaleax]

As an extra data point, I just ran into this with 1a3c7473ec9ca0e1acf0512996e05eecc870f7bf – the test in question takes a long time to run, so waiting for it to finish, seeing it fail, and then having to re-run it with a special environment variable just to get the output that was present before that commit is definitely annoying.

I’d be -1 on further PRs that do this unless there’s reason to believe that they affect test functionality in a positive way.

[HarshithaKP]

Closing this based on the feedback so far. My intent was definitely to improve tests, but this one does not look like helping towards that.