fix(jest-worker): fix hanging when workers are killed or unexpectedly exit

[gluxon]

Summary

Fixes #13183.

Before

Before this change, if a Jest worker process is killed externally (e.g. through kill <PID>), the Jest test harness is never informed and the test runs forever. This happens even if a finite timeout (default 5s) is set.

For my team specifically, we were observing OOM-killer on Linux kill jest-worker processes and cause CI tests to hang forever. Since OOM-killer is included on all Linux distributions, I believe this bug affects any users of Jest on Linux.

This was difficult to root cause since there were no logs of the failure. Once we realized more memory was required on CI for our project, we bumped our container's memory limit. Previously hanging tests completed successfully from there.

After

After the change in this PR, the test above exits with an error. See https://github.com/gluxon/test-jest-worker-killed-repro for the source code of this repro.

Although the scenarios in which a jest-worker running in a thread (rather than a subprocess) exit unexpectedly are much rarer, this situation was handled as well in the PR for consistency.

Test plan

This change contains a new test. Before the fix, the test fails with:

Execution

❯ yarn jest WorkerEdgeCases
 FAIL  packages/jest-worker/src/workers/__tests__/WorkerEdgeCases.test.ts (23.206 s)
  ✓ workers/processChild.js should exist (1 ms)
  ✓ workers/threadChild.js should exist
  ✓ types.js should exist
  ProcessWorker
    ✓ should get memory usage (45 ms)
    ✓ should recycle on idle limit breach (652 ms)
    should automatically recycle on idle limit breach
      ✓ initial state (1 ms)
      ✓ new worker starts (71 ms)
      ✓ worker continues to run after kill delay (601 ms)
      ✓ expected state order (1 ms)
    should cleanly exit on out of memory crash
      ✓ starting state
      ✓ worker ready (1 ms)
      ✓ worker crashes and exits (127 ms)
      ✓ worker stays dead (3 ms)
      ✓ expected state order
    should handle regular fatal crashes
      ✓ starting state (1 ms)
      ✓ processes restart (4003 ms)
      ✓ processes exits (2 ms)
  ThreadWorker
    ✓ should get memory usage (75 ms)
    ✓ should recycle on idle limit breach (644 ms)
    should automatically recycle on idle limit breach
      ✓ initial state
      ✓ new worker starts (69 ms)
      ✓ worker continues to run after kill delay (601 ms)
      ✓ expected state order (1 ms)
    should cleanly exit on out of memory crash
      ✓ starting state (1 ms)
      ✓ worker ready
      ✓ worker crashes and exits (137 ms)
      ✓ worker stays dead
      ✓ expected state order
    should handle regular fatal crashes
      ✓ starting state (1 ms)
      ✓ processes restart (4002 ms)
      ✓ processes exits (2 ms)
  should not hang on external process kill
    ✕ onEnd callback is called (10505 ms)

  ● should not hang on external process kill › onEnd callback is called

    thrown: "Exceeded timeout of 10000 ms for a test.
    Use jest.setTimeout(newTimeout) to increase the timeout value, if this is a long-running test."

      at test (packages/jest-worker/src/workers/__tests__/WorkerEdgeCases.test.ts:421:3)

Test Suites: 1 failed, 1 total
Tests:       1 failed, 31 passed, 32 total
Snapshots:   0 total
Time:        23.351 s
Ran all test suites matching /WorkerEdgeCases/i.

After the fix, the test passes:

❯ yarn jest WorkerEdgeCases

> @jest/[email protected] jest /Users/gluxon/Developer/jest
> node ./packages/jest-cli/bin/jest.js "WorkerEdgeCases"

 PASS  packages/jest-worker/src/workers/__tests__/WorkerEdgeCases.test.ts (13.28 s)
  ✓ workers/processChild.js should exist
  ✓ workers/threadChild.js should exist
  ✓ types.js should exist
  ProcessWorker
    ✓ should get memory usage (44 ms)
    ✓ should recycle on idle limit breach (649 ms)
    should automatically recycle on idle limit breach
      ✓ initial state (2 ms)
      ✓ new worker starts (80 ms)
      ✓ worker continues to run after kill delay (601 ms)
      ✓ expected state order (1 ms)
    should cleanly exit on out of memory crash
      ✓ starting state
      ✓ worker ready (1 ms)
      ✓ worker crashes and exits (141 ms)
      ✓ worker stays dead (4 ms)
      ✓ expected state order
    should handle regular fatal crashes
      ✓ starting state (1 ms)
      ✓ processes restart (4007 ms)
      ✓ processes exits (3 ms)
  ThreadWorker
    ✓ should get memory usage (78 ms)
    ✓ should recycle on idle limit breach (644 ms)
    should automatically recycle on idle limit breach
      ✓ initial state (1 ms)
      ✓ new worker starts (91 ms)
      ✓ worker continues to run after kill delay (601 ms)
      ✓ expected state order
    should cleanly exit on out of memory crash
      ✓ starting state
      ✓ worker ready
      ✓ worker crashes and exits (141 ms)
      ✓ worker stays dead
      ✓ expected state order (1 ms)
    should handle regular fatal crashes
      ✓ starting state (1 ms)
      ✓ processes restart (4003 ms)
      ✓ processes exits (2 ms)
  should not hang on external process kill
    ✓ onEnd callback is called (588 ms)

Test Suites: 1 passed, 1 total
Tests:       32 passed, 32 total
Snapshots:   0 total
Time:        13.45 s, estimated 24 s
Ran all test suites matching /WorkerEdgeCases/i.

[gluxon]

Note that this else branch has gone through several changes in the past.

• This PR added a check for signal === "SIGABRT": fix: when an out of memory event occurs process should exit correctly #13054
• But was removed in a followup PR feat: add workerIdleMemoryLimit to support worker recycling in the event of node >16.11.0 memory leaks #13056

[gluxon]

I observed a few tests within Jest fail without the isRequestStillPending check here. I don't believe this can happen in practice since instances of jest-worker are usually jest-runner, which is always sent a request. Some fixture workers in jest-worker appear to work differently.

Kept the check just in case. It felt safer to only throw an error in situations we're certain something went wrong.

❯ yarn jest WorkerEdgeCases
 FAIL  packages/jest-worker/src/workers/__tests__/WorkerEdgeCases.test.ts (32.687 s)
  ✓ workers/processChild.js should exist (1 ms)
  ✓ workers/threadChild.js should exist
  ✓ types.js should exist
  ProcessWorker
    ✕ should get memory usage (10003 ms)
    ✕ should recycle on idle limit breach (10001 ms)
    should automatically recycle on idle limit breach
      ✓ initial state (2 ms)
      ✓ new worker starts (86 ms)
      ✓ worker continues to run after kill delay (604 ms)
      ✓ expected state order (1 ms)
    should cleanly exit on out of memory crash
      ✓ starting state
      ✓ worker ready
      ✓ worker crashes and exits (136 ms)
      ✓ worker stays dead (3 ms)
      ✓ expected state order
    should handle regular fatal crashes
      ✓ starting state (1 ms)
      ✓ processes restart (4002 ms)
      ✓ processes exits (2 ms)
  ThreadWorker
    ✓ should get memory usage (74 ms)
    ✓ should recycle on idle limit breach (646 ms)
    should automatically recycle on idle limit breach
      ✓ initial state (1 ms)
      ✓ new worker starts (71 ms)
      ✓ worker continues to run after kill delay (603 ms)
      ✓ expected state order (2 ms)
    should cleanly exit on out of memory crash
      ✓ starting state (1 ms)
      ✓ worker ready (1 ms)
      ✓ worker crashes and exits (144 ms)
      ✓ worker stays dead (1 ms)
      ✓ expected state order
    should handle regular fatal crashes
      ✓ starting state (1 ms)
      ✓ processes restart (4002 ms)
      ✓ processes exits (1 ms)
  should not hang on external process kill
    ✓ onEnd callback is called (584 ms)

  ● ProcessWorker › should get memory usage

    TypeError: this._onProcessEnd is not a function

      at ChildProcessWorker._onProcessEnd [as _onExit] (packages/jest-worker/src/workers/ChildProcessWorker.ts:410:12)

  ● ProcessWorker › should get memory usage

    thrown: "Exceeded timeout of 10000 ms for a test.
    Use jest.setTimeout(newTimeout) to increase the timeout value, if this is a long-running test."

      at test (packages/jest-worker/src/workers/__tests__/WorkerEdgeCases.test.ts:111:3)
          at Array.forEach (<anonymous>)

  ● ProcessWorker › should recycle on idle limit breach

    TypeError: this._onProcessEnd is not a function

      at ChildProcessWorker._onProcessEnd [as _onExit] (packages/jest-worker/src/workers/ChildProcessWorker.ts:410:12)

  ● ProcessWorker › should recycle on idle limit breach

    thrown: "Exceeded timeout of 10000 ms for a test.
    Use jest.setTimeout(newTimeout) to increase the timeout value, if this is a long-running test."

      at test (packages/jest-worker/src/workers/__tests__/WorkerEdgeCases.test.ts:127:3)
          at Array.forEach (<anonymous>)

Test Suites: 1 failed, 1 total
Tests:       2 failed, 30 passed, 32 total
Snapshots:   0 total
Time:        32.854 s
Ran all test suites matching /WorkerEdgeCases/i.

[gluxon]

While we can reasonably guess when the Node.js internal max heap limit has been hit, it's difficult to guess other failure scenarios from exitCode and signal.

There was a previous discussion of this in the linked issue: #13183 (comment)

I feel propagating an error in the else block is the best way to handle unknown situations.

[SimenB]

great stuff! I guess this doesn't apply to the worker threads version as that doesn't have any subprocesses that can be killed "out of band"?

[gluxon]

I wonder if there's a better design pattern to guarantee this._request is handled in some manner. At the moment this happens through a difficult to follow sequence:

1. The this._onMessage method calls this._onProcessEnd. https://github.com/facebook/jest/blob/a0703c94936e2459ae8600a30895da6f6b8b05de/packages/jest-worker/src/workers/ChildProcessWorker.ts#L262-L263
2. The this._onProcessEnd method sets this._request to null. It can reasonably do this since the child process sent a successful response. https://github.com/facebook/jest/blob/a0703c94936e2459ae8600a30895da6f6b8b05de/packages/jest-worker/src/workers/ChildProcessWorker.ts#L432-L434

The this._onMessage has several cases that may or may not call this._onProcessEnd. Without better guarantees, it's possible a refactor of this class in the future reintroduces the bug.

[SimenB]

happy to take a follow-up if you figure out a better pattern for this. But I think it's fine as is as well

[gluxon]

great stuff! I guess this doesn't apply to the worker threads version as that doesn't have any subprocesses that can be killed "out of band"?

Exactly! Thanks for the fast review btw.

[gluxon]

I guess this doesn't apply to the worker threads version as that doesn't have any subprocesses that can be killed "out of band"?

Hm... I'm thinking this through a bit more and wonder if it's still worth applying the same logic. In theory someone might test a segment of code that unexpectedly calls process.exit(), which exits the current jest-worker thread.

To double check, I switched the default from ?? false to ?? true
https://github.com/facebook/jest/blob/50bab21a8e88215061228e4197bfe632a529692c/packages/jest-worker/src/index.ts#L97

And edited the repro to use process.exit():

import { wait } from "./utils/wait";

test("jest-worker exit", async () => {
    await wait(2_000);
}, 3_000);

setTimeout(() => {
    // Exits the thread and not the process in a worker thread environment
    process.exit()
}, 1_000);

I'm guessing it's probably better to do:

Going to commit that now and update the PR.

[gluxon]

Handling the case of process.exit() being called in testing code with enableWorkerThreads set to true here: f274baf

This actually simplifies the new WorkerEdgeCases test. I moved the test into the describe block iterating over ChildProcessWorker and NodeThreadsWorker. The NodeThreadsWorker was failing the test before the mentioned commit.

[SimenB]

Nice! 👍

[gluxon]

Thanks for the fast review and maintaining Jest @SimenB! ❤️

[jeysal]

Whoops, I'm late for reviewing. Anyway, looks solid from a quick glimpse

[SimenB]

https://github.com/facebook/jest/releases/tag/v29.3.0

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