From 5b6851f6ddc2b7fe71493143edf619dbf3bfa2af Mon Sep 17 00:00:00 2001 From: Moshe Atlow Date: Thu, 14 Jul 2022 11:11:42 +0300 Subject: [PATCH] feat: support timeout for tests PR-URL: https://github.com/nodejs/node/pull/43505 Refs: https://github.com/nodejs/node/issues/43490 Reviewed-By: Benjamin Gruenbaum Reviewed-By: Colin Ihrig (cherry picked from commit c1d659591d1c5a6002e762549ee46b69d495b70b) --- README.md | 6 ++++ lib/internal/per_context/primordials.js | 1 + lib/internal/test_runner/test.js | 39 +++++++++++++++++---- lib/timers/promises.js | 11 ++++++ package.json | 1 + test/message/test_runner_desctibe_it.js | 22 ++++++++++++ test/message/test_runner_desctibe_it.out | 43 +++++++++++++++++++++--- test/message/test_runner_output.js | 20 +++++++++++ test/message/test_runner_output.out | 36 +++++++++++++++++--- 9 files changed, 163 insertions(+), 16 deletions(-) create mode 100644 lib/timers/promises.js diff --git a/README.md b/README.md index c8105b0..dc21c98 100644 --- a/README.md +++ b/README.md @@ -339,6 +339,9 @@ internally. - `todo` {boolean|string} If truthy, the test marked as `TODO`. If a string is provided, that string is displayed in the test results as the reason why the test is `TODO`. **Default:** `false`. + - `timeout` {number} A number of milliseconds the test will fail after. + If unspecified, subtests inherit this value from their parent. + **Default:** `30_000`. - `fn` {Function|AsyncFunction} The function under test. The first argument to this function is a [`TestContext`][] object. If the test uses callbacks, the callback function is passed as the second argument. **Default:** A no-op @@ -483,6 +486,9 @@ execution of the test function. This function does not return a value. - `todo` {boolean|string} If truthy, the test marked as `TODO`. If a string is provided, that string is displayed in the test results as the reason why the test is `TODO`. **Default:** `false`. + - `timeout` {number} A number of milliseconds the test will fail after. + If unspecified, subtests inherit this value from their parent. + **Default:** `30_000`. - `fn` {Function|AsyncFunction} The function under test. The first argument to this function is a [`TestContext`][] object. If the test uses callbacks, the callback function is passed as the second argument. **Default:** A no-op diff --git a/lib/internal/per_context/primordials.js b/lib/internal/per_context/primordials.js index d11555a..c328ed8 100644 --- a/lib/internal/per_context/primordials.js +++ b/lib/internal/per_context/primordials.js @@ -30,6 +30,7 @@ exports.ReflectApply = (target, self, args) => Reflect.apply(target, self, args) exports.Promise = Promise exports.PromiseAll = iterator => Promise.all(iterator) exports.PromiseResolve = val => Promise.resolve(val) +exports.PromiseRace = val => Promise.race(val) exports.SafeArrayIterator = class ArrayIterator {constructor (array) { this.array = array }[Symbol.iterator] () { return this.array.values() }} exports.SafeMap = Map exports.SafeSet = Set diff --git a/lib/internal/test_runner/test.js b/lib/internal/test_runner/test.js index 3af0f70..29c550c 100644 --- a/lib/internal/test_runner/test.js +++ b/lib/internal/test_runner/test.js @@ -11,7 +11,8 @@ const { Number, PromiseResolve, ReflectApply, - SafeMap + SafeMap, + PromiseRace } = require('#internal/per_context/primordials') const { AsyncResource } = require('async_hooks') const { @@ -29,6 +30,7 @@ const { } = require('#internal/util') const { isPromise } = require('#internal/util/types') const { isUint32 } = require('#internal/validators') +const { setTimeout } = require('#timers/promises') const { cpus } = require('os') const { bigint: hrtime } = process.hrtime const kCallbackAndPromisePresent = 'callbackAndPromisePresent' @@ -36,13 +38,30 @@ const kCancelledByParent = 'cancelledByParent' const kParentAlreadyFinished = 'parentAlreadyFinished' const kSubtestsFailed = 'subtestsFailed' const kTestCodeFailure = 'testCodeFailure' +const kTestTimeoutFailure = 'testTimeoutFailure' const kDefaultIndent = ' ' +const kDefaultTimeout = null const noop = FunctionPrototype const isTestRunner = getOptionValue('--test') const testOnlyFlag = !isTestRunner && getOptionValue('--test-only') // TODO(cjihrig): Use uv_available_parallelism() once it lands. const rootConcurrency = isTestRunner ? cpus().length : 1 +function testTimeout (promise, timeout) { + if (timeout === kDefaultTimeout) { + return promise + } + return PromiseRace([ + promise, + setTimeout(timeout, null, { ref: false }).then(() => { + throw new ERR_TEST_FAILURE( + `test timed out after ${timeout}ms`, + kTestTimeoutFailure + ) + }) + ]) +} + class TestContext { #test @@ -79,7 +98,7 @@ class Test extends AsyncResource { super('Test') let { fn, name, parent, skip } = options - const { concurrency, only, todo } = options + const { concurrency, only, timeout, todo } = options if (typeof fn !== 'function') { fn = noop @@ -101,6 +120,7 @@ class Test extends AsyncResource { this.reporter = new TapStream() this.runOnlySubtests = this.only this.testNumber = 0 + this.timeout = kDefaultTimeout } else { const indent = parent.parent === null ? parent.indent @@ -113,12 +133,17 @@ class Test extends AsyncResource { this.reporter = parent.reporter this.runOnlySubtests = !this.only this.testNumber = parent.subtests.length + 1 + this.timeout = parent.timeout } if (isUint32(concurrency) && concurrency !== 0) { this.concurrency = concurrency } + if (isUint32(timeout)) { + this.timeout = timeout + } + if (testOnlyFlag && !this.only) { skip = '\'only\' option not set' } @@ -334,13 +359,13 @@ class Test extends AsyncResource { 'passed a callback but also returned a Promise', kCallbackAndPromisePresent )) - await ret + await testTimeout(ret, this.timeout) } else { - await promise + await testTimeout(promise, this.timeout) } } else { // This test is synchronous or using Promises. - await ReflectApply(this.runInAsyncScope, this, args) + await testTimeout(ReflectApply(this.runInAsyncScope, this, args), this.timeout) } this.pass() @@ -485,10 +510,10 @@ class Suite extends Test { this.parent.activeSubtests++ this.startTime = hrtime() const subtests = this.skipped || this.error ? [] : this.subtests - await ArrayPrototypeReduce(subtests, async (prev, subtest) => { + await testTimeout(ArrayPrototypeReduce(subtests, async (prev, subtest) => { await prev await subtest.run() - }, PromiseResolve()) + }, PromiseResolve()), this.timeout) this.pass() this.postRun() } diff --git a/lib/timers/promises.js b/lib/timers/promises.js new file mode 100644 index 0000000..16a5396 --- /dev/null +++ b/lib/timers/promises.js @@ -0,0 +1,11 @@ +'use strict' +try { + module.exports = require('node:timers/promises') +} catch { + const { promisify } = require('node:util') + module.exports = { + setImmediate: promisify(setImmediate), + setInterval: promisify(setInterval), + setTimeout: promisify(setTimeout) + } +} diff --git a/package.json b/package.json index 1ecdf3e..78f4037 100644 --- a/package.json +++ b/package.json @@ -13,6 +13,7 @@ }, "imports": { "#internal/*": "./lib/internal/*.js", + "#timers/*": "./lib/timers/*.js", "#node:test": "./lib/test.js" }, "scripts": { diff --git a/test/message/test_runner_desctibe_it.js b/test/message/test_runner_desctibe_it.js index f4673c6..4e55647 100644 --- a/test/message/test_runner_desctibe_it.js +++ b/test/message/test_runner_desctibe_it.js @@ -316,3 +316,25 @@ describe('describe async throw fails', async () => { it('should not run', () => {}) throw new Error('thrown from describe') }) + +describe('timeouts', () => { + it('timed out async test', { timeout: 5 }, async () => { + return new Promise((resolve) => { + setTimeout(resolve, 1000) + }) + }) + + it('timed out callback test', { timeout: 5 }, (done) => { + setTimeout(done, 1000) + }) + + it('large timeout async test is ok', { timeout: 30_000_000 }, async () => { + return new Promise((resolve) => { + setTimeout(resolve, 10) + }) + }) + + it('large timeout callback test is ok', { timeout: 30_000_000 }, (done) => { + setTimeout(done, 10) + }) +}) diff --git a/test/message/test_runner_desctibe_it.out b/test/message/test_runner_desctibe_it.out index 99da34e..3b3a68f 100644 --- a/test/message/test_runner_desctibe_it.out +++ b/test/message/test_runner_desctibe_it.out @@ -557,8 +557,43 @@ not ok 56 - describe async throw fails * * ... +# Subtest: timeouts + # Subtest: timed out async test + not ok 1 - timed out async test + --- + duration_ms: * + failureType: 'testTimeoutFailure' + error: 'test timed out after 5ms' + code: 'ERR_TEST_FAILURE' + ... + # Subtest: timed out callback test + not ok 2 - timed out callback test + --- + duration_ms: * + failureType: 'testTimeoutFailure' + error: 'test timed out after 5ms' + code: 'ERR_TEST_FAILURE' + ... + # Subtest: large timeout async test is ok + ok 3 - large timeout async test is ok + --- + duration_ms: * + ... + # Subtest: large timeout callback test is ok + ok 4 - large timeout callback test is ok + --- + duration_ms: * + ... + 1..4 +not ok 57 - timeouts + --- + duration_ms: * + failureType: 'subtestsFailed' + error: '2 subtests failed' + code: 'ERR_TEST_FAILURE' + ... # Subtest: invalid subtest fail -not ok 57 - invalid subtest fail +not ok 58 - invalid subtest fail --- duration_ms: * failureType: 'parentAlreadyFinished' @@ -567,16 +602,16 @@ not ok 57 - invalid subtest fail stack: |- * ... -1..57 +1..58 # Warning: Test "unhandled rejection - passes but warns" generated asynchronous activity after the test ended. This activity created the error "Error: rejected from unhandled rejection fail" and would have caused the test to fail, but instead triggered an unhandledRejection event. # Warning: Test "async unhandled rejection - passes but warns" generated asynchronous activity after the test ended. This activity created the error "Error: rejected from async unhandled rejection fail" and would have caused the test to fail, but instead triggered an unhandledRejection event. # Warning: Test "immediate throw - passes but warns" generated asynchronous activity after the test ended. This activity created the error "Error: thrown from immediate throw fail" and would have caused the test to fail, but instead triggered an uncaughtException event. # Warning: Test "immediate reject - passes but warns" generated asynchronous activity after the test ended. This activity created the error "Error: rejected from immediate reject fail" and would have caused the test to fail, but instead triggered an unhandledRejection event. # Warning: Test "callback called twice in different ticks" generated asynchronous activity after the test ended. This activity created the error "Error [ERR_TEST_FAILURE]: callback invoked multiple times" and would have caused the test to fail, but instead triggered an uncaughtException event. # Warning: Test "callback async throw after done" generated asynchronous activity after the test ended. This activity created the error "Error: thrown from callback async throw after done" and would have caused the test to fail, but instead triggered an uncaughtException event. -# tests 57 +# tests 58 # pass 23 -# fail 20 +# fail 21 # cancelled 0 # skipped 9 # todo 5 diff --git a/test/message/test_runner_output.js b/test/message/test_runner_output.js index d064a1a..583a650 100644 --- a/test/message/test_runner_output.js +++ b/test/message/test_runner_output.js @@ -329,3 +329,23 @@ test('subtest sync throw fails', async (t) => { throw new Error('thrown from subtest sync throw fails at second') }) }) + +test('timed out async test', { timeout: 5 }, async (t) => { + return new Promise((resolve) => { + setTimeout(resolve, 1000) + }) +}) + +test('timed out callback test', { timeout: 5 }, (t, done) => { + setTimeout(done, 1000) +}) + +test('large timeout async test is ok', { timeout: 30_000_000 }, async (t) => { + return new Promise((resolve) => { + setTimeout(resolve, 10) + }) +}) + +test('large timeout callback test is ok', { timeout: 30_000_000 }, (t, done) => { + setTimeout(done, 10) +}) diff --git a/test/message/test_runner_output.out b/test/message/test_runner_output.out index bada2fd..22d9794 100644 --- a/test/message/test_runner_output.out +++ b/test/message/test_runner_output.out @@ -562,8 +562,34 @@ not ok 56 - subtest sync throw fails error: '2 subtests failed' code: 'ERR_TEST_FAILURE' ... +# Subtest: timed out async test +not ok 57 - timed out async test + --- + duration_ms: * + failureType: 'testTimeoutFailure' + error: 'test timed out after 5ms' + code: 'ERR_TEST_FAILURE' + ... +# Subtest: timed out callback test +not ok 58 - timed out callback test + --- + duration_ms: * + failureType: 'testTimeoutFailure' + error: 'test timed out after 5ms' + code: 'ERR_TEST_FAILURE' + ... +# Subtest: large timeout async test is ok +ok 59 - large timeout async test is ok + --- + duration_ms: * + ... +# Subtest: large timeout callback test is ok +ok 60 - large timeout callback test is ok + --- + duration_ms: * + ... # Subtest: invalid subtest fail -not ok 57 - invalid subtest fail +not ok 61 - invalid subtest fail --- duration_ms: * failureType: 'parentAlreadyFinished' @@ -572,16 +598,16 @@ not ok 57 - invalid subtest fail stack: |- * ... -1..57 +1..61 # Warning: Test "unhandled rejection - passes but warns" generated asynchronous activity after the test ended. This activity created the error "Error: rejected from unhandled rejection fail" and would have caused the test to fail, but instead triggered an unhandledRejection event. # Warning: Test "async unhandled rejection - passes but warns" generated asynchronous activity after the test ended. This activity created the error "Error: rejected from async unhandled rejection fail" and would have caused the test to fail, but instead triggered an unhandledRejection event. # Warning: Test "immediate throw - passes but warns" generated asynchronous activity after the test ended. This activity created the error "Error: thrown from immediate throw fail" and would have caused the test to fail, but instead triggered an uncaughtException event. # Warning: Test "immediate reject - passes but warns" generated asynchronous activity after the test ended. This activity created the error "Error: rejected from immediate reject fail" and would have caused the test to fail, but instead triggered an unhandledRejection event. # Warning: Test "callback called twice in different ticks" generated asynchronous activity after the test ended. This activity created the error "Error [ERR_TEST_FAILURE]: callback invoked multiple times" and would have caused the test to fail, but instead triggered an uncaughtException event. # Warning: Test "callback async throw after done" generated asynchronous activity after the test ended. This activity created the error "Error: thrown from callback async throw after done" and would have caused the test to fail, but instead triggered an uncaughtException event. -# tests 57 -# pass 24 -# fail 18 +# tests 61 +# pass 26 +# fail 20 # cancelled 0 # skipped 10 # todo 5