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

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 7 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.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
58 changes: 31 additions & 27 deletions lib/server.js
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -1091,7 +1091,8 @@ Server.prototype._onHandlerError = function _onHandlerError(err, req, res) {
return;
}

res._handlersFinished = true;
// Handlers doesn't continue when error happen
self._onHandlerStop(req, res);
Copy link
Contributor

Choose a reason for hiding this comment

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

What are the implications of calling _onHandlerStop instead of "just" setting _handlersFinished = true?

Copy link
Member Author

Choose a reason for hiding this comment

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

reverted


// Preserve handler err for finish event
res.err = res.err || err;
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
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 _sent for audit
// as req is already closed connection
res.statusCode = err.statusCode;
res._sent = true;
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 to set _sent to true?

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,24 @@ 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
self._finishReqResCycle(req, res);
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 to call _finishReqResCycle here?

}
function onError(err) {

// Emitted when the response has been sent.
Copy link
Member

Choose a reason for hiding this comment

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

Is this still true? Also, I think I know the answer, but is it possible for close to get fired but _flushed is false?

function onResClose() {
res._flushed = true;
req._timeFlushed = process.hrtime();
// Finish may alread set flushed timer
Copy link
Contributor

Choose a reason for hiding this comment

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

nit: typo "already".

req._timeFlushed = req._timeFlushed || process.hrtime();

req.removeListener('close', onClose);
res.removeListener('finish', onFinish);
self._finishReqResCycle(req, res, err);
self._finishReqResCycle(req, res, res.err);
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 to call _finishReqResCycle 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.

To tigger after (after is triggered after both handlers are finished and req is flushed)

}
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 +1261,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
Original file line number Diff line number Diff line change
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) {}
);
});
});
34 changes: 25 additions & 9 deletions test/plugins/metrics.test.js
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -27,8 +27,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 @@ -63,7 +62,11 @@ describe('request metrics plugin', function() {
assert.isAtLeast(metrics.latency, 150);
assert.isAtLeast(metrics.totalLatency, 150);
assert.equal(metrics.path, '/foo');
assert.equal(metrics.connectionState, undefined);
// close in Node >= 10
assert.include(
[undefined, 'close'],
Copy link
Contributor

Choose a reason for hiding this comment

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

What does that '[undefined, 'close'] mean?

Copy link
Member Author

Choose a reason for hiding this comment

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

Any of them. Undefined is the unknown connection state basically.

Copy link
Contributor

Choose a reason for hiding this comment

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

What are the cases when the connection state would be 'close'? Shouldn't it be 'close' only when the request was aborted? In this case it doesn't seem like the request would be aborted.

Copy link
Contributor

Choose a reason for hiding this comment

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

The problem with using assert.include here is that if we run this test with Node.js >= 10.x and we expect the connection state to be 'close', the test would pass even if the connection state was undefined. Would it be too much work to differentiate between node >= 10.x and < 10.x here and have two different asserts, something like:

if (process.version >= 10.0) {
  assert.equal(metrics.connectionState, 'close');
} else {
  assert.equal(metrics.connectionState, undefined);
}

?

Same for all other connection state assertions in this file.

metrics.connectionState
);
assert.equal(metrics.method, 'GET');
assert.isNumber(metrics.inflightRequests);

Expand Down Expand Up @@ -103,6 +106,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 +143,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 +247,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 +271,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 All @@ -271,7 +283,11 @@ describe('request metrics plugin', function() {
assert.isNumber(metrics.latency, 200);
assert.equal(metrics.path, '/foo');
assert.equal(metrics.method, 'GET');
assert.equal(metrics.connectionState, undefined);
// close in Node >= 10
assert.include(
[undefined, 'close'],
Copy link
Contributor

Choose a reason for hiding this comment

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

Why is there two possible values here? Shouldn't we always expect 'close'?

metrics.connectionState
);
assert.isNumber(metrics.inflightRequests);
return done();
}
Expand Down
9 changes: 7 additions & 2 deletions test/server.test.js
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -1924,8 +1924,12 @@ test("should emit 'after' on successful request", function(t) {
});

SERVER.get('/foobar', function(req, res, next) {
res.send('hello world');
next();
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

@misterdjules misterdjules Jun 7, 2018 •
edited
Loading

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) {
Expand Down Expand Up @@ -1995,6 +1999,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