feat(async_hooks/timers): experimental support async_hooks module and timers module improvements

[nabetti1720]

Issue # (if available)

Fixed: #965 Related: #969

Description of changes

Experimental support for async_hooks compatible with nodejs.

It was created with the following module use cases in mind:

• OpenTelemetry async_hooks-based Context Managers
• aws-xray-sdk-node

Experimental support async_hooks :

• We will make our best effort, but don't expect behavior to match nodejs.
• It uses the new quickjs Promise Hook API, inspired by V8. The Promise Hook API supports init, before, after, and promiseResolve for Promise objects.
• The destroy event makes use of the FinalizationRegistry, a standard built-in object.
• Currently the only supported types are PROMISE, GETADDRINFOREQWRAP, Microtask, Immeditate, Interval and Timeout. The timing of firing events other than PROMISE is implemented independently by LLRT.

timers module improvements :

• queueMicrotask() has been reimplemented on the LLRT side to support asynchronous hooks. Internally, it simply registers the microtask in the queue, which is the same as the implementation method in quickjs-ng. However, before/after hooks cannot currently be detected.
• Previously, setImmediate() registered a task in a microtask queue, but we were replaced it with an implementation equivalent to setTimeout(fn, -86400). In other words, it will be treated as having been completed before setTimeout(fn, 0). Combined with the PR #969, this will bring the execution order of asynchronous timer operations into full agreement with other runtimes.

The current implementation allows you to execute code like this:

async_hook_test.js

const async_hooks = require('async_hooks');

let indent = 0;

async_hooks.createHook({
init(asyncId, type, triggerAsyncId) {
  const space = ' '.repeat(indent);
  console.log(`${space}init: asyncId=${asyncId}, type=${type}, triggerAsyncId=${triggerAsyncId}`);
},
before(asyncId) { 
  const space = ' '.repeat(indent);
  console.log(`${space}before: asyncId=${asyncId}`);
  indent += 2;
},
after(asyncId) {
  indent -= 2;
  const space = ' '.repeat(indent);
  console.log(`${space}after: asyncId=${asyncId}`);
},
destroy(asyncId) {
  const space = ' '.repeat(indent);
  console.log(`${space}destroy: asyncId=${asyncId}`);
},
promiseResolve(asyncId) {
  const space = ' '.repeat(indent);
  console.log(`${space}promiseResolve: asyncId=${asyncId}`);
}
}).enable();

function delay(ms, value) {
return new Promise((resolve) => {
  setTimeout(() => resolve(value), ms);
});
}

async function test() {
console.log(">>> 1. Promise.resolve");
await Promise.resolve("resolved!");
console.log("---");

console.log(">>> 2. Promise.reject w/catch");
await Promise.reject("error!").catch((e) => console.log("Caught:", e));
console.log("---");

console.log(">>> 3. Promise.all");
await Promise.all([delay(10, 1), delay(20, 2)]);
console.log("---");

console.log(">>> 4. Promise.race");
await Promise.race([delay(30, "A"), delay(10, "B")]);
console.log("---");

console.log(">>> 5. normal new Promise");
await new Promise((resolve) => {
    setTimeout(() => resolve("done"), 15);
});
console.log("---");

console.log(">>> 6. new Promise (call before/after event)");
await new Promise(resolve => resolve({then(resolve){ resolve() }}))
console.log("---");

console.log(">>> 7. new Promise reject");
await new Promise(resolve => resolve({then(resolve, reject) { reject() }}))
onsole.log("---");
}

await test(); 

% llrt async_hooks_test.js 
init: asyncId=2, type=PROMISE, triggerAsyncId=1
>>> 1. Promise.resolve
init: asyncId=3, type=PROMISE, triggerAsyncId=1
promiseResolve: asyncId=3
init: asyncId=4, type=PROMISE, triggerAsyncId=1
init: asyncId=5, type=PROMISE, triggerAsyncId=1
---
>>> 2. Promise.reject w/catch
init: asyncId=6, type=PROMISE, triggerAsyncId=1
init: asyncId=7, type=PROMISE, triggerAsyncId=6
destroy: asyncId=3
Caught: error!
promiseResolve: asyncId=7
destroy: asyncId=6
---
>>> 3. Promise.all
init: asyncId=8, type=PROMISE, triggerAsyncId=1
init: asyncId=9, type=Timeout, triggerAsyncId=1
init: asyncId=10, type=PROMISE, triggerAsyncId=1
init: asyncId=11, type=Timeout, triggerAsyncId=1
init: asyncId=12, type=PROMISE, triggerAsyncId=1
init: asyncId=13, type=PROMISE, triggerAsyncId=8
init: asyncId=14, type=PROMISE, triggerAsyncId=10
destroy: asyncId=7
before: asyncId=9
  promiseResolve: asyncId=8
after: asyncId=9
promiseResolve: asyncId=13
destroy: asyncId=9
destroy: asyncId=8
destroy: asyncId=13
promiseResolve: asyncId=10
promiseResolve: asyncId=12
promiseResolve: asyncId=14
destroy: asyncId=11
destroy: asyncId=10
---
>>> 4. Promise.race
init: asyncId=15, type=PROMISE, triggerAsyncId=1
init: asyncId=16, type=Timeout, triggerAsyncId=1
init: asyncId=17, type=PROMISE, triggerAsyncId=1
init: asyncId=18, type=Timeout, triggerAsyncId=1
init: asyncId=19, type=PROMISE, triggerAsyncId=1
init: asyncId=20, type=PROMISE, triggerAsyncId=15
init: asyncId=21, type=PROMISE, triggerAsyncId=17
destroy: asyncId=14
destroy: asyncId=12
before: asyncId=16
  promiseResolve: asyncId=17
after: asyncId=16
promiseResolve: asyncId=19
promiseResolve: asyncId=21
destroy: asyncId=18
destroy: asyncId=17
---
>>> 5. normal new Promise
init: asyncId=22, type=PROMISE, triggerAsyncId=1
init: asyncId=23, type=Timeout, triggerAsyncId=1
destroy: asyncId=21
before: asyncId=16
  promiseResolve: asyncId=22
after: asyncId=16
---
>>> 6. new Promise (call before/after event)
init: asyncId=24, type=PROMISE, triggerAsyncId=1
destroy: asyncId=23
destroy: asyncId=22
before: asyncId=24
  promiseResolve: asyncId=24
after: asyncId=24
---
>>> 7. new Promise reject
init: asyncId=25, type=PROMISE, triggerAsyncId=1
destroy: asyncId=24
before: asyncId=25
after: asyncId=25
destroy: asyncId=25
destroy: asyncId=2
promiseResolve: asyncId=4
promiseResolve: asyncId=5
destroy: asyncId=4
undefined

Checklist

• [ ] Created unit tests in tests/unit and/or in Rust for my feature if needed
• [x] Ran make fix to format JS and apply Clippy auto fixes
• [x] Made sure my code didn't add any additional warnings: make check
• [x] Added relevant type info in types/ directory
• [x] Updated documentation if needed (API.md/README.md/Other)

By submitting this pull request, I confirm that you can use, modify, copy, and redistribute this contribution, under the terms of your choice.

[Sytten]

This might be better as native C in quickjs-ng. The guys are pretty cool so I would check with them.

[nabetti1720]

This might be better as native C in quickjs-ng. The guys are pretty cool so I would check with them.

If Quickjs exposes hook points for its internal implementation and allows user functions to be attached to them, I think it will be possible to synchronize the firing timing of all implementations that use them (including async_hooks).

[bnoordhuis]

Can you guys check if quickjs-ng/quickjs#1033 works for what you want to do?

[nabetti1720]

@richarddavison, @bnoordhuis is doing a great job! We should try this out, but we need to update rquickjs deps to do so. Can you update them for us?

Additionally, we believe that additional APIs will be available through the rquickjs::qjs module, is that correct?

[nabetti1720]

NOTE: A PR for the quote has been submitted to DelSkayn/rquickjs, but I don't think it's right to use their comment section yet, so I'll comment here.

@bnoordhuis I tried to build it by changing Cargo.toml to point to your repository for the rquickjs reference used in LLRT, but it seems to have generated some errors. My development environment is darwin/arm64, so maybe there is a binding missing?

# Cargo.toml
rquickjs = { git = "https://github.com/bnoordhuis/rquickjs.git", branch = "promisehook", version = "0.9.0", default-features = false }

error[E0531]: cannot find unit struct, unit variant or constant `JSPromiseHookType_JS_PROMISE_HOOK_INIT` in module `qjs`
   --> /Users/shinya/.cargo/git/checkouts/rquickjs-068a5a2afbc2d9b3/ce398c0/core/src/runtime/raw.rs:303:26
    |
303 |                     qjs::JSPromiseHookType_JS_PROMISE_HOOK_INIT => PromiseHookType::Init,
    |                          ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ not found in `qjs`

error[E0531]: cannot find unit struct, unit variant or constant `JSPromiseHookType_JS_PROMISE_HOOK_BEFORE` in module `qjs`
   --> /Users/shinya/.cargo/git/checkouts/rquickjs-068a5a2afbc2d9b3/ce398c0/core/src/runtime/raw.rs:304:26
    |
304 |                     qjs::JSPromiseHookType_JS_PROMISE_HOOK_BEFORE => PromiseHookType::Before,
    |                          ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ not found in `qjs`

error[E0531]: cannot find unit struct, unit variant or constant `JSPromiseHookType_JS_PROMISE_HOOK_AFTER` in module `qjs`
   --> /Users/shinya/.cargo/git/checkouts/rquickjs-068a5a2afbc2d9b3/ce398c0/core/src/runtime/raw.rs:305:26
    |
305 |                     qjs::JSPromiseHookType_JS_PROMISE_HOOK_AFTER => PromiseHookType::After,
    |                          ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ not found in `qjs`

error[E0531]: cannot find unit struct, unit variant or constant `JSPromiseHookType_JS_PROMISE_HOOK_RESOLVE` in module `qjs`
   --> /Users/shinya/.cargo/git/checkouts/rquickjs-068a5a2afbc2d9b3/ce398c0/core/src/runtime/raw.rs:306:26
    |
306 |                     qjs::JSPromiseHookType_JS_PROMISE_HOOK_RESOLVE => PromiseHookType::Resolve,
    |                          ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ not found in `qjs`

error[E0425]: cannot find function, tuple struct or tuple variant `JS_SetPromiseHook` in module `qjs`
   --> /Users/shinya/.cargo/git/checkouts/rquickjs-068a5a2afbc2d9b3/ce398c0/core/src/runtime/raw.rs:324:14
    |
324 |         qjs::JS_SetPromiseHook(
    |              ^^^^^^^^^^^^^^^^^ not found in `qjs`

error[E0061]: this function takes 2 arguments but 1 argument was supplied
    --> /Users/shinya/.cargo/git/checkouts/rquickjs-068a5a2afbc2d9b3/ce398c0/core/src/value.rs:345:18
     |
345  |         unsafe { qjs::JS_IsArray(self.value) }
     |                  ^^^^^^^^^^^^^^^ ---------- argument #1 of type `*mut rquickjs_sys::JSContext` is missing
     |
note: function defined here
    --> /Users/shinya/.cargo/git/checkouts/rquickjs-068a5a2afbc2d9b3/ce398c0/sys/src/bindings/aarch64-apple-darwin.rs:1472:12
     |
1472 |     pub fn JS_IsArray(ctx: *mut JSContext, val: JSValue) -> ::std::os::raw::c_int;
     |            ^^^^^^^^^^
help: provide the argument
     |
345  -         unsafe { qjs::JS_IsArray(self.value) }
345  +         unsafe { qjs::JS_IsArray(/* *mut rquickjs_sys::JSContext */, self.value) }
     |

error[E0308]: mismatched types
   --> /Users/shinya/.cargo/git/checkouts/rquickjs-068a5a2afbc2d9b3/ce398c0/core/src/value.rs:345:18
    |
344 |     pub fn is_array(&self) -> bool {
    |                               ---- expected `bool` because of return type
345 |         unsafe { qjs::JS_IsArray(self.value) }
    |                  ^^^^^^^^^^^^^^^^^^^^^^^^^^^ expected `bool`, found `i32`

[bnoordhuis]

I can't generate those bindings locally (missing header files) but you can by running cargo build --manifest-path sys/Cargo.toml --features update-bindings --target aarch64-apple-darwin from the top-level directory.

[nabetti1720]

@bnoordhuis I was able to set hooks into the engine from Rust and it started working, but it seemed a bit odd.

reproduction.js

const async_hooks = require('async_hooks');

const hook = async_hooks.createHook({
init(asyncId, type, triggerAsyncId) {
  console.log(`init: asyncId=${asyncId}, type=${type}, triggerAsyncId=${triggerAsyncId}`);
},
before(asyncId) {
  console.log(`before: asyncId=${asyncId}`);
},
after(asyncId) {
  console.log(`after: asyncId=${asyncId}`);
},
promiseResolve(asyncId) {
  console.log(`promiseResolve: asyncId=${asyncId}`);
},
}).enable();

Promise.resolve().then(() => {
console.log("Promise resolved1");
});

% llrt reproduction.js
init: asyncId=0, type=PROMISE, triggerAsyncId=0
promiseResolve: asyncId=0
init: asyncId=0, type=PROMISE, triggerAsyncId=0
promiseResolve: asyncId=0
promiseResolve: asyncId=0
init: asyncId=0, type=PROMISE, triggerAsyncId=0
Promise resolved1
promiseResolve: asyncId=0
promiseResolve: asyncId=0
promiseResolve: asyncId=0
promiseResolve: asyncId=0

NOTE:Don't worry about the id being returned as zero. That's how it's implemented for now.

I don't think the PromiseHookType judgment is incorrect, but I'm getting a strange symptom where init is called three times. And promiseResolve is also displayed a lot.

@richarddavison @Sytten Is there anything you noticed?

[bnoordhuis]

I'm getting a strange symptom where init is called three times

If you're loading that script as ESM, then the module loader itself also creates two promises. See the upstream tests I added to api-test.c, they also expect at least three promises per test.

[nabetti1720]

I'm getting a strange symptom where init is called three times

If you're loading that script as ESM, then the module loader itself also creates two promises. See the upstream tests I added to api-test.c, they also expect at least three promises per test.

Thanks! By referring to api-test.c, we were also able to confirm cases where before/after events occurred.

new Promise(resolve => resolve({then(resolve){ resolve() }}))

% llrt reproduction.js
init: asyncId=0, type=PROMISE, triggerAsyncId=0
promiseResolve: asyncId=0
promiseResolve: asyncId=0
init: asyncId=0, type=PROMISE, triggerAsyncId=0
before: asyncId=0
promiseResolve: asyncId=0
after: asyncId=0
promiseResolve: asyncId=0
promiseResolve: asyncId=0
promiseResolve: asyncId=0

Please let me know if there is anything else I should check. :)

[bnoordhuis]

Does it cover all that you need to implement async_hooks? Node has fairly extensive coverage of the API surface in its test/parallel/test-async-hooks-* tests. You may want to try and port them over.

[nabetti1720]

Does it cover all that you need to implement async_hooks? Node has fairly extensive coverage of the API surface in its test/parallel/test-async-hooks-* tests. You may want to try and port them over.

@bnoordhuis Thank you for your comment. I'm sorry if my intention was unclear. I was just asking what we should have checked in order to have your PRs for rquickjs and quickjs-ng merged.

Additionally, we still need to review the provided Node.js test cases.

[Sytten]

Just FYI there should be a feature on all crates that use async hooks like timers.

[nabetti1720]

Just FYI there should be a feature on all crates that use async hooks like timers.

Yes, you're right. The hooking implementation other than Promise is not yet stable, so I was using the Timer part for testing. Now that we have prepared a helper library, will this make it easier to apply to other asynchronous processes?

However, I think there is a need for discussion about where to call hooks for all asynchronous processing, so I would like to separate this into a separate PR. :)

[Sytten]

Probably yeah, but we should make it opt-in for all crates that need to be modified for async hooks.

I will need to read more about them, I am not sure I fully get why we need to do calls on the rust side.

[nabetti1720]

Probably yeah, but we should make it opt-in for all crates that need to be modified for async hooks.

Currently, the function globalThis.invokeAsyncHook is exposed when the async_hooks module is loaded. llrt_hooking::invoke_async_hook is designed to do nothing if globalThis.invokeAsyncHook does not exist. This is an implicit opt-in implementation.

In addition, I think it would be possible to implement explicit opt-in by preparing a feature flag in a crate that contains asynchronous processing.

I will need to read more about them, I am not sure I fully get why we need to do calls on the rust side.

The only native hook supported by v8 is Promise (Promise Hook API). Native hooks other than Promise are not provided in v8, so I believe that hooking events for other asynchronous processing are implemented in the NodeJS core. I haven't looked into the nodejs implementation thoroughly, but since v8 doesn't support native hooks other than Promise, this seems to be the only way to implement it. This specification is the same for quickjs-ng.

[nabetti1720]

~Although I can now call FinalizationRegistry.register(), the next problem is that cleanup of objects registered from the Rust side has never been successful.~ ~When loading the async_hooks module, I have made it so that asyncFinalizationRegistry (an instance of FinalizationRegistry) is registered in globalThis.~ ~By using the register method of this instance to register it from the Javascript side, the destroy callback defined in createHook works correctly, so I think the instantiation including the callback function has been completed...~

The reason it wasn't working was because the register method wasn't being called correctly.

[richarddavison]

@nabetti1720 The API is now merged in rquickjs but a regression has been introduced by the introduction of JS_TAG_SMALL_BIG_INT. As soon as this PR is merged and rquickjs is updated we should revisit this one :)

[nabetti1720]

Now that there is nothing blocking it, the review is possible.

[nabetti1720]

@richarddavison I would appreciate it if you could take a look at it when you have time. Because rebasing is starting to become difficult. :)