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

conartist6 · 2021-02-04T20:00:37Z

See my investigation of that issue for more details.

conartist6 · 2021-02-04T22:01:21Z

I notice I'm also skipping a block of code that deals with printing and clearing status. I think the test I'm doing doesn't cover this situation. I'm using the verbose reporter with the in-band runner, but it is also possible for the verbose reporter to be used with the parallel runner. I'm guessing I can just leave that block while eliminating the buffering. Probably need to change the factoring around a bit though so I don't duplicate code.

conartist6 · 2021-02-04T22:14:35Z

OK I put that block back. I didn't refactor for DRYness as the amount of code duplicated is relatively minimal.

conartist6 · 2021-02-04T22:47:47Z

Looks like the various OSX tests have been failing recently...

conartist6 · 2021-02-08T04:20:25Z

I wasn't sure quite what the clearStatus and printStatus methods are for, but here's what I saw locally with the lines present vs missing.

Present:

Missing:

silverwind · 2021-04-30T10:27:19Z

Maybe remove the @types/node change to make this easier to review?

silverwind · 2021-04-30T10:29:47Z

Also, I think adding a test would be great.

SimenB · 2021-04-30T10:34:05Z

A rebase should fix CI.

A test would be great, yeah 👍

cc-ebay · 2021-05-08T03:59:21Z

@silverwind @conartist6 Can you rebase ?
I would like to see this merged!

conartist6 · 2021-05-26T14:09:52Z

OK I've rebased. A test would be great, but it's not exactly an easy test to write...

conartist6 · 2021-05-26T15:00:06Z

The nasty thing is that I don't think it's safe to spy on process.stdio.write in test setup code for this. The problem is that some of the buffering is in the implementation of that function itself, so merely seeing that it is called synchronously doesn't mean the output is written synchronously. So instead I'd have to have a handle on the real stdio stream, and since I can't get it on the node side I'd have to find a platform independent way to get the real stuff. That would presumably require writing a node executor that collects stream events but also allows the code under execution to know that it exists so that its recorded output can be queried... It'd be easier I think just to remove monkey-patching of process.stdio.write from the implementation so that it could safely be used in test assertions.

Long story short, I don't have the energy or will to get as involved as writing a test would be. If it breaks again it can be fixed again. Goodness knows it's been broken for long enough right now...

cpojer · 2021-05-29T22:40:47Z

We won't be merging PRs without tests associated, so if someone wants to see this fixed, please take this branch and add a test case.

conartist6 · 2021-05-29T22:49:03Z

@cpojer That somebody would be me. Any thoughts on the difficulties I mention in writing a test that really verifies this functionality?

conartist6 · 2021-05-30T16:22:44Z

OK, there's a test. I was wrong in saying the test couldn't monkey patch, it just has to monkey patch the monkey patch...

conartist6 · 2021-05-30T16:26:13Z

@cpojer If you say there's formal requirements around testing could you share what they are so that I can update CONTRIBUTING.md? I notice jest has coverage configured but it's only ~70% covered.

Fixes jestjs#8208

conartist6 · 2021-10-06T02:59:09Z

@SimenB This branch is up to date again, tests are passing and can be verified failing by disabling the fix. Also there is not longer any need to modify the package to an @types/node dependency. I don't know why that had been happening. Can we put this one to bed?

SimenB · 2021-10-06T06:19:15Z

I pushed up 2 commits - the first fixing a broken write. I wanted to verify the test failed without your changes, and it made node internals explode

TypeError: Cannot read property '_writableState' of undefined
    at Writable.write (internal/streams/writable.js:259:22)
    at WriteStream.global.process.__stdoutWriteMock [as write] (/Users/simen/repos/jest/e2e/console-debugging/stdout-spy.js:14:5)
    at print (/Users/simen/repos/jest/packages/jest-util/build/preRunMessage.js:34:12)
    at startRun (/Users/simen/repos/jest/packages/jest-core/build/cli/index.js:380:7)
    at runWithoutWatch (/Users/simen/repos/jest/packages/jest-core/build/cli/index.js:398:10)
    at _run10000 (/Users/simen/repos/jest/packages/jest-core/build/cli/index.js:320:13)
    at processTicksAndRejections (internal/process/task_queues.js:95:5)
    at async runCLI (/Users/simen/repos/jest/packages/jest-core/build/cli/index.js:173:3)
    at async Object.run (/Users/simen/repos/jest/packages/jest-cli/build/cli/index.js:155:37)

Binding the function fixes it to actually fail because of missing output 🙂

The second commit just adds missing copyright headers

SimenB

thanks!

SimenB · 2021-10-06T06:20:01Z

.vscode/settings.json

@@ -2,8 +2,6 @@
  "editor.rulers": [80],
  "files.exclude": {
    "**/.git": true,
-    "**/node_modules": true,


what does this do? (I don't use vs code)

ah, just saw

As a side note hiding all the build output from VScode is a pain, and again falls into the category of things I consider lying to developers. It wasted a bunch of my time because I couldn't tell that typescript watching was not working.

Yeah it just makes the directory invisible. If your IDE is your primary way to see what's going on in the filesystem you might assume the directories really just don't exist, which they do. It's unnecessarily confusing.

SimenB · 2021-10-06T06:43:53Z

Hmm, 2 thing.

I added a dep on @types/node - the reason this is needed is that now the method is protected rather than private, it's added to the exported interface of the class and since it uses NodeJS.* stuff, we need a dependency
My change to bind breaks the test. I pushed another take on it which captures all output, not just the last. Without your changes the log statement doesn't appear, but I added a comment above to specify

SimenB · 2021-10-06T07:24:58Z

E2E runner runs without tty, so I was fooled by running the test directly - original test approach works (and I added an assertion that the stream is not tty).

So, altogether the diff I've pushed is

diff --git c/e2e/__tests__/__snapshots__/consoleDebugging.test.ts.snap w/e2e/__tests__/__snapshots__/consoleDebugging.test.ts.snap
index f5bfd36dfb..9b6414ff5b 100644
--- c/e2e/__tests__/__snapshots__/consoleDebugging.test.ts.snap
+++ w/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 c/e2e/console-debugging/__tests__/console-debugging.test.js w/e2e/console-debugging/__tests__/console-debugging.test.js
index fbeff2a651..9d801e87b6 100644
--- c/e2e/console-debugging/__tests__/console-debugging.test.js
+++ w/e2e/console-debugging/__tests__/console-debugging.test.js
@@ -11,14 +11,17 @@ 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
+    "  console.log
+        test
 
-      at Object.log (__tests__/console-debugging.test.js:14:11)
+          at Object.log (__tests__/console-debugging.test.js:17:11)
 
-"
-`);
+    "
+  `);
 });
diff --git c/e2e/console-debugging/jest.config.js w/e2e/console-debugging/jest.config.js
index 7e74c7cc61..87ce2c8889 100644
--- c/e2e/console-debugging/jest.config.js
+++ w/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 c/e2e/console-debugging/stdout-spy.js w/e2e/console-debugging/stdout-spy.js
index 6369652476..737acf1f46 100644
--- c/e2e/console-debugging/stdout-spy.js
+++ w/e2e/console-debugging/stdout-spy.js
@@ -1,4 +1,12 @@
-const originalStdoutWrite = process.stdout.write;
+/**
+ * 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;
 
diff --git c/packages/jest-reporters/package.json w/packages/jest-reporters/package.json
index dd0886f9dd..ee4bf4712b 100644
--- c/packages/jest-reporters/package.json
+++ w/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 c/yarn.lock w/yarn.lock
index 94e28baf81..7996e76ba4 100644
--- c/yarn.lock
+++ w/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

Somewhat surprised e2e/__tests__/__snapshots__/consoleDebugging.test.ts.snap changed... Thoughts? I guess it's better than before since we now assert that we see the output also from the e2e test

SimenB · 2021-10-07T12:30:23Z

@conartist6 would love your thoughts on the final point above (extra output in e2e test). I think it might just be because I fixed the bug which made it explode, but not sure

conartist6

I'm not 100% on the terminology, by TTY you mean an interactive terminal with support for ansi control characters right? The alternative to a TTY then just a non-interactive terminal which just records/prints every character that goes by it. I don't know why that would be relevant though, as my code should deal entirely with what happens before the real output stream code happens anyway, which you noticed in noticing that the test was not doing any real output though it was still passing. So looking over the updated output I agree with you that the current snapshot is correct. And the lack of bind in my spy definitely was creating undefined behavior, so it certainly looks to me like you identified and fixed an issue. As to what you may have seen that contradicted that theory, I can't say. I certainly confused myself a lot as I was trying to come up with this. Once the bug is fixed I'm wiling to work on changing things so that the code doesn't rely on monkey patching at all.

conartist6 · 2021-10-07T15:07:38Z

.vscode/settings.json

@@ -2,8 +2,6 @@
  "editor.rulers": [80],
  "files.exclude": {
    "**/.git": true,
-    "**/node_modules": true,


Yeah it just makes the directory invisible. If your IDE is your primary way to see what's going on in the filesystem you might assume the directories really just don't exist, which they do. It's unnecessarily confusing.

conartist6 · 2021-10-07T15:14:20Z

e2e/console-debugging/stdout-spy.js

+global.process.__stdoutWriteMock = global.process.__stdoutWriteMock || null;
+
+/*
+  This is a terrible hack to ensure that we monkeyPath stdoutWrite before


oops I misspelled this

SimenB · 2021-10-08T13:30:30Z

I'm not 100% on the terminology, by TTY you mean an interactive terminal with support for ansi control characters right?

yup 👍

The alternative to a TTY then just a non-interactive terminal which just records/prints every character that goes by it.

Right, or piped to a file etc

But cool, let's

SimenB · 2021-10-08T13:30:59Z

Thanks for your patience with us (me)! ❤️

conartist6 · 2021-10-08T15:37:28Z

Hooray! Thanks!

github-actions · 2021-11-08T00:04:35Z

This pull request has been automatically locked since there has not been any recent activity after it was closed. Please open a new issue for related bugs.
Please note this issue tracker is not a help forum. We recommend using StackOverflow or our discord channel for questions.

facebook-github-bot added the cla signed label Feb 4, 2021

conartist6 force-pushed the verbose-sync-log branch 5 times, most recently from 198d87c to 044bdeb Compare February 4, 2021 20:53

conartist6 force-pushed the verbose-sync-log branch from 044bdeb to e8528eb Compare February 4, 2021 22:09

conartist6 changed the title ~~Ensure verbose mode prints output synchronously~~ fix(reporters) verbose reporter should not buffer writes Feb 4, 2021

conartist6 changed the title ~~fix(reporters) verbose reporter should not buffer writes~~ fix(reporters): verbose reporter should not buffer writes Feb 4, 2021

conartist6 force-pushed the verbose-sync-log branch from e8528eb to 582331c Compare February 4, 2021 22:18

conartist6 mentioned this pull request Apr 14, 2021

Verbose reporter buffers writes preventing debugging with logs #11299

Closed

cc-ebay mentioned this pull request May 17, 2021

Jest eats up all console.log messages during debugging #8208

Closed

conartist6 force-pushed the verbose-sync-log branch from 582331c to e18af6c Compare May 26, 2021 14:01

conartist6 force-pushed the verbose-sync-log branch 3 times, most recently from 02de105 to afc282e Compare May 30, 2021 15:37

conartist6 force-pushed the verbose-sync-log branch from 6ca944f to a2d0348 Compare August 23, 2021 17:03

conartist6 force-pushed the verbose-sync-log branch 2 times, most recently from 7223305 to d8b8d66 Compare October 6, 2021 01:32

conartist6 added 2 commits October 5, 2021 21:35

Ensure verbose mode prints output synchronously

6413244

Fixes jestjs#8208

Stop hiding folders

16c7118

conartist6 force-pushed the verbose-sync-log branch from d8b8d66 to 16c7118 Compare October 6, 2021 01:36

SimenB added 2 commits October 6, 2021 08:16

bind write to not mess ith its internal state

9ec5faf

add copyright headers

125e4be

SimenB approved these changes Oct 6, 2021

View reviewed changes

SimenB reviewed Oct 6, 2021

View reviewed changes

SimenB added 2 commits October 6, 2021 08:32

add missing types/node dep

b916bef

fix test

569299e

SimenB added 2 commits October 6, 2021 09:22

snapshot for non-tty

18a11e7

use original mock

77f8050

conartist6 commented Oct 7, 2021

View reviewed changes

SimenB merged commit 7f881af into jestjs:main Oct 8, 2021

conartist6 deleted the verbose-sync-log branch October 8, 2021 15:37

ajfisher mentioned this pull request Oct 9, 2021

chore(deps-dev): bump jest from 26.6.3 to 27.2.5 nodebots/nodebots-interchange#193

Closed

pbrisbin mentioned this pull request Oct 11, 2021

Bump jest from 27.2.4 to 27.2.5 freckle/commenter-action#68

Merged

ajfisher mentioned this pull request Oct 18, 2021

chore(deps-dev): bump jest from 26.6.3 to 27.3.0 nodebots/nodebots-interchange#197

Closed

github-actions bot locked as resolved and limited conversation to collaborators Nov 8, 2021

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

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

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

conartist6 commented Feb 4, 2021

conartist6 commented Feb 4, 2021 •

edited

conartist6 commented Feb 4, 2021

conartist6 commented Feb 4, 2021

conartist6 commented Feb 8, 2021 •

edited

silverwind commented Apr 30, 2021

silverwind commented Apr 30, 2021

SimenB commented Apr 30, 2021

cc-ebay commented May 8, 2021 •

edited

conartist6 commented May 26, 2021

conartist6 commented May 26, 2021

cpojer commented May 29, 2021

conartist6 commented May 29, 2021 via email •

edited

conartist6 commented May 30, 2021

conartist6 commented May 30, 2021

conartist6 commented Oct 6, 2021

SimenB commented Oct 6, 2021

SimenB left a comment

SimenB Oct 6, 2021

SimenB Oct 6, 2021

conartist6 Oct 7, 2021 •

edited

SimenB commented Oct 6, 2021

SimenB commented Oct 6, 2021 •

edited

SimenB commented Oct 7, 2021

conartist6 left a comment

conartist6 Oct 7, 2021 •

edited

conartist6 Oct 7, 2021

SimenB commented Oct 8, 2021

SimenB commented Oct 8, 2021

conartist6 commented Oct 8, 2021

github-actions bot commented Nov 8, 2021

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

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

Conversation

conartist6 commented Feb 4, 2021

conartist6 commented Feb 4, 2021 • edited

conartist6 commented Feb 4, 2021

conartist6 commented Feb 4, 2021

conartist6 commented Feb 8, 2021 • edited

silverwind commented Apr 30, 2021

silverwind commented Apr 30, 2021

SimenB commented Apr 30, 2021

cc-ebay commented May 8, 2021 • edited

conartist6 commented May 26, 2021

conartist6 commented May 26, 2021

cpojer commented May 29, 2021

conartist6 commented May 29, 2021 via email • edited

conartist6 commented May 30, 2021

conartist6 commented May 30, 2021

conartist6 commented Oct 6, 2021

SimenB commented Oct 6, 2021

SimenB left a comment

Choose a reason for hiding this comment

SimenB Oct 6, 2021

Choose a reason for hiding this comment

SimenB Oct 6, 2021

Choose a reason for hiding this comment

conartist6 Oct 7, 2021 • edited

Choose a reason for hiding this comment

SimenB commented Oct 6, 2021

SimenB commented Oct 6, 2021 • edited

SimenB commented Oct 7, 2021

conartist6 left a comment

Choose a reason for hiding this comment

conartist6 Oct 7, 2021 • edited

Choose a reason for hiding this comment

conartist6 Oct 7, 2021

Choose a reason for hiding this comment

SimenB commented Oct 8, 2021

SimenB commented Oct 8, 2021

conartist6 commented Oct 8, 2021

github-actions bot commented Nov 8, 2021

conartist6 commented Feb 4, 2021 •

edited

conartist6 commented Feb 8, 2021 •

edited

cc-ebay commented May 8, 2021 •

edited

conartist6 commented May 29, 2021 via email •

edited

conartist6 Oct 7, 2021 •

edited

SimenB commented Oct 6, 2021 •

edited

conartist6 Oct 7, 2021 •

edited