fix: print error and exit with status 1 if logging happens after tear…

…down

CHANGELOG.md

@@ -6,6 +6,7 @@
 
 - `[jest-cli]` Break dependency cycle when using Jest programmatically ([#7707](https://github.com/facebook/jest/pull/7707))
 - `[jest-config]` Extract setupFilesAfterEnv from preset ([#7724](https://github.com/facebook/jest/pull/7724))
+- `[jest-cli]` Fail tests if logging happens after test environment is torn down
 
 ### Chore & Maintenance
 

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

@@ -0,0 +1,20 @@
+// Jest Snapshot v1, https://goo.gl/fbAQLP
+
+exports[`console printing 1`] = `
+PASS __tests__/console.test.js
+
+
+  ●  Cannot log after tests are done. Did you forget to wait for something async in your test?
+    Attempted to log "hello!".
+
+       9 | test('throws error', () => {
+      10 |   setTimeout(() => {
+    > 11 |     console.log('hello!');
+         |             ^
+      12 |   }, 500);
+      13 | });
+      14 | 
+
+      at Function.write (../../packages/jest-util/build/BufferedConsole.js:82:12)
+      at Timeout.log [as _onTimeout] (__tests__/console.test.js:11:13)
+`;

e2e/__tests__/consoleAfterTeardown.test.js

@@ -0,0 +1,20 @@
+/**
+ * Copyright (c) Facebook, Inc. and its affiliates. All Rights Reserved.
+ *
+ * This source code is licensed under the MIT license found in the
+ * LICENSE file in the root directory of this source tree.
+ *
+ * @flow
+ */
+
+import {extractSummary} from '../Utils';
+import runJest from '../runJest';
+import {wrap} from 'jest-snapshot-serializer-raw';
+
+test('console printing', () => {
+  const {stderr, status} = runJest('console-after-teardown');
+  const {rest} = extractSummary(stderr);
+
+  expect(status).toBe(1);
+  expect(wrap(rest)).toMatchSnapshot();
+});

e2e/console-after-teardown/__tests__/console.test.js

@@ -0,0 +1,13 @@
+/**
+ * Copyright (c) Facebook, Inc. and its affiliates. All Rights Reserved.
+ *
+ * This source code is licensed under the MIT license found in the
+ * LICENSE file in the root directory of this source tree.
+ */
+'use strict';
+
+test('throws error', () => {
+  setTimeout(() => {
+    console.log('hello!');
+  }, 500);
+});

e2e/console-after-teardown/package.json

@@ -0,0 +1,6 @@
+{
+  "jest": {
+    "testEnvironment": "node",
+    "verbose": false
+  }
+}

packages/jest-runner/src/runTest.js

@@ -7,11 +7,13 @@
  * @flow
  */
 
+import type {ConsoleBuffer} from 'types/Console';
 import type {EnvironmentClass} from 'types/Environment';
 import type {GlobalConfig, Path, ProjectConfig} from 'types/Config';
 import type {Resolver} from 'types/Resolve';
 import type {TestFramework} from 'types/TestRunner';
 import type {TestResult} from 'types/TestResult';
+import type {SourceMapRegistry} from 'types/SourceMaps';
 import type RuntimeClass from 'jest-runtime';
 
 import fs from 'graceful-fs';
@@ -34,6 +36,27 @@ type RunTestInternalResult = {
   result: TestResult,
 };
 
+function freezeConsole(buffer: ConsoleBuffer, config: ProjectConfig) {
+  // $FlowFixMe: overwrite it for pretty errors. `Object.freeze` works, but gives ugly errors
+  buffer.push = function fakeConsolePush({message}) {
+    const error = new ErrorWithStack(
+      `Cannot log after tests are done. Did you forget to wait for something async in your test?\nAttempted to log "${message}".`,
+      fakeConsolePush,
+    );
+
+    const formattedError = formatExecError(
+      error,
+      config,
+      {noStackTrace: false},
+      undefined,
+      true,
+    );
+
+    process.stderr.write(formattedError);
+    process.exitCode = 1;
+  };
+}
+
 // Keeping the core of "runTest" as a separate function (as "runTestInternal")
 // is key to be able to detect memory leaks. Since all variables are local to
 // the function, when "runTestInternal" finishes its execution, they can all be
@@ -76,29 +99,35 @@ async function runTestInternal(
 
   let runtime = undefined;
 
+  const getRuntimeSourceMaps: () => ?SourceMapRegistry = () =>
+    runtime && runtime.getSourceMaps();
   const consoleOut = globalConfig.useStderr ? process.stderr : process.stdout;
   const consoleFormatter = (type, message) =>
     getConsoleOutput(
       config.cwd,
       !!globalConfig.verbose,
       // 4 = the console call is buried 4 stack frames deep
-      BufferedConsole.write(
-        [],
-        type,
-        message,
-        4,
-        runtime && runtime.getSourceMaps(),
-      ),
+      BufferedConsole.write([], type, message, 4, getRuntimeSourceMaps()),
     );
 
   let testConsole;
 
   if (globalConfig.silent) {
-    testConsole = new NullConsole(consoleOut, process.stderr, consoleFormatter);
+    testConsole = new NullConsole(
+      consoleOut,
+      process.stderr,
+      consoleFormatter,
+      getRuntimeSourceMaps,
+    );
   } else if (globalConfig.verbose) {
-    testConsole = new Console(consoleOut, process.stderr, consoleFormatter);
+    testConsole = new Console(
+      consoleOut,
+      process.stderr,
+      consoleFormatter,
+      getRuntimeSourceMaps,
+    );
   } else {
-    testConsole = new BufferedConsole(() => runtime && runtime.getSourceMaps());
+    testConsole = new BufferedConsole(getRuntimeSourceMaps);
   }
 
   const environment = new TestEnvironment(config, {
@@ -197,6 +226,8 @@ async function runTestInternal(
       throw err;
     }
 
+    freezeConsole(testConsole.getBuffer(), config);
+
     const testCount =
       result.numPassingTests +
       result.numFailingTests +

packages/jest-util/src/CustomConsole.js

@@ -8,29 +8,43 @@
  */
 /* global stream$Writable */
 
-import type {LogType, LogMessage, LogCounters, LogTimers} from 'types/Console';
+import type {
+  ConsoleBuffer,
+  LogType,
+  LogMessage,
+  LogCounters,
+  LogTimers,
+} from 'types/Console';
+import type {SourceMapRegistry} from 'types/SourceMaps';
 
 import assert from 'assert';
 import {format} from 'util';
 import {Console} from 'console';
 import chalk from 'chalk';
 import clearLine from './clearLine';
+import getCallsite from './getCallsite';
 
 type Formatter = (type: LogType, message: LogMessage) => string;
 
 export default class CustomConsole extends Console {
+  // This buffer exists so we can throw errors if it's changed after test env is torn down
+  _buffer: ConsoleBuffer;
   _stdout: stream$Writable;
   _formatBuffer: Formatter;
   _counters: LogCounters;
   _timers: LogTimers;
   _groupDepth: number;
+  _getSourceMaps: () => ?SourceMapRegistry;
 
   constructor(
     stdout: stream$Writable,
     stderr: stream$Writable,
     formatBuffer: ?Formatter,
+    getSourceMaps: () => ?SourceMapRegistry,
   ) {
     super(stdout, stderr);
+    this._buffer = [];
+    this._getSourceMaps = getSourceMaps;
     this._formatBuffer = formatBuffer || ((type, message) => message);
     this._counters = {};
     this._timers = {};
@@ -41,11 +55,25 @@ export default class CustomConsole extends Console {
     super.log(message);
   }
 
+  _storeInBuffer(message: string, type: LogType) {
+    const callsite = getCallsite(3, this._getSourceMaps());
+    const origin = callsite.getFileName() + ':' + callsite.getLineNumber();
+
+    this._buffer.push({message, origin, type});
+    // we might want to keep this in the future for reporters (https://github.com/facebook/jest/issues/6441)
+    this._buffer.pop();
+  }
+
   _log(type: LogType, message: string) {
     clearLine(this._stdout);
-    this._logToParentConsole(
-      this._formatBuffer(type, '  '.repeat(this._groupDepth) + message),
+
+    const formattedMessage = this._formatBuffer(
+      type,
+      '  '.repeat(this._groupDepth) + message,
     );
+
+    this._storeInBuffer(formattedMessage, type);
+    this._logToParentConsole(formattedMessage);
   }
 
   assert(...args: Array<any>) {
@@ -138,6 +166,6 @@ export default class CustomConsole extends Console {
   }
 
   getBuffer() {
-    return null;
+    return this._buffer;
   }
 }