feat: Add timing for Socket Close

* Stop using the request module. Use the standard http and https modules.
  This also fixed the DNS Lookup timing, which was set, although no DNS
  lookup took place.

Author: prantlf

README.md

@@ -2,7 +2,7 @@
 
 [![NPM Downloads](https://nodei.co/npm/nettime.png?downloads=true&stars=true)](https://www.npmjs.com/package/nettime)
 
-Prints timings of a HTTP/S request, including DNS lookup, TLS handshake etc.
+Prints time duration of various stages of a HTTP/S request, like DNS lookup, TLS handshake, Time to First Byte etc. You can find more information in [Understanding & Measuring HTTP Timings with Node.js](https://blog.risingstack.com/measuring-http-timings-node-js/).
 
 ## Command-line usage
 
@@ -40,8 +40,8 @@ const nettime = require('nettime')
 nettime('http://www.google.com').then(result => {
   if (result.statusCode === 200) {
     let timings = result.timings
-    let duration = nettime.getDuration(timings.responseBegin,
-          timings.responseEnd)
+    let duration = nettime.getDuration(timings.firstByte,
+          timings.contentTransfer)
     console.log(nettime.getMilliseconds(duration) + 'ms')
   }
 })
@@ -64,6 +64,7 @@ your code using Grunt.
 
 ## Release History
 
+* 2017-10-22   v0.2.0   Add timing for Socket Close
 * 2017-10-21   v0.1.0   Initial release
 
 ## License

lib/nettime.js

@@ -1,6 +1,8 @@
 'use strict'
 
-const request = require('request')
+const http = require('http')
+const https = require('https')
+const url = require('url')
 
 function nettime (options) {
   if (typeof options === 'string') {
@@ -9,33 +11,54 @@ function nettime (options) {
       url: url
     }
   }
+  const connection = url.parse(options.url)
+  const protocol = connection.protocol === 'http:' ? http : https
+  const timings = {}
+  var start, response
+  connection.agent = false
   return new Promise((resolve, reject) => {
-    const req = request({
-      url: options.url,
-      time: true
-    }, (error, response) => {
-      if (error) {
-        reject(error)
-      } else {
-        let timings = req.timings
+    start = getTime(process.hrtime())
+    protocol.get(connection, localResponse => {
+      response = localResponse
+      response.once('readable', () => {
+        timings.firstByte = getDuration()
+      })
+      .on('data', () => {
+      })
+      .on('end', () => {
+        timings.contentTransfer = getDuration()
+      })
+    })
+    .on('socket', socket => {
+      timings.socketOpen = getDuration()
+      socket.on('lookup', () => {
+        timings.dnsLookup = getDuration()
+      })
+      .on('connect', () => {
+        timings.tcpConnection = getDuration()
+      })
+      .on('secureConnect', () => {
+        timings.tlsHandshake = getDuration()
+      })
+      .on('close', () => {
+        timings.socketClose = getDuration()
         resolve({
-          statusCode: response.statusCode,
-          timings: {
-            socketOpen: getTiming(timings.socket),
-            dnsLookup: getTiming(timings.lookup),
-            tcpConnection: getTiming(timings.connect),
-            responseBegin: getTiming(timings.response),
-            responseEnd: getTiming(timings.end)
-          }
+          statusCode: response ? response.statusCode : 0,
+          timings: timings
         })
-      }
+      })
     })
+    .on('error', reject)
   })
-}
 
-function getTiming (duration) {
-  const seconds = parseInt(duration / 1000)
-  return [seconds, parseInt(duration * 1e6 - seconds * 1e9)]
+  function getDuration () {
+    const duration = getTime(process.hrtime()) - start
+    return [parseInt(duration / 1e9), duration % 1e9]
+  }
+
+  function getTime (timing) {
+    return timing[0] * 1e9 + timing[1]
+  }
 }
 
 function getDuration (start, end) {

lib/printer.js

@@ -6,8 +6,9 @@ const labels = {
   socketOpen: 'Socket Open',
   dnsLookup: 'DNS Lookup',
   tcpConnection: 'TCP Connection',
-  responseBegin: 'Response Start',
-  responseEnd: 'Response Finish',
+  tlsHandshake: 'TLS Handshake',
+  firstByte: 'First Byte',
+  contentTransfer: 'Content Transfer',
   socketClose: 'Socket Close'
 }
 
@@ -18,13 +19,13 @@ module.exports = function (timings, unit) {
 
 function printMilliseconds (timings) {
   var lastTiming = [0, 0]
-  console.log('Phase           Finished Duration')
-  console.log('---------------------------------')
+  console.log('Phase             Finished Duration')
+  console.log('-----------------------------------')
   for (let part in labels) {
     let timing = timings[part]
     if (timing) {
       let duration = getDuration(lastTiming, timing)
-      console.log(sprintf('%-15s %3d.%03ds %3d.%03ds',
+      console.log(sprintf('%-17s %3d.%03ds %3d.%03ds',
         labels[part], timing[0], parseInt(timing[1] / 1e6),
         duration[0], parseInt(duration[1] / 1e6)))
       lastTiming = timing
@@ -34,13 +35,13 @@ function printMilliseconds (timings) {
 
 function printNanoseconds (timings) {
   var lastTiming = [0, 0]
-  console.log('Phase           Finished       Duration')
-  console.log('---------------------------------------------')
+  console.log('Phase             Finished       Duration')
+  console.log('-----------------------------------------------')
   for (let part in labels) {
     let timing = timings[part]
     if (timing) {
       let duration = getDuration(lastTiming, timing)
-      console.log(sprintf('%-15s %3ds %7.3fms %3ds %7.3fms',
+      console.log(sprintf('%-17s %3ds %7.3fms %3ds %7.3fms',
         labels[part], timing[0], parseInt(timing[1] / 1000) / 1000,
         duration[0], parseInt(duration[1] / 1000) / 1000))
       lastTiming = timing

tests/test.js

@@ -48,16 +48,16 @@ function makeRequest (protocol, host, port, path) {
 function checkRequest (result) {
   const timings = result.timings
   const tcpConnection = timings.tcpConnection
-  const responseBegin = timings.responseBegin
+  const firstByte = timings.firstByte
   assert.equal(typeof result, 'object')
   assert.equal(Object.keys(result).length, 2)
   assert.equal(typeof result.timings, 'object')
   checkTiming(timings.socketOpen)
   checkTiming(tcpConnection)
-  checkTiming(responseBegin)
-  checkTiming(timings.responseEnd)
-  checkNull(timings.socketClose)
-  assert.ok(getDuration(tcpConnection, responseBegin) >= 100 * 1e6)
+  checkTiming(firstByte)
+  checkTiming(timings.contentTransfer)
+  checkTiming(timings.socketClose)
+  assert.ok(getDuration(tcpConnection, firstByte) >= 100 * 1e6)
   return result
 }
 
@@ -85,7 +85,7 @@ function testHostname () {
     .then(result => {
       const timings = result.timings
       assert.equal(result.statusCode, 204)
-      assert.equal(Object.keys(timings).length, 5)
+      assert.equal(Object.keys(timings).length, 6)
       checkTiming(timings.dnsLookup)
     })
 }
@@ -96,7 +96,7 @@ function testIPAddress () {
       const timings = result.timings
       assert.equal(result.statusCode, 204)
       assert.equal(Object.keys(timings).length, 5)
-      checkTiming(timings.dnsLookup)
+      checkNull(timings.dnsLookup)
     })
 }
 
@@ -106,7 +106,7 @@ function testMissingPage () {
       const timings = result.timings
       assert.equal(result.statusCode, 404)
       assert.equal(Object.keys(timings).length, 5)
-      checkTiming(timings.dnsLookup)
+      checkNull(timings.dnsLookup)
     })
 }
 
@@ -124,7 +124,7 @@ function testInvalidURL () {
     .then(assert.fail)
     .catch(error => {
       assert.ok(error instanceof Error)
-      assert.equal(error.message, 'Invalid protocol: dummy:')
+      assert.ok(error.message.indexOf('dummy:') > 0)
     })
 }