doc: add guidance on console output in tests

[sam-github]

I'd like the test writing guide to include some information on expected usage of console.log/error, to avoid having to discuss it (as much) in individual PRs.

As long as I've been writing node.js unit tests (since 0.10), I've written my tests with console.log statements (or added them while debugging), then removed them before PRing the changes. I'm not entirely sure why this is the node.js convention, or even if it is widely agreed that its the convention (I count over 200 tests with 2 or more calls to console.log() or console.error()).

Output is surpressed by the test runner if the test passes, so it does not increase the noise/verbosity of most test runs, but it will be included as context if a test fails.

Since its going to be in the tap output and show up in jenkins, as well as the local display, the output should not be so excessive as to overwhelm the display, but other than that, I can't see why anyone other than a test author/maintainer should have concerns over what the test outputs.

What do other @nodejs/collaborators think?

If the consensus is that console output should be avoided, I'll modify the text. No matter what the text ends up being, by documenting it, it should make PR review clearer since there will be agreement on the general policy.

cf. discussion with @jasnell and @addaleax preceeding
#26209 (comment)

Checklist

• documentation is changed or added
• commit message follows commit guidelines

[nodejs-github-bot]

@sam-github build started: https://ci.nodejs.org/blue/organizations/jenkins/node-test-pull-request-lite-pipeline/detail/node-test-pull-request-lite-pipeline/2771/pipeline

[Trott]

The guidance suggested in this PR seems measured and balanced to me. Here's some additional context that does not need to be integrated, but feel free if you think it's useful:

• console.log() is indispensable when troubleshooting tests that timeout in CI. With no log statements, you have no idea where the test got hung up.

• That said, I have definitely seen cases where a test fails without console.log() but then passes once a console.log() is added. So there are definitely cases where adding console.log() will mask bugs.

[Trott]

(Oh, and it might be good to suggest a standard way to note when a console.* call is part of the test instead of simply being debugging info for human consumption.)

[jasnell]

For myself, the issue is not really about verbosity of output. It's about not having clarity if the console output is informational or part of the actual test. For message tests, for instance, a change in a console.log can break the test needlessly. I would much rather have a separate common.debug() type of mechanism that builds on debuglog thanks suppresses this kind of informational output by default and has a clearly defined semantic that the message is informational and not actual a part of what is being tested.

[jasnell]

Going to mark this request changes for now so it's not landed prematurely. I'd like there to be more discussion first.

[bengl]

@jasnell

It's about not having clarity if the console output is informational or part of the actual test.

Maybe just clearly defining use-cases for both console.log and console.error can address this?

[lpinca]

I'm ok with it when it makes sense. In most cases an assertion with a good error message is sufficient though.

[richardlau]

I would much rather have a separate common.debug() type of mechanism that builds on debuglog thanks suppresses this kind of informational output by default and has a clearly defined semantic that the message is informational and not actual a part of what is being tested.

There was #22206 which stalled.

[jasnell]

Maybe just clearly defining use-cases for both console.log and console.error can address this?

I don't think that's quite enough as it would still have the issue of not being generally appliable to every test. Message and console tests would have to use a different convention.

[mhdawson]

I'm ok with what is written. It might be possible to address part of @jasnell concern by including a requirement that informational console.log start with 'INFO:' and then we can provide tooling to help do that later (although if we had agreement that was enough or enough to start with its probably easy to add a method to the test framework to add the INFO: part).

[mhdawson]

LGTM

[cjihrig]

requirement that informational console.log start with 'INFO:'

Just throwing this out as an idea, but we could lint for console.log() and use one of the other console methods, such as console.info() more specifically for this.

[jasnell]

Just asking, but what do folks have against using debuglog() for this? Even if we don't introduce a common.debug(), tests themselves could easily include a const debug = util.debuglog('test'); /*...*/ debug('a debug statement here') as a convention.

[cjihrig]

Using util.debuglog() seems fine to me. It also signals more intent than console.log().

[antsmartian]

+1 on the overall idea, but only concern here is that whether the console statement is providing actual info about the test or not. However, as @jasnell points out, we can very well use util.debuglog instead of console statements..

[Trott]

util.debuglog('test') seems fine to me, although it will require some coordination with @nodejs/build as we'll want to decide if we want this output in CI runs (we do) so they will have to make sure the NODE_DEBUG environment variable is set everywhere. (Presumably tests that need NODE_DEBUG to be unset launch something via child_process and clean the environment variables that way, but if not, then we may have a handful of tests to clean up too.)

It will result in a huge amount of churn in our tests if we want it to replace non-functionality-testing uses of console.log() and console.error() in our tests. Uh... Code & Learn maybe?

[sam-github]

As far as this PR goes, I'd like to provide guidance on current practice, so while the conversation about how we wish things were is useful, and might lead somewhere, it should be possible to land guidance for what to now. The guidance can change when there is a better way. I updated the guidance to add discussion on all the points raised above (at least, I tried). Please take another look.

Right now there are 538 console.log and 297 console.error statements in test/parallel. That I can't tell from grep which are APIs under test, and which are for console output of informative messages is a good point in favour of having a specific test API, though I can't honestly say I've ever had difficulty in distinguishing while reading a test.

I think util.debuglog() isn't a great API to use, because it has the "is this an API under a test, or is it just called for info?" problem. It also has the "needs env configuration" problem, and while build infrastructure can do anything, the less configuration in jenkins the better, IMNSHO. Also, having tests run with different envs locally and remotely seems like a rich source of "works for me" problems.

Use of common. instead of util. or some other legit node API module makes it crystal clear that its not an API under test. I'd be in favour of common.log = console.log, or perhaps a 1-line wrapper of that to add test: or INFO: to the beginning of the common.log() output... though if I see it on the console, it seems obvious the output is info for me, sitting at the console (if it was for the test to evaluate, it would not be dumped into the console).

Converting existing tests would definitely fit into the code-n-learns well.

[Trott]

My discomfort with adding stuff to common is that there's too much stuff in common already and it is very often not intuitive what the heck it's doing. IMO, if your first guess as to what something is doing when it's in common is wrong, then it shouldn't be there. That's an argument for removing a lot of stuff that is currently there, but is also a pretty OK argument for including common.log() rather than omitting it. So, you know, there, that solves my past objection to it, I suppose.

Another issue with common.log() is that we will be giving nits until the end of time telling new contributors to change console.log() and console.error() to common.log(). I guess we could add a lint rule. So that would solve another concern, I suppose again.

Is this perhaps a solution in search of a problem? As @sam-github noted, it's never been difficult (in my experience, at least) to differentiate "this is debug information" vs. "this is part of the test" in console.log() calls in tests. Are we perhaps optimizing for a hypothetical? Is it likely this has never caused any real-world this-actually-happened stuff? Would the massive churn of changing to common.log() be a headache that doesn't actually solve anything that's caused anyone significant difficulty?

Anyway, I agree that for documenting current practice, the text that was there was good. The expanded text seems OK to me too.

[Trott]

And just to be both extra clear and extra frustrating: Despite all my long-winded comments, I'm not (at this point) opposed to switching to either util.debuglog('test') or common.log(). I would prefer not. And of those two choices, I would prefer the first one. But I'm A-OK with the last one too. I have my problems with it, but I can also see the arguments for it and I won't stand in the way of consensus if I'm the only one.

[Trott]

I think util.debuglog() isn't a great API to use, because it has the "is this an API under a test, or is it just called for info?"

Seems solvable. You could have util.debuglog('test') always be "called for debug info" and util.debuglog("foo") or something like that for "this is an API under test". The general rule could be: As long as the string is meaningless and/or ridiculous, it's under test and not for debugging. (Yeah, meaningless to me is not meaningless to someone else, but I think strings like 'foo', 'foobar', and 'fhqwhgads' are pretty universally clear about their meaninglessness to most people in a programming context.)

Also, having tests run with different envs locally and remotely seems like a rich source of "works for me" problems.

Yeah, that one's a concern I certainly share and why I slightly favor just keeping things the way they are.

[sam-github]

@jasnell You requested changes, PTAL

Probably unnecessary, but:

ci: https://ci.nodejs.org/job/node-test-pull-request-lite-pipeline/2805/

Primary concerns addressed

[sam-github]

Landed in 4d89fcc