Fix synchronous timeouts (#7074)

## Summary

Building on #6950, this adds an e2e test and the requested circus fix.

fixes #6947
closes #695

To Do:
- [x] make sure new tests pass
- [x] clean up circus fix with proper error information
- [x] update CHANGELOG.md

## Test plan

The e2e test is failing and I'm having trouble figuring out why, so I'd like to see if it fails on CI too.

CHANGELOG.md

@@ -25,6 +25,8 @@
 - `[jest-jasmine2`] Fix crash when test return Promise rejected with null ([#7049](https://github.com/facebook/jest/pull/7049))
 - `[jest-runtime]` Check `_isMockFunction` is true rather than truthy on potential global mocks ([#7017](https://github.com/facebook/jest/pull/7017))
 - `[jest-jasmine]` Show proper error message from async `assert` errors ([#6821](https://github.com/facebook/jest/pull/6821))
+- `[jest-circus]` Fail synchronous hook timeouts ([#7074](https://github.com/facebook/jest/pull/7074))
+- `[jest-jasmine2]` Fail synchronous test timeouts ([#7074](https://github.com/facebook/jest/pull/7074))
 
 ### Chore & Maintenance
 

e2e/__tests__/__snapshots__/timeouts.test.js.snap

@@ -1,5 +1,38 @@
 // Jest Snapshot v1, https://goo.gl/fbAQLP
 
+exports[`before hook does not exceed the timeout 1`] = `
+"PASS __tests__/a-banana.js
+ ✓ banana
+
+"
+`;
+
+exports[`before hook does not exceed the timeout 2`] = `
+"Test Suites: 1 passed, 1 total
+Tests: 1 passed, 1 total
+Snapshots: 0 total
+Time: <<REPLACED>>
+Ran all test suites."
+`;
+
+exports[`before hook exceeds the timeout 1`] = `
+"Test Suites: 1 failed, 1 total
+Tests: 1 failed, 1 total
+Snapshots: 0 total
+Time: <<REPLACED>>
+Ran all test suites.
+"
+`;
+
+exports[`before hook exceeds the timeout synchronously 1`] = `
+"Test Suites: 1 failed, 1 total
+Tests: 1 failed, 1 total
+Snapshots: 0 total
+Time: <<REPLACED>>
+Ran all test suites.
+"
+`;
+
 exports[`does not exceed the timeout 1`] = `
 "PASS __tests__/a-banana.js
  ✓ banana
@@ -23,3 +56,12 @@ Time: <<REPLACED>>
 Ran all test suites.
 "
 `;
+
+exports[`exceeds the timeout synchronously 1`] = `
+"Test Suites: 1 failed, 1 total
+Tests: 1 failed, 1 total
+Snapshots: 0 total
+Time: <<REPLACED>>
+Ran all test suites.
+"
+`;

e2e/__tests__/timeouts.test.js

@@ -40,6 +40,29 @@ test('exceeds the timeout', () => {
  expect(status).toBe(1);
 });
 
+test('exceeds the timeout synchronously', () => {
+ writeFiles(DIR, {
+ '__tests__/a-banana.js': `
+ jest.setTimeout(20);
+
+ test('banana', () => {
+ const startTime = Date.now();
+ while (Date.now() - startTime < 100) {
+ }
+ });
+ `,
+ 'package.json': '{}',
+ });
+
+ const {stderr, status} = runJest(DIR, ['-w=1', '--ci=false']);
+ const {rest, summary} = extractSummary(stderr);
+ expect(rest).toMatch(
+ /(jest\.setTimeout|jasmine\.DEFAULT_TIMEOUT_INTERVAL|Exceeded timeout)/,
+ );
+ expect(summary).toMatchSnapshot();
+ expect(status).toBe(1);
+});
+
 test('does not exceed the timeout', () => {
  writeFiles(DIR, {
  '__tests__/a-banana.js': `
@@ -60,3 +83,75 @@ test('does not exceed the timeout', () => {
  expect(summary).toMatchSnapshot();
  expect(status).toBe(0);
 });
+
+test('before hook exceeds the timeout', () => {
+ writeFiles(DIR, {
+ '__tests__/a-banana.js': `
+ jest.setTimeout(20);
+
+ beforeEach(() => {
+ return new Promise(resolve => {
+ setTimeout(resolve, 100);
+ });
+ })
+
+ test('banana', () => {});
+ `,
+ 'package.json': '{}',
+ });
+
+ const {stderr, status} = runJest(DIR, ['-w=1', '--ci=false']);
+ const {rest, summary} = extractSummary(stderr);
+ expect(rest).toMatch(
+ /(jest\.setTimeout|jasmine\.DEFAULT_TIMEOUT_INTERVAL|Exceeded timeout)/,
+ );
+ expect(summary).toMatchSnapshot();
+ expect(status).toBe(1);
+});
+
+test('before hook exceeds the timeout synchronously', () => {
+ writeFiles(DIR, {
+ '__tests__/a-banana.js': `
+ jest.setTimeout(20);
+
+ beforeEach(() => {
+ const startTime = Date.now();
+ while (Date.now() - startTime < 100) {}
+ })
+
+ test('banana', () => {});
+ `,
+ 'package.json': '{}',
+ });
+
+ const {stderr, status} = runJest(DIR, ['-w=1', '--ci=false']);
+ const {rest, summary} = extractSummary(stderr);
+ expect(rest).toMatch(
+ /(jest\.setTimeout|jasmine\.DEFAULT_TIMEOUT_INTERVAL|Exceeded timeout)/,
+ );
+ expect(summary).toMatchSnapshot();
+ expect(status).toBe(1);
+});
+
+test('before hook does not exceed the timeout', () => {
+ writeFiles(DIR, {
+ '__tests__/a-banana.js': `
+ jest.setTimeout(100);
+
+ beforeEach(() => {
+ return new Promise(resolve => {
+ setTimeout(resolve, 20);
+ });
+ })
+
+ test('banana', () => {});
+ `,
+ 'package.json': '{}',
+ });
+
+ const {stderr, status} = runJest(DIR, ['-w=1', '--ci=false']);
+ const {rest, summary} = extractSummary(stderr);
+ expect(rest).toMatchSnapshot();
+ expect(summary).toMatchSnapshot();
+ expect(status).toBe(0);
+});

packages/jest-circus/src/event_handler.js

@@ -16,6 +16,7 @@ import {
  invariant,
  makeTest,
  describeBlockHasTests,
+ getTimestamp,
 } from './utils';
 import {
  injectGlobalErrorHandlers,
@@ -117,7 +118,7 @@ const handler: EventHandler = (event, state): void => {
  }
  case 'test_start': {
  state.currentlyRunningTest = event.test;
- event.test.startedAt = Date.now();
+ event.test.startedAt = getTimestamp();
  event.test.invocations += 1;
  break;
  }

packages/jest-circus/src/utils.js

@@ -155,7 +155,7 @@ export const getEachHooksForTest = (
 export const describeBlockHasTests = (describe: DescribeBlock) =>
  describe.tests.length || describe.children.some(describeBlockHasTests);
 
-const _makeTimeoutMessage = (timeout, isHook) =>
+const _makeTimeoutMessage = (timeout: number, isHook: ?boolean) =>
  `Exceeded timeout of ${timeout}ms for a ${
  isHook ? 'hook' : 'test'
  }.\nUse jest.setTimeout(newTimeout) to increase the timeout value, if this is a long-running test.`;
@@ -167,9 +167,10 @@ const {setTimeout, clearTimeout} = global;
 export const callAsyncCircusFn = (
  fn: AsyncFn,
  testContext: ?TestContext,
- {isHook, timeout}: {isHook?: ?boolean, timeout: number},
+ {isHook, timeout}: {isHook: ?boolean, timeout: number},
 ): Promise<mixed> => {
  let timeoutID;
+ const startedAt = getTimestamp();
 
  return new Promise((resolve, reject) => {
  timeoutID = setTimeout(
@@ -236,6 +237,9 @@ export const callAsyncCircusFn = (
  // it's resolved.
  timeoutID.unref && timeoutID.unref();
  clearTimeout(timeoutID);
+ if (getTimestamp() - startedAt > timeout) {
+ throw new Error(_makeTimeoutMessage(timeout, isHook));
+ }
  })
  .catch(error => {
  timeoutID.unref && timeoutID.unref();
@@ -244,9 +248,11 @@ export const callAsyncCircusFn = (
  });
 };
 
+export const getTimestamp = Date.now.bind(Date);
+
 export const getTestDuration = (test: TestEntry): ?number => {
  const {startedAt} = test;
- return startedAt ? Date.now() - startedAt : null;
+ return startedAt ? getTimestamp() - startedAt : null;
 };
 
 export const makeRunResult = (

packages/jest-jasmine2/src/__tests__/p_timeout.test.js

@@ -16,7 +16,14 @@ describe('pTimeout', () => {
  it('calls `clearTimeout` and resolves when `promise` resolves.', async () => {
  const onTimeout = jest.fn();
  const promise = Promise.resolve();
- await pTimeout(promise, 1000, clearTimeout, setTimeout, onTimeout);
+ await pTimeout(
+ promise,
+ Date.now(),
+ 1000,
+ clearTimeout,
+ setTimeout,
+ onTimeout,
+ );
  expect(setTimeout).toHaveBeenCalled();
  expect(clearTimeout).toHaveBeenCalled();
  expect(onTimeout).not.toHaveBeenCalled();
@@ -26,7 +33,14 @@ describe('pTimeout', () => {
  const onTimeout = jest.fn();
  const promise = Promise.reject();
  try {
- await pTimeout(promise, 1000, clearTimeout, setTimeout, onTimeout);
+ await pTimeout(
+ promise,
+ Date.now(),
+ 1000,
+ clearTimeout,
+ setTimeout,
+ onTimeout,
+ );
  } catch (e) {}
  expect(setTimeout).toHaveBeenCalled();
  expect(clearTimeout).toHaveBeenCalled();
@@ -39,6 +53,7 @@ describe('pTimeout', () => {
  const promise = new Promise(() => {});
  const timeoutPromise = pTimeout(
  promise,
+ Date.now(),
  1000,
  clearTimeout,
  setTimeout,

packages/jest-jasmine2/src/p_timeout.js

@@ -10,11 +10,13 @@
 // Try getting the real promise object from the context, if available. Someone
 // could have overridden it in a test.
 const Promise = global[Symbol.for('jest-native-promise')] || global.Promise;
+const timestamp = Date.now.bind(Date);
 
 // A specialized version of `p-timeout` that does not touch globals.
 // It does not throw on timeout.
 export default function pTimeout(
  promise: Promise<any>,
+ startTime: number,
  ms: number,
  clearTimeout: (timeoutID: number) => void,
  setTimeout: (func: () => void, delay: number) => number,
@@ -25,7 +27,13 @@ export default function pTimeout(
  promise.then(
  val => {
  clearTimeout(timer);
- resolve(val);
+
+ // when running single threaded, we need to double check the timeout
+ if (timestamp() - startTime > ms) {
+ resolve(onTimeout());
+ } else {
+ resolve(val);
+ }
  },
  err => {
  clearTimeout(timer);

packages/jest-jasmine2/src/queue_runner.js

@@ -11,6 +11,7 @@
 // could have overridden it in a test.
 const Promise: Class<Promise> =
  global[Symbol.for('jest-native-promise')] || global.Promise;
+const timestamp = Date.now.bind(Date);
 
 import PCancelable from './p_cancelable';
 import pTimeout from './p_timeout';
@@ -35,6 +36,8 @@ export default function queueRunner(options: Options) {
  });
 
  const mapper = ({fn, timeout, initError = new Error()}) => {
+ // Flow wants us to initialize this even though it's safe
+ let startTime: number = timestamp();
  let promise = new Promise(resolve => {
  const next = function(err) {
  if (err) {
@@ -48,6 +51,7 @@ export default function queueRunner(options: Options) {
  resolve();
  };
  try {
+ startTime = timestamp();
  fn.call(options.userContext, next);
  } catch (e) {
  options.onException(e);
@@ -65,6 +69,7 @@ export default function queueRunner(options: Options) {
 
  return pTimeout(
  promise,
+ startTime,
  timeoutMs,
  options.clearTimeout,
  options.setTimeout,