test: add a common.debuglog function #22206

SirR4T · 2018-08-09T10:20:43Z

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

SirR4T · 2018-08-09T10:23:47Z

@gibfahn: the test passes when invoked with NODE_DEBUG=test ./node test/parallel/test-common-log, but fails when invoked with ./node test/parallel/test-common-log, even though I'm trying to mutate process.env.NODE_DEBUGfrom within the test case.

How do I fix this?

richardlau · 2018-08-09T11:24:45Z

the test passes when invoked with NODE_DEBUG=test ./node test/parallel/test-common-log, but fails when invoked with ./node test/parallel/test-common-log, even though I'm trying to mutate process.env.NODE_DEBUG from within the test case.

How do I fix this?

@SirR4T Please see #21914 (comment). I'd suggest that rather than hijack stderr the test should instead spawn another process (with NODE_DEBUG set in the env passed to the spawn) and capture the stderr from that,

SirR4T · 2018-08-09T12:28:45Z

thanks @richardlau ! fixed the test cases now.

vsemozhetbyt · 2018-08-09T21:16:33Z

test/common/README.md

+* `msg` [&lt;string>] The string to be printed to stderr
+* `msgs` [&lt;string>] Additional arguments to the function
+
+Prints messages (optionally, formatted using `fmt`) to `process.stderr`, using `util.debuglog('test')`.


Not sure why linter does not warn about this (maybe we do not lint docs outside api?) but it seems this line needs to be wrapped at 80 characters or less)

@vsemozhetbyt test is omitted from the markdown linting. I have a PR in the works to add it. Will have it ready to be opened today, I think.

@vsemozhetbyt #22221

richardlau

Left some inline comments.

With regards to the test, it would be good to add the case where NODE_DEBUG is not set (no output expected) and/or possiblty also if NODE_DEBUG is set to something other than test.

richardlau · 2018-08-09T22:40:46Z

test/parallel/test-common-debuglog-dummy.js

+const common = require('../common');
+
+// argv[0] is the execPath, argv[1] is the test script filename
+common.debuglog.apply(null, process.argv.slice(2));


This should either be inlined into the new test/parallel/test-common-debuglog.js (see test/parallel/test-child-process-spawnsync-env.js for how tests that spawn other processes are typically written) or this file should be moved to test/fixtures.

will move it to test/fixtures, since the same file will need to be invoked with on different child processes... Inlining it might make it needlessly complex, to test for different values of NODE_DEBUG

richardlau · 2018-08-09T22:43:12Z

test/parallel/test-common-debuglog.js

@@ -0,0 +1,18 @@
+'use strict';
+
+const common = require('../common'); // eslint-disable-line no-unused-vars


Just write

require('../common');

instead of disabling the lint rule.

sagirk

LGTM! 🎉

You might want to wrap that long line at 80 chars, though.

SirR4T · 2018-08-10T05:38:33Z

@sagirk sorry, missed that! pushed now, thanks!

richardlau

Left a couple of suggestions, otherwise LGTM.

richardlau · 2018-08-10T05:51:55Z

test/parallel/test-common-debuglog.js

+{
+  process.env.NODE_DEBUG = 'test';
+  const { stderr } = spawnSync(process.execPath, [
+    path.resolve(__dirname, '../fixtures/common-debuglog.js'),


Use fixtures.path from https://github.com/nodejs/node/blob/master/test/common/README.md#fixtures-module.

richardlau · 2018-08-10T05:58:39Z

test/common/README.md

+* `msgs` [&lt;string>] Additional arguments to the function
+
+Prints messages (optionally, formatted using `fmt`) to `process.stderr`,
+using `util.debuglog('test')`.


Perhaps the wording should clarify that the messages are conditionally printed to stderr based on the value of NODE_DEBUG ?

Or maybe omit the stderr part, e.g.

* `msg` [<string>] The string to be printed

and

Prints messages (optionally, formatted using `fmt`) using `util.debuglog('test')`.

richardlau · 2018-08-10T06:29:52Z

test/fixtures/common-debuglog.js

+const common = require('../common');
+
+// argv[0] is the execPath, argv[1] is the test script filename
+common.debuglog.apply(null, process.argv.slice(2));


Could this be simplified to

common.debuglog(process.argv.slice(2));

?

that ends up printing TEST 2461: [ 'message' ] instead of TEST 2461: message, since slice returns an array. So resorted to common.debuglog(...process.argv.slice(2)) instead.

gdams · 2018-08-12T18:37:22Z

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

Trott · 2018-08-13T18:55:57Z

Could stand to get one more approval. @nodejs/testing

Trott · 2018-08-13T18:57:36Z

(Not approving myself because I generally don't 👍 adding stuff to common that we're not actually using--the thing is enough of a monolith already--but I won't stand in the way if others think this will be useful.)

BridgeAR

I am -0 on this. I agree with @Trott that we have a lot in common already and adding more is not ideal. Besides the fact that we could just all agree on always using test in which case it would be possible to just directly use util.debuglog().

refack

Doing design review

refack · 2018-08-21T19:14:39Z

Hello @SirR4T and thank you very much for this contribution.
I would like us to do a design review of this change.

Could you explain why you chose this solution?
What are the use cases you envision this will solve?
Is this sufficiently different than running through test.py?
Does this require changes in test.py?
Is this better then hijacking console.log?

jasnell · 2018-08-21T19:41:11Z

Is this sufficiently different than running through test.py?
Does this require changes in test.py?

Given that the PR does not touch test.py and does not change test.py, how are these questions relevant to this PR?

jasnell · 2018-08-21T19:42:43Z

Is this better then hijacking console.log?

I definitely believe so in that it makes the intent of the statements far more explicit and gives clear separation between output that is purely intended as debug output vs. output that is part of exercising the test.

refack · 2018-08-21T21:25:51Z

Given that the PR does not touch test.py and does not change test.py, how are these questions relevant to this PR?

Is this sufficiently different than running through test.py?

When running tests through test.py it will swallow stdout and stderr if the tests pass. Providing the "noise reduction" requirement.

Does this require changes in test.py?

If we move tracing output to use common.debuglog IMHO we should change test.py to set NODE_DEBUG=test in certain configuration, so that tracing information will still be available.

SirR4T · 2018-08-22T03:50:11Z

Hi @refack !

I was basing my approach on this comment by @gibfahn :

I guess there's always a balance, but I'd say that for me a console.log (or I guess a common.log()) can sometimes be as helpful as a comment, depending on the situation. I agree that too many of them adds complexity.

Using the existing debuglog in a common.log() makes sense to me.

When tackling test cases, I see myself adding some log statements for debugging, in two varieties:
1. ones that are trivial, and would ultimately be removed (has execution reached here yet? what is the typeof of this thingy?)
2. ones that are informational, and might make sense to keep them in, if someone else were trying to revisit the test case. (on nth repetition, total bytes sent were x, total bytes received were y).
Having a debuglog() allows to add statements of the second type, in a non-invasive way (won't
clutter test output, unless NODE_DEBUG is set), imho.
test.py is helpful when running a whole suite of tests. We may not want to set NODE_DEBUG, and thereby clutter the test output, when many tests are run. _{(On the contrary, if all the tests for a module (say child_process) followed a pattern while using debuglog() (something like say, to track which ones are being emitted by the child fork, as opposed to parent fork), it might be helpful there too.)}
I have not looked into how test.py works, and haven't changed it for this PR either.
Not too sure if this is better or not, but I believe with this change, we may start discouraging the usage of console.log() (and 2.i type statements) in tests, in favour of using debuglog() (and 2.ii type statements) if and where necessary. Maybe even add a linter rule, to disallow console.log statements in tests.

SirR4T · 2018-08-27T06:47:38Z

Hi @refack ! how do we proceed on this?

SirR4T · 2018-09-05T05:09:52Z

Hi @refack ! Ping! how do we move forward here?

BridgeAR · 2018-09-05T20:20:37Z

@nodejs/tsc please weight in.

cjihrig · 2018-09-05T22:32:55Z

I'm against this change, since util.debuglog() can just be used directly, but I won't block this.

ofrobots

Seems like a convenient and readable thing to have in the tests. LGTM.

mcollina

LGTM

cc @Trott there are a lot of console.log() statements in test/parallel, it might be good for code&learn exercises.

joyeecheung · 2018-10-02T17:11:04Z

test/common/index.js

@@ -804,3 +804,6 @@ exports.runWithInvalidFD = function(func) {

  exports.printSkipMessage('Could not generate an invalid fd');
 };
+
+const utilDebugLog = util.debuglog('test');


If the intention is to get all the tests to slowly refactor to use common.debuglog, then I am -1 to this since I think something like out/Release/node test/paralell/test-*.js should still give useful output without any tweak to the environment.

In that sense at least this PR needs to also modify test.py to add NODE_DEBUG=test to

node/tools/test.py

Line 197 in f4e4ef5

print "Command: %s" % EscapeCommand(failed.command)

or even a hint in CONTRIBUTING.md (even though I believe many people don't read it through before contributing) if that's where it's going, otherwise when the test fail, the hint won't be too useful to a new contributor.

If the intention is to get all the tests to slowly refactor to use common.debuglog, then I am -1 to this since I think something like out/Release/node test/paralell/test-*.js should still give useful output without any tweak to the environment.

@joyeecheung do you mean that it should still give output for tests that fail, or that it should always give output for all tests?

@gibfahn I am not sure if it's reasonable to only give output for tests that fail unless we implement this in the test runner - we test our process.exit() hooks in JS, among many things. If the hooks are broken, common.debuglog() can be broken as well - unless we setup some signal handlers in the native layer to do this, but I am not sure if that is a good idea.

Trott · 2018-12-05T02:47:15Z

Seems like this has stalled and has some mild opposition. I'm going to close it, but if it's still being worked on, feel free to re-open or comment asking for someone else to re-open.

Thanks for the pull request and I hope you continue to contribute!

nodejs-github-bot added the test Issues and PRs related to the tests. label Aug 9, 2018

vsemozhetbyt reviewed Aug 9, 2018

View reviewed changes

richardlau requested changes Aug 9, 2018

View reviewed changes

SirR4T force-pushed the fix9314-add-common-log branch from b1b2463 to cee02c7 Compare August 10, 2018 05:14

sagirk approved these changes Aug 10, 2018

View reviewed changes

SirR4T force-pushed the fix9314-add-common-log branch from cee02c7 to 8363dcf Compare August 10, 2018 05:38

richardlau approved these changes Aug 10, 2018

View reviewed changes

richardlau reviewed Aug 10, 2018

View reviewed changes

SirR4T force-pushed the fix9314-add-common-log branch 3 times, most recently from 37ca6e2 to 80295d8 Compare August 10, 2018 07:05

BridgeAR reviewed Aug 13, 2018

View reviewed changes

SirR4T force-pushed the fix9314-add-common-log branch from 80295d8 to 8942222 Compare August 21, 2018 09:53

jasnell approved these changes Aug 21, 2018

View reviewed changes

refack suggested changes Aug 21, 2018

View reviewed changes

SirR4T force-pushed the fix9314-add-common-log branch from 8942222 to 68a4476 Compare August 27, 2018 06:46

test: add a common.debuglog function

0e69a09

SirR4T added 3 commits August 29, 2018 13:56

test: add tests for common.debuglog

1c5cbb5

test: incorporating suggested changes for common.debuglog

a9fb74a

test: add docs for common.debuglog behaviour

93aa055

SirR4T force-pushed the fix9314-add-common-log branch from 68a4476 to 93aa055 Compare August 29, 2018 08:26

ofrobots reviewed Sep 5, 2018

View reviewed changes

mcollina approved these changes Sep 6, 2018

View reviewed changes

joyeecheung requested changes Oct 2, 2018

View reviewed changes

Trott closed this Dec 5, 2018

richardlau mentioned this pull request Mar 5, 2019

doc: add guidance on console output in tests #26456

Closed

2 tasks

		@@ -0,0 +1,18 @@
		'use strict';

		const common = require('../common'); // eslint-disable-line no-unused-vars

test: add a common.debuglog function #22206

test: add a common.debuglog function #22206

Conversation

SirR4T commented Aug 9, 2018 • edited Loading

Checklist

SirR4T commented Aug 9, 2018

richardlau commented Aug 9, 2018

SirR4T commented Aug 9, 2018

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

richardlau left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

sagirk left a comment

Choose a reason for hiding this comment

SirR4T commented Aug 10, 2018

richardlau left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

gdams commented Aug 12, 2018

Trott commented Aug 13, 2018

Trott commented Aug 13, 2018

BridgeAR left a comment

Choose a reason for hiding this comment

refack left a comment

Choose a reason for hiding this comment

refack commented Aug 21, 2018

jasnell commented Aug 21, 2018

jasnell commented Aug 21, 2018

refack commented Aug 21, 2018 • edited Loading

SirR4T commented Aug 22, 2018 • edited Loading

SirR4T commented Aug 27, 2018

SirR4T commented Sep 5, 2018

BridgeAR commented Sep 5, 2018

cjihrig commented Sep 5, 2018

ofrobots left a comment

Choose a reason for hiding this comment

mcollina left a comment

Choose a reason for hiding this comment

joyeecheung Oct 2, 2018 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

joyeecheung Oct 5, 2018 • edited Loading

Choose a reason for hiding this comment

Trott commented Dec 5, 2018 • edited Loading

SirR4T commented Aug 9, 2018 •

edited

Loading

refack commented Aug 21, 2018 •

edited

Loading

SirR4T commented Aug 22, 2018 •

edited

Loading

joyeecheung Oct 2, 2018 •

edited

Loading

joyeecheung Oct 5, 2018 •

edited

Loading

Trott commented Dec 5, 2018 •

edited

Loading