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

hekike · 2018-06-05T21:51:59Z

Req close always fires in Node 10 and fires in a process.nextTick
This PR handles the close event in restify in a way that we only return an error if the response is not flushed yet.

Related changes in Node:

Changes introduced in: nodejs/node#20941 nodejs/node#20611

misterdjules · 2018-06-06T16:05:04Z

lib/server.js

        req._connectionState = 'close';

+        // Do no handle close if request is already flushed


Typo "Do not"?

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.

good catch!

misterdjules · 2018-06-06T16:12:03Z

lib/server.js

        req._connectionState = 'close';

+        // Do no handle close if request is already flushed
+        // In Node >= 10 res's close event is always emitted


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

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.

misterdjules · 2018-06-06T16:25:22Z

lib/server.js

+    // 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() {


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.

Yes, what would you recommend to make it more robust?

misterdjules · 2018-06-06T16:26:43Z

test/server.test.js

+            res.send('hello world');
+            setTimeout(function() {
+                next();
+            }, 500);


Why do we need any setTimeout call here?

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.

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?

Remaining questions above still relevant:

Should we document why we want to control the timing of those operations in this test?

Should we also keep the original test and add a new test with those changes?

misterdjules · 2018-06-07T01:16:34Z

test/plugins/metrics.test.js

-                    assert.equal(metrics.connectionState, undefined);
+                    // close in Node >= 10
+                    assert.include(
+                        [undefined, 'close'],


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

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

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.

misterdjules · 2018-06-07T01:21:22Z

lib/server.js

-    res.once('error', onError);
+
+    // Request events
+    req.once('close', onReqClose);


The new logic seems a lot more robust than the original changes 👍

It's also ironic that the Node.js documentation states that after the 'finish' event, no more events will be emitted on the response object, when it's clearly not true after the change at nodejs/node#20611.

misterdjules · 2018-06-07T05:23:36Z

In general it seems that we should not consider that a 'close' event emitted on a request object on the server side means that the request was prematurely closed.

For instance, such an event will always be emitted when the server finishes writing on the response stream, regardless of the state of the request.

That 'close' event will also be emitted when a request aborts, which I think is the use case we're trying to handle. In that case though, the 'aborted' event is always emitted.

So instead of using the 'close' event, it seems that we should only care about the 'aborted' event on request objects on the server side. The 'aborted' event is only emitted in case the request is prematurely closed.

It might allow to simplify the current changes even further.

…equestCloseError

hekike · 2018-06-07T16:53:40Z

Excellent idea, implemented!

misterdjules · 2018-06-07T17:19:53Z

lib/server.js

        res._flushed = true;
-        req._timeFlushed = process.hrtime();
+        // Finish may alread set flushed timer


nit: typo "already".

misterdjules · 2018-06-07T17:24:36Z

lib/server.js

@@ -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);


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

DonutEspresso · 2018-06-07T17:40:11Z

lib/server.js

        self._finishReqResCycle(req, res);
    }
-    function onError(err) {
+
+    // Emitted when the response has been sent.


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

misterdjules · 2018-06-07T17:44:41Z

lib/server.js

-        req.removeListener('close', onClose);
-        res.removeListener('error', onError);
-
-        // Do not trigger false
        self._finishReqResCycle(req, res);


Why do we need to call _finishReqResCycle here?

misterdjules · 2018-06-07T17:44:49Z

lib/server.js

-        req.removeListener('close', onClose);
-        res.removeListener('finish', onFinish);
-        self._finishReqResCycle(req, res, err);
+        self._finishReqResCycle(req, res, res.err);


Why do we need to call _finishReqResCycle here?

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

misterdjules · 2018-06-07T17:51:00Z

test/plugins/metrics.test.js

@@ -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);


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?

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

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?

misterdjules · 2018-06-07T17:51:45Z

test/plugins/metrics.test.js

@@ -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);


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

see comment above

misterdjules · 2018-06-07T17:53:54Z

test/plugins/metrics.test.js

-                    assert.equal(metrics.connectionState, undefined);
+                    // close in Node >= 10
+                    assert.include(
+                        [undefined, 'close'],


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

misterdjules · 2018-06-07T17:56:04Z

test/plugins/metrics.test.js

@@ -260,6 +271,7 @@ describe('request metrics plugin', function() {
                {
                    server: SERVER
                },
+                // TODO: test timeouts if any of the following asserts fails


Should we file a corresponding issue?

misterdjules · 2018-06-07T17:57:26Z

@hekike Added a bunch more comments, but I think this is going in the right direction, thank you very much again for considering my feedback!

misterdjules · 2018-06-07T18:22:12Z

test/plugins/metrics.test.js

-                    assert.equal(metrics.connectionState, undefined);
+                    // close doesn't always fire in Node < 10
+                    assert.include(
+                        [undefined, 'close'],


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.

misterdjules · 2018-06-07T19:55:21Z

test/plugins/metrics.test.js

@@ -63,6 +63,7 @@ describe('request metrics plugin', function() {
                    assert.isAtLeast(metrics.latency, 150);
                    assert.isAtLeast(metrics.totalLatency, 150);
                    assert.equal(metrics.path, '/foo');
+                    // close doesn't always fire in Node < 10


Is that comment still relevant?

misterdjules · 2018-06-07T19:55:44Z

test/plugins/metrics.test.js

@@ -271,6 +281,7 @@ describe('request metrics plugin', function() {
                    assert.isNumber(metrics.latency, 200);
                    assert.equal(metrics.path, '/foo');
                    assert.equal(metrics.method, 'GET');
+                    // close doesn't always fire in Node < 10


Is that comment still relevant?

misterdjules · 2018-06-07T20:25:48Z

lib/server.js

+        // Set status code and _sent for audit
+        // as req is already closed connection
+        res.statusCode = err.statusCode;
+        res._sent = true;


Why do we need to set _sent to true?

misterdjules

Beautiful! Thanks for being persistent and patient with me!

hekike · 2018-06-07T20:33:28Z

Thanks for re-reviewing, restify just get better ;)

retrohacker mentioned this pull request Jun 5, 2018

style: fix failing check-style #1671

Merged

hekike force-pushed the fix/node-10 branch from 4b23613 to b6491ec Compare June 5, 2018 23:55

fix(restify): handle res close event in Node >= 10

929f9a1

Changes introduced in: nodejs/node#20941 nodejs/node#20611

hekike force-pushed the fix/node-10 branch from b6491ec to 929f9a1 Compare June 6, 2018 15:23

hekike changed the title ~~WIP: fix(server): address Node v10.x req close event firing order~~ fix(server): address Node v10.x req close event firing order Jun 6, 2018

hekike requested review from DonutEspresso and yunong June 6, 2018 15:28

misterdjules reviewed Jun 6, 2018

View reviewed changes

Peter Marton added 5 commits June 6, 2018 11:27

docs(server): fix close event comments

b237d3e

fix(server): fix req/res lifecycle state machine

99bc0bf

test(metrics): fix tests for Node < 10

c54c3c1

fix(server): set connectionState to close only when req is early closed

5996573

docs(server): RequestCloseError improve logs

245a91d