Node: async_hooks: hooks are fired in an unexpected order, init triggered by already destroyed resource

[vinczedani]

• Version: 12.1.0
• Platform: Darwin {{name}} 18.5.0 Darwin Kernel Version 18.5.0: Mon Mar 11 20:40:32 PDT 2019; root:xnu-4903.251.3~3/RELEASE_X86_64 x86_64
• Subsystem: async_hooks

Hello NodeJS team!

We are trying to track our requests inside our applications using a "context storage" based on async_hooks. In Node version 10 and 11 the async resource Ids were properly chained and we were able to keep track of our requests. But in NodeJs v12 it seems like something is changed. I created a sample application and it logs out strange things (at least to me) There are async resources that are triggered by a resource, that is already deleted. I am not sure if it is intended, but I wanted to let you guys know about it.

The application that can reproduce the issue:

const fs = require('fs');
const http = require('http');
const request = require('request');
const asyncHooks = require('async_hooks');

function debug(string) {
  fs.writeSync(1, string + '\n');
}

asyncHooks.createHook({
  init: function init(id, type, triggerId) {
    debug(`${id}(${type}) init by ${triggerId}`);
  },
  destroy: function destroy(id) {
    debug(`destroy ${id}`);
  },
}).enable();

http.createServer(function (req, res) {
  request.get('https://google.com', (err, resp, body) => {
    debug('Response from google in ' + asyncHooks.executionAsyncId() + ' triggered by ' + asyncHooks.triggerAsyncId());
    return res.end('asd');
  });
}).listen(3000);

And a sample output of the application after the run on my machine using NodeJS 12.1.0: https://pastebin.com/6iPjd6VW
The output of the same application ran with NodeJS 10.15.3: https://pastebin.com/7qGLWvRa

I called the http://localhost:3000 from my chrome browser both times. The callback is called twice, I am not sure why it happens, but more importantly, with NodeJS v12.1.0. the async resource with id 17 (in my logs) is destroyed four times (line 40, 243, 289 and 492 on pastebin) and there are resources triggered by 17 after it was first destroyed. Because of this, we are unable to track the origin of the request, as we delete our data related to an async id when it is destroyed.

Expected behaviour is that after a resource is destroyed, it doesn't triggers more async resources, like when we are using NodeJs v10.15.3, where the callbacks are triggered by 40 are initiated before 40 is destroyed.

The implementation of our context storage can be found here: https://github.com/vicanso/async-local-storage

Thanks for the help in advance,
Daniel

[Flarna]

Maybe #27477 fixed this. Could you try with a nightly build from master?

[Trott]

Maybe #27477 fixed this. Could you try with a nightly build from master?

I've confirmed that the bug is in Node.js 12.1.0 but not in node compiled from the master branch. So this should be fixed in Node.js 12.2.0 coming out literally in the next several minutes or (at most) hours.

[Trott]

And, 12.2.0 is out!

[Trott]

Confirmed fixed in Node.js 12.2.0!

[vinczedani]

Yes, I just checked it is working properly, thank you!