Asynchook is using destroyed AsyncId for new executions #27467
Description
- 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 TCPWRAPExecuted 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