[heft] Heft clean fails with ENOTEMPTY due to lingering Jest subprocesses

octogonz commented 3 years ago

Summary

When Heft is terminated using CTRL+C, Jest subprocesses sometimes linger and interfere with future operations.

Repro steps

# Start Heft
$ heft test --clean

# press CTRL+C, then immediately afterwards invoke this command
$ heft test --clean --debug

Our users report that occasionally they will see an error like this:

. . .
Starting test
[TypeScript Plugin] Config file "/path/to/my-project/config/typescript.json" does not exist. Attempting to load via rig.
 ---- Clean started ----
[delete-globs] Config file "/path/to/my-project/config/heft.json" does not exist. Attempting to load via rig.
[delete-globs] Deleted folder "/path/to/my-project/lib-commonjs"
[delete-globs] Deleted folder "/path/to/my-project/dist"
[delete-globs] Deleted folder "/path/to/my-project/lib"
[delete-globs] Deleted folder "/path/to/my-project/temp"
 ---- Clean encountered an error (10022ms) ----
-------------------- Finished (18.946s) --------------------
Project: @hbo/hbomax-dataservices-content@0.0.0
Heft version: 0.30.2
Node version: v12.17.0
Error: ENOTEMPTY: directory not empty, rmdir '/path/to/my-project/.heft/build-cache/jest-cache/jest-transform-cache-0eae658f6b074ec5d72ad887a12ed0b2-f8238a99880aac6151736010e575fab1'
Error: ENOTEMPTY: directory not empty, rmdir '/path/to/my-project/.heft/build-cache/jest-cache/jest-transform-cache-0eae658f6b074ec5d72ad887a12ed0b2-f8238a99880aac6151736010e575fab1'
    at Object.rmdirSync (fs.js:843:3)
    at rmkidsSync (/path/to/my-rush-repo/common/temp/node_modules/.pnpm/fs-extra@7.0.1/node_modules/fs-extra/lib/remove/rimraf.js:308:25)
    at rmdirSync (/path/to/my-rush-repo/common/temp/node_modules/.pnpm/fs-extra@7.0.1/node_modules/fs-extra/lib/remove/rimraf.js:281:7)
    at rimrafSync (/path/to/my-rush-repo/common/temp/node_modules/.pnpm/fs-extra@7.0.1/node_modules/fs-extra/lib/remove/rimraf.js:252:7)
    at /path/to/my-rush-repo/common/temp/node_modules/.pnpm/fs-extra@7.0.1/node_modules/fs-extra/lib/remove/rimraf.js:291:39
    at Array.forEach (<anonymous>)
    at rmkidsSync (/path/to/my-rush-repo/common/temp/node_modules/.pnpm/fs-extra@7.0.1/node_modules/fs-extra/lib/remove/rimraf.js:291:26)
    at rmdirSync (/path/to/my-rush-repo/common/temp/node_modules/.pnpm/fs-extra@7.0.1/node_modules/fs-extra/lib/remove/rimraf.js:281:7)
    at Object.rimrafSync (/path/to/my-rush-repo/common/temp/node_modules/.pnpm/fs-extra@7.0.1/node_modules/fs-extra/lib/remove/rimraf.js:252:7)
    at /path/to/my-rush-repo/common/temp/node_modules/.pnpm/@rushstack+node-core-library@3.37.0/node_modules/@rushstack/node-core-library/lib/FileSystem.js:320:17
The script failed with exit code 1

Details

Possible fixes:

More aggressively terminate Jest subprocesses when Heft terminates.
Make heft clean more robust for this scenario.

The .heft/build-cache/jest-cache/ folder gets registered for heft clean by this code:

https://github.com/microsoft/rushstack/blob/78aa5aded8051d9f38e8cf0d1513f20707edc54a/apps/heft/src/plugins/JestPlugin/JestPlugin.ts#L143-L152

The race condition happens like this:

When you press CTRL+C, the Heft process finishes, but one of the Jest subprocesses continues running in the background.
When you redo rushx build, Heft's Jest plugin tries to delete the .heft/build-cache/jest-cache/ folder using FileSystem.deleteFolderAsync(). For each subfolder, it first deletes all the contents, then tries to delete the subfolder itself.
But in the middle of that, the old Jest subprocess writes a new file in the folder. So we get an ENOTEMPTY error because the folder is not empty.

Note that the FileSystem.js callstack is truncated because some code is still using promises instead of async /await. We should fix that if possible.

Standard questions

Please answer these questions to help us investigate your issue more quickly:

Question	Answer
`@rushstack/heft` version?	0.30.2
Operating system?	Mac
Node.js version (`node -v`)?	v12.17.0

octogonz commented 3 years ago

I bet that this will be fixed by the improved subprocess management in PR https://github.com/microsoft/rushstack/pull/2717

octogonz commented 3 years ago

PR #2717 did not fix the problem. :-/

iclanton commented 3 years ago

Does Jest give us its subprocess PIDs? Wonder if we can just aggressively kill those.

microsoft / rushstack