feat: support timeout for tests

PR-URL: nodejs/node#43505
Refs: nodejs/node#43490
Reviewed-By: Benjamin Gruenbaum <[email protected]>
Reviewed-By: Colin Ihrig <[email protected]>
(cherry picked from commit c1d659591d1c5a6002e762549ee46b69d495b70b)

Author: MoLow

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

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

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,20 +30,38 @@ 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'
 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()
   }

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)
+  }
+}

package.json

@@ -13,6 +13,7 @@
   },
   "imports": {
     "#internal/*": "./lib/internal/*.js",
+    "#timers/*": "./lib/timers/*.js",
     "#node:test": "./lib/test.js"
   },
   "scripts": {

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)
+  })
+})

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

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)
+})

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