From 6413244d60093114bfcf563a0c6b4d306fefbd78 Mon Sep 17 00:00:00 2001 From: Conrad Buck Date: Mon, 23 Aug 2021 12:46:25 -0400 Subject: [PATCH 1/8] Ensure verbose mode prints output synchronously Fixes #8208 --- CHANGELOG.md | 1 + .../consoleDebugging.test.ts.snap | 16 +++++++++++++ e2e/__tests__/consoleDebugging.test.ts | 23 ++++++++++++++++++ .../__tests__/console-debugging.test.js | 24 +++++++++++++++++++ e2e/console-debugging/jest.config.js | 6 +++++ e2e/console-debugging/package.json | 1 + e2e/console-debugging/stdout-spy.js | 18 ++++++++++++++ .../jest-reporters/src/DefaultReporter.ts | 24 ++++++++++--------- .../jest-reporters/src/VerboseReporter.ts | 15 ++++++++++++ 9 files changed, 117 insertions(+), 11 deletions(-) create mode 100644 e2e/__tests__/__snapshots__/consoleDebugging.test.ts.snap create mode 100644 e2e/__tests__/consoleDebugging.test.ts create mode 100644 e2e/console-debugging/__tests__/console-debugging.test.js create mode 100644 e2e/console-debugging/jest.config.js create mode 100644 e2e/console-debugging/package.json create mode 100644 e2e/console-debugging/stdout-spy.js diff --git a/CHANGELOG.md b/CHANGELOG.md index 573ddf17f723..6b2a3e7409e2 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -10,6 +10,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 diff --git a/e2e/__tests__/__snapshots__/consoleDebugging.test.ts.snap b/e2e/__tests__/__snapshots__/consoleDebugging.test.ts.snap new file mode 100644 index 000000000000..f5bfd36dfb92 --- /dev/null +++ b/e2e/__tests__/__snapshots__/consoleDebugging.test.ts.snap @@ -0,0 +1,16 @@ +// Jest Snapshot v1, https://goo.gl/fbAQLP + +exports[`console debugging with --verbose 1`] = ``; + +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: <> +Ran all test suites. +`; diff --git a/e2e/__tests__/consoleDebugging.test.ts b/e2e/__tests__/consoleDebugging.test.ts new file mode 100644 index 000000000000..4aca32566208 --- /dev/null +++ b/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(); +}); diff --git a/e2e/console-debugging/__tests__/console-debugging.test.js b/e2e/console-debugging/__tests__/console-debugging.test.js new file mode 100644 index 000000000000..fbeff2a65114 --- /dev/null +++ b/e2e/console-debugging/__tests__/console-debugging.test.js @@ -0,0 +1,24 @@ +/** + * 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', () => { + console.log('test'); + + expect(stdoutWrite.text).toMatchInlineSnapshot(` +" console.log + test + + at Object.log (__tests__/console-debugging.test.js:14:11) + +" +`); +}); diff --git a/e2e/console-debugging/jest.config.js b/e2e/console-debugging/jest.config.js new file mode 100644 index 000000000000..7e74c7cc6124 --- /dev/null +++ b/e2e/console-debugging/jest.config.js @@ -0,0 +1,6 @@ +require('./stdout-spy'); + +module.exports = { + testEnvironment: 'node', + verbose: true, +}; diff --git a/e2e/console-debugging/package.json b/e2e/console-debugging/package.json new file mode 100644 index 000000000000..0967ef424bce --- /dev/null +++ b/e2e/console-debugging/package.json @@ -0,0 +1 @@ +{} diff --git a/e2e/console-debugging/stdout-spy.js b/e2e/console-debugging/stdout-spy.js new file mode 100644 index 000000000000..636965247645 --- /dev/null +++ b/e2e/console-debugging/stdout-spy.js @@ -0,0 +1,18 @@ +const originalStdoutWrite = process.stdout.write; + +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; diff --git a/packages/jest-reporters/src/DefaultReporter.ts b/packages/jest-reporters/src/DefaultReporter.ts index 77b1fbe94b46..d9aeee5b210a 100644 --- a/packages/jest-reporters/src/DefaultReporter.ts +++ b/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 = []; 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) { diff --git a/packages/jest-reporters/src/VerboseReporter.ts b/packages/jest-reporters/src/VerboseReporter.ts index 5d7de322f330..dfe5901ef7bd 100644 --- a/packages/jest-reporters/src/VerboseReporter.ts +++ b/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, ): Array { From 16c71188680c02cf93bbeb25ab4696d2b1a56182 Mon Sep 17 00:00:00 2001 From: Conrad Buck Date: Mon, 23 Aug 2021 12:46:55 -0400 Subject: [PATCH 2/8] Stop hiding folders --- .vscode/settings.json | 2 -- 1 file changed, 2 deletions(-) diff --git a/.vscode/settings.json b/.vscode/settings.json index 0dcce386c953..bb5f7b2d11d9 100644 --- a/.vscode/settings.json +++ b/.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 --", From 9ec5faf4ce0c7a2437d6b6e5f2ad335a0c98c6dc Mon Sep 17 00:00:00 2001 From: Simen Bekkhus Date: Wed, 6 Oct 2021 08:16:22 +0200 Subject: [PATCH 3/8] bind write to not mess ith its internal state --- e2e/console-debugging/stdout-spy.js | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/e2e/console-debugging/stdout-spy.js b/e2e/console-debugging/stdout-spy.js index 636965247645..ead679cb6e22 100644 --- a/e2e/console-debugging/stdout-spy.js +++ b/e2e/console-debugging/stdout-spy.js @@ -1,4 +1,4 @@ -const originalStdoutWrite = process.stdout.write; +const originalStdoutWrite = process.stdout.write.bind(process.stdout); global.process.__stdoutWriteMock = global.process.__stdoutWriteMock || null; From 125e4bed6374ce2c5a4eb5abb397cbedf79afcb3 Mon Sep 17 00:00:00 2001 From: Simen Bekkhus Date: Wed, 6 Oct 2021 08:17:34 +0200 Subject: [PATCH 4/8] add copyright headers --- e2e/console-debugging/jest.config.js | 8 ++++++++ e2e/console-debugging/stdout-spy.js | 8 ++++++++ 2 files changed, 16 insertions(+) diff --git a/e2e/console-debugging/jest.config.js b/e2e/console-debugging/jest.config.js index 7e74c7cc6124..87ce2c88899b 100644 --- a/e2e/console-debugging/jest.config.js +++ b/e2e/console-debugging/jest.config.js @@ -1,3 +1,11 @@ +/** + * 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 = { diff --git a/e2e/console-debugging/stdout-spy.js b/e2e/console-debugging/stdout-spy.js index ead679cb6e22..737acf1f4678 100644 --- a/e2e/console-debugging/stdout-spy.js +++ b/e2e/console-debugging/stdout-spy.js @@ -1,3 +1,11 @@ +/** + * 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; From b916befca0c018c46a8fb282fe008f7946b26487 Mon Sep 17 00:00:00 2001 From: Simen Bekkhus Date: Wed, 6 Oct 2021 08:32:35 +0200 Subject: [PATCH 5/8] add missing types/node dep --- packages/jest-reporters/package.json | 1 + yarn.lock | 1 + 2 files changed, 2 insertions(+) diff --git a/packages/jest-reporters/package.json b/packages/jest-reporters/package.json index dd0886f9dd53..ee4bf4712ba7 100644 --- a/packages/jest-reporters/package.json +++ b/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", diff --git a/yarn.lock b/yarn.lock index 94e28baf81a6..7996e76ba4e0 100644 --- a/yarn.lock +++ b/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 From 569299e1deb4322f631fa217ccc4c0cf2799ac97 Mon Sep 17 00:00:00 2001 From: Simen Bekkhus Date: Wed, 6 Oct 2021 08:43:03 +0200 Subject: [PATCH 6/8] fix test --- .../__tests__/console-debugging.test.js | 17 +++++++++++------ e2e/console-debugging/stdout-spy.js | 9 ++++++++- 2 files changed, 19 insertions(+), 7 deletions(-) diff --git a/e2e/console-debugging/__tests__/console-debugging.test.js b/e2e/console-debugging/__tests__/console-debugging.test.js index fbeff2a65114..da3188fb3c30 100644 --- a/e2e/console-debugging/__tests__/console-debugging.test.js +++ b/e2e/console-debugging/__tests__/console-debugging.test.js @@ -13,12 +13,17 @@ process.stdout.write = jest.fn(process.stdout.write); test('verbose mode prints console output synchronously', () => { console.log('test'); + // this asserts the console log exists in the output before this test exits expect(stdoutWrite.text).toMatchInlineSnapshot(` -" console.log - test + Array [ + "Determining test suites to run...", + "RUNS __tests__/console-debugging.test.js", + "RUNS __tests__/console-debugging.test.js", + "console.log + test - at Object.log (__tests__/console-debugging.test.js:14:11) - -" -`); + at Object.log (__tests__/console-debugging.test.js:14:11)", + "RUNS __tests__/console-debugging.test.js", + ] + `); }); diff --git a/e2e/console-debugging/stdout-spy.js b/e2e/console-debugging/stdout-spy.js index 737acf1f4678..d4459bad69fc 100644 --- a/e2e/console-debugging/stdout-spy.js +++ b/e2e/console-debugging/stdout-spy.js @@ -6,6 +6,8 @@ */ 'use strict'; +const stripAnsi = require('strip-ansi'); + const originalStdoutWrite = process.stdout.write.bind(process.stdout); global.process.__stdoutWriteMock = global.process.__stdoutWriteMock || null; @@ -16,10 +18,15 @@ global.process.__stdoutWriteMock = global.process.__stdoutWriteMock || null; */ if (!global.process.__stdoutWriteMock) { global.process.__stdoutWriteMock = (...args) => { - global.process.__stdoutWriteMock.text = args[0]; + const plainText = stripAnsi(args[0]).trim(); + if (plainText.length > 0) { + global.process.__stdoutWriteMock.text.push(plainText); + } originalStdoutWrite(...args); }; + global.process.__stdoutWriteMock.text = []; + process.stdout.write = global.process.__stdoutWriteMock; } From 18a11e726745ad8114e3b08119812a5323c02367 Mon Sep 17 00:00:00 2001 From: Simen Bekkhus Date: Wed, 6 Oct 2021 09:20:14 +0200 Subject: [PATCH 7/8] snapshot for non-tty --- .../__snapshots__/consoleDebugging.test.ts.snap | 8 +++++++- .../__tests__/console-debugging.test.js | 9 ++++----- 2 files changed, 11 insertions(+), 6 deletions(-) diff --git a/e2e/__tests__/__snapshots__/consoleDebugging.test.ts.snap b/e2e/__tests__/__snapshots__/consoleDebugging.test.ts.snap index f5bfd36dfb92..9b6414ff5b70 100644 --- a/e2e/__tests__/__snapshots__/consoleDebugging.test.ts.snap +++ b/e2e/__tests__/__snapshots__/consoleDebugging.test.ts.snap @@ -1,6 +1,12 @@ // Jest Snapshot v1, https://goo.gl/fbAQLP -exports[`console debugging with --verbose 1`] = ``; +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 diff --git a/e2e/console-debugging/__tests__/console-debugging.test.js b/e2e/console-debugging/__tests__/console-debugging.test.js index da3188fb3c30..d428a94d54b8 100644 --- a/e2e/console-debugging/__tests__/console-debugging.test.js +++ b/e2e/console-debugging/__tests__/console-debugging.test.js @@ -11,19 +11,18 @@ 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'); // this asserts the console log exists in the output before this test exits expect(stdoutWrite.text).toMatchInlineSnapshot(` Array [ - "Determining test suites to run...", - "RUNS __tests__/console-debugging.test.js", - "RUNS __tests__/console-debugging.test.js", "console.log test - at Object.log (__tests__/console-debugging.test.js:14:11)", - "RUNS __tests__/console-debugging.test.js", + at Object.log (__tests__/console-debugging.test.js:17:11)", ] `); }); From 77f805036e1693263cf89c9d10b7ddc5673bc562 Mon Sep 17 00:00:00 2001 From: Simen Bekkhus Date: Wed, 6 Oct 2021 09:23:46 +0200 Subject: [PATCH 8/8] use original mock --- .../__tests__/console-debugging.test.js | 9 ++++----- e2e/console-debugging/stdout-spy.js | 9 +-------- 2 files changed, 5 insertions(+), 13 deletions(-) diff --git a/e2e/console-debugging/__tests__/console-debugging.test.js b/e2e/console-debugging/__tests__/console-debugging.test.js index d428a94d54b8..9d801e87b6c5 100644 --- a/e2e/console-debugging/__tests__/console-debugging.test.js +++ b/e2e/console-debugging/__tests__/console-debugging.test.js @@ -16,13 +16,12 @@ test('verbose mode prints console output synchronously', () => { console.log('test'); - // this asserts the console log exists in the output before this test exits expect(stdoutWrite.text).toMatchInlineSnapshot(` - Array [ - "console.log + " console.log test - at Object.log (__tests__/console-debugging.test.js:17:11)", - ] + at Object.log (__tests__/console-debugging.test.js:17:11) + + " `); }); diff --git a/e2e/console-debugging/stdout-spy.js b/e2e/console-debugging/stdout-spy.js index d4459bad69fc..737acf1f4678 100644 --- a/e2e/console-debugging/stdout-spy.js +++ b/e2e/console-debugging/stdout-spy.js @@ -6,8 +6,6 @@ */ 'use strict'; -const stripAnsi = require('strip-ansi'); - const originalStdoutWrite = process.stdout.write.bind(process.stdout); global.process.__stdoutWriteMock = global.process.__stdoutWriteMock || null; @@ -18,15 +16,10 @@ global.process.__stdoutWriteMock = global.process.__stdoutWriteMock || null; */ if (!global.process.__stdoutWriteMock) { global.process.__stdoutWriteMock = (...args) => { - const plainText = stripAnsi(args[0]).trim(); - if (plainText.length > 0) { - global.process.__stdoutWriteMock.text.push(plainText); - } + global.process.__stdoutWriteMock.text = args[0]; originalStdoutWrite(...args); }; - global.process.__stdoutWriteMock.text = []; - process.stdout.write = global.process.__stdoutWriteMock; }