Why does my use of the async hooks API cause an abnormal termination of Node.js?

Question

I've broken Node.js!!

I'm using the async hooks API and my code is making Node.js terminate abnormally.

My question is: what is it about this code that makes Node.js terminate in this way and is there anything I can change in the code that fixes the problem?

My application Data-Forge Notebook needs to be able to track asynchronous operations across the evaluation of a JavaScript notebook to know when the notebook's evaluation has completed.

So I created a JavaScript class called AsyncTracker that wraps the async hooks API and so that I can enable async tracking for a section of code. At the end of the section of code I can then disable tracking and wait for current async operations to complete.

To initialize tracking I do this:

this.asyncHook = async_hooks.createHook({ 
    init: (asyncId, type, triggerAsyncId, resource) => {
        this.addAsyncOperation(asyncId, type);
    },
    after: asyncId => {
        this.removeAsyncOperation(asyncId);
    },
    destroy: asyncId => {
        this.removeAsyncOperation(asyncId);
    },
    promiseResolve: asyncId => {
        this.removeAsyncOperation(asyncId);
    },
});

this.asyncHook.enable();

Async operations are recorded in a JS map, but they are only added when tracking has been enabled by setting trackAsyncOperations to true. This is this variable that allows tracking to be enabled at the start of the code section:

addAsyncOperation(asyncId, type) {
    if (this.trackAsyncOperations) {
        this.asyncOperations.add(asyncId);
        this.openAsyncOperations.set(asyncId, type);
    }
}

Various async hooks cause an async operation to be removed from the map:

removeAsyncOperation(asyncId) {
    if (this.asyncOperations.has(asyncId)) {
        this.asyncOperations.delete(asyncId);
        this.openAsyncOperations.delete(asyncId);

        if (this.asyncOperationsAwaitResolver && 
            this.asyncOperations.size <= 0) {
            this.asyncOperationsAwaitResolver();
            this.asyncOperationsAwaitResolver = undefined;
        }
    }
}

Notice the line of code this.asyncOperationsAwaitResolver(), this is what triggers the resolution of the promise we are waiting for at the end of the code section to await completion of pending async operations.

The function that disables tracking and then awaits completion of pending async operations looks like this:

awaitCurrentAsyncOperations() {

    // At this point we stop tracking new async operations.
    // We don't care about any async op started after this point.
    this.trackAsyncOperations = false; 

    let promise;

    if (this.asyncOperations.size > 0) {
        promise = new Promise(resolve => {
            // Extract the resolve function so we can call it when all current async operations have completed.
            this.asyncOperationsAwaitResolver = resolve; 
        });
    }
    else {
        this.asyncOperationsAwaitResolver = undefined;
        promise = Promise.resolve();
    }

    return promise;
}

All in all here's a minimal example of using the tracker that makes Node.js abort without warning:

const asyncTracker = new AsyncTracker();
asyncTracker.init();
asyncTracker.enableTracking(); // Enable async operation tracking.

// ---- Async operations created from here on are tracked.

// The simplest async operation that causes this problem.
// If you comment out this code the program completes normally.
await Promise.resolve(); 

// ---  Now we disable tracking of async operations, 
// then wait for all current operations to complete before continuing.

// Disable async tracking and wait.
await asyncTracker.awaitCurrentAsyncOperations(); 

Please note that this code is not broken across the board. It appears to work ok (Node.js terminates normally) when used with a callback-based or promise-based async operation. It only fails when I add the await keyword into the mix. So for example if I replace the await Promise.resolve() with a call to setTimeout it works as expected.

There is a working example of this on GitHub:

https://github.com/ashleydavis/nodejs-async-tracking-example

Run that code to make Node.js explode. To reproduce clone the repo, run npm install, followed by npm start.

This code has been tested on Windows 10 with Node.js versions 8.9.4, 10.15.2 and 12.6.0.

This code has now been tested on MacOS v8.11.3, 10.15.0 and 12.6.0.

It has the same behaviour on all versions tested.

Answer 1

Code review

After looking at the full code on GitHub and running it with Node v10.16.0 on Windows 10, it looks like the promise returned in AsyncTracker.awaitCurrentAsyncOperations is never resolved, which prevents the code in main() to move beyond the await asyncTracker.awaitCurrentAsyncOperations(); part.

That explains why the ** 33 ** part is never output and why the then(...) callback of main() never prints out Done. The resolve method of the said promise is assigned to this.asyncOperationsAwaitResolver, but (as per the current implementation) it will only get called if there are no more promises in the this.asyncOperation set. As shown in the 1st console output below, this is not the case.

Problem reproduction

I have slightly modified the code to handle process.on events at the end of the index.js script

process.on('exit', () => { console.log('Process exited') });
process.on('uncaughtException', (err) => { console.error(err && err.stack || err) });
process.on('unhandledRejection', (reason, promise) => { console.error('Unhandled Rejection at: ', promise, ', reason: ', reason) });
process.on('multipleResolves', (type, promise, reason) => { console.error(type, promise, reason) });

and the exit callback is the only one being called. The console output after the ** 22 ** mark is:

** 22 **
>>>>>>> Cell has ended, async operation tracking has been disabled, currently have 3 async ops in progress.
Waiting for operations to complete, creating a promise.
!! Have 3 remaining async operations:
  #9 - PROMISE.
  #10 - PROMISE.
  #11 - PROMISE.
%% removed async operation #9
!! Have 2 remaining async operations:
  #10 - PROMISE.
  #11 - PROMISE.
Process exited

Solution

The problem was caused by a typo in the removeAsyncOperation(asyncId) method. Instead of:

  removeAsyncOperation(asyncId) {
      // ...
      if (this.asyncOperationsAwaitResolver && this.asyncOperations.size <= 0) {
        //...
      }
    }
  } 

which blocks the promise from being resolved if there are promises in the queue, you need to do:

  removeAsyncOperation(asyncId) {
      // ...
      if (this.asyncOperationsAwaitResolver && this.asyncOperations.size >= 0) {
        //...
      }
    }
  } 

such that the promise is resolved as long as there are promises in the queue.

After making the above change to async-tracker.js, the application behaves as expected, generating the output:

** 22 **
>>>>>>> Cell has ended, async operation tracking has been disabled, currently have 3 async ops in progress.
Waiting for operations to complete, creating a promise.
!! Have 3 remaining async operations:
  #9 - PROMISE.
  #10 - PROMISE.
  #11 - PROMISE.
%% removed async operation #9
!! Have 2 remaining async operations:
  #10 - PROMISE.
  #11 - PROMISE.
%% resolving the async op promise!
** 33 **
Done
%% removed async operation #10
!! Have 1 remaining async operations:
  #11 - PROMISE.
%% removed async operation #11
!! Have 0 remaining async operations:
Process exited

Answer 2

Ok I have an answer now. I'll continue to update this as I better understand this problem I have caused.

My answer doesn't yet fully explain the way Node.js operates but it is some kind of a solution.

My code is trying to await the completion of arbitrary async operations that happen within a section of code. In my code example the tracking of async operations happens within the main function yet the then and catch handlers happen outside the main function. My theory is that async operations that are being tracked are 'kept alive' by code that is never going to be executed: the code that causes the async operations to complete is never executed.

I discovered this by removing the then and catch callbacks which makes my program terminate normally.

So my working theory is that I'm causing some kind of Node.js promises deadlock that Node.js can't handle (why would it?) so it just exits.

I realize this is a completely pathological use case for Node.js that no-one in there right mind is going to use. But I've built a developer tool and I'm exploring this because I want to be able track and monitor arbitrary async operations that my users have initiated.