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

Repository.open doesn't resolve in some cases #1679

Open
Means88 opened this issue May 22, 2019 · 10 comments
Open

Repository.open doesn't resolve in some cases #1679

Means88 opened this issue May 22, 2019 · 10 comments

Comments

@Means88
Copy link

Means88 commented May 22, 2019

System information

  • node version: 10.15.3
  • npm or yarn version: yarn 1.9.4
  • OS/version/architecture: macOS (Darwin bogon 18.0.0 Darwin Kernel Version 18.0.0: Wed Aug 22 20:13:40 PDT 2018; root:xnu-4903.201.2~1/RELEASE_X86_64 x86_64)
  • Applicable nodegit version: 0.24.3

Here is the example: https://github.com/Means88/nodegit-test

It contains 5 same tests

it('should pass', async () => {
  await nodegit.Repository.open(
    path.resolve(__dirname, '..', 'repo', '.git'),
  );
}, 10000);
git init repo
yarn test

yarn run v1.9.4
$ jest
 PASS  test/second.test.ts
 PASS  test/fifth.test.ts
 PASS  test/first.test.ts
 FAIL  test/third.test.ts (10.176s)
  ● third test › should pass

    Timeout - Async callback was not invoked within the 10000ms timeout specified by jest.setTimeout.

      3 | 
      4 | describe('third test', () => {
    > 5 |   it('should pass', async () => {
        |   ^
      6 |     await nodegit.Repository.open(
      7 |       path.resolve(__dirname, '..', 'repo', '.git'),
      8 |     );

      at Spec (node_modules/jest-jasmine2/build/jasmine/Spec.js:85:20)
      at Suite.<anonymous> (test/third.test.ts:5:3)

 FAIL  test/fourth.test.ts (10.167s)
  ● first test › should pass

    Timeout - Async callback was not invoked within the 10000ms timeout specified by jest.setTimeout.

      3 | 
      4 | describe('first test', () => {
    > 5 |   it('should pass', async () => {
        |   ^
      6 |     await nodegit.Repository.open(
      7 |       path.resolve(__dirname, '..', 'repo', '.git'),
      8 |     );

      at Spec (node_modules/jest-jasmine2/build/jasmine/Spec.js:85:20)
      at Suite.<anonymous> (test/first.test.ts:5:3)

----------|----------|----------|----------|----------|-------------------|
File      |  % Stmts | % Branch |  % Funcs |  % Lines | Uncovered Line #s |
----------|----------|----------|----------|----------|-------------------|
All files |  Unknown |  Unknown |  Unknown |  Unknown |                   |
----------|----------|----------|----------|----------|-------------------|
Test Suites: 2 failed, 3 passed, 5 total
Tests:       2 failed, 3 passed, 5 total
Snapshots:   0 total
Time:        12.219s
Ran all test suites.
error Command failed with exit code 1.
info Visit https://yarnpkg.com/en/docs/cli/run for documentation about this command.

And if I run jest with yarn test --maxWorkers 4, there will be 4 test cases passed and 1 test case failed. But it will pass if I open the repository several times in one test case like

it('should pass', async () => {
  await nodegit.Repository.open(
    path.resolve(__dirname, '..', 'repo', '.git'),
  );
  await nodegit.Repository.open(
    path.resolve(__dirname, '..', 'repo', '.git'),
  );
}, 10000);

Maybe there are something like mutex lock and didn't clean up after test? I've tried enableThreadSafety and setThreadSafetyStatus but nothing changed.

@Means88
Copy link
Author

Means88 commented May 22, 2019

It works well with mocha

➜ yarn mocha -r ts-node/register test/**/*.test.ts
yarn run v1.9.4


  fifth test
    ✓ should pass

  first test
    ✓ should pass

  first test
    ✓ should pass

  second test
    ✓ should pass

  third test
    ✓ should pass


  5 passing (21ms)

✨  Done in 2.49s.

@julienvincent
Copy link

julienvincent commented Jun 16, 2019

I am getting this same issue. Repository.init or Repository.open hang indefinitely when run in a jest test suite. Only happens when there are more than one test() using nodegit

Could not consistently reproduce on my MacBook, but can consistently (100%) reproduce within a node docker container running version 10 or 11.

Anyone manage to resolve this?

@JoostK
Copy link

JoostK commented Aug 20, 2019

This is caused by jestjs/jest#3552. I recently experienced the same problem after adding a 9th testsuite on a quad-core hyperthreaded machine, therefore having 8 threads, and that let me down the rabbit hole.

In the end we managed to find the culprit and I now fully understand why this issue occurs. First some context on how Jest works, as it is relevant in understanding the problem.

Explanation

Jest has its own module resolution logic to support mocking modules, and it evicts the module caches between running testsuites. By default, it will spawn N processes, with N being equal to the number of threads you have available. Therefore, as long as there's fewer testsuites than the number of threads, each process runs only a single testsuite. Once you start having more testsuites than threads, or run Jest with the --runInBand option to prevent forking child processes, some of the processes may need to run multiple testsuites. Since Jest's module loader evicts its module caches between testsuites, the nodegit JavaScript module is unloaded with it. However, the native nodegit binary is not unloaded, as Jest cannot influence native modules.

Unfortunately, the initial load of the nodegit JavaScript module has affected the state of the native module. There's some work being done to alleviate this problem, but it doesn't appear to work (anymore):

// For disccussion on why `cloneDeep` is required, see:
// https://github.com/facebook/jest/issues/3552
// https://github.com/facebook/jest/issues/3550
// https://github.com/nodejs/node/issues/5016
rawApi = _.cloneDeep(rawApi);

What I found is that this nodegit.js file modifies the native functions to become promise based instead of callback based, using promisify. The result of the function call ends up being written into the native module. The _.cloneDeep does not prevent this from happening, as the result of promisify is written into properties on functions, which are not eligible for deep cloning.

Now, when Jest loads the nodegit JavaScript module again it will execute that nodegit.js file once again. This time however, the functions in the native module that it promisifies have already been promisified before, resulting in repeated promisification (lovely word, if it even is one 😄). I don't know exactly what happens from there, but the double promisified function will fail to resolve. It looks like https://github.com/nodegit/promisify-node gets into a state that it doesn't expect, leading to a dead end.

Workarounds

I found essentially two workarounds for the issue, as follows:

  1. Make Jest believe that the nodegit JavaScript module is actually a builtin module. This prevents Jest from using its own module resolution logic and module cache, so nodegit won't be loaded multiple times.

There doesn't appear to be any configuration options to achieve this, it requires a patch inside of node_modules/jest-resolve/build/isBuiltinModule.js:

- const EXPERIMENTAL_MODULES = ['worker_threads'];
+ const EXPERIMENTAL_MODULES = ['worker_threads', 'nodegit'];
  1. [No longer works since Jest 25.2.0 due to feat: override module.createRequire jestjs/jest#9469] Sidestep Jest's module loader for the nodegit module. For this, you'll need to register a Jest setup script in your Jest configuration file:
setupFilesAfterEnv: ['./jest.setup.js'],

Then, create the jest.setup.js file with the following script:

// In order to patch jest's Runtime class, we need to require it using NodeJS's require function, *not* the require
// function that is provided by jest here. The reason is that using jest's require will load the Runtime code a second
// time, so that we won't get a reference to the actual instance that needs to be patched. Since jest does not expose
// any API to obtain the native NodeJS require function, we load the native "module" module instead that allows us to
// create a native NodeJS require function. Mind is blown!
const Module = require('module');
const nativeRequire = Module.createRequireFromPath(__filename);

const jestRuntime = nativeRequire('jest-runtime');

if (!jestRuntime.prototype.__nodegit_patched) {
    jestRuntime.prototype.__nodegit_patched = true;

    const originalRequireModule = jestRuntime.prototype.requireModule;
    jestRuntime.prototype.requireModule = function(from, moduleName) {
        // When requiring the "nodegit" module, sidestep jest's module system as it would cause nodegit to be loaded
        // multiple times (once per test file), corrupting the bound functions to native code.
        // See https://github.com/facebook/jest/issues/3552
        if (moduleName === 'nodegit') {
            return nativeRequire('nodegit');
        }

        return originalRequireModule.apply(this, arguments);
    };
}

Essentially what this does is patch the Jest runtime to rewire module resolution to the native NodeJS module loader, but only if the module to load is nodegit.

Disclaimer

With both workarounds, you'll end up in a situation where nodegit has a different module loader compared to the rest of your test code. For us this meant that e.g. Date instances created within nodegit were no longer matching with Date instances in the testcases, so assertions like jasmine.any(Date) would now fail. We didn't look into this but simply changed the assertion to jasmine.anything() as that will avoid the issue, while being a little less strict.

Wrapping up

I suspect that from the nodegit side of things, it should be possible to no longer write the promisified functions into the native module. That would avoid this problem, although I don't really understand the current way of how nodegit.js is structured so there could be reasons why that wouldn't be possible.

From the Jest side of the equation, I think it could be very valuable to be able to configure the module loader in some ways. Either its module loader should be able to disable altogether, or it should be possible for specific modules to sidestep its module loader.

Bottom line, this was one of the most annoying bugs I have ever had to debug. I haven't had the time to report issues, if anyone feels like doing so please feel free to link to this post.

@bhubr
Copy link

bhubr commented Jan 2, 2020

@JoostK Thank you so much for the thorough break-down of this bug. It took me forever to track down that my test suite was hanging on a repo init, and once I found the culprit, I wouldn't have guessed how to solve it, by far.
Btw, sorry if it's kind of a noob question, do you know a means to find which precise bit of code makes a Jest test suite hang?
Thanks again, cheers!

@JoostK
Copy link

JoostK commented Jan 3, 2020

Btw, sorry if it's kind of a noob question, do you know a means to find which precise bit of code makes a Jest test suite hang?

@bhubr It's not Jest that is hanging, it's somewhere in the nodegit-promise library. What I found during debugging was that the double promisification seems to introduce some internal state that causes the promise resolution to get stuck. I don't know the exact details as I'm not really familiar with its internals.

I wouldn't have guessed how to solve it, by far.

Oh well, this took me 4 hours to figure out and fix so it was a pretty deep rabbit hole.

williamthorsen added a commit to skypilot-dev/nodegit-tools that referenced this issue May 3, 2021
Three unit tests were frequently timing out, for reasons possibly documented in nodegit/nodegit#1679.

Changed these tests to integration tests to avoid CI failures. They can be run selectively instead.
williamthorsen added a commit to skypilot-dev/nodegit-tools that referenced this issue May 3, 2021
Three unit tests were frequently timing out, for reasons possibly documented in nodegit/nodegit#1679.

Changed these tests to integration tests to avoid CI failures. They can be run selectively instead.
williamthorsen added a commit to skypilot-dev/nodegit-tools that referenced this issue May 3, 2021
Three unit tests were frequently timing out, for reasons possibly documented in nodegit/nodegit#1679.

Changed these tests to integration tests to avoid CI failures. They can be run selectively instead.
williamthorsen added a commit to skypilot-dev/nodegit-tools that referenced this issue May 3, 2021
Three unit tests were frequently timing out, for reasons possibly documented in nodegit/nodegit#1679.

Changed these tests to integration tests to avoid CI failures. They can be run selectively instead.
@tommoor
Copy link

tommoor commented May 25, 2021

I've been banging my head against this for a few hours now, unfortunately the workarounds suggested don't seem to work any more. In todays version of jest that monkey patch is never called.

I thought I could mock my way around this by mocking out nodegit-promise because all of the functionality it provides is available in node native now but even with a fully mocked nodegit-promise the problem persists 😢

@JoostK
Copy link

JoostK commented May 25, 2021

@tommoor Yeah, the createRequire workaround broke due to jestjs/jest#9469, which the workaround was actively exploiting to break out of the sandbox. We have switched to the first workaround I described (patching EXPERIMENTAL_MODULES) which continues to work.

@tommoor
Copy link

tommoor commented Jun 3, 2021

@JoostK you have a private fork of Jest just for this? 😭

@JoostK
Copy link

JoostK commented Jun 3, 2021

@JoostK you have a private fork of Jest just for this? 😭

Nope just patching node_modules in a postinstall hook (not using Yarn pnp nor pnpm)

@tommoor
Copy link

tommoor commented Jun 3, 2021

I see, thank you, unfortunately this workaround doesn't seem to work when setting rootDirs config as it's unable to resolve the module in the child root directory (which makes sense)…

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

5 participants