always emit after event. capture request state in req._connectionState (

#1249)

* always emit after event, even on uncaughtException
* capture request state in req._connectionState

lib/errorTypes.js

@@ -0,0 +1,6 @@
+'use strict';
+
+var errors = require('restify-errors');
+
+errors.makeConstructor('RequestCloseError');
+errors.makeConstructor('RequestAbortedError');

lib/index.js

@@ -11,6 +11,7 @@ var Server = require('./server');
 var shallowCopy = require('./utils').shallowCopy;
 
 var InternalError = errors.InternalError;
+require('./errorTypes');
 
 /**
  * creates a server.

lib/server.js

@@ -45,6 +45,20 @@ var PROXY_EVENTS = [
 
 ///--- Helpers
 
+
+/**
+ * helper function that returns true if the request was closed or aborted.
+ * @private
+ * @function _reqClosed
+ * @param {Object} req the request object
+ * @returns {Boolean}
+ */
+function _reqClosed(req) {
+    return (req._connectionState === 'close' ||
+            req._connectionState === 'aborted');
+}
+
+
 /**
  * helper function to help verify and flatten an array of arrays.
  * takes an arguments object and an index frmo which to slice, then
@@ -832,24 +846,22 @@ Server.prototype._run = function _run(req, res, route, chain, cb) {
     var self = this;
     var handlerName = null;
     var emittedError = false;
-    var reqClosed = false;
 
     if (cb) {
         cb = once(cb);
     }
 
-    // attach a listener for 'close' event, this will let us set a flag so that
-    // we can stop processing the request if the client closes the connection
-    // (or we lose the connection).
+    // attach a listener for 'close' and 'aborted' events, this will let us set
+    // a flag so that we can stop processing the request if the client closes
+    // the connection (or we lose the connection).
     function _requestClose() {
-        reqClosed = true;
-        req.clientClosed = true;
-        // set status code to 0 - this isn't technically a real http status
-        // code, but a closed connection isn't really a 200 or a 500 either. 0
-        // seems like a neutral value.
-        res.status(0);
+        req._connectionState = 'close';
+    }
+    function _requestAborted() {
+        req._connectionState = 'aborted';
     }
     req.once('close', _requestClose);
+    req.once('aborted', _requestAborted);
 
     // attach a listener for the response's 'redirect' event
     res.on('redirect', function (redirectLocation) {
@@ -975,7 +987,8 @@ Server.prototype._run = function _run(req, res, route, chain, cb) {
         }
 
         // Run the next handler up
-        if (!done && chain[++i] && !reqClosed) {
+        if (!done && chain[++i] && !_reqClosed(req)) {
+
             if (chain[i]._skip) {
                 return (next());
             }
@@ -1013,6 +1026,7 @@ Server.prototype._run = function _run(req, res, route, chain, cb) {
             self.emit('preDone', req, res);
         } else {
             req.removeListener('close', _requestClose);
+            req.removeListener('aborted', _requestAborted);
             self.emit('done', req, res, route);
         }
 
@@ -1060,6 +1074,7 @@ Server.prototype._run = function _run(req, res, route, chain, cb) {
         } else {
             log.trace({err: err}, 'uncaughtException');
             self.emit('uncaughtException', req, res, route, err);
+            self._finishReqResCycle(req, res, route, err);
         }
     });
     d.run(n1);
@@ -1133,11 +1148,24 @@ function _finishReqResCycle(req, res, route, err) {
     // regardless of res status.
 
     // after event has signature of function(req, res, route, err) {...}
-    if (!res.finished && !req.clientClosed) {
+    if (!res.finished && !_reqClosed(req)) {
         res.once('finish', function resFinished() {
             self.emit('after', req, res, route, err || res.formatterErr);
         });
     } else {
-        self.emit('after', req, res, route, err);
+        // if there was an error in the processing of that request, use it.
+        // if not, check to see if the request was closed or aborted early and
+        // create an error out of that for audit logging.
+        var afterErr = err;
+
+        if (!afterErr) {
+            if (req._connectionState === 'close') {
+                afterErr = new errors.RequestCloseError();
+            } else if (req._connectionState === 'aborted') {
+                afterErr = new errors.RequestAbortedError();
+            }
+        }
+
+        self.emit('after', req, res, route, afterErr);
     }
 };

test/server.test.js

@@ -2018,7 +2018,9 @@ test('GH-733 if request closed early, stop processing. ensure only ' +
                 t.ok(ringbuffer.records[0], 'no log records');
                 t.equal(ringbuffer.records.length, 1,
                         'should only have 1 log record');
-                t.equal(ringbuffer.records[0].req.clientClosed, true);
+                // TODO: fix this after plugin is fixed to use
+                // req._connectionState
+                // t.equal(ringbuffer.records[0].req.clientClosed, true);
 
                 // check timers
                 var handlers = Object.keys(ringbuffer.records[0].req.timers);
@@ -2445,3 +2447,136 @@ function (t) {
         });
     });
 });
+
+
+test('should emit \'after\' on successful request', function (t) {
+
+    SERVER.on('after', function (req, res, route, err) {
+        t.ifError(err);
+        t.end();
+    });
+
+    SERVER.get('/foobar', function (req, res, next) {
+        res.send('hello world');
+        next();
+    });
+
+    CLIENT.get('/foobar', function (err, _, res) {
+        t.ifError(err);
+        t.equal(res.statusCode, 200);
+    });
+});
+
+
+test('should emit \'after\' on errored request', function (t) {
+
+    SERVER.on('after', function (req, res, route, err) {
+        t.ok(err);
+        t.end();
+    });
+
+    SERVER.get('/foobar', function (req, res, next) {
+        next(new Error('oh noes'));
+    });
+
+    CLIENT.get('/foobar', function (err, _, res) {
+        t.ok(err);
+        t.equal(res.statusCode, 500);
+    });
+});
+
+
+test('should emit \'after\' on uncaughtException', function (t) {
+
+    SERVER.on('after', function (req, res, route, err) {
+        t.ok(err);
+        t.equal(err.message, 'oh noes');
+    });
+
+    SERVER.get('/foobar', function (req, res, next) {
+        throw new Error('oh noes');
+    });
+
+    CLIENT.get('/foobar', function (err, _, res) {
+        t.ok(err);
+        t.equal(err.name, 'InternalError');
+        t.end();
+    });
+});
+
+
+test('should emit \'after\' when sending res on uncaughtException',
+function (t) {
+
+    SERVER.on('after', function (req, res, route, err) {
+        t.ok(err);
+        t.equal(err.message, 'oh noes');
+    });
+
+    SERVER.on('uncaughtException', function (req, res, route, err) {
+        res.send(504, 'boom');
+    });
+
+
+    SERVER.get('/foobar', function (req, res, next) {
+        throw new Error('oh noes');
+    });
+
+    CLIENT.get('/foobar', function (err, _, res) {
+        t.ok(err);
+        t.equal(err.name, 'GatewayTimeoutError');
+        t.end();
+    });
+});
+
+
+test('should emit \'after\' on client closed request ' +
+'(req._connectionState: \'close\')', function (t) {
+
+    SERVER.on('after', function (req, res, route, err) {
+        t.ok(err);
+        t.equal(req._connectionState, 'close');
+        t.equal(err.name, 'RequestCloseError');
+        t.end();
+    });
+
+    SERVER.get('/foobar', function (req, res, next) {
+        // fast client times out at 500ms, wait for 800ms which should cause
+        // client to timeout
+        setTimeout(function () {
+            return next();
+        }, 800);
+    });
+
+    FAST_CLIENT.get('/foobar', function (err, _, res) {
+        t.ok(err);
+        t.equal(err.name, 'RequestTimeoutError');
+    });
+});
+
+
+test('should \'emit\' after on aborted request ' +
+'(req._connectionState: \'aborted\')', function (t) {
+
+    SERVER.on('after', function (req, res, route, err) {
+        t.ok(err);
+        t.equal(req._connectionState, 'aborted');
+        t.equal(err.name, 'RequestAbortedError');
+    });
+
+    SERVER.get('/foobar', function (req, res, next) {
+
+        req.emit('aborted');
+        // fast client times out at 500ms, wait for 800ms which should cause
+        // client to timeout
+        setTimeout(function () {
+            return next();
+        }, 800);
+    });
+
+    FAST_CLIENT.get('/foobar', function (err, _, res) {
+        t.ok(err);
+        t.equal(err.name, 'RequestTimeoutError');
+        t.end();
+    });
+});