Record response time at response end instead of response start

HISTORY.md

@@ -1,6 +1,7 @@
 unreleased
 ==========
 
+  * Add `:total-time` token
   * Fix trailing space in colored status code for `dev` format
   * deps: basic-auth@~2.0.1
      - deps: [email protected]

README.md

@@ -212,6 +212,14 @@ If the request/response cycle completes before a response was sent to the
 client (for example, the TCP socket closed prematurely by a client aborting
 the request), then the status will be empty (displayed as `"-"` in the log).
 
+##### :total-time[digits]
+
+The time between the request coming into `morgan` and when the response
+has finished being written out to the connection, in milliseconds.
+
+The `digits` argument is a number that specifies the number of digits to
+include on the number, defaulting to `3`, which provides microsecond precision.
+
 ##### :url
 
 The URL of the request. This will use `req.originalUrl` if exists, otherwise `req.url`.

index.js

@@ -239,6 +239,26 @@ morgan.token('response-time', function getResponseTimeToken (req, res, digits) {
   return ms.toFixed(digits === undefined ? 3 : digits)
 })
 
+/**
+ * total time in milliseconds
+ */
+
+morgan.token('total-time', function getTotalTimeToken (req, res, digits) {
+  if (!req._startAt || !res._startAt) {
+    // missing request and/or response start time
+    return
+  }
+
+  // time elapsed from request start
+  var elapsed = process.hrtime(req._startAt)
+
+  // cover to milliseconds
+  var ms = (elapsed[0] * 1e3) + (elapsed[1] * 1e-6)
+
+  // return truncated value
+  return ms.toFixed(digits === undefined ? 3 : digits)
+})
+
 /**
  * current date
  */

test/morgan.js

@@ -641,12 +641,14 @@ describe('morgan()', function () {
           .expect(200, cb)
       })
 
-      it('should not include response latency', function (done) {
+      it('should not include response write time', function (done) {
         var cb = after(2, function (err, res, line) {
           if (err) return done(err)
+          var end = Date.now()
           var ms = parseFloat(line)
-          assert.ok(ms > 0, 'positive milliseconds')
-          assert.ok(ms < end - start + 1, 'response time expected to be < ' + (end - start + 1) + ', but was ' + ms)
+          assert(ms > 0)
+          assert(ms < end - start + 1)
+          assert(ms < write - start + 1)
           done()
         })
 
@@ -656,15 +658,15 @@ describe('morgan()', function () {
 
         var server = createServer(':response-time', { stream: stream }, function (req, res) {
           res.write('hello, ')
-          end = Date.now()
+          write = Date.now()
 
           setTimeout(function () {
             res.end('world!')
           }, 50)
         })
 
-        var end
         var start = Date.now()
+        var write = null
 
         request(server)
           .get('/')
@@ -796,6 +798,180 @@ describe('morgan()', function () {
       })
     })
 
+    describe(':total-time', function () {
+      it('should be in milliseconds', function (done) {
+        var cb = after(2, function (err, res, line) {
+          if (err) return done(err)
+          var end = Date.now()
+          var ms = parseFloat(line)
+          assert(ms > 0)
+          assert(ms < end - start + 1)
+          done()
+        })
+
+        var stream = createLineStream(function (line) {
+          cb(null, null, line)
+        })
+
+        var start = Date.now()
+
+        request(createServer(':total-time', { stream: stream }))
+          .get('/')
+          .expect(200, cb)
+      })
+
+      it('should have three digits by default', function (done) {
+        var cb = after(2, function (err, res, line) {
+          if (err) return done(err)
+          assert.ok(/^[0-9]+\.[0-9]{3}$/.test(line))
+          done()
+        })
+
+        var stream = createLineStream(function (line) {
+          cb(null, null, line)
+        })
+
+        request(createServer(':total-time', { stream: stream }))
+          .get('/')
+          .expect(200, cb)
+      })
+
+      it('should have five digits with argument "5"', function (done) {
+        var cb = after(2, function (err, res, line) {
+          if (err) return done(err)
+          assert.ok(/^[0-9]+\.[0-9]{5}$/.test(line))
+          done()
+        })
+
+        var stream = createLineStream(function (line) {
+          cb(null, null, line)
+        })
+
+        request(createServer(':total-time[5]', { stream: stream }))
+          .get('/')
+          .expect(200, cb)
+      })
+
+      it('should have no digits with argument "0"', function (done) {
+        var cb = after(2, function (err, res, line) {
+          if (err) return done(err)
+          assert.ok(/^[0-9]+$/.test(line))
+          done()
+        })
+
+        var stream = createLineStream(function (line) {
+          cb(null, null, line)
+        })
+
+        request(createServer(':total-time[0]', { stream: stream }))
+          .get('/')
+          .expect(200, cb)
+      })
+
+      it('should include response write time', function (done) {
+        var cb = after(2, function (err, res, line) {
+          if (err) return done(err)
+          var end = Date.now()
+          var ms = parseFloat(line)
+          assert(ms > 0)
+          assert(ms > write - start - 1)
+          assert(ms < end - start + 1)
+          done()
+        })
+
+        var stream = createLineStream(function (line) {
+          cb(null, null, line)
+        })
+
+        var server = createServer(':total-time', { stream: stream }, function (req, res) {
+          res.write('hello, ')
+          write = Date.now()
+
+          setTimeout(function () {
+            res.end('world!')
+          }, 50)
+        })
+
+        var start = Date.now()
+        var write = null
+
+        request(server)
+          .get('/')
+          .expect(200, cb)
+      })
+
+      it('should be empty without hidden property', function (done) {
+        var cb = after(2, function (err, res, line) {
+          if (err) return done(err)
+          assert.strictEqual(line, '-')
+          done()
+        })
+
+        var stream = createLineStream(function (line) {
+          cb(null, null, line)
+        })
+
+        var server = createServer(':total-time', { stream: stream }, function (req, res, next) {
+          delete req._startAt
+          next()
+        })
+
+        request(server)
+          .get('/')
+          .expect(200, cb)
+      })
+
+      it('should be empty before response', function (done) {
+        var cb = after(2, function (err, res, line) {
+          if (err) return done(err)
+          assert.strictEqual(line, '-')
+          done()
+        })
+
+        var stream = createLineStream(function (line) {
+          cb(null, null, line)
+        })
+
+        var server = createServer(':total-time', {
+          immediate: true,
+          stream: stream
+        })
+
+        request(server)
+          .get('/')
+          .expect(200, cb)
+      })
+
+      it('should be empty if morgan invoked after response sent', function (done) {
+        var cb = after(3, function (err, res, line) {
+          if (err) return done(err)
+          assert.strictEqual(line, '-')
+          done()
+        })
+
+        var stream = createLineStream(function (line) {
+          cb(null, null, line)
+        })
+
+        var logger = morgan(':total-time', {
+          immediate: true,
+          stream: stream
+        })
+
+        var server = http.createServer(function (req, res) {
+          setTimeout(function () {
+            logger(req, res, cb)
+          }, 10)
+
+          res.end()
+        })
+
+        request(server)
+          .get('/')
+          .expect(200, cb)
+      })
+    })
+
     describe(':url', function () {
       it('should get request URL', function (done) {
         var cb = after(2, function (err, res, line) {