test: make common.mustNotCall show file:linenumber #17257

lance · 2017-11-22T19:16:03Z

When a test fails via common.mustNotCall it is sometimes hard to
determine exactly what was called. This modification stores the
caller's file and line number by using the V8 Error API to capture
a stack at the time common.mustNotCall() is called. In the event
of failure, this information is printed.

I tried to write a test for this, but common.mustNotCall() ultimately
calls assert.fail() which made it difficult to do. I did simulate a
failure, and this is what the output looked like:

assert.js:42
  throw new errors.AssertionError({
  ^

AssertionError [ERR_ASSERTION]: function should not have been called at /Users/lanceball/src/node/test/parallel/test-http-host-headers.js:60
    at ClientRequest.mustNotCall (/Users/lanceball/src/node/test/common/index.js:587:12)
    at ClientRequest.emit (events.js:159:13)
    at Socket.socketErrorListener (_http_client.js:389:9)
    at Socket.emit (events.js:159:13)
    at emitErrorNT (internal/streams/destroy.js:64:8)
    at _combinedTickCallback (internal/process/next_tick.js:137:11)
    at process._tickCallback (internal/process/next_tick.js:179:9)

~~@nodejs/collaborators if you have a recommendation for testing this, I'm all ears.~~

Checklist

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

Affected core subsystem(s)

test

targos · 2017-11-22T19:41:10Z

if you have a recommendation for testing this, I'm all ears.

with a message test?

lance · 2017-11-22T19:57:57Z

@jasnell @targos I pushed a new commit with some minor modifications. I think it makes the code easier to read. Just FYI since you've already approved.

lance · 2017-11-22T20:11:56Z

@targos do you mean by testing the message against an expected value? The only way I can think of achieving that without resulting in a call to assert.fail() is by exposing common.getCallSite() via exports and testing that value. Is there something else you had in mind?

targos · 2017-11-22T20:17:21Z

I mean adding a test in test/message that results in the output you want to check.

targos · 2017-11-22T20:19:33Z

test/common/index.js

+  err.stack;
+  Error.prepareStackTrace = originalStackFormatter;
+  err.stack;
+}


I don't understand how this works. There is no return.

Stupid mistake. Fixed and test added.

lance · 2017-11-22T20:46:56Z

@targos test added - it actually wasn't very complicated.

lance · 2017-11-22T20:53:17Z

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

jasnell · 2017-11-23T00:14:33Z

Lance... CI was generally good but I bumped the freebsd run to later in the queue to get another one of the code-and-learn PRs finished up first https://ci.nodejs.org/job/node-test-commit-freebsd/13516/

refack · 2017-11-22T21:00:47Z

test/common/index.js

@@ -568,9 +568,24 @@ exports.canCreateSymLink = function() {
  return true;
 };

+function getCallSite(level = 2) {


Could you export this, it might be useful in other places.

AFAIK the second argument to Error.captureStackTrace is a function pointer so this should be:

function getCallSite(level) { ... Error.prepareStackTrace = (err, stack) => `${stack[0].getFileName()}:${stack[0].getLineNumber()}`; ... Error.captureStackTrace(err, level); ... const callSite = getCallSite(exports.mustNotCall);

You are right. I'm not sure why I put level as the second arg. I will take 'hours before Thanksgiving holiday' as my excuse this time. In any case, it seems that Error.captureStackTrace just quietly ignores that parameter it if it's not a function pointer, so things still worked.

I agree though that using the function pointer is probably a more reliable, and easier to grok way of indexing into the stack than by using an index number. Change coming soon.

refack · 2017-11-23T00:47:28Z

You cracked half of #13115. 🤸‍♀️

lance · 2017-11-23T14:51:48Z

@refack changes addressed. However, by exporting common.getCallSite() I think I've added a new task to document it...

tniessen · 2017-11-24T06:11:48Z

test/common/index.js

+  const err = new Error();
+  Error.captureStackTrace(err, top);
+  // the way V8 Error API works, the stack is not
+  // formatted until it is accessed


This fits into one line.

lance · 2017-11-24T17:10:00Z

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

The first one indicated some inconsistent failures on Windows. E.g.

not ok 88 parallel/test-common-must-not-call
  ---
  duration_ms: 0.318
  severity: fail
  stack: |-
    assert.js:42
      throw new errors.AssertionError({
      ^
    
    AssertionError [ERR_ASSERTION]: 'c' strictEqual 'test-common-must-not-call.js'
        at common.mustCall (c:\workspace\node-test-binary-windows\test\parallel\test-common-must-not-call.js:15:10)
        at c:\workspace\node-test-binary-windows\test\common\index.js:522:15
        at Object.<anonymous> (c:\workspace\node-test-binary-windows\test\parallel\test-common-must-not-call.js:22:3)
        at Module._compile (module.js:647:30)
        at Object.Module._extensions..js (module.js:658:10)
        at Module.load (module.js:566:32)
        at tryModuleLoad (module.js:506:12)
        at Function.Module._load (module.js:498:3)
        at Function.Module.runMain (module.js:688:10)
        at startup (bootstrap_node.js:192:16)

And... just as I pasted this, I realized the problem...

lance · 2017-11-28T17:34:00Z

Another CI after changes to accommodate Windows paths.

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

lance · 2017-11-28T19:54:31Z

CI looks good, with the exception of the following unrelated errors.

centos6-64

/usr/bin/python tools/test.py -j 2 -p tap --logfile test.tap \
	--mode=release --flaky-tests=dontcare \
	 async-hooks default addons addons-napi \
	doctool known_issues
Traceback (most recent call last):
  File "tools/test.py", line 1759, in 
    sys.exit(Main())
  File "tools/test.py", line 1662, in Main
    'type': get_env_type(vm, options.type),
  File "tools/test.py", line 1569, in get_env_type
    if "fips" in subprocess.check_output([vm, "-p",
AttributeError: 'module' object has no attribute 'check_output'
Makefile:408: recipe for target 'test-ci' failed
make[1]: *** [test-ci] Error 1
Makefile:608: recipe for target 'run-ci' failed
make: *** [run-ci] Error 2
Build step 'Execute shell' marked build as failure

ubuntu1604_sharedlibs_openssl110_x64

12:36:00 gyp info ok 
12:36:00 touch test/addons-napi/.buildstamp
12:36:00 make[1]: write error: stdout
12:36:00 Makefile:608: recipe for target 'run-ci' failed

lance · 2017-11-28T19:55:36Z

@refack if this looks good to you now, I can land it.

thefourtheye · 2017-12-01T05:40:33Z

test/common/README.md

@@ -136,6 +136,12 @@ Path to the 'fixtures' directory.

 Returns an instance of all possible `ArrayBufferView`s of the provided Buffer.

+### getCallSite(func)
+* `func` [&lt;Function]


Shouldn't there be a > after Function?

thefourtheye · 2017-12-01T05:52:04Z

test/common/index.js

@@ -568,9 +568,23 @@ exports.canCreateSymLink = function() {
  return true;
 };

+exports.getCallSite = function getCallSite(top) {


Would it be better if we validated that if top is actually a function?

It doesn't really matter, in my opinion. The only place it is used is in Error.captureStackTrace() which does that checking for us. I.e. if it's not a function, the parameter is ignored and the top frame in the stack will be where Error.captureStackTrace() was called.

> const common = require('./test/common'); undefined > let x = common.getCallSite() undefined > x '/Users/lanceball/src/node/test/common/index.js:576' > x = common.getCallSite('abc'); '/Users/lanceball/src/node/test/common/index.js:576' > x = common.getCallSite(123) '/Users/lanceball/src/node/test/common/index.js:576' >

When a test fails via `common.mustNotCall` it is sometimes hard to determine exactly what was called. This modification stores the caller's file and line number by using the V8 Error API to capture a stack at the time `common.mustNotCall()` is called. In the event of failure, this information is printed.

Instead of indexing into the call stack to find the right level to store, just use the `Error.captureStackTrace()` function's second parameter - a function pointer.

Because of the way this test splits up the message string on ':' we need to ensure that the initial drive letter does not affect the string manipulation. Shortening it by 2 characters solves this.

lance · 2017-12-04T16:44:32Z

Landed in: a322b8e

When a test fails via `common.mustNotCall` it is sometimes hard to determine exactly what was called. This modification stores the caller's file and line number by using the V8 Error API to capture a stack at the time `common.mustNotCall()` is called. In the event of failure, this information is printed. This change also exposes a new function in test/common, `getCallSite()` which accepts a `function` and returns a `String` with the file name and line number for the function. PR-URL: #17257 Reviewed-By: James M Snell <[email protected]> Reviewed-By: Michaël Zasso <[email protected]> Reviewed-By: Gibson Fahnestock <[email protected]> Reviewed-By: Tobias Nießen <[email protected]> Reviewed-By: Joyee Cheung <[email protected]> Reviewed-By: Sakthipriyan Vairamani <[email protected]> Reviewed-By: Khaidi Chu <[email protected]>

gibfahn · 2017-12-20T00:22:11Z

Should this be backported to v6.x-staging? If yes please follow the guide and raise a backport PR, if no let me know or add the dont-land-on label.

When a test fails via `common.mustNotCall` it is sometimes hard to determine exactly what was called. This modification stores the caller's file and line number by using the V8 Error API to capture a stack at the time `common.mustNotCall()` is called. In the event of failure, this information is printed. This change also exposes a new function in test/common, `getCallSite()` which accepts a `function` and returns a `String` with the file name and line number for the function. PR-URL: #17257 Reviewed-By: James M Snell <[email protected]> Reviewed-By: Michaël Zasso <[email protected]> Reviewed-By: Gibson Fahnestock <[email protected]> Reviewed-By: Tobias Nießen <[email protected]> Reviewed-By: Joyee Cheung <[email protected]> Reviewed-By: Sakthipriyan Vairamani <[email protected]> Reviewed-By: Khaidi Chu <[email protected]>

lance · 2018-03-13T20:30:38Z

@gibfahn apologies for the delay on this. I am only now coming up from a lot of internal work that has prevented me from contributing to node as much as I would have liked. In any case, I'm a little more open now and will look into a backport to 6.x for this.

When a test fails via `common.mustNotCall` it is sometimes hard to determine exactly what was called. This modification stores the caller's file and line number by using the V8 Error API to capture a stack at the time `common.mustNotCall()` is called. In the event of failure, this information is printed. This change also exposes a new function in test/common, `getCallSite()` which accepts a `function` and returns a `String` with the file name and line number for the function. Backport-PR-URL: #19355 PR-URL: #17257 Reviewed-By: James M Snell <[email protected]> Reviewed-By: Michaël Zasso <[email protected]> Reviewed-By: Gibson Fahnestock <[email protected]> Reviewed-By: Tobias Nießen <[email protected]> Reviewed-By: Joyee Cheung <[email protected]> Reviewed-By: Sakthipriyan Vairamani <[email protected]> Reviewed-By: Khaidi Chu <[email protected]>

lance added the test Issues and PRs related to the tests. label Nov 22, 2017

jasnell approved these changes Nov 22, 2017

View reviewed changes

targos approved these changes Nov 22, 2017

View reviewed changes

targos reviewed Nov 22, 2017

View reviewed changes

targos approved these changes Nov 22, 2017

View reviewed changes

gibfahn approved these changes Nov 22, 2017

View reviewed changes

refack reviewed Nov 23, 2017

View reviewed changes

lance self-assigned this Nov 23, 2017

tniessen approved these changes Nov 24, 2017

View reviewed changes

joyeecheung approved these changes Nov 29, 2017

View reviewed changes

thefourtheye approved these changes Dec 1, 2017

View reviewed changes

XadillaX approved these changes Dec 4, 2017

View reviewed changes

targos approved these changes Dec 4, 2017

View reviewed changes

lance added 4 commits December 4, 2017 11:14

test: add test for common.mustNotCall

c54e1e1

test: export commmon.getCallSite

b9402b7

test: change common.getCallSite to take a function

9e0363d

Instead of indexing into the call stack to find the right level to store, just use the `Error.captureStackTrace()` function's second parameter - a function pointer.

lance added 4 commits December 4, 2017 11:14

test: fix comment formatting

451ea32

test: document common.getCallSite()

ae47bce

test: add check for win32 and modify message

9e23ec2

Because of the way this test splits up the message string on ':' we need to ensure that the initial drive letter does not affect the string manipulation. Shortening it by 2 characters solves this.

test: fix typo in common.getCallSite doc

8e7589c

lance closed this Dec 4, 2017

MylesBorins mentioned this pull request Dec 12, 2017

v9.3.0 proposal #17631

Merged

gibfahn added backport-requested-v6.x labels Dec 20, 2017

gibfahn mentioned this pull request Dec 20, 2017

v8.9.4 proposal #17772

Closed

gibfahn mentioned this pull request Dec 20, 2017

v8.9.4 proposal #17774

Merged

lance mentioned this pull request Mar 14, 2018

[v6.x backport] test: make common.mustNotCall show file:linenumber #19355

Closed

4 tasks

MylesBorins added backported-to-v6.x and removed backport-requested-v6.x labels Mar 20, 2018

MylesBorins mentioned this pull request Apr 13, 2018

v6.14.2 proposal #19996

Merged

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

test: make common.mustNotCall show file:linenumber #17257

test: make common.mustNotCall show file:linenumber #17257

lance commented Nov 22, 2017 •

edited

Loading

targos commented Nov 22, 2017

lance commented Nov 22, 2017

lance commented Nov 22, 2017

targos commented Nov 22, 2017

targos Nov 22, 2017

lance Nov 22, 2017

lance commented Nov 22, 2017

lance commented Nov 22, 2017

jasnell commented Nov 23, 2017

refack Nov 22, 2017

lance Nov 23, 2017

refack commented Nov 23, 2017

lance commented Nov 23, 2017

tniessen Nov 24, 2017

lance commented Nov 24, 2017

lance commented Nov 28, 2017

lance commented Nov 28, 2017

lance commented Nov 28, 2017

thefourtheye Dec 1, 2017

thefourtheye Dec 1, 2017

lance Dec 1, 2017

lance commented Dec 4, 2017

gibfahn commented Dec 20, 2017

lance commented Mar 13, 2018

test: make common.mustNotCall show file:linenumber #17257

test: make common.mustNotCall show file:linenumber #17257

Conversation

lance commented Nov 22, 2017 • edited Loading

Checklist

Affected core subsystem(s)

targos commented Nov 22, 2017

lance commented Nov 22, 2017

lance commented Nov 22, 2017

targos commented Nov 22, 2017

Choose a reason for hiding this comment

Choose a reason for hiding this comment

lance commented Nov 22, 2017

lance commented Nov 22, 2017

jasnell commented Nov 23, 2017

Choose a reason for hiding this comment

Choose a reason for hiding this comment

refack commented Nov 23, 2017

lance commented Nov 23, 2017

Choose a reason for hiding this comment

lance commented Nov 24, 2017

lance commented Nov 28, 2017

lance commented Nov 28, 2017

lance commented Nov 28, 2017

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

lance commented Dec 4, 2017

gibfahn commented Dec 20, 2017

lance commented Mar 13, 2018

lance commented Nov 22, 2017 •

edited

Loading