From 62c91f7893e568ebf0392a429eb288324359984e Mon Sep 17 00:00:00 2001 From: Ruben Bridgewater Date: Mon, 20 Jan 2020 19:00:52 +0100 Subject: [PATCH 1/2] test: improve logged errors To indicate which lines are test lines and which from Node.js core, it's good to rely on `util.inspect()` while inspecting errors. The stack was accessed directly instead in multiple cases and logging that does not provide as much information as using `util.inspect()`. --- test/common/index.js | 28 +++++++++---------- test/common/wpt.js | 3 +- test/fixtures/uncaught-exceptions/domain.js | 2 +- test/message/vm_display_runtime_error.js | 2 +- test/message/vm_display_syntax_error.js | 2 +- test/parallel/test-assert-if-error.js | 2 +- test/parallel/test-assert.js | 2 +- test/parallel/test-http-request-agent.js | 2 +- test/parallel/test-http-unix-socket.js | 2 +- .../test-promises-unhandled-rejections.js | 11 ++++---- test/parallel/test-tls-min-max-version.js | 3 +- test/parallel/test-tls-securepair-server.js | 6 +--- test/parallel/test-tls-set-ciphers.js | 7 +++-- test/parallel/test-vm-context.js | 4 +-- 14 files changed, 39 insertions(+), 37 deletions(-) diff --git a/test/common/index.js b/test/common/index.js index 300ea60377876b..175058a76c2073 100644 --- a/test/common/index.js +++ b/test/common/index.js @@ -30,7 +30,7 @@ const fs = require('fs'); // Do not require 'os' until needed so that test-os-checked-fucnction can // monkey patch it. If 'os' is required here, that test will fail. const path = require('path'); -const util = require('util'); +const { inspect } = require('util'); const { isMainThread } = require('worker_threads'); const tmpdir = require('./tmpdir'); @@ -88,7 +88,7 @@ if (process.argv.length === 2 && (process.features.inspector || !flag.startsWith('--inspect'))) { console.log( 'NOTE: The test started as a child_process using these flags:', - util.inspect(flags), + inspect(flags), 'Use NODE_SKIP_FLAG_CHECK to run the test with the original flags.' ); const args = [...flags, ...process.execArgv, ...process.argv.slice(1)]; @@ -129,7 +129,7 @@ if (process.env.NODE_TEST_WITH_ASYNC_HOOKS) { process.on('exit', () => { // Iterate through handles to make sure nothing crashes for (const k in initHandles) - util.inspect(initHandles[k]); + inspect(initHandles[k]); }); const _queueDestroyAsyncId = async_wrap.queueDestroyAsyncId; @@ -139,19 +139,19 @@ if (process.env.NODE_TEST_WITH_ASYNC_HOOKS) { process._rawDebug(); throw new Error(`same id added to destroy list twice (${id})`); } - destroyListList[id] = new Error().stack; + destroyListList[id] = inspect(new Error()); _queueDestroyAsyncId(id); }; require('async_hooks').createHook({ - init(id, ty, tr, r) { + init(id, ty, tr, resource) { if (initHandles[id]) { process._rawDebug( - `Is same resource: ${r === initHandles[id].resource}`); + `Is same resource: ${resource === initHandles[id].resource}`); process._rawDebug(`Previous stack:\n${initHandles[id].stack}\n`); throw new Error(`init called twice for same id (${id})`); } - initHandles[id] = { resource: r, stack: new Error().stack.substr(6) }; + initHandles[id] = { resource, stack: inspect(new Error()).substr(6) }; }, before() { }, after() { }, @@ -161,7 +161,7 @@ if (process.env.NODE_TEST_WITH_ASYNC_HOOKS) { process._rawDebug(); throw new Error(`destroy called for same id (${id})`); } - destroydIdsList[id] = new Error().stack; + destroydIdsList[id] = inspect(new Error()); }, }).enable(); } @@ -345,7 +345,7 @@ function _mustCallInner(fn, criteria = 1, field) { const context = { [field]: criteria, actual: 0, - stack: (new Error()).stack, + stack: inspect(new Error()), name: fn.name || '' }; @@ -511,7 +511,7 @@ function expectWarning(nameOrMap, expected, code) { if (!catchWarning[warning.name]) { throw new TypeError( `"${warning.name}" was triggered without being expected.\n` + - util.inspect(warning) + inspect(warning) ); } catchWarning[warning.name](warning); @@ -530,9 +530,9 @@ function expectWarning(nameOrMap, expected, code) { function expectsError(validator, exact) { return mustCall((...args) => { if (args.length !== 1) { - // Do not use `assert.strictEqual()` to prevent `util.inspect` from + // Do not use `assert.strictEqual()` to prevent `inspect` from // always being called. - assert.fail(`Expected one argument, got ${util.inspect(args)}`); + assert.fail(`Expected one argument, got ${inspect(args)}`); } const error = args.pop(); const descriptor = Object.getOwnPropertyDescriptor(error, 'message'); @@ -661,9 +661,9 @@ function invalidArgTypeHelper(input) { if (input.constructor && input.constructor.name) { return ` Received an instance of ${input.constructor.name}`; } - return ` Received ${util.inspect(input, { depth: -1 })}`; + return ` Received ${inspect(input, { depth: -1 })}`; } - let inspected = util.inspect(input, { colors: false }); + let inspected = inspect(input, { colors: false }); if (inspected.length > 25) inspected = `${inspected.slice(0, 25)}...`; return ` Received type ${typeof input} (${inspected})`; diff --git a/test/common/wpt.js b/test/common/wpt.js index c227f2e6fa3529..f6ac07bdfd296c 100644 --- a/test/common/wpt.js +++ b/test/common/wpt.js @@ -7,6 +7,7 @@ const fs = require('fs'); const fsPromises = fs.promises; const path = require('path'); const vm = require('vm'); +const { inspect } = require('util'); // https://github.com/w3c/testharness.js/blob/master/testharness.js // TODO: get rid of this half-baked harness in favor of the one @@ -354,7 +355,7 @@ class WPTRunner { this.fail(filename, { name: '', message: err.message, - stack: err.stack + stack: inspect(err) }, 'UNCAUGHT'); this.inProgress.delete(filename); } diff --git a/test/fixtures/uncaught-exceptions/domain.js b/test/fixtures/uncaught-exceptions/domain.js index 9ede6993a7331b..8b69f52f14e9da 100644 --- a/test/fixtures/uncaught-exceptions/domain.js +++ b/test/fixtures/uncaught-exceptions/domain.js @@ -2,7 +2,7 @@ const domain = require('domain'); var d = domain.create(); d.on('error', function(err) { - console.log('[ignored]', err.stack); + console.log('[ignored]', err); }); d.run(function() { diff --git a/test/message/vm_display_runtime_error.js b/test/message/vm_display_runtime_error.js index 230c45feab19a7..3ebbb1464d135d 100644 --- a/test/message/vm_display_runtime_error.js +++ b/test/message/vm_display_runtime_error.js @@ -28,7 +28,7 @@ console.error('beginning'); try { vm.runInThisContext('throw new Error("boo!")', { filename: 'test.vm' }); } catch (err) { - console.error(err.stack); + console.error(err); } vm.runInThisContext('throw new Error("spooky!")', { filename: 'test.vm' }); diff --git a/test/message/vm_display_syntax_error.js b/test/message/vm_display_syntax_error.js index 097b8e368c1249..ac9b4d17bd147b 100644 --- a/test/message/vm_display_syntax_error.js +++ b/test/message/vm_display_syntax_error.js @@ -28,7 +28,7 @@ console.error('beginning'); try { vm.runInThisContext('var 4;', { filename: 'foo.vm', displayErrors: true }); } catch (err) { - console.error(err.stack); + console.error(err); } vm.runInThisContext('var 5;', { filename: 'test.vm' }); diff --git a/test/parallel/test-assert-if-error.js b/test/parallel/test-assert-if-error.js index cd6f99dfa43ea7..6765870e357d67 100644 --- a/test/parallel/test-assert-if-error.js +++ b/test/parallel/test-assert-if-error.js @@ -83,7 +83,7 @@ assert.ifError(undefined); } catch (e) { threw = true; assert.strictEqual(e.message, 'Missing expected exception.'); - assert(!e.stack.includes('throws'), e.stack); + assert(!e.stack.includes('throws'), e); } assert(threw); } diff --git a/test/parallel/test-assert.js b/test/parallel/test-assert.js index 23e1734aff235c..f5037b900a260b 100644 --- a/test/parallel/test-assert.js +++ b/test/parallel/test-assert.js @@ -401,7 +401,7 @@ assert.throws( threw = true; assert.ok(e.message.includes(rangeError.message)); assert.ok(e instanceof assert.AssertionError); - assert.ok(!e.stack.includes('doesNotThrow'), e.stack); + assert.ok(!e.stack.includes('doesNotThrow'), e); } assert.ok(threw); } diff --git a/test/parallel/test-http-request-agent.js b/test/parallel/test-http-request-agent.js index a1f3077ed2820f..453ac380d0908f 100644 --- a/test/parallel/test-http-request-agent.js +++ b/test/parallel/test-http-request-agent.js @@ -34,7 +34,7 @@ server.listen(0, common.mustCall(function() { res.resume(); server.close(); })).on('error', function(e) { - console.error(e.stack); + console.error(e); process.exit(1); }); })); diff --git a/test/parallel/test-http-unix-socket.js b/test/parallel/test-http-unix-socket.js index d6ce23bb19f4b1..f8362d6183d8e1 100644 --- a/test/parallel/test-http-unix-socket.js +++ b/test/parallel/test-http-unix-socket.js @@ -69,7 +69,7 @@ server.listen(common.PIPE, common.mustCall(function() { })); req.on('error', function(e) { - assert.fail(e.stack); + assert.fail(e); }); req.end(); diff --git a/test/parallel/test-promises-unhandled-rejections.js b/test/parallel/test-promises-unhandled-rejections.js index f4294800fa9dab..86a4370c518c56 100644 --- a/test/parallel/test-promises-unhandled-rejections.js +++ b/test/parallel/test-promises-unhandled-rejections.js @@ -2,6 +2,7 @@ const common = require('../common'); const assert = require('assert'); const domain = require('domain'); +const { inspect } = require('util'); common.disableCrashOnUnhandledRejection(); @@ -14,8 +15,8 @@ const asyncTest = (function() { function fail(error) { const stack = currentTest ? - `${error.stack}\nFrom previous event:\n${currentTest.stack}` : - error.stack; + `${inspect(error)}\nFrom previous event:\n${currentTest.stack}` : + inspect(error); if (currentTest) process.stderr.write(`'${currentTest.description}' failed\n\n`); @@ -44,11 +45,11 @@ const asyncTest = (function() { } return function asyncTest(description, fn) { - const stack = new Error().stack.split('\n').slice(1).join('\n'); + const stack = inspect(new Error()).split('\n').slice(1).join('\n'); asyncTestQueue.push({ action: fn, - stack: stack, - description: description + stack, + description }); if (!asyncTestsEnabled) { asyncTestsEnabled = true; diff --git a/test/parallel/test-tls-min-max-version.js b/test/parallel/test-tls-min-max-version.js index 179ae1fa637d92..7ef0f12426537c 100644 --- a/test/parallel/test-tls-min-max-version.js +++ b/test/parallel/test-tls-min-max-version.js @@ -1,6 +1,7 @@ 'use strict'; const common = require('../common'); const fixtures = require('../common/fixtures'); +const { inspect } = require('util'); // Check min/max protocol versions. @@ -16,7 +17,7 @@ function test(cmin, cmax, cprot, smin, smax, sprot, proto, cerr, serr) { // Report where test was called from. Strip leading garbage from // at Object. (file:line) // from the stack location, we only want the file:line part. - const where = (new Error()).stack.split('\n')[2].replace(/[^(]*/, ''); + const where = inspect(new Error()).split('\n')[2].replace(/[^(]*/, ''); connect({ client: { checkServerIdentity: (servername, cert) => { }, diff --git a/test/parallel/test-tls-securepair-server.js b/test/parallel/test-tls-securepair-server.js index 5e3cd4130cba9f..78cd9f725401ed 100644 --- a/test/parallel/test-tls-securepair-server.js +++ b/test/parallel/test-tls-securepair-server.js @@ -37,7 +37,7 @@ const key = fixtures.readKey('rsa_private.pem'); const cert = fixtures.readKey('rsa_cert.crt'); function log(a) { - console.error(`***server*** ${a}`); + console.error('***server***', a); } const server = net.createServer(common.mustCall(function(socket) { @@ -74,21 +74,18 @@ const server = net.createServer(common.mustCall(function(socket) { pair.cleartext.on('error', function(err) { log('got error: '); log(err); - log(err.stack); socket.destroy(); }); pair.encrypted.on('error', function(err) { log('encrypted error: '); log(err); - log(err.stack); socket.destroy(); }); socket.on('error', function(err) { log('socket error: '); log(err); - log(err.stack); socket.destroy(); }); @@ -99,7 +96,6 @@ const server = net.createServer(common.mustCall(function(socket) { pair.on('error', function(err) { log('secure error: '); log(err); - log(err.stack); socket.destroy(); }); })); diff --git a/test/parallel/test-tls-set-ciphers.js b/test/parallel/test-tls-set-ciphers.js index fbca83b3d5d286..50fb6edc3a2431 100644 --- a/test/parallel/test-tls-set-ciphers.js +++ b/test/parallel/test-tls-set-ciphers.js @@ -1,7 +1,10 @@ 'use strict'; const common = require('../common'); -if (!common.hasCrypto) common.skip('missing crypto'); +if (!common.hasCrypto) + common.skip('missing crypto'); + const fixtures = require('../common/fixtures'); +const { inspect } = require('util'); // Test cipher: option for TLS. @@ -12,7 +15,7 @@ const { function test(cciphers, sciphers, cipher, cerr, serr) { assert(cipher || cerr || serr, 'test missing any expectations'); - const where = (new Error()).stack.split('\n')[2].replace(/[^(]*/, ''); + const where = inspect(new Error()).split('\n')[2].replace(/[^(]*/, ''); connect({ client: { checkServerIdentity: (servername, cert) => { }, diff --git a/test/parallel/test-vm-context.js b/test/parallel/test-vm-context.js index 247b8a17cc675e..5226f0e6ac0ea2 100644 --- a/test/parallel/test-vm-context.js +++ b/test/parallel/test-vm-context.js @@ -22,7 +22,7 @@ 'use strict'; require('../common'); const assert = require('assert'); - +const { inspect } = require('util'); const vm = require('vm'); const Script = vm.Script; let script = new Script('"passed";'); @@ -59,7 +59,7 @@ try { } catch (e) { gh1140Exception = e; assert.ok(/expected-filename/.test(e.stack), - `expected appearance of filename in Error stack: ${e.stack}`); + `expected appearance of filename in Error stack: ${inspect(e)}`); } // This is outside of catch block to confirm catch block ran. assert.strictEqual(gh1140Exception.toString(), 'Error'); From f4f440c6cfbfc2f6f34e44b75751e344e701e763 Mon Sep 17 00:00:00 2001 From: Ruben Bridgewater Date: Fri, 24 Jan 2020 08:49:52 +0100 Subject: [PATCH 2/2] fixup: address comment --- test/common/index.js | 25 ++++++++++++++----------- 1 file changed, 14 insertions(+), 11 deletions(-) diff --git a/test/common/index.js b/test/common/index.js index 175058a76c2073..2e2d14dc0e6d43 100644 --- a/test/common/index.js +++ b/test/common/index.js @@ -30,7 +30,7 @@ const fs = require('fs'); // Do not require 'os' until needed so that test-os-checked-fucnction can // monkey patch it. If 'os' is required here, that test will fail. const path = require('path'); -const { inspect } = require('util'); +const util = require('util'); const { isMainThread } = require('worker_threads'); const tmpdir = require('./tmpdir'); @@ -88,7 +88,7 @@ if (process.argv.length === 2 && (process.features.inspector || !flag.startsWith('--inspect'))) { console.log( 'NOTE: The test started as a child_process using these flags:', - inspect(flags), + util.inspect(flags), 'Use NODE_SKIP_FLAG_CHECK to run the test with the original flags.' ); const args = [...flags, ...process.execArgv, ...process.argv.slice(1)]; @@ -129,7 +129,7 @@ if (process.env.NODE_TEST_WITH_ASYNC_HOOKS) { process.on('exit', () => { // Iterate through handles to make sure nothing crashes for (const k in initHandles) - inspect(initHandles[k]); + util.inspect(initHandles[k]); }); const _queueDestroyAsyncId = async_wrap.queueDestroyAsyncId; @@ -139,7 +139,7 @@ if (process.env.NODE_TEST_WITH_ASYNC_HOOKS) { process._rawDebug(); throw new Error(`same id added to destroy list twice (${id})`); } - destroyListList[id] = inspect(new Error()); + destroyListList[id] = util.inspect(new Error()); _queueDestroyAsyncId(id); }; @@ -151,7 +151,10 @@ if (process.env.NODE_TEST_WITH_ASYNC_HOOKS) { process._rawDebug(`Previous stack:\n${initHandles[id].stack}\n`); throw new Error(`init called twice for same id (${id})`); } - initHandles[id] = { resource, stack: inspect(new Error()).substr(6) }; + initHandles[id] = { + resource, + stack: util.inspect(new Error()).substr(6) + }; }, before() { }, after() { }, @@ -161,7 +164,7 @@ if (process.env.NODE_TEST_WITH_ASYNC_HOOKS) { process._rawDebug(); throw new Error(`destroy called for same id (${id})`); } - destroydIdsList[id] = inspect(new Error()); + destroydIdsList[id] = util.inspect(new Error()); }, }).enable(); } @@ -345,7 +348,7 @@ function _mustCallInner(fn, criteria = 1, field) { const context = { [field]: criteria, actual: 0, - stack: inspect(new Error()), + stack: util.inspect(new Error()), name: fn.name || '' }; @@ -511,7 +514,7 @@ function expectWarning(nameOrMap, expected, code) { if (!catchWarning[warning.name]) { throw new TypeError( `"${warning.name}" was triggered without being expected.\n` + - inspect(warning) + util.inspect(warning) ); } catchWarning[warning.name](warning); @@ -532,7 +535,7 @@ function expectsError(validator, exact) { if (args.length !== 1) { // Do not use `assert.strictEqual()` to prevent `inspect` from // always being called. - assert.fail(`Expected one argument, got ${inspect(args)}`); + assert.fail(`Expected one argument, got ${util.inspect(args)}`); } const error = args.pop(); const descriptor = Object.getOwnPropertyDescriptor(error, 'message'); @@ -661,9 +664,9 @@ function invalidArgTypeHelper(input) { if (input.constructor && input.constructor.name) { return ` Received an instance of ${input.constructor.name}`; } - return ` Received ${inspect(input, { depth: -1 })}`; + return ` Received ${util.inspect(input, { depth: -1 })}`; } - let inspected = inspect(input, { colors: false }); + let inspected = util.inspect(input, { colors: false }); if (inspected.length > 25) inspected = `${inspected.slice(0, 25)}...`; return ` Received type ${typeof input} (${inspected})`;