Fix socket event listener leak, pin Node version, and standardize formatting

.prettierignore

@@ -0,0 +1,4 @@
+__snapshots__
+node_modules
+package-lock.json
+yarn.lock

.prettierrc.json

@@ -0,0 +1,7 @@
+{
+  "semi": true,
+  "singleQuote": true,
+  "trailingComma": "es5",
+  "tabWidth": 2,
+  "useTabs": false
+}

.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,
+}

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! :)
+
+PRs are welcome! :)

__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 {

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,74 +9,104 @@ 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', () => {
           eventTimes.firstByteAt = getTimeNotASubjectOfClockDrift();
         });
         (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
-}
+  return diffInNanoSecond / MS_PER_NS;
+}

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;
-  }, {})
+  }, {});
 }

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"
-}
+}

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"