Search code examples
javascriptnode.jsasynchronousasync-awaitasync-hooks

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


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.


Solution

  • 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.