Skip to content

Commit

Permalink
test_runner: support timeout for tests
Browse files Browse the repository at this point in the history
PR-URL: #43505
Refs: #43490
Reviewed-By: Benjamin Gruenbaum <benjamingr@gmail.com>
Reviewed-By: Colin Ihrig <cjihrig@gmail.com>
  • Loading branch information
MoLow authored and danielleadams committed Jul 26, 2022
1 parent c2db4f4 commit e404a3e
Show file tree
Hide file tree
Showing 6 changed files with 160 additions and 15 deletions.
14 changes: 14 additions & 0 deletions doc/api/test.md
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand All @@ -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
Expand Down Expand Up @@ -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
Expand All @@ -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
Expand Down
38 changes: 32 additions & 6 deletions lib/internal/test_runner/test.js
Original file line number Diff line number Diff line change
Expand Up @@ -9,6 +9,7 @@ const {
PromiseResolve,
ReflectApply,
SafeMap,
PromiseRace,
} = primordials;
const { AsyncResource } = require('async_hooks');
const {
Expand All @@ -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;

Expand Down Expand Up @@ -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;
Expand All @@ -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;
Expand All @@ -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';
}
Expand Down Expand Up @@ -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();
Expand Down Expand Up @@ -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();
}
Expand Down
23 changes: 23 additions & 0 deletions test/message/test_runner_describe_it.js
Original file line number Diff line number Diff line change
Expand Up @@ -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);
});
});
43 changes: 39 additions & 4 deletions test/message/test_runner_describe_it.out
Original file line number Diff line number Diff line change
Expand Up @@ -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'
Expand All @@ -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
Expand Down
21 changes: 21 additions & 0 deletions test/message/test_runner_output.js
Original file line number Diff line number Diff line change
Expand Up @@ -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);
});
36 changes: 31 additions & 5 deletions test/message/test_runner_output.out
Original file line number Diff line number Diff line change
Expand Up @@ -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'
Expand All @@ -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
Expand Down

0 comments on commit e404a3e

Please sign in to comment.