From e117315320bd43cf7bb3e3f84c596c8523fe4991 Mon Sep 17 00:00:00 2001 From: James Talmage Date: Sat, 14 Nov 2015 17:04:01 -0500 Subject: [PATCH 1/6] make AppVeyor retry failed runs. Tests are just too brittle on AppVeyor. `npm install` fails frequently, and Node on Windows does not seem to reliably flush stdout/stderr of forked child processes. I don't like this, but I'm at a loss for other solutions. --- appveyor.yml | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/appveyor.yml b/appveyor.yml index 5d3f9dec8..3cad5ff9c 100644 --- a/appveyor.yml +++ b/appveyor.yml @@ -7,9 +7,9 @@ environment: install: - ps: Install-Product node $env:nodejs_version - set CI=true - - npm -g install npm@latest + - npm -g install npm@latest || (timeout 30 && npm -g install npm@latest) - set PATH=%APPDATA%\npm;%PATH% - - npm install + - npm install || (timeout 30 && npm install) matrix: fast_finish: true build: off @@ -19,4 +19,4 @@ clone_depth: 1 test_script: - node --version - npm --version - - npm run test-win + - npm run test-win || (timeout 30 && npm run test-win) From cbb5e720a8cec1ddb66595cff04906f39a38bdb3 Mon Sep 17 00:00:00 2001 From: James Talmage Date: Fri, 13 Nov 2015 05:06:16 -0500 Subject: [PATCH 2/6] report unhandled promise rejections --- cli.js | 12 ++++++++-- lib/babel.js | 40 ++++++++++++++++++++++++++++++++-- lib/fork.js | 10 ++++++++- lib/logger.js | 20 ++++++++++++++++- package.json | 2 ++ test/fixture/loud-rejection.js | 9 ++++++++ test/test.js | 9 ++++++++ 7 files changed, 96 insertions(+), 6 deletions(-) create mode 100644 test/fixture/loud-rejection.js diff --git a/cli.js b/cli.js index 2029410ce..09839142d 100755 --- a/cli.js +++ b/cli.js @@ -45,6 +45,7 @@ var cli = meow({ var testCount = 0; var fileCount = 0; +var unhandledRejectionCount = 0; var errors = []; function error(err) { @@ -116,11 +117,18 @@ function run(file) { return fork(args) .on('stats', stats) .on('test', test) + .on('unhandledRejections', rejections) .on('data', function (data) { process.stdout.write(data); }); } +function rejections(data) { + var unhandled = data.unhandledRejections; + log.unhandledRejections(data.file, unhandled); + unhandledRejectionCount += unhandled.length; +} + function sum(arr, key) { var result = 0; @@ -145,7 +153,7 @@ function exit(results) { var failed = sum(stats, 'failCount'); log.write(); - log.report(passed, failed); + log.report(passed, failed, unhandledRejectionCount); log.write(); if (failed > 0) { @@ -158,7 +166,7 @@ function exit(results) { // timeout required to correctly flush stderr on Node 0.10 Windows setTimeout(function () { - process.exit(failed > 0 ? 1 : 0); + process.exit(failed > 0 || unhandledRejectionCount > 0 ? 1 : 0); }, 0); } diff --git a/lib/babel.js b/lib/babel.js index 78957dae3..2f61507eb 100644 --- a/lib/babel.js +++ b/lib/babel.js @@ -1,7 +1,9 @@ 'use strict'; +var loudRejection = require('loud-rejection/api')(process); var resolveFrom = require('resolve-from'); var createEspowerPlugin = require('babel-plugin-espower/create'); var requireFromString = require('require-from-string'); +var destroyCircular = require('destroy-circular'); var hasGenerators = parseInt(process.version.slice(1), 10) > 0; var testPath = process.argv[2]; @@ -45,7 +47,41 @@ if (!avaRequired) { } process.on('message', function (message) { - if (message['ava-kill-command']) { - process.exit(0); + var command = message['ava-child-process-command']; + if (command) { + process.emit('ava-' + command, message.data); } }); + +process.on('ava-kill', function () { + process.exit(0); +}); + +process.on('ava-cleanup', function () { + var unhandled = loudRejection.currentlyUnhandled(); + if (unhandled.length) { + unhandled = unhandled.map(function (entry) { + var err = entry.reason; + if (typeof err === 'object') { + return destroyCircular(err); + } + if (typeof err === 'function') { + return '[Function ' + err.name + ']'; + } + return err; + }); + process.send({ + name: 'unhandledRejections', + data: { + unhandledRejections: unhandled + } + }); + } + + setTimeout(function () { + process.send({ + name: 'cleaned-up', + data: {} + }); + }, 100); +}); diff --git a/lib/fork.js b/lib/fork.js index 8700b86a3..44e6da096 100644 --- a/lib/fork.js +++ b/lib/fork.js @@ -18,6 +18,10 @@ module.exports = function (args) { var ps = childProcess.fork(babel, args, options); + function send(command, data) { + ps.send({'ava-child-process-command': command, 'data': data}); + } + var promise = new Promise(function (resolve, reject) { var testResults; @@ -26,7 +30,11 @@ module.exports = function (args) { // after all tests are finished and results received // kill the forked process, so AVA can exit safely - ps.send({'ava-kill-command': true}); + send('cleanup', true); + }); + + ps.on('cleaned-up', function () { + send('kill', true); }); ps.on('error', reject); diff --git a/lib/logger.js b/lib/logger.js index 7691023eb..a334ab0ba 100644 --- a/lib/logger.js +++ b/lib/logger.js @@ -70,10 +70,28 @@ x.errors = function (results) { }); }; -x.report = function (passed, failed) { +x.report = function (passed, failed, unhandled) { if (failed > 0) { log.writelpad(chalk.red(failed, plur('test', failed), 'failed')); } else { log.writelpad(chalk.green(passed, plur('test', passed), 'passed')); } + if (unhandled > 0) { + log.writelpad(chalk.red(unhandled, 'unhandled', plur('rejection', unhandled))); + } +}; + +x.unhandledRejections = function (file, rejections) { + if (!(rejections && rejections.length)) { + return; + } + rejections.forEach(function (rejection) { + log.write(chalk.red('Unhandled Rejection: ', file)); + if (rejection.stack) { + log.writelpad(chalk.red(beautifyStack(rejection.stack))); + } else { + log.writelpad(chalk.red(JSON.stringify(rejection))); + } + log.write(); + }); }; diff --git a/package.json b/package.json index aae3f9f8e..1582f7946 100644 --- a/package.json +++ b/package.json @@ -33,6 +33,7 @@ }, "scripts": { "test": "xo && nyc tape test/*.js | tap-spec", + "debug": "tape test/*.js | tap-spec", "test-win": "tape test/*.js | tap-spec", "coveralls": "nyc report --reporter=text-lcov | coveralls" }, @@ -77,6 +78,7 @@ "globby": "^3.0.1", "has-flag": "^1.0.0", "is-generator": "^1.0.2", + "loud-rejection": "^1.2.0", "meow": "^3.3.0", "plur": "^2.0.0", "power-assert-formatter": "^1.3.0", diff --git a/test/fixture/loud-rejection.js b/test/fixture/loud-rejection.js new file mode 100644 index 000000000..f5dee4b46 --- /dev/null +++ b/test/fixture/loud-rejection.js @@ -0,0 +1,9 @@ +const test = require('../../'); + +test('creates an unhandled rejection', t => { + Promise.reject(new Error(`You can't handle this!`)); + + setTimeout(function () { + t.end(); + }, 0); +}); diff --git a/test/test.js b/test/test.js index 0491540f5..10e25ffde 100644 --- a/test/test.js +++ b/test/test.js @@ -1066,6 +1066,15 @@ test('Babel require hook only applies to the test file', function (t) { }); }); +test('Unhandled promises will be reported to console', function (t) { + execCli('fixture/loud-rejection.js', function (err, stdout, stderr) { + t.ok(err); + t.ok(/You can't handle this/.test(stderr)); + t.ok(/1 unhandled rejection[^s]/.test(stderr)); + t.end(); + }); +}); + test('absolute paths in CLI', function (t) { t.plan(2); From 0b9978c9bbc1c3220b59d0ba19d09b027b3e8346 Mon Sep 17 00:00:00 2001 From: James Talmage Date: Sat, 14 Nov 2015 20:53:31 -0500 Subject: [PATCH 3/6] report uncaught exceptions --- cli.js | 11 +++++++++-- index.js | 2 +- lib/babel.js | 31 ++++++++++++------------------ lib/fork.js | 4 ++++ lib/logger.js | 15 ++++++++++++++- lib/serialize-value.js | 15 +++++++++++++++ test/fixture/uncaught-exception.js | 7 +++++++ test/fork.js | 10 +++++----- test/test.js | 13 +++++++++++-- 9 files changed, 78 insertions(+), 30 deletions(-) create mode 100644 lib/serialize-value.js create mode 100644 test/fixture/uncaught-exception.js diff --git a/cli.js b/cli.js index 09839142d..e82d05cda 100755 --- a/cli.js +++ b/cli.js @@ -46,6 +46,7 @@ var cli = meow({ var testCount = 0; var fileCount = 0; var unhandledRejectionCount = 0; +var uncaughtExceptionCount = 0; var errors = []; function error(err) { @@ -118,6 +119,7 @@ function run(file) { .on('stats', stats) .on('test', test) .on('unhandledRejections', rejections) + .on('uncaughtException', uncaughtException) .on('data', function (data) { process.stdout.write(data); }); @@ -129,6 +131,11 @@ function rejections(data) { unhandledRejectionCount += unhandled.length; } +function uncaughtException(data) { + uncaughtExceptionCount++; + log.uncaughtException(data.file, data.uncaughtException); +} + function sum(arr, key) { var result = 0; @@ -153,7 +160,7 @@ function exit(results) { var failed = sum(stats, 'failCount'); log.write(); - log.report(passed, failed, unhandledRejectionCount); + log.report(passed, failed, unhandledRejectionCount, uncaughtExceptionCount); log.write(); if (failed > 0) { @@ -166,7 +173,7 @@ function exit(results) { // timeout required to correctly flush stderr on Node 0.10 Windows setTimeout(function () { - process.exit(failed > 0 || unhandledRejectionCount > 0 ? 1 : 0); + process.exit(failed > 0 || unhandledRejectionCount > 0 || uncaughtExceptionCount > 0 ? 1 : 0); }, 0); } diff --git a/index.js b/index.js index 29469f6fd..204063db1 100644 --- a/index.js +++ b/index.js @@ -4,7 +4,7 @@ var setImmediate = require('set-immediate-shim'); var hasFlag = require('has-flag'); var chalk = require('chalk'); var relative = require('path').relative; -var serializeError = require('destroy-circular'); +var serializeError = require('./lib/serialize-value'); var Runner = require('./lib/runner'); var log = require('./lib/logger'); var runner = new Runner(); diff --git a/lib/babel.js b/lib/babel.js index 2f61507eb..86857735d 100644 --- a/lib/babel.js +++ b/lib/babel.js @@ -3,7 +3,7 @@ var loudRejection = require('loud-rejection/api')(process); var resolveFrom = require('resolve-from'); var createEspowerPlugin = require('babel-plugin-espower/create'); var requireFromString = require('require-from-string'); -var destroyCircular = require('destroy-circular'); +var serializeValue = require('./serialize-value'); var hasGenerators = parseInt(process.version.slice(1), 10) > 0; var testPath = process.argv[2]; @@ -34,6 +34,14 @@ module.exports = { } }; +function send(name, data) { + process.send({name: name, data: data}); +} + +process.on('uncaughtException', function (exception) { + send('uncaughtException', {uncaughtException: serializeValue(exception)}); +}); + var transpiled = babel.transformFileSync(testPath, options); requireFromString(transpiled.code, testPath, { appendPaths: module.paths @@ -61,27 +69,12 @@ process.on('ava-cleanup', function () { var unhandled = loudRejection.currentlyUnhandled(); if (unhandled.length) { unhandled = unhandled.map(function (entry) { - var err = entry.reason; - if (typeof err === 'object') { - return destroyCircular(err); - } - if (typeof err === 'function') { - return '[Function ' + err.name + ']'; - } - return err; - }); - process.send({ - name: 'unhandledRejections', - data: { - unhandledRejections: unhandled - } + return serializeValue(entry.reason); }); + send('unhandledRejections', {unhandledRejections: unhandled}); } setTimeout(function () { - process.send({ - name: 'cleaned-up', - data: {} - }); + send('cleaned-up', {}); }, 100); }); diff --git a/lib/fork.js b/lib/fork.js index 44e6da096..45530061d 100644 --- a/lib/fork.js +++ b/lib/fork.js @@ -37,6 +37,10 @@ module.exports = function (args) { send('kill', true); }); + ps.on('uncaughtException', function () { + send('cleanup', true); + }); + ps.on('error', reject); ps.on('exit', function (code) { diff --git a/lib/logger.js b/lib/logger.js index a334ab0ba..1275658f2 100644 --- a/lib/logger.js +++ b/lib/logger.js @@ -70,7 +70,7 @@ x.errors = function (results) { }); }; -x.report = function (passed, failed, unhandled) { +x.report = function (passed, failed, unhandled, uncaught) { if (failed > 0) { log.writelpad(chalk.red(failed, plur('test', failed), 'failed')); } else { @@ -79,6 +79,9 @@ x.report = function (passed, failed, unhandled) { if (unhandled > 0) { log.writelpad(chalk.red(unhandled, 'unhandled', plur('rejection', unhandled))); } + if (uncaught > 0) { + log.writelpad(chalk.red(uncaught, 'uncaught', plur('exceptions', uncaught))); + } }; x.unhandledRejections = function (file, rejections) { @@ -95,3 +98,13 @@ x.unhandledRejections = function (file, rejections) { log.write(); }); }; + +x.uncaughtException = function (file, error) { + log.write(chalk.red('Uncaught Exception: ', file)); + if (error.stack) { + log.writelpad(chalk.red(beautifyStack(error.stack))); + } else { + log.writelpad(chalk.red(JSON.stringify(error))); + } + log.write(); +}; diff --git a/lib/serialize-value.js b/lib/serialize-value.js new file mode 100644 index 000000000..8901fa9f4 --- /dev/null +++ b/lib/serialize-value.js @@ -0,0 +1,15 @@ +'use strict'; +var destroyCircular = require('destroy-circular'); + +// Make a value ready for JSON.stringify() / process.send() + +module.exports = function serializeValue(value) { + if (typeof value === 'object') { + return destroyCircular(value); + } + if (typeof value === 'function') { + // JSON.stringify discards functions + return '[Function ' + value.name + ']'; + } + return value; +}; diff --git a/test/fixture/uncaught-exception.js b/test/fixture/uncaught-exception.js new file mode 100644 index 000000000..da5d47db9 --- /dev/null +++ b/test/fixture/uncaught-exception.js @@ -0,0 +1,7 @@ +const test = require('../../'); + +test('throw an uncaught exception', t => { + setImmediate(() => { + throw new Error(`Can't catch me!`) + }); +}); diff --git a/test/fork.js b/test/fork.js index 487747cf3..5d8e45b21 100644 --- a/test/fork.js +++ b/test/fork.js @@ -28,14 +28,14 @@ test('resolves promise with tests info', function (t) { }); test('rejects on error and streams output', function (t) { - var buffer = ''; - + t.plan(2); fork(fixture('broken.js')) - .on('data', function (data) { - buffer += data; + .on('uncaughtException', function (data) { + var exception = data.uncaughtException; + t.ok(/no such file or directory/.test(exception.message)); }) .catch(function () { - t.ok(/no such file or directory/.test(buffer)); + t.pass(); t.end(); }); }); diff --git a/test/test.js b/test/test.js index 10e25ffde..f66af150c 100644 --- a/test/test.js +++ b/test/test.js @@ -1058,8 +1058,7 @@ test('change process.cwd() to a test\'s directory', function (t) { test('Babel require hook only applies to the test file', function (t) { execCli('fixture/babel-hook.js', function (err, stdout, stderr) { - t.ok(/exited with a non-zero exit code/.test(stderr)); - t.ok(/Unexpected token/.test(stdout)); + t.ok(/Unexpected token/.test(stderr)); t.ok(err); t.is(err.code, 1); t.end(); @@ -1075,6 +1074,16 @@ test('Unhandled promises will be reported to console', function (t) { }); }); +test('uncaught exception will be reported to console', function (t) { + execCli('fixture/uncaught-exception.js', function (err, stdout, stderr) { + t.ok(err); + t.ok(/Can't catch me!/.test(stderr)); + // TODO: The promise ends up rejected, so we need to track this differently + // t.ok(/1 uncaught exception[^s]/.test(stdout)); + t.end(); + }); +}); + test('absolute paths in CLI', function (t) { t.plan(2); From 9fc428fe3d9c7fff0b709263e832649a087c89bf Mon Sep 17 00:00:00 2001 From: James Talmage Date: Sat, 14 Nov 2015 21:53:22 -0500 Subject: [PATCH 4/6] make shure IO streams are flushed before exiting a process. wait for forked streams to end before resolving promise (cherry picked from commit 4539ccc) wait for io streams to end even when fork promise is rejected (cherry picked from commit 6bff82a) --- cli.js | 15 ++++++++++++--- lib/fork.js | 18 +++++++++++++++--- 2 files changed, 27 insertions(+), 6 deletions(-) diff --git a/cli.js b/cli.js index e82d05cda..97a2f1f65 100755 --- a/cli.js +++ b/cli.js @@ -51,7 +51,7 @@ var errors = []; function error(err) { console.error(err.stack); - process.exit(1); + flushIoAndExit(1); } function prefixTitle(file) { @@ -167,13 +167,22 @@ function exit(results) { log.errors(flatten(tests)); } + process.stdout.write(''); + + flushIoAndExit( + failed > 0 || unhandledRejectionCount > 0 || uncaughtExceptionCount > 0 ? 1 : 0 + ); +} + +function flushIoAndExit(code) { // TODO: figure out why this needs to be here to // correctly flush the output when multiple test files process.stdout.write(''); + process.stderr.write(''); - // timeout required to correctly flush stderr on Node 0.10 Windows + // timeout required to correctly flush io on Node 0.10 Windows setTimeout(function () { - process.exit(failed > 0 || unhandledRejectionCount > 0 || uncaughtExceptionCount > 0 ? 1 : 0); + process.exit(code); }, 0); } diff --git a/lib/fork.js b/lib/fork.js index 45530061d..8a0bf7f02 100644 --- a/lib/fork.js +++ b/lib/fork.js @@ -79,11 +79,23 @@ module.exports = function (args) { ps.emit('data', data); }); - promise.on = function () { - ps.on.apply(ps, arguments); + var stdout = new Promise(function (resolve) { + ps.stdout.on('end', resolve); + }); + + var stderr = new Promise(function (resolve) { + ps.stderr.on('end', resolve); + }); + var endPromise = Promise.all([promise.reflect(), stdout, stderr]).then(function () { return promise; + }); + + endPromise.on = function () { + ps.on.apply(ps, arguments); + + return endPromise; }; - return promise; + return endPromise; }; From cfbba40b3b7780f0e5668a73709b161658be5986 Mon Sep 17 00:00:00 2001 From: James Talmage Date: Sat, 14 Nov 2015 22:16:37 -0500 Subject: [PATCH 5/6] extend exit delay on AppVeyor add small delay on exit from babel (cherry picked from commit 11961f7) if AVA is not required in a test, throw an error instead of process.exit --- cli.js | 2 +- lib/babel.js | 9 ++++----- test/test.js | 4 ++-- 3 files changed, 7 insertions(+), 8 deletions(-) diff --git a/cli.js b/cli.js index 97a2f1f65..538b753d7 100755 --- a/cli.js +++ b/cli.js @@ -183,7 +183,7 @@ function flushIoAndExit(code) { // timeout required to correctly flush io on Node 0.10 Windows setTimeout(function () { process.exit(code); - }, 0); + }, process.env.APPVEYOR ? 500 : 0); } function init(files) { diff --git a/lib/babel.js b/lib/babel.js index 86857735d..9d7d29266 100644 --- a/lib/babel.js +++ b/lib/babel.js @@ -48,10 +48,7 @@ requireFromString(transpiled.code, testPath, { }); if (!avaRequired) { - console.error('No tests found in ' + testPath + ', make sure to import "ava" at the top of your test file'); - setImmediate(function () { - process.exit(1); - }); + throw new Error('No tests found in ' + testPath + ', make sure to import "ava" at the top of your test file'); } process.on('message', function (message) { @@ -62,7 +59,9 @@ process.on('message', function (message) { }); process.on('ava-kill', function () { - process.exit(0); + setTimeout(function () { + process.exit(0); + }, process.env.APPVEYOR ? 100 : 0); }); process.on('ava-cleanup', function () { diff --git a/test/test.js b/test/test.js index f66af150c..18870a979 100644 --- a/test/test.js +++ b/test/test.js @@ -1109,9 +1109,9 @@ test('titles of both passing and failing tests and AssertionErrors are displayed test('empty test files creates a failure with a helpful warning', function (t) { t.plan(2); - execCli('fixture/empty.js', function (err, stdout) { + execCli('fixture/empty.js', function (err, stdout, stderr) { t.ok(err); - t.ok(/No tests found.*?import "ava"/.test(stdout)); + t.ok(/No tests found.*?import "ava"/.test(stderr)); t.end(); }); }); From 5c4e7626920f2a2cc283fb747fa58844b0f509ff Mon Sep 17 00:00:00 2001 From: James Talmage Date: Sun, 15 Nov 2015 18:15:33 -0500 Subject: [PATCH 6/6] mega less IO promises --- lib/fork.js | 18 +++--------------- 1 file changed, 3 insertions(+), 15 deletions(-) diff --git a/lib/fork.js b/lib/fork.js index 8a0bf7f02..45530061d 100644 --- a/lib/fork.js +++ b/lib/fork.js @@ -79,23 +79,11 @@ module.exports = function (args) { ps.emit('data', data); }); - var stdout = new Promise(function (resolve) { - ps.stdout.on('end', resolve); - }); - - var stderr = new Promise(function (resolve) { - ps.stderr.on('end', resolve); - }); - - var endPromise = Promise.all([promise.reflect(), stdout, stderr]).then(function () { - return promise; - }); - - endPromise.on = function () { + promise.on = function () { ps.on.apply(ps, arguments); - return endPromise; + return promise; }; - return endPromise; + return promise; };