From cc92696a30fd8c22bde748244e2c1aaead175763 Mon Sep 17 00:00:00 2001 From: 0xHristo Date: Sun, 21 Dec 2025 14:21:07 +0200 Subject: [PATCH] fix: prevent socket listener leak, pin Node range, add Prettier config --- .prettierignore | 4 ++ .prettierrc.json | 7 +++ .vscode/settings.json | 8 +++ README.md | 50 +++++++++------- __snapshots__/index.test.js.snap | 4 +- index.js | 98 +++++++++++++++++++++----------- index.test.js | 60 ++++++++++++------- package.json | 7 ++- yarn.lock | 5 ++ 9 files changed, 166 insertions(+), 77 deletions(-) create mode 100644 .prettierignore create mode 100644 .prettierrc.json create mode 100644 .vscode/settings.json diff --git a/.prettierignore b/.prettierignore new file mode 100644 index 0000000..248dad8 --- /dev/null +++ b/.prettierignore @@ -0,0 +1,4 @@ +__snapshots__ +node_modules +package-lock.json +yarn.lock diff --git a/.prettierrc.json b/.prettierrc.json new file mode 100644 index 0000000..2212127 --- /dev/null +++ b/.prettierrc.json @@ -0,0 +1,7 @@ +{ + "semi": true, + "singleQuote": true, + "trailingComma": "es5", + "tabWidth": 2, + "useTabs": false +} diff --git a/.vscode/settings.json b/.vscode/settings.json new file mode 100644 index 0000000..b7d94cc --- /dev/null +++ b/.vscode/settings.json @@ -0,0 +1,8 @@ +{ + "editor.defaultFormatter": "esbenp.prettier-vscode", + "editor.formatOnSave": true, + "editor.formatOnSaveMode": "file", + "prettier.prettierPath": "./node_modules/prettier", + "prettier.configPath": ".prettierrc.json", + "javascript.format.enable": false, +} \ No newline at end of file diff --git a/README.md b/README.md index 9d1224d..c393a8b 100644 --- a/README.md +++ b/README.md @@ -4,23 +4,29 @@ npm i --save superagent-node-http-timings ``` # HTTP Timings + This plugin for superagent gives you an easy interface to get http timings information. Primary use case is to be able to monitor and optimize network requests in node in a similar way to how you do it in browser with network inspector. # Example + ```js const request = require('superagent'); const logNetworkTime = require('superagent-node-http-timings'); request .get(`https://google.com`) - .use(logNetworkTime((err, result) => { - if (err) { - return console.error(err); - } - console.log(result); - })) - .then(x => x); + .use( + logNetworkTime((err, result) => { + if (err) { + return console.error(err); + } + console.log(result); + }) + ) + .then((x) => x); ``` + Sample results (timings are in milliseconds)1: + ```json { "status": 301, @@ -36,17 +42,21 @@ Sample results (timings are in milliseconds)1: "url": "https://google.com" } ``` - ## Results interpretation - - `socketAssigned` - time since call was initiated until socket got assigned to request - - `dnsLookup` - time since socketAssigned until dns lookup end, will be `undefined` when request was sent to IP (no domain) - - `tcpConnection` - time since dnsLookup (or socketAssigned if IP was used) until connection was established - - `tlsHandshake` - time since tcpConnection until until ssl negotiation end, will be `undefined` when request was sent via http - - `firstByte` - time since tlsHandshake (or tcpConnection for http request) until first byte - - `contentTransfer` - time since firstByte until response end - -# Inspired by - - https://blog.risingstack.com/measuring-http-timings-node-js/ - - https://github.com/RisingStack/example-http-timings - + +## Results interpretation + +- `socketAssigned` - time since call was initiated until socket got assigned to request +- `dnsLookup` - time since socketAssigned until dns lookup end, will be `undefined` when request was sent to IP (no domain) +- `tcpConnection` - time since dnsLookup (or socketAssigned if IP was used) until connection was established +- `tlsHandshake` - time since tcpConnection until until ssl negotiation end, will be `undefined` when request was sent via http +- `firstByte` - time since tlsHandshake (or tcpConnection for http request) until first byte +- `contentTransfer` - time since firstByte until response end + +# Inspired by + +- https://blog.risingstack.com/measuring-http-timings-node-js/ +- https://github.com/RisingStack/example-http-timings + # Contributing to this repo -PRs are welcome! :) \ No newline at end of file + +PRs are welcome! :) diff --git a/__snapshots__/index.test.js.snap b/__snapshots__/index.test.js.snap index 41dfb29..c1a19d2 100644 --- a/__snapshots__/index.test.js.snap +++ b/__snapshots__/index.test.js.snap @@ -1,6 +1,6 @@ // Jest Snapshot v1, https://goo.gl/fbAQLP -exports[`GIVEN plugin was used WHEN response arrives THEN callback should get timings information timings 1`] = ` +exports[`GIVEN plugin was used WHEN response arrives THEN callback should get timings information timings population 1`] = ` Object { "status": "number", "timings": Object { @@ -16,7 +16,7 @@ Object { } `; -exports[`GIVEN plugin was used WHEN response arrives THEN callback should get timings information works with reusable keepAlive agent, we simply call the same request again with the same agent 1`] = ` +exports[`GIVEN plugin was used WHEN response arrives THEN callback should get timings information timings population 2`] = ` Object { "status": "number", "timings": Object { diff --git a/index.js b/index.js index e6a6769..9634860 100644 --- a/index.js +++ b/index.js @@ -1,6 +1,6 @@ module.exports = function logRequestDetailsMiddleware(callback) { return function logRequestDetails(agent) { - agent.on('request', ({req}) => { + agent.on('request', ({ req }) => { const url = agent.url; const eventTimes = { startAt: getTimeNotASubjectOfClockDrift(), @@ -9,24 +9,28 @@ module.exports = function logRequestDetailsMiddleware(callback) { tcpConnectionAt: undefined, tlsHandshakeAt: undefined, firstByteAt: undefined, - endAt: undefined + endAt: undefined, }; req.on('socket', (socket) => { eventTimes.socketAssigned = getTimeNotASubjectOfClockDrift(); - socket.on('lookup', () => { - eventTimes.dnsLookupAt = getTimeNotASubjectOfClockDrift(); - }); - socket.on('connect', () => { - eventTimes.tcpConnectionAt = getTimeNotASubjectOfClockDrift(); - }); - socket.on('secureConnect', () => { - eventTimes.tlsHandshakeAt = getTimeNotASubjectOfClockDrift(); - }); - socket.on('timeout', () => { - const err = new Error(`ETIMEDOUT for req.url: ${req.url}`); - err.code = `ETIMEDOUT`; - callback(err); - }); + if (!socket.haveEvents) { + socket.haveEvents = true; + + socket.on('lookup', () => { + eventTimes.dnsLookupAt = getTimeNotASubjectOfClockDrift(); + }); + socket.on('connect', () => { + eventTimes.tcpConnectionAt = getTimeNotASubjectOfClockDrift(); + }); + socket.on('secureConnect', () => { + eventTimes.tlsHandshakeAt = getTimeNotASubjectOfClockDrift(); + }); + socket.on('timeout', () => { + const err = new Error(`ETIMEDOUT for req.url: ${req.url}`); + err.code = `ETIMEDOUT`; + callback(err); + }); + } }); req.on('response', (res) => { res.once('readable', () => { @@ -34,49 +38,75 @@ module.exports = function logRequestDetailsMiddleware(callback) { }); (function consumeStreamSoEndEventAlwaysFire() { res.on('data', () => {}); - }()); + })(); res.on('end', () => { eventTimes.endAt = getTimeNotASubjectOfClockDrift(); callback(null, { url, status: res.statusCode, - timings: getTimings(eventTimes) + timings: getTimings(eventTimes), }); }); }); }); - } + }; }; function getTimeNotASubjectOfClockDrift() { return process.hrtime(); } -function getTimings (eventTimes) { +function getTimings(eventTimes) { return { - socketAssigned: getHrTimeDurationInMs(eventTimes.startAt, eventTimes.socketAssigned), + socketAssigned: getHrTimeDurationInMs( + eventTimes.startAt, + eventTimes.socketAssigned + ), // There is no DNS lookup with IP address - dnsLookup: eventTimes.dnsLookupAt !== undefined ? - getHrTimeDurationInMs(eventTimes.socketAssigned, eventTimes.dnsLookupAt) : undefined, - tcpConnection: eventTimes.tcpConnectionAt !== undefined ? - getHrTimeDurationInMs(eventTimes.dnsLookupAt || eventTimes.socketAssigned, eventTimes.tcpConnectionAt) : undefined, + dnsLookup: + eventTimes.dnsLookupAt !== undefined + ? getHrTimeDurationInMs( + eventTimes.socketAssigned, + eventTimes.dnsLookupAt + ) + : undefined, + tcpConnection: + eventTimes.tcpConnectionAt !== undefined + ? getHrTimeDurationInMs( + eventTimes.dnsLookupAt || eventTimes.socketAssigned, + eventTimes.tcpConnectionAt + ) + : undefined, // There is no TLS handshake without https - tlsHandshake: eventTimes.tlsHandshakeAt !== undefined ? - (getHrTimeDurationInMs(eventTimes.tcpConnectionAt, eventTimes.tlsHandshakeAt)) : undefined, - firstByte: getHrTimeDurationInMs((eventTimes.tlsHandshakeAt || eventTimes.tcpConnectionAt || eventTimes.socketAssigned), eventTimes.firstByteAt), - contentTransfer: getHrTimeDurationInMs(eventTimes.firstByteAt, eventTimes.endAt), - total: getHrTimeDurationInMs(eventTimes.startAt, eventTimes.endAt) - } + tlsHandshake: + eventTimes.tlsHandshakeAt !== undefined + ? getHrTimeDurationInMs( + eventTimes.tcpConnectionAt, + eventTimes.tlsHandshakeAt + ) + : undefined, + firstByte: getHrTimeDurationInMs( + eventTimes.tlsHandshakeAt || + eventTimes.tcpConnectionAt || + eventTimes.socketAssigned, + eventTimes.firstByteAt + ), + contentTransfer: getHrTimeDurationInMs( + eventTimes.firstByteAt, + eventTimes.endAt + ), + total: getHrTimeDurationInMs(eventTimes.startAt, eventTimes.endAt), + }; } const NS_PER_SEC = 1e9; const MS_PER_NS = 1e6; -function getHrTimeDurationInMs (startTime, endTime) { +function getHrTimeDurationInMs(startTime, endTime) { const secondDiff = endTime[0] - startTime[0]; const nanoSecondDiff = endTime[1] - startTime[1]; const diffInNanoSecond = secondDiff * NS_PER_SEC + nanoSecondDiff; - return diffInNanoSecond / MS_PER_NS -} \ No newline at end of file + return diffInNanoSecond / MS_PER_NS; +} diff --git a/index.test.js b/index.test.js index b100096..cfd388e 100644 --- a/index.test.js +++ b/index.test.js @@ -1,40 +1,62 @@ const request = require('superagent'); const logNetworkTime = require('./index'); -const https = require('https') +const https = require('https'); jest.setTimeout(10000); -const httpAgent = new https.Agent({keepAlive: true}); +const httpAgent = new https.Agent({ keepAlive: true, maxSockets: 1 }); describe('GIVEN plugin was used WHEN response arrives THEN callback should get timings information', () => { - test('timings', () => { + test('timings population', async () => { const assertions = [ - 'verified that timings were populated' + 'verified that all timings were populated', + 'verified that socket lookup, connect, secureConnect are not populated', ]; expect.assertions(assertions.length); - return expect(makeRequest()).resolves.toMatchSnapshot(); + await expect(makeRequest()).resolves.toMatchSnapshot(); + await expect(makeRequest()).resolves.toMatchSnapshot(); }); - test('works with reusable keepAlive agent, we simply call the same request again with the same agent', () => { + test('preventing memorry leak when keepAlive agent is used', async () => { const assertions = [ - 'verified that timings were populated' + 'verified that the sockets created from the https agent is exactly one', + 'verified that there is one handler for event lookup', + 'verified that there is one handler for event connect', + 'verified that there is one handler for event secureConnect', + 'verified that there is two handler for event timeout (one from the superagent implementation and one from the plugin)', ]; + expect.assertions(assertions.length); - return expect(makeRequest()).resolves.toMatchSnapshot(); - }) + await makeRequest(); + await makeRequest(); + await makeRequest(); + await makeRequest(); + + const totalSockets = Object.values(httpAgent.sockets).flat(); + // Keep this check: without maxSockets, multiple near-simultaneous sockets could mask listener leaks. + expect(totalSockets.length).toBe(1); + + const socket = totalSockets[0]; + expect(socket.listenerCount('lookup')).toBe(1); + expect(socket.listenerCount('connect')).toBe(1); + expect(socket.listenerCount('secureConnect')).toBe(1); + expect(socket.listenerCount('timeout')).toBe(2); + }); function makeRequest() { return new Promise((res, rej) => { request .get(`https://google.com`) - .use(logNetworkTime((err, result) => { - if (err) { - return rej(err) - } - res(valuesToTypes(result)) - })) .agent(httpAgent) - .then(x => x) - .catch(rej) - }) + .use( + logNetworkTime((err, result) => { + if (err) { + return rej(err); + } + res(valuesToTypes(result)); + }) + ) + .then((x) => x) + .catch(rej); + }); } }); @@ -44,5 +66,5 @@ function valuesToTypes(obj) { const type = typeof value; acc[key] = type === 'object' ? valuesToTypes(value) : type; return acc; - }, {}) + }, {}); } diff --git a/package.json b/package.json index 4d55ba7..84ebeec 100644 --- a/package.json +++ b/package.json @@ -7,7 +7,7 @@ "type": "git" }, "engines": { - "node": ">=6.5.0" + "node": ">=15.14.0 <24" }, "main": "index.js", "peerDependencies": { @@ -16,9 +16,12 @@ "devDependencies": { "jest": "^24.9.0", "np": "^10.1.0", + "prettier": "^1.19.1", "superagent": "^5.1.0" }, "scripts": { + "format": "prettier --write .", + "format:check": "prettier --check .", "test": "jest", "release": "np" }, @@ -32,4 +35,4 @@ "registry": "https://registry.npmjs.org" }, "packageManager": "yarn@1.22.22" -} +} \ No newline at end of file diff --git a/yarn.lock b/yarn.lock index a53f567..15849fb 100644 --- a/yarn.lock +++ b/yarn.lock @@ -3999,6 +3999,11 @@ prelude-ls@~1.1.2: resolved "https://registry.yarnpkg.com/prelude-ls/-/prelude-ls-1.1.2.tgz#21932a549f5e52ffd9a827f570e04be62a97da54" integrity sha1-IZMqVJ9eUv/ZqCf1cOBL5iqX2lQ= +prettier@^1.19.1: + version "1.19.1" + resolved "https://registry.yarnpkg.com/prettier/-/prettier-1.19.1.tgz#f7d7f5ff8a9cd872a7be4ca142095956a60797cb" + integrity sha512-s7PoyDv/II1ObgQunCbB9PdLmUcBZcnWOcxDh7O0N/UwDEsHyqkW+Qh28jW+mVuCdx7gLB0BotYI1Y6uI9iyew== + pretty-format@^24.9.0: version "24.9.0" resolved "https://registry.yarnpkg.com/pretty-format/-/pretty-format-24.9.0.tgz#12fac31b37019a4eea3c11aa9a959eb7628aa7c9"