René's URL Explorer Experiment

{"@context":"https://schema.org","@type":"DiscussionForumPosting","headline":"Socket timeouts are checked before pending incoming requests are assigned sockets, causing `ECONNRESET`s","articleBody":"### Version\n\n14.19.1 and others\n\n### Platform\n\nLinux qa01-api-1 5.13.0-1024-gcp #29~20.04.1-Ubuntu SMP Thu Apr 14 23:15:00 UTC 2022 x86_64 x86_64 x86_64 GNU/Linux\n\n### Subsystem\n\nnet\n\n### What steps will reproduce the bug?\n\n##### Process 1:\r\n```js\r\nconst crypto = require(\"crypto\");\r\nconst http = require('http');\r\n\r\nconst a = Buffer.alloc(1e8);\r\nfunction doWork(ms) {\r\n\tconst start = Date.now();\r\n\twhile (Date.now() - start \u003c ms) {\r\n\t\tcrypto.randomFillSync(a);\r\n\t}\r\n}\r\n\r\nlet socketId = 0;\r\nconst server = http.createServer((req, res) => {\r\n\tif (req.socket.__socketId === undefined) {\r\n\t\treq.socket.__socketId = socketId++;\r\n\t\tconst st = req.socket.setTimeout;\r\n\t\treq.socket.setTimeout = (a, b) => {\r\n\t\t\tconsole.log(new Date(), \"Setting timeout on socket \", req.socket.__socketId);\r\n\t\t\treturn st.call(req.socket, a, b);\r\n\t\t};\r\n\t\treq.socket.once(\"close\", () => console.log(new Date(), `Closing ${req.socket.__socketId}`));\r\n\t}\r\n\r\n\tconst reqId = req.headers[\"x-request-id\"];\r\n\tconsole.log(new Date(), `[${reqId}] got request on socket ${req.socket.__socketId}`);\r\n\tdoWork(1500);\r\n\tconsole.log(new Date(), `[${reqId}] sending response`);\r\n\tres.end('hello world\\r\\n');\r\n});\r\n\r\nserver.keepAliveTimeout = 1000; // shortened from default 5000 to make test faster\r\n\r\nserver.listen(8080, '127.0.0.1');\r\n```\r\n\r\n##### Process 2:\r\n```js\r\nconst http = require('http');\r\n\r\nconst keepAliveAgent = new http.Agent({\r\n\tkeepAlive: true,\r\n\tmaxSockets: 2\r\n});\r\n\r\nlet socketId = 0;\r\n\r\nfor (let i = 0; i \u003c 3; i++) {\r\n\tconst req = http.request({\r\n\t\tagent: keepAliveAgent,\r\n\t\thost: '127.0.0.1',\r\n\t\tport: 8080,\r\n\t\tmethod: 'GET',\r\n\t\theaders: {\r\n\t\t\t\"X-Request-Id\": `${i}`\r\n\t\t}\r\n\t});\r\n\r\n\treq.end();\r\n\r\n\treq.once(\"socket\", socket => {\r\n\t\tif (socket.__id === undefined) socket.__id = socketId++;\r\n\t\tconsole.log(new Date(), `[${i}] assigned socket ${socket.__id}`);\r\n\t});\r\n\r\n\treq.on('response', function _onResponse(res) {\r\n\t\tres.on('data', function _onData(chunk) {});\r\n\r\n\t\tres.on('end', function _doneResponse() {\r\n\t\t\tconsole.log(new Date(), `[${i}] res.end`);\r\n\t\t});\r\n\t});\r\n\r\n\treq.on('error', function _onError(err) {\r\n\t\tconsole.log(new Date(), `[${i}] req.error`, err);\r\n\t});\r\n}\r\n```\n\n### How often does it reproduce? Is there a required condition?\n\n100%\n\n### What is the expected behavior?\n\nAll three requests should succeed.\n\n### What do you see instead?\n\nThe server logs will look like this:\r\n```\r\n2022-06-16T22:37:50.307Z [0] got request on socket 0\r\n2022-06-16T22:37:51.809Z [0] sending response\r\n2022-06-16T22:37:51.813Z Setting timeout on socket  0\r\n2022-06-16T22:37:51.814Z [1] got request on socket 1\r\n2022-06-16T22:37:53.317Z [1] sending response\r\n2022-06-16T22:37:53.318Z Setting timeout on socket  1\r\n2022-06-16T22:37:53.320Z Closing 0\r\n2022-06-16T22:37:53.323Z Closing 1\r\n```\r\n\r\nand client\r\n```\r\n2022-06-16T22:37:50.303Z [0] assigned socket 0\r\n2022-06-16T22:37:50.305Z [1] assigned socket 1\r\n2022-06-16T22:37:51.814Z [0] res.end\r\n2022-06-16T22:37:51.815Z [2] assigned socket 0\r\n2022-06-16T22:37:53.318Z [1] res.end\r\n2022-06-16T22:37:53.321Z [2] req.error Error: read ECONNRESET\r\n    at TCP.onStreamRead (internal/stream_base_commons.js:209:20) {\r\n  errno: -104,\r\n  code: 'ECONNRESET',\r\n  syscall: 'read'\r\n}\r\n```\r\n\r\nNotice: req[2] is assigned a socket at 51.815, just after req[1] is received by the server. Server socket[0] is closed at 53.320, just after the blocking work on req[2], even though there's a request that could be assigned to that socket. I think what's happening is that timers are checked *before* pending incoming messages are assigned sockets.\n\n### Additional information\n\n`ECONNRESET`s due to Keep-Alive races need to be handled by clients (see #20256, #38890 and several others), but I think this particular scenario can be fixed to avoid a subset of them.","author":{"url":"https://github.com/zbjornson","@type":"Person","name":"zbjornson"},"datePublished":"2022-06-16T22:46:37Z","url":"https://github.com/nodejs/node/issues/43456"}