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.

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
30 changes: 24 additions & 6 deletions lib/server.js
Expand Up @@ -1143,19 +1143,37 @@ Server.prototype._setupRequest = function _setupRequest(req, res) {
// 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);

req._connectionState = 'close';

// Do no handle close if request is already flushed
Copy link
Contributor

Choose a reason for hiding this comment

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

Typo "Do not"?

Copy link
Contributor

Choose a reason for hiding this comment

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

Also, is it "if response is already flushed" here, or do we mean "request" in the sense of "the whole request/response"? I think it'd help to distinguish between request and response here for clarity, and in this case it seems we're checking if the response is flushed.

Copy link
Member Author

Choose a reason for hiding this comment

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

good catch!

// In Node >= 10 res's close event is always emitted
Copy link
Contributor

Choose a reason for hiding this comment

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

Is is Node > 10.4.0 at least? It seems that change hasn't been made it to any release yet.

Copy link
Member Author

Choose a reason for hiding this comment

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

This fix seems to be working with all supported Node.js versions, 6,8 10.0.0 and 10.4.0 as well.
I made the comment more accurate.

// Introduced in: https://github.com/nodejs/node/pull/20611
if (res._flushed) {
return;
}

// Handle close and return error if request is not flushed yet
res._flushed = true;
req._timeFlushed = process.hrtime();

// Request was aborted or closed. Override the status code
res.statusCode = 444;

self._finishReqResCycle(req, res, new errors.RequestCloseError());
self._finishReqResCycle(
req,
res,
res.err || new errors.RequestCloseError()
);
}
req.once('close', onClose);

// Handle res's close on to the next cycle
// Required in Node >= 10:
// introduced in: https://github.com/nodejs/node/pull/20941
req.once('close', function onReqClose() {
Copy link
Contributor

Choose a reason for hiding this comment

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

Is it that because res' 'close' event can now be emitted using process.nextTick we want to handle req's 'close' event on the actual next tick of the libuv event loop so that we process req's 'close' event after res's 'close' event?

It seems this ordering could break if .e.g node started emitting the res' 'close' event using setImmediate, which seems a bit brittle.

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, what would you recommend to make it more robust?

setImmediate(onClose);
});

// Response lifecycle events
function onFinish() {
Expand Down
17 changes: 12 additions & 5 deletions test/plugins/audit.test.js
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) {}
);
});
});
8 changes: 6 additions & 2 deletions test/server.test.js
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

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