fix(reporters): verbose reporter should not buffer writes (#11054)

.vscode/settings.json

@@ -2,8 +2,6 @@
   "editor.rulers": [80],
   "files.exclude": {
     "**/.git": true,
-    "**/node_modules": true,
-    "**/build": true
   },
   "javascript.validate.enable": false,
   "jest.pathToJest": "yarn jest --",

CHANGELOG.md

@@ -12,6 +12,7 @@
 - `[@jest/types]` Mark deprecated configuration options as `@deprecated` ([#11913](https://github.com/facebook/jest/pull/11913))
 - `[jest-cli]` Improve `--help` printout by removing defunct `--browser` option ([#11914](https://github.com/facebook/jest/pull/11914))
 - `[jest-haste-map]` Use distinct cache paths for different values of `computeDependencies` ([#11916](https://github.com/facebook/jest/pull/11916))
+- `[@jest/reporters]` Do not buffer `console.log`s when using verbose reporter [#11054](https://github.com/facebook/jest/pull/11054)
 
 ### Chore & Maintenance
 

e2e/__tests__/__snapshots__/consoleDebugging.test.ts.snap

@@ -0,0 +1,22 @@
+// Jest Snapshot v1, https://goo.gl/fbAQLP
+
+exports[`console debugging with --verbose 1`] = `
+  console.log
+    test
+
+      at Object.log (__tests__/console-debugging.test.js:17:11)
+
+`;
+
+exports[`console debugging with --verbose 2`] = `
+PASS __tests__/console-debugging.test.js
+  ✓ verbose mode prints console output synchronously
+`;
+
+exports[`console debugging with --verbose 3`] = `
+Test Suites: 1 passed, 1 total
+Tests:       1 passed, 1 total
+Snapshots:   1 passed, 1 total
+Time:        <<REPLACED>>
+Ran all test suites.
+`;

e2e/__tests__/consoleDebugging.test.ts

@@ -0,0 +1,23 @@
+/**
+ * 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.
+ */
+
+import {wrap} from 'jest-snapshot-serializer-raw';
+import {extractSummary} from '../Utils';
+import runJest from '../runJest';
+
+test('console debugging with --verbose', () => {
+  const {stderr, stdout, exitCode} = runJest('console-debugging', [
+    '--noStackTrace',
+    '--no-cache',
+  ]);
+  const {summary, rest} = extractSummary(stderr);
+
+  expect(exitCode).toBe(0);
+  expect(wrap(stdout)).toMatchSnapshot();
+  expect(wrap(rest)).toMatchSnapshot();
+  expect(wrap(summary)).toMatchSnapshot();
+});

e2e/console-debugging/__tests__/console-debugging.test.js

@@ -0,0 +1,27 @@
+/**
+ * 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';
+
+const stdoutWrite = require('../stdout-spy');
+
+process.stdout.write = jest.fn(process.stdout.write);
+
+test('verbose mode prints console output synchronously', () => {
+  // test only works consistently without tty
+  expect(process.stdout.isTTY).not.toBe(true);
+
+  console.log('test');
+
+  expect(stdoutWrite.text).toMatchInlineSnapshot(`
+    "  console.log
+        test
+
+          at Object.log (__tests__/console-debugging.test.js:17:11)
+
+    "
+  `);
+});

e2e/console-debugging/jest.config.js

@@ -0,0 +1,14 @@
+/**
+ * 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';
+
+require('./stdout-spy');
+
+module.exports = {
+  testEnvironment: 'node',
+  verbose: true,
+};

e2e/console-debugging/package.json

@@ -0,0 +1 @@
+{}

e2e/console-debugging/stdout-spy.js

@@ -0,0 +1,26 @@
+/**
+ * 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';
+
+const originalStdoutWrite = process.stdout.write.bind(process.stdout);
+
+global.process.__stdoutWriteMock = global.process.__stdoutWriteMock || null;
+
+/*
+  This is a terrible hack to ensure that we monkeyPath stdoutWrite before
+  the jest reporter does...
+*/
+if (!global.process.__stdoutWriteMock) {
+  global.process.__stdoutWriteMock = (...args) => {
+    global.process.__stdoutWriteMock.text = args[0];
+    originalStdoutWrite(...args);
+  };
+
+  process.stdout.write = global.process.__stdoutWriteMock;
+}
+
+module.exports = global.process.__stdoutWriteMock;

packages/jest-reporters/package.json

@@ -14,6 +14,7 @@
     "@jest/test-result": "^27.2.4",
     "@jest/transform": "^27.2.4",
     "@jest/types": "^27.2.4",
+    "@types/node": "*",
     "chalk": "^4.0.0",
     "collect-v8-coverage": "^1.0.0",
     "exit": "^0.1.2",

packages/jest-reporters/src/DefaultReporter.ts

@@ -43,16 +43,18 @@ export default class DefaultReporter extends BaseReporter {
     this._err = process.stderr.write.bind(process.stderr);
     this._status = new Status();
     this._bufferedOutput = new Set();
-    this._wrapStdio(process.stdout);
-    this._wrapStdio(process.stderr);
+    this.__wrapStdio(process.stdout);
+    this.__wrapStdio(process.stderr);
     this._status.onChange(() => {
-      this._clearStatus();
-      this._printStatus();
+      this.__clearStatus();
+      this.__printStatus();
     });
   }
 
-  private _wrapStdio(stream: NodeJS.WritableStream | NodeJS.WriteStream) {
-    const originalWrite = stream.write;
+  protected __wrapStdio(
+    stream: NodeJS.WritableStream | NodeJS.WriteStream,
+  ): void {
+    const write = stream.write.bind(stream);
 
     let buffer: Array<string> = [];
     let timeout: NodeJS.Timeout | null = null;
@@ -62,11 +64,11 @@ export default class DefaultReporter extends BaseReporter {
       buffer = [];
 
       // This is to avoid conflicts between random output and status text
-      this._clearStatus();
+      this.__clearStatus();
       if (string) {
-        originalWrite.call(stream, string);
+        write(string);
       }
-      this._printStatus();
+      this.__printStatus();
 
       this._bufferedOutput.delete(flushBufferedOutput);
     };
@@ -103,7 +105,7 @@ export default class DefaultReporter extends BaseReporter {
     }
   }
 
-  private _clearStatus() {
+  protected __clearStatus(): void {
     if (isInteractive) {
       if (this._globalConfig.useStderr) {
         this._err(this._clear);
@@ -113,7 +115,7 @@ export default class DefaultReporter extends BaseReporter {
     }
   }
 
-  private _printStatus() {
+  protected __printStatus(): void {
     const {content, clear} = this._status.get();
     this._clear = clear;
     if (isInteractive) {

packages/jest-reporters/src/VerboseReporter.ts

@@ -29,6 +29,21 @@ export default class VerboseReporter extends DefaultReporter {
     this._globalConfig = globalConfig;
   }
 
+  // Verbose mode is for debugging. Buffering of output is undesirable.
+  // See https://github.com/facebook/jest/issues/8208
+  protected __wrapStdio(
+    stream: NodeJS.WritableStream | NodeJS.WriteStream,
+  ): void {
+    const write = stream.write.bind(stream);
+
+    stream.write = (chunk: string) => {
+      this.__clearStatus();
+      write(chunk);
+      this.__printStatus();
+      return true;
+    };
+  }
+
   static filterTestResults(
     testResults: Array<AssertionResult>,
   ): Array<AssertionResult> {

yarn.lock

@@ -2654,6 +2654,7 @@ __metadata:
     "@types/istanbul-lib-report": ^3.0.0
     "@types/istanbul-lib-source-maps": ^4.0.0
     "@types/istanbul-reports": ^3.0.0
+    "@types/node": "*"
     "@types/node-notifier": ^8.0.0
     chalk: ^4.0.0
     collect-v8-coverage: ^1.0.0