Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

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

Merged
merged 8 commits into from
Oct 8, 2021

Conversation

conartist6
Copy link
Contributor

Fixes #8208

See my investigation of that issue for more details.

@conartist6
Copy link
Contributor Author

conartist6 commented Feb 4, 2021

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
Copy link
Contributor Author

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

@conartist6 conartist6 changed the title Ensure verbose mode prints output synchronously fix(reporters) verbose reporter should not buffer writes Feb 4, 2021
@conartist6 conartist6 changed the title fix(reporters) verbose reporter should not buffer writes fix(reporters): verbose reporter should not buffer writes Feb 4, 2021
@conartist6
Copy link
Contributor Author

Looks like the various OSX tests have been failing recently...
Screen Shot 2021-02-04 at 5 45 39 PM

@conartist6
Copy link
Contributor Author

conartist6 commented Feb 8, 2021

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:
Screen Shot 2021-02-07 at 11 12 41 PM

Missing:
Screen Shot 2021-02-07 at 11 09 50 PM

@silverwind
Copy link
Contributor

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

@silverwind
Copy link
Contributor

Also, I think adding a test would be great.

@SimenB
Copy link
Member

SimenB commented Apr 30, 2021

A rebase should fix CI.

A test would be great, yeah 👍

@cc-ebay
Copy link

cc-ebay commented May 8, 2021

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

@conartist6
Copy link
Contributor Author

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

@conartist6
Copy link
Contributor Author

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
Copy link
Member

cpojer commented May 29, 2021

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
Copy link
Contributor Author

conartist6 commented May 29, 2021 via email

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

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
Copy link
Contributor Author

@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.

@conartist6
Copy link
Contributor Author

@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
Copy link
Member

SimenB commented Oct 6, 2021

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

Copy link
Member

@SimenB SimenB left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

thanks!

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

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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.

Copy link
Contributor Author

@conartist6 conartist6 Oct 7, 2021

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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
Copy link
Member

SimenB commented Oct 6, 2021

Hmm, 2 thing.

  1. 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
  2. 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
Copy link
Member

SimenB commented Oct 6, 2021

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
Copy link
Member

SimenB commented Oct 7, 2021

@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

Copy link
Contributor Author

@conartist6 conartist6 left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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.

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

@conartist6 conartist6 Oct 7, 2021

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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.

global.process.__stdoutWriteMock = global.process.__stdoutWriteMock || null;

/*
This is a terrible hack to ensure that we monkeyPath stdoutWrite before
Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

oops I misspelled this

@SimenB
Copy link
Member

SimenB commented Oct 8, 2021

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 :shipit:

@SimenB SimenB merged commit 7f881af into jestjs:main Oct 8, 2021
@SimenB
Copy link
Member

SimenB commented Oct 8, 2021

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

@conartist6
Copy link
Contributor Author

Hooray! Thanks!

@github-actions
Copy link

github-actions bot commented Nov 8, 2021

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.

@github-actions github-actions bot locked as resolved and limited conversation to collaborators Nov 8, 2021
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Projects
None yet
Development

Successfully merging this pull request may close these issues.

Jest eats up all console.log messages during debugging
9 participants