Jest RANDOMBYTESREQUEST

[guiaramos]

Describe the bug

uuid is not allowing jest to exit:

Jest has detected the following 1 open handle potentially keeping Jest from exiting:

  ●  RANDOMBYTESREQUEST

      3 | import { UserAuth } from 'src/auth/dto/user.jwt';
      4 | 
    > 5 | export const CurrentUser = createParamDecorator(
        |                            ^
      6 |   (data: unknown, context: ExecutionContext): UserAuth => {
      7 |     const ctx = GqlExecutionContext.create(context);
      8 |     return ctx.getContext().req.user;

      at rng (node_modules/uuid/dist/rng.js:18:21)
      at Object.v4 (node_modules/uuid/dist/v4.js:17:63)
      at Object.createParamDecorator (node_modules/@nestjs/common/decorators/http/create-route-param-metadata.decorator.js:14:30)
      at Object.<anonymous> (src/common/guards/current-user.guard.ts:5:28)

the error is located on

uuid/src/rng.js

Line 8 in 91805f6

crypto.randomFillSync(rnds8Pool);

How to reproduce

on a Nestjs server just execute:

jest --runInBand --detectOpenHandles

Expected behavior

exit jest without open handlers

Runtime

• OS: macOs
• Runtime: Node.js
• Runtime Version: v15.6.0

Additional information

https://stackoverflow.com/questions/66958699/jest-open-handle-randombytesrequest-on-nestjs-graphql

[broofa]

Weird. I guess Jest is using async_hooks to track async tasks and complaining when one fails to end. But uuid is, on the surface, not async. As shown in your trace, we're calling randomFillSync().

That said, the async_hooks module does mention RANDOMBYTESREQUEST as one of the hook types. Generating cryptographic-quality RNGs is a non-trivial process and relies on the underlying OS to provide a certain amount of entropy. There may be something going on in the internals of node on your system that's causing it to block for some reason(???)

Without a reproducible test case, I don't think this is actionable. If you want to reduce it down to a Minimal, Complete, and Verifiable example, I or one of the other contributors might be able to take a look, though.

[guiaramos]

you can check on this repo:
https://github.com/guiaramos/nestj-jest-failing

just do npm i and npm t

[broofa]

Note the "Minimal" part of "Minimal, Complete, and Verifiable example". Your repo is installing 1,500+ modules 😕 . And, as I think was noted in that other issue, this is more an integration test than a unit test, so makes for a rather complex environment.

Also, when I try running this on Repl.it, it runs out of memory. See https://replit.com/@broofa/nestj-jest-failing. So I'm not particularly inclined to investigate this further at this time.

If you want us to pursue this, I suggest you par your test case down to something that can be reproduced on Repl.it. Ideally a single script that requires just ('uuid') and any node-internal modules that might be needed. Failing that, delete any/all code and dependencies that aren't absolutely necessary to reproduce the issue. Maybe look into what Jest is doing to track open handles, and use that to further reduce the overhead?

[piranna]

I found myself this issue last week, and found some more info at https://stackoverflow.com/questions/65653226/jest-and-randombytesrequest-open-handles. Seems like an issue related with latests versions of Node.js.

[ctavan]

@jasnell I think you have made lots of significant contributions to Node.js crypto recently, do you have any pointers regarding the issue described above?

[jasnell]

Yeah there were recently some changes in this area that may be causing this. I'll investigate this morning. randomFillSync uses the same underlying mechanism as randomFill but invokes it synchronously. It's supposed to be marked weak so gc can clean it up immediately after but this error suggests that might not be happening so that's where I'll look first.

[broofa]

FWIW I put together this test yesterday to see if randomFillSync() was triggering any async hooks, but didn't see anything because I was using node@14. (Failed to note @guiaramos was on node@15, dooh!)

'Tried it again on node@15 this morning after seeing @jasnell's comments and (surprise!) it shows an async task being generated.

---

$ cat randomFillSync_test.js
const async_hooks = require('async_hooks');
const crypto = require('crypto');
const fs = require('fs');
const util = require('util');

// Sync console.log (avoids "Maximum call stack size exceeded error")
function debug(...args) {
  fs.writeFileSync(1, `${util.format(...args)}\n`, { flag: 'a' });
}

const asyncHook = async_hooks.createHook({
  init: debug.bind(null, 'INIT'),
});

asyncHook.enable();

const buf = Buffer.alloc(10);
crypto.randomFillSync(buf)

asyncHook.disable();

$ nvm use 14
Now using node v14.16.1 (npm v6.14.12)

$ node randomFillSync_test.js

$ nvm use 15
Now using node v15.14.0 (npm v7.7.6)

$ node randomFillSync_test.js
INIT 2 RANDOMBYTESREQUEST 1 RandomBytesJob {}

---

[When your fellow contributors once again "just know"...]

[jasnell]

Ok, so I just confirmed that randomFillSync() is definitely setting the weak flag on the underlying object and is getting cleaned up on gc(). It's possible, however, possibly depending on how jest is tracking things, that a reference could be getting retained somewhere that's not allowing gc to clean it up.

Here's the sample code I'm using to check:

const { createHook } = require('async_hooks')

const { randomFillSync } = require('crypto');

const set = new Set();

const hook = createHook({
  init(id, type) {
    process._rawDebug(type);
    if (type === 'RANDOMBYTESREQUEST') {
      set.add(id);
      process._rawDebug(`init ${id} ${type}`);
    }
  },
  destroy(id) {
    if (set.has(id)) {
      process._rawDebug(`destroy ${id}`);
      set.delete(id);
    }
  }
});

hook.enable();

const buf = new Uint8Array(10);

randomFillSync(buf);

gc();

Run this with the --expose-gc flag in Node.js 15+

You should see:

RANDOMBYTESREQUEST
init 2 RANDOMBYTESREQUEST
destroy 2

To explain a bit about what's happening under the covers here: All of the randomFill()/randomFillSync()/randomBytes() variants use the same underlying RandomBytesRequest object under the covers. When running in async mode, this object is marked strong (which means gc won't automatically clean it up), and the random bytes are generated in the libuv threadpool. The object is destroyed once the async callback is invoked. When running sync mode, the object is marked weak (which means gc will clean it up and destroy it as soon as there are no longer any strong references to it). Within Node.js internals, for randomFillSync(), the only strong reference we retain on the request object is scoped within the function itself. That said, RandomBytesRequest (whether invoked synchronously or asynchronously) is an "async wrap" object, which means that it will be recorded by async_hooks regardless of how it is invoked. Calling randomFillSync() will immediately trigger an async_hooks init() callback. If the request is async, the corresponding destroy() callback will trigger after the async callback is invoked. If the request is sync, the corresponding destroy() callback will trigger after the object is garbage collected. If the async_hook retains a strong reference to the weak async object then, it will never be garbage collected, and therefore will never be destroyed. I can't say for sure that's what jest is doing but I'm not familiar with whatever mechanism they are using to track so I can't say for sure.

[broofa]

I've created the above issue with the Jest project and am going to close this out, as it's pretty clear at this point that the issue lies outside our (uuid) codebase.

[broofa]

@jasnell As always, we appreciate your prompt and insightful help on this!

[guiaramos]

Sorry for the large repo @broofa, and ty guys for the help!

[jasnell]

we appreciate your prompt and insightful help on this!

Any time, happy to help :-)