[async_hooks] - A possible bug or requirement of clarity? Perhaps another hook needed?

[bradennapier]

• Version: 10.7.0
• Platform: OSX

Note: Sorry this got so long but I think it does help to illustrate the flow and process that brought this issue up! Please bare with me as I do feel this may be part of a larger issue at this point?

Update: Added a repro async_hooks_repro

Hey Guys!

So I am playing with async_hooks and definitely some powerful stuff here! It's a bit hard to grasp at first and seems fairly prone to potential problems for people using it to cause memory leaks and such.

I think one source of that is that the destroy is called when the garbage collector actually collects a given resource while the after doesn't fire for many things. This seems like it will lead towards confusion and people likely causing larger problems in their applications that may be difficult to see (with the garbage collector which is notoriously difficult to troubleshoot - no complaints there though, understand fully).

I was wondering if it makes sense to have another hook for complete which is similar to after but is guaranteed to fire once the asynchronous task itself has finished its job. This may not be possible for whatever reason but it does seem to fit better with how it feels it should operate.

To illustrate, just want to show what my experience as I was trying to grasp what was going on was as it may help to hear from avg user that doesn't necessarily understand the intimate details of the gc may approach this.

---

The Project

So in order to learn this, I wanted to build what most others already have built for the most part and make sure I understood the overall flow of everything. Basically a replacement for the node-continuation library.

Essentially a way to create an asynchronous state that is available for the length of a scope regardless of asynchronous calls made in-between.

I have a couple general goals:

• Allow "contexts" (namespace) to be created which are used to capture the state throughout a lifecycle.
• Enable the created hooks only when we have a running asynchronous context
• Disable the created hooks as soon as we are no longer executing

Test Code

I ended up adding logs (using fs.writeSync) to each hook to see where and when things occur so I could grasp the exact flow. My test code for a simple example here looks like this:

const ctx = require('./dist').default;
const log = require('./dist/log').default;

function fn() {
  // outputs using fs.writeSync(1, message)
  log(`
    Context State: ${JSON.stringify(ctx.get('foo').state())}
  `);
}

ctx.run('foo', () => {
  ctx.get('foo').set('myvar', 'value3');
  setTimeout(fn);
});

In this simple example it works exactly as I'd expect, outputting the following:

[ENABLING HOOKS]
[START]: Context Base EID: 5
1533096660930 | [INIT]     | Timeout     | asyncId 6 | trigger: 5
1533096660930 | [INIT]     | TIMERWRAP   | asyncId 7 | trigger: 5

    Context State: {"root":5,"myvar":"value3"}

1533096660931 | [AFTER]    | asyncId 6
1533096660931 | [AFTER]    | asyncId 7
1533096660931 | [DESTROY]  | asyncId 6   | remaining 1   | ids left: 7
1533096660931 | [DESTROY]  | asyncId 7   | remaining 0   | ids left:
[DISABLING HOOKS]

In case there is confusion, the "state" value includes whatever is set on it and a key "root" which saves the root eid that started the context.

Where it gets tricky

This may be less of an issue than I'm worried about, but where I started to run into confusion was when other things started going on within the example. For example, if I add a timeout outside of the entire context/hooks process, now we run into a larger issue:

Note: This is where I actually solved the problem but the solution is so subtle and it is very hard to understand exactly what was happening here. I think it likely still should have better handling in some way so that leaks are not so simple to occur.

So my issue came in when I then wanted to embed a call to run within another call to run. When I would do this, each time I ended up with a memory leak situation where a single value was never calling after, promiseResolve, or destroy.

Script

function fn() {
  // outputs using fs.writeSync(1, message)
  log(`
    Context State: ${JSON.stringify(ctx.get('foo').state())}
  `);
}

ctx.run('foo', () => {
  ctx.get('foo').set('myvar', 'value1');
  setTimeout(fn);
  ctx.run('foo', () => {
    ctx.get('foo').set('myvar', 'value2');
    setTimeout(fn);
  });
});

setTimeout(() => {
  console.log(`${String(Date.now())} | EVALUATION COMPLETED`);
}, 8000);

Outputs

[ENABLING HOOKS]
[START]: Context Base EID: 5
1533098775911 | [INIT]     | Timeout     | asyncId 6 | trigger: 5
1533098775911 | [INIT]     | TIMERWRAP   | asyncId 7 | trigger: 5
1533098775911 | [INIT]     | PROMISE     | asyncId 8 | trigger: 5
1533098775911 | [INIT]     | PROMISE     | asyncId 9 | trigger: 5
[START]: Context Base EID: 10
1533098775912 | [INIT]     | Timeout     | asyncId 11 | trigger: 10
1533098775912 | [AFTER]    | asyncId 10
1533098775912 | [DESTROY]  | asyncId 10  | remaining 6   | ids left: 5, 6, 7, 8, 9, 11
1533098775912 | [RESOLVE]  | asyncId 9
1533098775912 | [DESTROY]  | asyncId 9   | remaining 5   | ids left: 5, 6, 7, 8, 11
1533098775912 | [AFTER]    | asyncId 5
1533098775912 | [DESTROY]  | asyncId 5   | remaining 4   | ids left: 6, 7, 8, 11

    Context State: {"root":5,"myvar":"value1"}

1533098775913 | [AFTER]    | asyncId 6
1533098775913 | [DESTROY]  | asyncId 6   | remaining 3   | ids left: 7, 8, 11

    Context State: {"root":10,"myvar":"value2"}

1533098775913 | [AFTER]    | asyncId 11
1533098775913 | [DESTROY]  | asyncId 11  | remaining 2   | ids left: 7, 8
1533098775913 | [AFTER]    | asyncId 7
1533098775913 | [DESTROY]  | asyncId 7   | remaining 1   | ids left: 8

1533098783913 | EVALUATION COMPLETED

So here we seem to have a problem. A promise (asyncId 8) is never being handled by our hooks. In order to evaluate further, I ended up saving id 8 during init to global and later logging it so it wouldn't be caught by console.log and it ended up showing that there is a Promise that is never resolved, it remains pending forever.

What is weird and I still don't fully grasp, is that the problem was with an async function which actually really wasn't using any async features (my original hope was that .run() would return a promise outside of the asynchronous context - but that proved pointless.

Still, this tiny little problem would cause memory leaks that 99% of people probably would never be aware existed.

So ctx.run(...args) looked like this:

export async function runInContext(contextID, fn, ...args) {
  const context = AsyncContexts.get(contextID) || createAsyncContext(contextID);
  const runner = new ContextRoot(context, fn);
  runner.run(args);
}

export default Object.freeze({
  create: createAsyncContext,
  get: getContext,
  run: runInContext,
});

This is the promise that will remain pending forever (async id 8). This is a really odd place in my mind for the problem to be happening - I would imagine that this promise would be resolved immediately after the 3 lines shown are completed. The functions that it calls do complete within a millisecond so the entire body of runInContext absolutely is finished right away.

In Summary

Just wanted to say thanks, I know it got long but I actually feel this is either part of a larger bug or might help me understand what about the gc would cause this type of thing. We have ongoing issues with gc issues freezing up a larger application that I have been brought on to help and the problem seems largely due to Promises as well so I am wondering if there is a quirk about them and the gc that I am not fully grasping that could help in both areas here.

Anyway, by just making runInContext a function instead of async function it appears to work as expected for the most part:

[ENABLING HOOKS]
[START]: Context Base EID: 5
1533099546996 | [INIT]     | Timeout     | asyncId 6 | trigger: 5
1533099546997 | [INIT]     | TIMERWRAP   | asyncId 7 | trigger: 5
[START]: Context Base EID: 8
1533099546997 | [INIT]     | Timeout     | asyncId 9 | trigger: 8
1533099546997 | [AFTER]    | asyncId 8
1533099546997 | [DESTROY]  | asyncId 8   | remaining 4   | ids left: 5, 6, 7, 9
1533099546997 | [AFTER]    | asyncId 5
1533099546997 | [DESTROY]  | asyncId 5   | remaining 3   | ids left: 6, 7, 9

    Context State: {"root":5,"myvar":"value1"}

1533099546998 | [AFTER]    | asyncId 6
1533099546998 | [DESTROY]  | asyncId 6   | remaining 2   | ids left: 7, 9

    Context State: {"root":8,"myvar":"value2"}

1533099546998 | [AFTER]    | asyncId 9
1533099546998 | [DESTROY]  | asyncId 9   | remaining 1   | ids left: 7
1533099546998 | [AFTER]    | asyncId 7
1533099546998 | [DESTROY]  | asyncId 7   | remaining 0   | ids left:
[DISABLING HOOKS]

1533099554997 | EVALUATION COMPLETED

[bradennapier]

Hmm, so it actually seems that Promise may be a problem in general. While I read the part about the Promises closely, I think the problem remains that in many cases you are guaranteed a memory leak when using Promises with this (and perhaps in other major areas of the application?).

This is obviously a bit difficult to see every detail of but to see if I could re-create the problem using promises elsewhere it did not take very long.

Problem 1 - Back to the Original Issue (using an async function for ctx.run)

So I first wanted to test something by trying to resolve the promise that is stuck pending forever (the one created by runInContext that prevents the completion here).

Since it is always asyncId 8 that is breaking here, i tried saving that promise to global and then resolving it. node actually seems to ignore me completely and just never resolves that Promise, which as far as I know should not be possible! (unless im missing some major thing here)

Script

function fn() {
  // outputs using fs.writeSync(1, message)
  log(`
    Context State: ${JSON.stringify(ctx.get('foo').state())}
  `);
}

ctx.run('foo', () => {
  ctx.get('foo').set('myvar', 'value1');
  setTimeout(fn);
  ctx.run('foo', () => {
    ctx.get('foo').set('myvar', 'value2');
    setTimeout(fn);
  });
});

setTimeout(() => {
  console.log(global._RESOURCE.promise);
  Promise.resolve(global._RESOURCE.promise).then(() => {
    console.log('Resolved!');
  });
  console.log(`${String(Date.now())} | EVALUATION COMPLETED`);
}, 8000);

Outputs

[ENABLING HOOKS]
[START]: Context Base EID: 5
1533099965264 | [INIT]     | Timeout     | asyncId 6 | trigger: 5
1533099965265 | [INIT]     | TIMERWRAP   | asyncId 7 | trigger: 5
1533099965265 | [INIT]     | PROMISE     | asyncId 8 | trigger: 5
1533099965265 | [INIT]     | PROMISE     | asyncId 9 | trigger: 5
[START]: Context Base EID: 10
1533099965265 | [INIT]     | Timeout     | asyncId 11 | trigger: 10
1533099965265 | [AFTER]    | asyncId 10
1533099965265 | [DESTROY]  | asyncId 10  | remaining 6   | ids left: 5, 6, 7, 8, 9, 11
1533099965265 | [INIT]     | PROMISE     | asyncId 12 | trigger: 9
1533099965265 | [INIT]     | PROMISE     | asyncId 13 | trigger: 12
1533099965265 | [RESOLVE]  | asyncId 12
1533099965265 | [DESTROY]  | asyncId 12  | remaining 7   | ids left: 5, 6, 7, 8, 9, 11, 13
1533099965265 | [AFTER]    | asyncId 5
1533099965265 | [DESTROY]  | asyncId 5   | remaining 6   | ids left: 6, 7, 8, 9, 11, 13
1533099965266 | [RESOLVE]  | asyncId 9
1533099965266 | [DESTROY]  | asyncId 9   | remaining 5   | ids left: 6, 7, 8, 11, 13
1533099965266 | [RESOLVE]  | asyncId 13
1533099965266 | [DESTROY]  | asyncId 13  | remaining 4   | ids left: 6, 7, 8, 11

    Context State: {"root":5,"myvar":"value1"}

1533099965266 | [AFTER]    | asyncId 6
1533099965266 | [DESTROY]  | asyncId 6   | remaining 3   | ids left: 7, 8, 11

    Context State: {"root":10,"myvar":"value2"}

1533099965266 | [AFTER]    | asyncId 11
1533099965266 | [DESTROY]  | asyncId 11  | remaining 2   | ids left: 7, 8
1533099965266 | [AFTER]    | asyncId 7
1533099965266 | [DESTROY]  | asyncId 7   | remaining 1   | ids left: 8


Promise { <pending> }
1533099973273 | [INIT]     | PROMISE     | asyncId 20 | trigger: 8
1533099973273 | EVALUATION COMPLETED

[bradennapier]

Problem 2 - Creating a Promise anywhere else

So this is where I (believe) I figured out the actual cause of this entire fiasco. It appears that if a promise is not explicitly resolved it will never stop being pending, even if it and all context associated with it are complete and there is no longer any possibility of this function now being resolved. It remains pending forever and thus is likely to break a good amount of logic using this module in a sublte way?

In the case of the async function it isn't even possible to "resolve" it since I don't have access to any resolve function (so I would assume resolve just means the function has completed execution which I confirmed occurs).

Here is another case where the slightest little hiccup causes what is likely to be a fairly big problem:

Script

function fn() {
  // outputs using fs.writeSync(1, message)
  log(`
    Context State: ${JSON.stringify(ctx.get('foo').state())}
  `);
}

ctx.run('foo', () => {
  ctx.get('foo').set('myvar', 'value1');
  setTimeout(fn);
  ctx.run('foo', () => {
    ctx.get('foo').set('myvar', 'value2');
    new Promise(resolve => {
      setTimeout(fn);
    });
  });
});

setTimeout(() => {
  console.log(`${String(Date.now())} | EVALUATION COMPLETED`);
}, 8000);

Outputs

[ENABLING HOOKS]
[START]: Context Base EID: 5
1533100672622 | [INIT]     | Timeout     | asyncId 6 | trigger: 5
1533100672622 | [INIT]     | TIMERWRAP   | asyncId 7 | trigger: 5
[START]: Context Base EID: 8
1533100672622 | [INIT]     | PROMISE     | asyncId 9 | trigger: 8
1533100672622 | [INIT]     | Timeout     | asyncId 10 | trigger: 8
1533100672623 | [AFTER]    | asyncId 8
1533100672623 | [DESTROY]  | asyncId 8   | remaining 5   | ids left: 5, 6, 7, 9, 10
1533100672623 | [AFTER]    | asyncId 5
1533100672623 | [DESTROY]  | asyncId 5   | remaining 4   | ids left: 6, 7, 9, 10

    Context State: {"root":5,"myvar":"value1"}

1533100672624 | [AFTER]    | asyncId 6
1533100672624 | [DESTROY]  | asyncId 6   | remaining 3   | ids left: 7, 9, 10

    Context State: {"root":8,"myvar":"value2"}

1533100672624 | [AFTER]    | asyncId 10
1533100672624 | [DESTROY]  | asyncId 10  | remaining 2   | ids left: 7, 9
1533100672624 | [AFTER]    | asyncId 7
1533100672624 | [DESTROY]  | asyncId 7   | remaining 1   | ids left: 9

1533100680686 | EVALUATION COMPLETED

tl;dr

Does using async functions and/or accidentally forgetting to explicitly resolve a Promise mean that those promises will cause a memory leak as they remain pending even after there is no possibility of them being resolved?

Also, with this meaning that any tiny mistake in any use of Promise along the way will cause issues like this, is there perhaps another guaranteed event that could make things more manageable here?

Or - the more likely possibility - am I forgetting some major piece along this whole process and this will end up being one major embarrassing "wow .. duh" :-P

[bradennapier]

Update: Added a repro async_hooks_repro

[Nevon]

I just wanted to pop in to say that I highly appreciate you looking into this and documenting it so thoroughly. A colleague and I have been battling a crippling memory leak for the past couple of days where for some reason the Domain is being held onto forever for each request, and it looks highly related to some interaction with async_hooks.

[bradennapier]

@Nevon thanks! Hope it can be helpful to more in general. I am sure it's just something I am not considering here and is not as much of an issue but I think the general response and reasoning will be extremely helpful.

I think this lib can also be a helpful way of testing async_hooks as well with how it logs and keeps track of things in each root context. Have been considering how it can be expanded to be more useful for others as well (like building diagrams of execution automatically, etc). Definitely excited for this package to become stable regardless!

Now lets make Promise fast and lightweight af! ;-)