AndreasMadsen / async-hook

Inspect the life of handle objects in node
MIT License
36 stars 14 forks source link

setInverval: unexpected behavior #12

Closed gms1 closed 7 years ago

gms1 commented 7 years ago

Thank you for your work on this project! There seems to be a small bug or unexpected behavior regarding the monkey patched 'setInverval', because the events are triggered in unexpected order ('destroy' before 'post'), after 'clearInterval' has been called:

const asyncHook = require('async-hook');
asyncHook.addHooks({
    init: (uid, handle, provider, parentUid, parentHandle) => {
        let fn = handle ? handle.constructor ? handle.constructor.name : handle.toString() : 'null';
        process._rawDebug(`init   : uid: ${uid} handle: ${fn}`);
    },
    pre: (uid) => {
        process._rawDebug(`pre    : uid: ${uid}`);
    },
    post: (uid, didThrow) => {
        process._rawDebug(`post   : uid: ${uid}`);
    },
    destroy: (uid) => {
        process._rawDebug(`destroy: uid: ${uid}`);
    }
});
asyncHook.enable();
const timer1 = setInterval(() => {
    process._rawDebug('in interval');
    clearInterval(timer1);
    asyncHook.disable();
}, 100);
gms@sirius:~/test-async-hook$ node dist/index.js
warning: you are using async-hook which is unstable.
init   : uid: -1 handle: IntervalWrap
pre    : uid: -1
in interval
destroy: uid: -1
post   : uid: -1
gms@sirius:~/test-async-hook$ 

I would also have a question about promises:

asyncHook.enable();
new Promise((resolve, reject) => {
    process._rawDebug('resolving promise');
    resolve(42);
}).then((val) => {
    process._rawDebug(`promise resolved ${val}`);
    asyncHook.disable();
    return val;
});

which produces the following output:

resolving promise
init   : uid: -1 handle: PromiseWrap
pre    : uid: -1
promise resolved 42
post   : uid: -1
destroy: uid: -1

Here, the promise-executor function does not trigger any events, as opposed to the 'then' call. Is this a problem of the 'async-hook' project or is this more 'AsyncWrap' related?

Regards Guenter

AndreasMadsen commented 7 years ago

set timeout issue

this is indeed a bug, good catch!

promise question:

The promise-executor fires (oddly enough) as soon as the promise is created (synchronously), for this reason some believe that AsyncWrap shouldn't have anything to do with that part of the promise lifetime. There have been a great deal of discussion about this: https://github.com/nodejs/node-eps/pull/18

Form the async-hook perspective, we have implemented the only perspective that can be implemented in pure javascript. If we wanted events for the entire Promise object, we would have to know when the was garbage collected, such we could call emit destroy appropriately.

gms1 commented 7 years ago

Thanks for the detailed answer!

Guenter

gms1 commented 7 years ago

btw in the README.md the link to AsyncWrap is broken, the new location is: https://github.com/nodejs/diagnostics/blob/master/tracing/AsyncWrap/README.md

AndreasMadsen commented 7 years ago

Thanks, I've updated the link. Maybe I can fix the timer issue tomorrow.

gms1 commented 7 years ago

Thank you but that is in no way urgent ;-) I have just pushed an initial version of a new small module, based on async-hook: Https://github.com/gms1/node-async-context As a temporary workaround, I had only to delay the deletion from uid map until the arrival of the post-event

Thank you for your support Guenter

AndreasMadsen commented 7 years ago

Should be fixed in https://github.com/AndreasMadsen/async-hook/commit/4ef3b4dcd5750513460282a71d26c90cff71899e (version 1.7.0)