Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

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

Merged
merged 15 commits into from Jun 7, 2018
Merged

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

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
15 commits
Select commit Hold shift + click to select a range
929f9a1
fix(restify): handle res close event in Node >= 10
Jun 5, 2018
b237d3e
docs(server): fix close event comments
Jun 6, 2018
99bc0bf
fix(server): fix req/res lifecycle state machine
Jun 6, 2018
c54c3c1
test(metrics): fix tests for Node < 10
Jun 6, 2018
5996573
fix(server): set connectionState to close only when req is early closed
Jun 6, 2018
245a91d
docs(server): RequestCloseError improve logs
Jun 6, 2018
f82c3a6
refactor(server): use aborted event instead of close to determinate R…
Jun 7, 2018
b84caa8
feat(server): improve close
Jun 7, 2018
4e8e5de
docs(server): fix typos
Jun 7, 2018
6cb9fc7
test(metrics): use process specific assertations
Jun 7, 2018
ee3b338
fix(server): do not set connction state to close in happy path
Jun 7, 2018
df356c9
docs(server): improve res close event docs
Jun 7, 2018
10410fb
test(metrics): add a test without timeouts
Jun 7, 2018
def6164
test(server): add a test without timeouts
Jun 7, 2018
3d0bd42
refactor(server): remove res._sent from req close handling
Jun 7, 2018
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Jump to
Jump to file
Failed to load files.
Diff view
Diff view
60 changes: 34 additions & 26 deletions lib/server.js
View file
Open in desktop
Expand Up @@ -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
Expand Down Expand Up @@ -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;
Expand All @@ -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) {
Expand Down Expand Up @@ -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;
Expand Down
17 changes: 12 additions & 5 deletions test/plugins/audit.test.js
View file
Open in desktop
Expand Up @@ -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) {}
);
});
});
23 changes: 16 additions & 7 deletions test/plugins/metrics.test.js
View file
Open in desktop
Expand Up @@ -3,6 +3,7 @@

// external requires
var assert = require('chai').assert;

var restify = require('../../lib/index.js');
var restifyClients = require('restify-clients');

Expand All @@ -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();
Expand Down Expand Up @@ -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);
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Is there any exception thrown in this test? It doesn't seem so, it seems there's only an error being passed to a handler's next callback? If so, why does the server emit 'uncaughtException'?

Also, why do we need to res.send() now when we wouldn't need to do it before?

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

f you listen to this event, you must send a response to the client. This behavior is different from the standard error events. If you do not listen to this event, restify’s default behavior is to call res.send() with the error that was thrown. - docs

So it should have been there

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

So in this test before your changes we would call done() because the 'after' event would be emitted no matter what, but we wouldn't execute the assertions in the client's request's callback?

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

yes

});

SERVER.on(
Expand Down Expand Up @@ -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);
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Same question regarding 'uncaughtException' and the need for res.send() than above.

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

see comment above

});

SERVER.on(
Expand Down Expand Up @@ -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) {
Expand All @@ -260,6 +268,7 @@ describe('request metrics plugin', function() {
{
server: SERVER
},
// TODO: test timeouts if any of the following asserts fails
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Should we file a corresponding issue?

function(err, metrics, req, res, route) {
assert.ok(err);
assert.equal(err.name, 'Error');
Expand Down
24 changes: 24 additions & 0 deletions test/server.test.js
View file
Open in desktop
Expand Up @@ -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);
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Why do we need any setTimeout call here?

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

We generate some "work" in the server to be sure that events are firing in the right order. In my previous fix tests passed with positive false.

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

What do you mean by "some work"? It seems it's not CPU-bound "work", so is it a way to make events on request/response objects to happen in a specific order or within a certain timeframe? If so, should we document what the test is actually testing?

EDIT: I get it now: we want to send the response and call the next callback on separate turns of the event loop to exercise a specific edge case. Following question + whether we should document what we're doing with this test still relevant:

Why not keeping the original test? Should be add a new test instead of replacing the existing one?

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Remaining questions above still relevant:

  1. Should we document why we want to control the timing of those operations in this test?
  2. Should we also keep the original test and add a new test with those changes?

}, 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);
Expand Down Expand Up @@ -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();
});
Expand Down