Asynchook is using destroyed AsyncId for new executions

[rvillar]

• Version: 12.0.0 vs 11.4.0
• Platform: MacOs

I was using asyncHook to create a request context middleware on a http server.
But on the v12.0.0, asynchook is using destroyed AsyncIds for new executions/requests.

Below is code to simulate this behavior and two logs.
One running on Node v12.0.0 and another on v11.14.0

//Http client request monitored by asynchook
const asyncHooks = require('async_hooks');
const express = require('express');
const httpServer = express();
const httpClient = require('http');

const port = 1234;

//Client request config
const clientRequestConfig = {
    host: 'localhost',
    path: '/',
    port: port,
    method: 'GET'
};

//Save Async info
let tracked = {};

const trackAsync = types => {
    asyncHooks
        .createHook({
            init: (pAsyncId, pType, pTriggerAsyncId, pResource) => {
                if (!types || types.includes(pType)) {
                    const xMeta = {
                        asyncId: pAsyncId,
                        type: pType,
                        triggerAsyncId: pTriggerAsyncId,
                        resource: pResource
                    };
                    //Save async info
                    tracked[pAsyncId] = xMeta;
                    printMeta('init', xMeta);
                }
            },

            destroy: pAsyncId => {
                const xMeta = tracked[pAsyncId];
                if (xMeta) {
                    printMeta('DEST', xMeta);
                }
                // delete asyncInfo
                delete tracked[pAsyncId];
            }
        })
        .enable();

    const printMeta = (pEventName, pMeta) => {
        process._rawDebug(
            pEventName,
            pMeta.triggerAsyncId,
            pMeta.asyncId,
            pMeta.type
        );
    };
};

//Start asynchook
trackAsync();

//Start http server
httpServer.listen(port, pErr => {
    if (pErr) {
        return process._rawDebug('something bad happened', pErr);
    }
    process._rawDebug('Server is listening on ' + port);
});

//Create http server route
httpServer.get('/', (_, pRes, pNext) => {
    let xMsg = '';
    const xAsyncId = asyncHooks.executionAsyncId();
    process._rawDebug('\tClient Request with AsyncId:' + xAsyncId);
    if (tracked[xAsyncId]) {
        xMsg = 'Ok: AsyncId ' + xAsyncId;
        pRes.end(xMsg);
    } else {
        xMsg = 'Error: AsyncId ' + xAsyncId + ' was destroyed';
        pRes.status(500).end(xMsg);
    }
    pNext();
});

//Execute client Requests util get error
let interval = setInterval(() => {
    const req = httpClient.request(clientRequestConfig, pRes => {
        let xStr = '';
        pRes.on('data', pChunk => {
            xStr += pChunk;
        });

        pRes.on('end', () => {
            process._rawDebug('\tStatus:' + pRes.statusCode + ':' + xStr);
            //Stop requests
            if (pRes.statusCode == 500) {
                clearInterval(interval);
            }
        });
    });
    req.write('data');
    req.end();
}, 1000);

Executed on node 12.0.0
New requests receives destroyed asyncIds

init 1 4 TCPSERVERWRAP
init 4 5 TickObject
init 1 6 Timeout
Server is listening on 1234
DEST 4 5 TickObject
init 6 7 TCPWRAP
init 6 8 DNSCHANNEL
init 7 9 GETADDRINFOREQWRAP
init 6 10 TickObject
init 10 11 HTTPINCOMINGMESSAGE
init 10 12 TickObject
init 7 13 TCPCONNECTWRAP
DEST 6 10 TickObject
DEST 10 12 TickObject
DEST 7 9 GETADDRINFOREQWRAP
init 4 14 TCPWRAP
init 14 15 Timeout
init 14 16 HTTPINCOMINGMESSAGE
init 14 17 Timeout
init 14 18 TickObject
DEST 14 18 TickObject
DEST 7 13 TCPCONNECTWRAP
        Client Request with AsyncId:16
init 14 19 TickObject
init 16 20 TickObject
init 16 21 Immediate
init 16 22 TickObject
init 16 23 TickObject
init 16 24 TickObject
init 19 25 TickObject
init 19 26 TickObject
init 22 27 TickObject
init 25 28 TickObject
init 25 29 TickObject
init 25 30 TickObject
DEST 14 15 Timeout
DEST 14 19 TickObject
DEST 16 20 TickObject
DEST 16 22 TickObject
DEST 16 23 TickObject
DEST 16 24 TickObject
DEST 19 25 TickObject
DEST 19 26 TickObject
DEST 22 27 TickObject
DEST 25 28 TickObject
DEST 25 29 TickObject
DEST 25 30 TickObject
init 11 31 TickObject
init 11 32 TickObject
init 11 33 TickObject
init 7 34 TickObject
init 31 35 TickObject
init 31 36 TickObject
init 31 37 TickObject
init 32 38 TickObject
        Status:200:Ok: AsyncId 16
DEST 16 21 Immediate
DEST 14 16 HTTPINCOMINGMESSAGE    <--------------------DESTROYED
DEST 4 14 TCPWRAP
DEST 11 31 TickObject
DEST 11 32 TickObject
DEST 11 33 TickObject
DEST 7 34 TickObject
DEST 31 35 TickObject
DEST 31 36 TickObject
DEST 31 37 TickObject
DEST 32 38 TickObject
DEST 10 11 HTTPINCOMINGMESSAGE
DEST 6 7 TCPWRAP
DEST 14 17 Timeout
init 6 39 TCPWRAP
init 39 40 GETADDRINFOREQWRAP
init 6 41 TickObject
init 41 42 TickObject
init 39 43 TCPCONNECTWRAP
DEST 6 41 TickObject
DEST 41 42 TickObject
DEST 39 40 GETADDRINFOREQWRAP
init 4 44 TCPWRAP
init 44 45 Timeout
init 44 46 Timeout
init 44 47 TickObject
DEST 44 47 TickObject
DEST 39 43 TCPCONNECTWRAP
        Client Request with AsyncId:16
init 44 48 TickObject
init 16 49 TickObject
init 16 50 Immediate
init 16 51 TickObject
init 16 52 TickObject
init 16 53 TickObject
init 48 54 TickObject
init 48 55 TickObject
init 51 56 TickObject
init 54 57 TickObject
init 54 58 TickObject
init 54 59 TickObject
DEST 44 45 Timeout
DEST 44 48 TickObject
DEST 16 49 TickObject
DEST 16 51 TickObject
DEST 16 52 TickObject
DEST 16 53 TickObject
DEST 48 54 TickObject
DEST 48 55 TickObject
DEST 51 56 TickObject
DEST 54 57 TickObject
DEST 54 58 TickObject
DEST 54 59 TickObject
init 11 60 TickObject
init 11 61 TickObject
init 11 62 TickObject
init 39 63 TickObject
init 60 64 TickObject
init 60 65 TickObject
init 60 66 TickObject
init 61 67 TickObject
        Status:500:Error: AsyncId 16 was destroyed
DEST 16 50 Immediate
DEST 4 44 TCPWRAP
DEST 11 60 TickObject
DEST 11 61 TickObject
DEST 11 62 TickObject
DEST 39 63 TickObject
DEST 60 64 TickObject
DEST 1 6 Timeout
DEST 60 65 TickObject
DEST 60 66 TickObject
DEST 61 67 TickObject
DEST 6 39 TCPWRAP

Executed on node 11.14.0
New requests receives different asyncIds

init 1 4 TCPSERVERWRAP
init 4 5 TickObject
init 1 6 Timeout
Server is listening on 1234
DEST 4 5 TickObject
init 6 7 TCPWRAP
init 6 8 DNSCHANNEL
init 7 9 GETADDRINFOREQWRAP
init 6 10 TickObject
init 10 11 HTTPPARSER
init 10 12 TickObject
init 7 13 TCPCONNECTWRAP
DEST 6 10 TickObject
DEST 10 12 TickObject
DEST 7 9 GETADDRINFOREQWRAP
init 4 14 TCPWRAP
init 14 15 Timeout
init 14 16 HTTPPARSER
init 14 17 Timeout
init 14 18 TickObject
DEST 14 18 TickObject
DEST 7 13 TCPCONNECTWRAP
        Client Request with AsyncId:16
init 14 19 TickObject
init 16 20 TickObject
init 16 21 Immediate
init 16 22 TickObject
init 16 23 TickObject
init 16 24 TickObject
init 19 25 TickObject
init 19 26 TickObject
init 22 27 TickObject
init 25 28 TickObject
init 25 29 TickObject
init 25 30 TickObject
DEST 14 15 Timeout
DEST 14 19 TickObject
DEST 16 20 TickObject
DEST 16 22 TickObject
DEST 16 23 TickObject
DEST 16 24 TickObject
DEST 19 25 TickObject
DEST 19 26 TickObject
DEST 22 27 TickObject
DEST 25 28 TickObject
DEST 25 29 TickObject
DEST 25 30 TickObject
init 11 31 TickObject
init 11 32 TickObject
init 11 33 TickObject
init 7 34 TickObject
init 31 35 TickObject
init 31 36 TickObject
init 31 37 TickObject
init 32 38 TickObject
        Status:200:Ok: AsyncId 16
DEST 16 21 Immediate
DEST 14 16 HTTPPARSER
DEST 4 14 TCPWRAP
DEST 11 31 TickObject
DEST 11 32 TickObject
DEST 11 33 TickObject
DEST 7 34 TickObject
DEST 31 35 TickObject
DEST 31 36 TickObject
DEST 31 37 TickObject
DEST 32 38 TickObject
init 11 39 TickObject
DEST 10 11 HTTPPARSER
DEST 11 39 TickObject
DEST 6 7 TCPWRAP
DEST 14 17 Timeout
init 6 40 TCPWRAP
init 40 41 GETADDRINFOREQWRAP
init 6 42 TickObject
init 42 43 HTTPPARSER
init 42 44 TickObject
init 40 45 TCPCONNECTWRAP
DEST 6 42 TickObject
DEST 42 44 TickObject
DEST 40 41 GETADDRINFOREQWRAP
init 4 46 TCPWRAP
init 46 47 Timeout
init 46 48 HTTPPARSER
init 46 49 Timeout
init 46 50 TickObject
DEST 46 50 TickObject
DEST 40 45 TCPCONNECTWRAP
        Client Request with AsyncId:48
init 46 51 TickObject
init 48 52 TickObject
init 48 53 Immediate
init 48 54 TickObject
init 48 55 TickObject
init 48 56 TickObject
init 51 57 TickObject
init 51 58 TickObject
init 54 59 TickObject
init 57 60 TickObject
init 57 61 TickObject
init 57 62 TickObject
DEST 46 47 Timeout
DEST 46 51 TickObject
DEST 48 52 TickObject
DEST 48 54 TickObject
DEST 48 55 TickObject
DEST 48 56 TickObject
DEST 51 57 TickObject
DEST 51 58 TickObject
DEST 54 59 TickObject
DEST 57 60 TickObject
DEST 57 61 TickObject
DEST 57 62 TickObject
init 43 63 TickObject
init 43 64 TickObject
init 43 65 TickObject
init 40 66 TickObject
init 63 67 TickObject
init 63 68 TickObject
init 63 69 TickObject
init 64 70 TickObject
        Status:200:Ok: AsyncId 48
DEST 48 53 Immediate
DEST 46 48 HTTPPARSER
DEST 4 46 TCPWRAP
DEST 43 63 TickObject
DEST 43 64 TickObject
DEST 43 65 TickObject
DEST 40 66 TickObject
DEST 63 67 TickObject
DEST 63 68 TickObject
DEST 63 69 TickObject
DEST 64 70 TickObject
init 43 71 TickObject
DEST 42 43 HTTPPARSER
DEST 43 71 TickObject
DEST 6 40 TCPWRAP
DEST 46 49 Timeout
init 6 72 TCPWRAP
init 72 73 GETADDRINFOREQWRAP
init 6 74 TickObject
init 74 75 HTTPPARSER
init 74 76 TickObject
init 72 77 TCPCONNECTWRAP
DEST 6 74 TickObject
DEST 74 76 TickObject
DEST 72 73 GETADDRINFOREQWRAP
init 4 78 TCPWRAP
init 78 79 Timeout
init 78 80 HTTPPARSER
init 78 81 Timeout
init 78 82 TickObject
DEST 78 82 TickObject
DEST 72 77 TCPCONNECTWRAP
        Client Request with AsyncId:80
init 78 83 TickObject
init 80 84 TickObject
init 80 85 Immediate
init 80 86 TickObject
init 80 87 TickObject
init 80 88 TickObject
init 83 89 TickObject
init 83 90 TickObject
init 86 91 TickObject
init 89 92 TickObject
init 89 93 TickObject
init 89 94 TickObject
DEST 78 79 Timeout
DEST 78 83 TickObject
DEST 80 84 TickObject
DEST 80 86 TickObject
DEST 80 87 TickObject
DEST 80 88 TickObject
DEST 83 89 TickObject
DEST 83 90 TickObject
DEST 86 91 TickObject
DEST 89 92 TickObject
DEST 89 93 TickObject
DEST 89 94 TickObject
init 75 95 TickObject
init 75 96 TickObject
init 75 97 TickObject
init 72 98 TickObject
init 95 99 TickObject
init 95 100 TickObject
init 95 101 TickObject
init 96 102 TickObject

[devsnek]

@nodejs/async_hooks

[Flarna]

see #26961 (comment)
Before #25094 was committed we have seen double destroy on reused HttpParsers, now it seems init is missing.
I'm working on a fix but it's not yet ready for a PR.

[addaleax]

@Flarna Let us know if you need anything, and you can always open a WIP PR if you want.

[Flarna]

@addaleax most likely I will create a PR today. Another option would be to revert #25094. We would still have the double destroy reported in #26961 but I think they are easier to fix and even if not fixed the impact is lower.
I think the essence of #25094 got lost during the review phase - HttpParser still gets reused for parsing and async hooks.