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: print log entries if logging happens after teardown #7731

Merged
merged 16 commits into from
Jan 29, 2019

Conversation

SimenB
Copy link
Member

@SimenB SimenB commented Jan 27, 2019

Summary

Ref #3853

With this test:

test('throws error', () => {
  setTimeout(() => {
    console.log('hello!');
  }, 500);
});

Before this PR:
image

After this PR:
image

Test plan

Integration test added

@jeysal
Copy link
Contributor

jeysal commented Jan 27, 2019

Wow this is awesome, it blows my mind that the error formatting to achieve this UX can be done with so little new code 🎉
A few general points without having looked at the code in detail:

  • I would definitely consider the exit code breaking, this might be a candidate for warn first, introduce exiting with 1 in a major
  • I think people might have a lot of these in some codebases, usually in the next 1 or 2 ticks after the test completes, so maybe we should come up with something that prevents flooding them with warnings?
  • Tried this out locally, watch mode seems to not show the warnings anymore on the second run?
  • "Attempted to log" looks different for me:
    image

@SimenB
Copy link
Member Author

SimenB commented Jan 27, 2019

I would definitely consider the exit code breaking, this might be a candidate for warn first, introduce exiting with 1 in a major

Sure

I think people might have a lot of these in some codebases, usually in the next 1 or 2 ticks after the test completes, so maybe we should come up with something that prevents flooding them with warnings?

I think yelling at them is better than silently dropping the messages (it won't show up in reporters or anything). And I also think it's fair to expect people to clean up from their tests before exiting - a failure to do so is IMO a bug in their code.

Tried this out locally, watch mode seems to not show the warnings anymore on the second run?

I didn't test in watch mode - I thought it'd work the same. Will have to dig into that

"Attempted to log" looks different for me:

Fixed

@SimenB
Copy link
Member Author

SimenB commented Jan 27, 2019

Added some color:

image

@jeysal I have no issues with watch mode...

image

Re-runs look the same

CHANGELOG.md Outdated Show resolved Hide resolved
@SimenB SimenB changed the title fix: print error and exit with status 1 if logging happens after teardown fix: print log entries if logging happens after teardown Jan 27, 2019
@SimenB SimenB force-pushed the no-console-after-teardown branch 2 times, most recently from d05b222 to 82b6231 Compare January 27, 2019 23:26
@SimenB
Copy link
Member Author

SimenB commented Jan 27, 2019

Not sure why this broke forceExit :(

@jeysal
Copy link
Contributor

jeysal commented Jan 28, 2019

Not sure why this broke forceExit :(

The forceExit test wants TIMER_DONE printed to stdout, but because the frozen console catches it, it only goes to stderr :)

BTW sorry, still didn't get around to reviewing properly, I'll try to do it tomorrow

@SimenB
Copy link
Member Author

SimenB commented Jan 29, 2019

Cool, makes sense. Fixed it (by just looking at stderr)

Copy link
Contributor

@jeysal jeysal 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 still not getting the warning sometimes, now even without --watch. Might just be overlooking something, but I'll have to investigate later

e2e/__tests__/forceExit.test.js Outdated Show resolved Hide resolved
@SimenB SimenB merged commit 0633a61 into jestjs:master Jan 29, 2019
@SimenB SimenB deleted the no-console-after-teardown branch January 29, 2019 16:11
@jeysal
Copy link
Contributor

jeysal commented Jan 29, 2019

Regarding the missing warnings in watch mode, it looks like this is just me hitting the console output issue, because even on master the actual console.log messages from the setTimeout go missing as well.

@SimenB
Copy link
Member Author

SimenB commented Jan 29, 2019

Oh, that's weird! I don't have that issue... If you could try to get a fix, that'd be awesome 🙂

@jeysal
Copy link
Contributor

jeysal commented Jan 29, 2019

It's super annoying to hunt down - it doesn't occur in --watch --runInBand

@jeysal
Copy link
Contributor

jeysal commented Jan 29, 2019

Do we perhaps kill workers while they still have the setTimeout in their queue? I'm not very familiar with the workers and their communication with the main process yet, but it seems to be related to the workers if it doesn't happen w/ runInBand.

@jeysal
Copy link
Contributor

jeysal commented Jan 29, 2019

It's definitely some gross race condition. setTimeout with 5ms is about the delay where it's printed on half of the runs and gets lost on the other half.

@jeysal
Copy link
Contributor

jeysal commented Jan 29, 2019

Do we perhaps kill workers while they still have the setTimeout in their queue?

Looks like this was the right idea. If I delay the worker cleanup in https://github.com/facebook/jest/blob/master/packages/jest-runner/src/index.js#L157,
it does not happen. I'll put it on my todo list for when I'm less tired to come up with something. Not sure if this is the exact thing that others who reported this bug saw though, this should only be for cases where logs happen after the tests have finished.

@SimenB
Copy link
Member Author

SimenB commented Jan 29, 2019

We can wait say 100-200ms before killing the worker without much issue. Best would be if we could query the worker if it's done or not though

@jeysal
Copy link
Contributor

jeysal commented Jan 29, 2019

Yep, that's what I had in mind. Looks like I'll finally get to dig deeper into the worker stuff then 😄

@jeysal
Copy link
Contributor

jeysal commented Mar 24, 2019

Best would be if we could query the worker if it's done or not though

FYI I looked into this for 1-2h today.
I implemented graceful exit for the worker with force exit after a delay if it fails to exit on its own. Still some work to do (e.g. I did not care about NodeThreadsWorker at all yet).
Can make jest-worker end() return a Promise, which would contain info how it exited so we can await that and print a warning if it had to force exit without using console in jest-worker itself. It's not even a breaking change because right now jest-worker doesn't guarantee either that the worker processes have exited when end() returns (and why should the user care about some leftover worker processes, as long as they will eventually exit).

@SimenB
Copy link
Member Author

SimenB commented Mar 24, 2019

I think that makes sense. @mjesun @rubennorte @scotthovestadt any reason not to make that change?

@scotthovestadt
Copy link
Contributor

Sounds good to me. Let's be extra-sure that the worker can't hang forever, though. :)

@jeysal jeysal mentioned this pull request Mar 24, 2019
7 tasks
captain-yossarian pushed a commit to captain-yossarian/jest that referenced this pull request Jul 18, 2019
@github-actions
Copy link

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 May 11, 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.

5 participants