fix: print log entries if logging happens after teardown

[SimenB]

Summary

Ref #3853

With this test:

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

Before this PR:

After this PR:

Test plan

Integration test added

[jeysal]

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:
  

[SimenB]

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]

Added some color:

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

Re-runs look the same

[SimenB]

Not sure why this broke forceExit :(

[jeysal]

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]

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

[jeysal]

I'm still not getting the warning sometimes, now even without --watch. Might just be overlooking something, but I'll have to investigate later

[jeysal]

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]

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

[jeysal]

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

[jeysal]

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]

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]

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]

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]

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

[jeysal]

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]

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

[scotthovestadt]

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

[github-actions]

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.