diff --git a/lib/server.js b/lib/server.js index 3aeea5c4f..de17a128e 100644 --- a/lib/server.js +++ b/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; diff --git a/test/plugins/audit.test.js b/test/plugins/audit.test.js index ed7bab084..8959ce53c 100644 --- a/test/plugins/audit.test.js +++ b/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) {} + ); }); }); diff --git a/test/plugins/metrics.test.js b/test/plugins/metrics.test.js index e99315817..638f14ce6 100644 --- a/test/plugins/metrics.test.js +++ b/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'); diff --git a/test/server.test.js b/test/server.test.js index f9b7fd225..f5bb4b60f 100644 --- a/test/server.test.js +++ b/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(); });