test_runner: support timeout for tests

PR-URL: #43505 Refs: #43490 Reviewed-By: Benjamin Gruenbaum <benjamingr@gmail.com> Reviewed-By: Colin Ihrig <cjihrig@gmail.com>
nodejs · Jul 26, 2022 · e404a3ef6d1aa575fa1cbf52f4bd1d3b21c4f2de · e404a3e
1 parent c2db4f4
commit e404a3ef6d1aa575fa1cbf52f4bd1d3b21c4f2de
Show file tree

Hide file tree

Showing 6 changed files with 160 additions and 15 deletions.
diff --git a/doc/api/test.md b/doc/api/test.md
@@ -320,6 +320,10 @@ internally.
 
 <!-- YAML
 added: v18.0.0
+changes:
+  - version: REPLACEME
+    pr-url: https://github.com/nodejs/node/pull/43505
+    description: add a timeout to tests and allow setting it in options.
 -->
 
 * `name` {string} The name of the test, which is displayed when reporting test
@@ -339,6 +343,9 @@ added: v18.0.0
   * `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
@@ -519,6 +526,10 @@ test('top level test', (t) => {
 
 <!-- YAML
 added: v18.0.0
+changes:
+  - version: REPLACEME
+    pr-url: https://github.com/nodejs/node/pull/43505
+    description: add a timeout to tests and allow setting it in options.
 -->
 
 * `name` {string} The name of the subtest, which is displayed when reporting
@@ -538,6 +549,9 @@ added: v18.0.0
   * `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/test_runner/test.js b/lib/internal/test_runner/test.js
@@ -9,6 +9,7 @@ const {
   PromiseResolve,
   ReflectApply,
   SafeMap,
+  PromiseRace,
 } = primordials;
 const { AsyncResource } = require('async_hooks');
 const {
@@ -26,20 +27,39 @@ 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;
 
@@ -76,7 +96,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;
@@ -98,6 +118,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 :
         parent.indent + parent.indentString;
@@ -109,12 +130,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';
     }
@@ -329,13 +355,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();
@@ -480,10 +506,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/test/message/test_runner_describe_it.js b/test/message/test_runner_describe_it.js
@@ -316,3 +316,26 @@ 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_describe_it.out b/test/message/test_runner_describe_it.out
@@ -551,8 +551,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'
@@ -561,16 +596,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
@@ -328,3 +328,24 @@ 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
@@ -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