fix(server): address Node v10.x req close event firing order

lib/server.js

@@ -1091,6 +1091,7 @@ Server.prototype._onHandlerError = function _onHandlerError(err, req, res) {
         return;
     }
 
+    // Handlers don't continue when error happen
     res._handlersFinished = true;
 
     // Preserve handler err for finish event
@@ -1138,27 +1139,29 @@ Server.prototype._setupRequest = function _setupRequest(req, res) {
     }
 
     // Request lifecycle events
-    // attach a listener for 'close' events, this will let us set
-    // a flag so that we can stop processing the request if the client closes
+
+    // attach a listener for 'aborted' events, this will let us set
+    // a flag so that we can stop processing the request if the client aborts
     // the connection (or we lose the connection).
     // we consider a closed request as flushed from metrics point of view
-    function onClose() {
-        res._flushed = true;
-        req._timeFlushed = process.hrtime();
-
-        res.removeListener('finish', onFinish);
-        res.removeListener('error', onError);
+    function onReqAborted() {
+        // Request was aborted, override the status code
+        var err = new errors.RequestCloseError();
+        err.statusCode = 444;
+
+        // For backward compatibility we only set connection state to "close"
+        // for RequestCloseError, also aborted is always immediatly followed
+        // by a "close" event.
+        // We don't set _connectionState to "close" in the happy path
         req._connectionState = 'close';
 
-        // Request was aborted or closed. Override the status code
-        res.statusCode = 444;
-
-        self._finishReqResCycle(req, res, new errors.RequestCloseError());
+        // Set status code and err for audit as req is already closed connection
+        res.statusCode = err.statusCode;
+        res.err = err;
     }
-    req.once('close', onClose);
 
     // Response lifecycle events
-    function onFinish() {
+    function onResFinish() {
         var processHrTime = process.hrtime();
 
         res._flushed = true;
@@ -1170,22 +1173,28 @@ Server.prototype._setupRequest = function _setupRequest(req, res) {
         req._timeUseEnd = req._timeUseEnd || processHrTime;
         req._timeRouteEnd = req._timeRouteEnd || processHrTime;
 
-        req.removeListener('close', onClose);
-        res.removeListener('error', onError);
-
-        // Do not trigger false
+        // In Node < 10 "close" event dont fire always
+        // https://github.com/nodejs/node/pull/20611
         self._finishReqResCycle(req, res);
     }
-    function onError(err) {
+
+    // We are handling when connection is being closed prematurely outside of
+    // restify. It's not because the req is aborted.
+    function onResClose() {
         res._flushed = true;
-        req._timeFlushed = process.hrtime();
 
-        req.removeListener('close', onClose);
-        res.removeListener('finish', onFinish);
-        self._finishReqResCycle(req, res, err);
+        // Finish may already set the req._timeFlushed
+        req._timeFlushed = req._timeFlushed || process.hrtime();
+
+        self._finishReqResCycle(req, res, res.err);
     }
-    res.once('finish', onFinish);
-    res.once('error', onError);
+
+    // Request events
+    req.once('aborted', onReqAborted);
+
+    // Response events
+    res.once('finish', onResFinish);
+    res.once('close', onResClose);
 
     // attach a listener for the response's 'redirect' event
     res.on('redirect', function onRedirect(redirectLocation) {
@@ -1256,7 +1265,6 @@ Server.prototype._routeErrorResponse = function _routeErrorResponse(
 ) {
     var self = this;
 
-    // if (self.handleUncaughtExceptions) {
     if (self.listenerCount('uncaughtException') > 1) {
         self.emit('uncaughtException', req, res, req.route, err);
         return;

test/plugins/audit.test.js

@@ -676,16 +676,23 @@ describe('audit logger', function() {
             assert.ok(data);
             assert.ok(data.req_id);
             assert.isNumber(data.latency);
-            assert.equal(444, data.res.statusCode);
+            assert.equal(data.res.statusCode, 444);
             done();
         });
 
         SERVER.get('/audit', function(req, res, next) {
-            req.emit('close');
-            res.send();
-            next();
+            setTimeout(function() {
+                res.send();
+                next();
+            }, 100);
         });
 
-        CLIENT.get('/audit', function(err, req, res) {});
+        CLIENT.get(
+            {
+                path: '/audit',
+                requestTimeout: 50
+            },
+            function(err, req, res) {}
+        );
     });
 });

test/plugins/metrics.test.js

@@ -3,6 +3,7 @@
 
 // external requires
 var assert = require('chai').assert;
+
 var restify = require('../../lib/index.js');
 var restifyClients = require('restify-clients');
 
@@ -27,8 +28,7 @@ describe('request metrics plugin', function() {
             CLIENT = restifyClients.createJsonClient({
                 url: 'http://127.0.0.1:' + PORT,
                 dtrace: helper.dtrace,
-                retry: false,
-                requestTimeout: 200
+                retry: false
             });
 
             done();
@@ -103,6 +103,7 @@ describe('request metrics plugin', function() {
     it('should return metrics with pre error', function(done) {
         SERVER.on('uncaughtException', function(req, res, route, err) {
             assert.ok(err);
+            res.send(err);
         });
 
         SERVER.on(
@@ -139,6 +140,7 @@ describe('request metrics plugin', function() {
     it('should return metrics with use error', function(done) {
         SERVER.on('uncaughtException', function(req, res, route, err) {
             assert.ok(err);
+            res.send(err);
         });
 
         SERVER.on(
@@ -242,11 +244,17 @@ describe('request metrics plugin', function() {
             }
         );
 
-        CLIENT.get('/foo?a=1', function(err, _, res) {
-            // request should timeout
-            assert.ok(err);
-            assert.equal(err.name, 'RequestTimeoutError');
-        });
+        CLIENT.get(
+            {
+                path: '/foo?a=1',
+                requestTimeout: 200
+            },
+            function(err, _, res) {
+                // request should timeout
+                assert.ok(err);
+                assert.equal(err.name, 'RequestTimeoutError');
+            }
+        );
     });
 
     it('should handle uncaught exceptions', function(done) {
@@ -260,6 +268,7 @@ describe('request metrics plugin', function() {
                 {
                     server: SERVER
                 },
+                // TODO: test timeouts if any of the following asserts fails
                 function(err, metrics, req, res, route) {
                     assert.ok(err);
                     assert.equal(err.name, 'Error');

test/server.test.js

@@ -1934,6 +1934,29 @@ test("should emit 'after' on successful request", function(t) {
     });
 });
 
+test("should emit 'after' on successful request with work", function(t) {
+    SERVER.on('after', function(req, res, route, err) {
+        t.ifError(err);
+        t.end();
+    });
+
+    SERVER.get('/foobar', function(req, res, next) {
+        // with timeouts we are testing that request lifecycle
+        // events are firing in the correct order
+        setTimeout(function() {
+            res.send('hello world');
+            setTimeout(function() {
+                next();
+            }, 500);
+        }, 500);
+    });
+
+    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);
@@ -1995,6 +2018,7 @@ test(
         SERVER.on('after', function(req, res, route, err) {
             t.ok(err);
             t.equal(req.connectionState(), 'close');
+            t.equal(res.statusCode, 444);
             t.equal(err.name, 'RequestCloseError');
             t.end();
         });