Questions: async_hooks destroy callback vs setImmediate

[JiaLiPassion]

• Version:
  v8.0.0-nightly20170527f84666f923

• Platform:
  Mac OS

• Subsystem:

I just tried the new async_hooks callback API, I want to confirm the behaviors below is correct or not?

const async_hooks = require('async_hooks');

function init(id, provider, parentId, parentHandle) {
    process._rawDebug('init ', id, provider);
}

function before(id) { 
    process._rawDebug('before', id);
 }
function after(id) { 
    process._rawDebug('after', id);
 }
function destroy(id) {
    process._rawDebug('destroy', id);
}

async_hooks.createHook({init, before, after, destroy}).enable();

const timerId1 = setImmediate(() => {
    process._rawDebug('setImmediate');
});
clearImmediate(timerId1);

It is just a simple setImmediate and it was clear by clearImmediate.
I expect the result will be

 init  2 Immediate
destroy 2

but the result is

 init  2 Immediate

only.

If I add some other setTimeout logic in the test program, the destroy will be called.

const async_hooks = require('async_hooks');

function init(id, provider, parentId, parentHandle) {
    process._rawDebug('init ', id, provider, parentId, parentHandle);
}

function before(id) { 
    process._rawDebug('before', id);
 }
function after(id) { 
    process._rawDebug('after', id);
 }
function destroy(id) {
    process._rawDebug('destroy', id);
}

async_hooks.createHook({init, before, after, destroy}).enable();

const timerId1 = setImmediate(() => {
    process._rawDebug('setImmediate');
});
clearImmediate(timerId1);

const timerId = setTimeout(() => {
    process._rawDebug('settimeout');
}, 100);
clearTimeout(timerId);

the result will look like

init  2 Immediate
init  3 Timeout
init  4 TIMERWRAP
destroy 2
destroy 3

Is this the correct behaviors? And how to ensure the destroy callback is called ?

Thanks a lot!

[addaleax]

Thanks for this report! I suspect this has something to do with the destroy callback being called asynchronously (we have to do that, unfortunately), and the loop exiting too early for that callback to be run.

[JiaLiPassion]

@addaleax , Thank you for reply, got it! I will continue to test other async APIs.

[AndreasMadsen]

I suspect this has something to do with the destroy callback being called asynchronously (we have to do that, unfortunately), and the loop exiting too early for that callback to be run.

Indeed, we can't always guarantee the destroy event to be emitted during process termination, but since clearImmediate directly indicates a destroy it should be possible in this case.

The emit is queued using uv_idle_start here https://github.com/nodejs/node/blob/master/src/async-wrap.cc#L177

I guess we can check the env->destroy_ids_list() list when validating that there is no more to do.

[AndreasMadsen]

Looking at how setImmediate works (basically we need setImmediate(drainDestroyQueue)) I think we should use uv_check_start instead of uv_idle_start.

[Fishrock123]

This seems like a simple bug: destroy() should be emitted from clearImmediate(). Similar to timers, although it is in unenroll() for timers.

[AndreasMadsen]

@Fishrock123 it already is "emitted" in clearImmediate using emitDestroy similarly to unenroll. But emitDestroy doesn't emit until the next event loop iteration because it uses uv_idle_start. Since the event queue is empty the next event loop iteration never happens.