7.x: new router and middleware system #1561

hekike · 2017-11-09T12:29:54Z

Replace the router and middleware logic with a more performant solution.
Goal: zero or almost zero API/functionality change with significant performance improvement.

Pt 1. (#1554) was nice for dumb servers and synthetic tests; this should be more useful for real-world applications, especially ones with many routes.

Changes

Replaces the router with the Radix Tree based find-my-way
New middleware system called chain.js, similar to connect
Move versioning and contentType routing into a conditionalHandler plugin, see:

server.use(restify.plugins.conditionalHandler({
   contentType: 'application/json',
   version: '1.0.0'
   handler: function (req, res, next) {
       next();
   })
});

server.get('/hello/:name', restify.plugins.conditionalHandler([
  {
     version: '1.0.0',
     handler: function(req, res, next) { res.send('1.x') }
  },
  {
     version: ['1.5.0', '2.0.0'],
     handler: function(req, res, next) { res.send('1.5.x, 2.x') }
  },
  {
     version: '3.0.0',
     contentType: ['text/html', 'text/html']
     handler: function(req, res, next) { res.send('3.x, text') }
  },
  {
     version: '3.0.0',
     contentType: 'application/json'
     handler: function(req, res, next) { res.send('3.x, json') }
  }
]);

Hints for review:

response.js: 100% new, do not review it by diff
server.js: the complete request handling logic is new, I recommend to review it as a new file

TODO

Breaking Changes

Nonstrict-routing is not available
Limited RegExp usage in router path see https://github.com/delvedor/find-my-way
Remove already deprecated next.ifError
disable DTrace probes by default ( I know it's painful, but most of the people don't know/use it, it causes ~10% throughput improvement in all benchmark tests), createServer({ dtrace: true })
Router versioning and contentType routing moved to conditioalHandler plugin, see above
once is not applied automatically for multiple next() calls, use the new onceNext: true server option, strictNext is the same

Results

Test machine: Mid 2014 MBP, 2.6 i5 16GB RAM
(~30% improvement compared to 6.3.2 (#1554), ~50% compared to 6.3.1)

Result: dumb server

Note: Most of the performance improvements in these benchmarks come from the new middleware logic and other optimizations, the router performance is not tested here as it uses LRU cache.

---- response-json ----
✔ Results saved for head/response-json
✔ Results saved for stable/response-json
response-json throughput:
{
    "significant": "***",
    "equal": false,
    "wins": "head",
    "diff": "30.21%"
}

---- response-text ----
✔ Results saved for head/response-text
✔ Results saved for stable/response-text
response-text throughput:
{
    "significant": "***",
    "equal": false,
    "wins": "head",
    "diff": "34.18%"
}

Result: middleware

---- middleware ----
✔ Results saved for head/middleware
✔ Results saved for stable/middleware
middleware throughput:
{
    "significant": "***",
    "equal": false,
    "wins": "head",
    "diff": "44.68%"
}

Result: heavy router

Note: Disabling (mocking out) cache in a stable version: it's not fair as it aims to the worst case, cache hit ratio is 0%. However, it's still better than the worst case scenario as it least doesn't require extra time to maintain the LRU cache.
There is no other way to simulate 100+ different endpoint calls with the current benchmark suite.

---- router-heavy ----
✔ Results saved for head/router-heavy
✔ Results saved for stable/router-heavy
router-heavy throughput:
{
    "significant": "***",
    "equal": false,
    "wins": "head",
    "diff": "3086.8%"
}

hekike · 2017-11-09T13:37:33Z

@DonutEspresso @retrohacker @yunong what do you think, should I continue? Even if I'm going to end up with necessary API change?

I mean it's huge and risky but those numbers look great :)

retrohacker

I love the overall approach! Surprisingly reduces complexity in the process!

retrohacker · 2017-11-09T18:16:34Z

lib/middle.js

+var proto = {};
+
+/* istanbul ignore next */
+var defer =


Why are we checking for the existence of setImmediate?

Sry, I didn't make it clear that this is connect, I copy-pasted it, because I needed to extend it with the next(false) -> abort logic. :( Later we can try to open a PR or replace next(false) with something else.

hekike · 2017-11-10T08:07:24Z

@retrohacker I added two more benchmarks: middleware and router-heavy
You can find the results in the description.

hekike · 2017-11-10T10:04:50Z

Question: should next(false) only prevent to run the handlers in the same category or all of the handlers, which one:

next(false) in pre, stops the next pre handlers but runs all the use and router handlers
next(false) in pre, stops the next pre and use handlers but runs router
next(false) in pre, stops all the upcoming handlers

hekike · 2017-11-11T09:47:52Z

Question: I don't find where the createServer({ dtrace }) options it handled, does it still exist? I mean the option itself?

DonutEspresso · 2017-11-15T22:01:16Z

Whoaaaaaaa this is awesome 🎉 🎉 🎉

Question: should next(false) only prevent to run the handlers in the same category or all of the handlers

The intention of false was to originally stop all subsequent middlewares in the event you had flushed a response already and considered this request complete. So I think 3 should be the desired behavior (if it isn't already).

hekike · 2017-11-16T16:14:22Z

@DonutEspresso @yunong @retrohacker I have an issue with the 'close' and 'aborted' test cases:
https://github.com/restify/node-restify/blob/master/test/server.test.js#L2648

No matter how I end/destroy/close the req/res/socket I always have both the server.on('aborted') and server.on('close') events, I cannot abort without close event, and I cannot close without aborted event. Is it possible to trigger close event without aborted? Does it make sense to separate the two connection states in restify? If I understand correctly we will always have close https://nodejs.org/api/http.html#http_event_aborted

yunong · 2017-11-17T20:54:48Z

@hekike I think it may be the case that Node core actually fires both events? We could check the source code to be sure, but if that's the case, then it's okay that both events fire.

DonutEspresso · 2017-11-17T23:21:53Z

Hmm great question - I was under impression a close wouldn't cause an abort but I can see both events being fired now. Short answer: I don't know! May have to dig into core to see if there is anything worth differentiating there.

hekike · 2017-11-18T09:03:06Z

close and aborted: Thanks for the help! I've checked out Node core and seems to be that emit('aborted') is always immediately followed by an emit('close') in node core. (I'm not 100% sure) I also opened a question here: nodejs/help#978

See: _http_server.js#L417 and http2/compat.js#L14

in 7.x I unified server close and aborted events. restify throws only RequestCloseError, see: 0da8219

DonutEspresso

This is ridiculously awesome @hekike!! 💯 🍾 🎉 Thank you for all the hard work. I left some questions and minor comments. I am in favor of nearly all the proposed changes in this PR. The only one I have some concerns with are:

Not super comfortable dropping the free from regexp routes. This may not be palatable to some of the power users. As it's not supported directly via find-my-way, this would be a pretty big undertaking if we wanted to continue supporting. Would love to have more discussions around this one.

More general feedback around the proposed implementation:

Unless I'm missing something, I think the order of request processing being proposed in this PR (pre -> use -> route vs pre -> route -> use) is different than the current behavior. If we keep the existing ordering I think we can keep bothserver.param and current usage of req.params.
There's lots of async orchestration in the processing of a request (pre/route/use/handler/chain) - would love to see if we could use something like vasync to help facilitate that. Generally, an error anywhere in the processing jumps us directly to the end, so would like to see if this would help with that (try vasync.waterfall or vasync.pipeline). Since vasync also keeps returns internal async state as a variable to us, we could store it on the request, which could be used in core dumps. That combined with req._currentHandler would make debugging stuck requests a lot easier!
With conditionalHandler, how will we handle multiple matches/order of precedence?

DonutEspresso · 2017-11-21T23:35:02Z

lib/chain.js

+ * @public
+ * @class Chain
+ * @param {Object} [options] - options
+ * @param {Boolean} [options.onceNext=false] - Prevents calling next multiple


Is there a use case where we would want this to be false? Or is this primarily for backwards compatibility? Actually, now that I think about it, I would be in favor of moving to strictNext as the default behavior.

Yes, it's for backward compatibility. Making strictNext to the default causes performance degradation.

DonutEspresso · 2017-11-21T23:37:08Z

lib/chain.js

+    }
+
+    // continue
+    next(error, req, res);


Maybe this is something for prettify in another PR - but I'd like to add some rules around always returning on known cb handles (callback, next, cb, done, etc.)

👍 on leaving style changes to their own PR and fixing there if they pass lint. Suspect this isn't the only place in the code base we do this.

DonutEspresso · 2017-11-21T23:38:07Z

lib/chain.js

+ */
+Chain.prototype.getHandlers = function getHandlers() {
+    return this._stack.map(function map(stackItem) {
+        return stackItem.handle;


It looks like an item is just { handle: <fn> }. Could we add some documentation maybe in the ctor section describing structure of the items in the stack?

DonutEspresso · 2017-11-21T23:41:55Z

lib/chain.js

+ * @param {Function|Chain} handle - handler or Chain instance
+ * @returns {undefined} no return value
+ */
+Chain.prototype.use = function use(handle) {


I think we're probably trying to reflect well known nomenclature, but is this closer to doing something like "add a function to this chain"? If so, what do you think about just calling it chain.add()/append()?

DonutEspresso · 2017-11-21T23:42:55Z

lib/chain.js

+ * @param {Function} done - final handler
+ * @returns {undefined} no return value
+ */
+Chain.prototype.handle = function handle(req, res, done) {


Thoughts on calling it run() or execute()? I found handle.handle() a little confusing :)

DonutEspresso · 2017-11-22T00:01:28Z

lib/server.js

 */
-Server.prototype._routeAndRun = function _routeAndRun(req, res) {
+Server.prototype._onRequest = function _onRequest(req, res) {


So clean, so simple 💯

DonutEspresso · 2017-11-22T00:15:18Z

lib/server.js

+
+/**
+ * Wrapper method for emitting the after event. this is needed in scenarios
+ * where the async formatter has failed, and the ot assume that the


This comment looks a little outdated since we don't have async formatters anymore - don't want to bikeshed on this PR but could make a note to come back and clean up comments in another PR.

DonutEspresso · 2017-11-22T00:16:58Z

lib/server.js

@@ -1528,7 +1283,7 @@ function errEvtNameFromError(err) {
        // remap the name for router errors
        return 'VersionNotAllowed';
    } else {
-        return err.name.replace(/Error$/, '');
+        return err.name ? err.name.replace(/Error$/, '') : 'Error';


Under what scenarios does err.name not exist?

DonutEspresso · 2017-11-22T00:25:08Z

lib/server.js

+//            4.2 _afterRoute (runs after last handler called next)
+//              4.3 _afterRoute (when, next('string') called)
+//              4.3 _routeErrorResponse (when error happaned in router)
+// 5. _finishReqResCycle (on response "finish" and "error" events)


This waterfall is great! The additional granularity is nice. Is this order different than the current behavior? I thought the order is as follows:

pre

router.find

use (use only applies to routes that were successfully routed)

done/done(err)

You are right, I was dumb enough to work based on my express and koa experience instead of reading the docs carefully :/

Allows you to add in handlers that run for all routes. Note that handlers added via use() will run only after the router has found a matching route. If no match is found, these handlers will never run. - restify docs

(In express/koa everything is a middleware, the router as well, so they don't make difference between pre/after route, it depends on the order of the middleware "registration")

Btw maybe it's misleading for others as well coming from the express world, shouldn't we keep use as an alias and introduce a new term that reflects it's behavior better? Like afterRoute() or useRoute(), these are not very good names, but something like these :)

DonutEspresso · 2017-11-22T00:42:23Z

benchmark/benchmarks/router-heavy.js

+    : require('restify');
+
+var server = restify.createServer();
+var path = '/whiskeys/scotch/islay/lagavulin/16-years/50';


DonutEspresso · 2018-02-05T22:00:09Z

docs/guides/6to7guide.md

+
+## Breaking Changes
+
+### Server throws `RequestCloseError` instead of `RequestAbortedError`


I don't think the server actually "throws" right? Do we mean that the server just logs a RequestCloseError? We may also want to update RequestCloseError's default status code to 444.

DonutEspresso · 2018-02-05T22:01:45Z

docs/guides/6to7guide.md

+DTrace probes comes with some performance impact that's fine for the sake of
+observability but you may don't use it at all.
+
+### Change in calling `next` multiple times


Is performance the motivation behind this new default behavior?

Also have a preference for this to remain unchanged. Throwing by default helps us catch a whole class of bugs.

Yes, performance is the motivation behind.
@retrohacker do you mean at Netflix? We can re-enable it with the option for NQ services.

@hekike I just mean in general. We are a framework for building production ready REST services, I'm not sure this is in line with our goals as a project.

DonutEspresso · 2018-02-05T22:02:01Z

docs/guides/6to7guide.md

+### Router versioning and content type
+
+`accept-version` and `accept` based conditional routing moved to the
+`conditioalHandler` plugin, see docs or example:


s/conditioalHandler/conditionalHandler

DonutEspresso · 2018-02-05T22:02:54Z

lib/errorTypes.js

@@ -3,4 +3,4 @@
 var errors = require('restify-errors');

 errors.makeConstructor('RequestCloseError');
-errors.makeConstructor('RequestAbortedError');
+errors.makeConstructor('RouteMissingError');


Where is this error used?

This error existed before but was created locally.
When a code calls next('route-name') but the route doesn't exist.
It's a programmatic error.

DonutEspresso · 2018-02-05T22:06:08Z

lib/plugins/inflightRequestThrottle.js

@@ -65,8 +65,7 @@ function inflightRequestThrottle(opts) {
                },
                'maximum inflight requests exceeded, rejecting request'
            );
-            res.send(plugin._err);
-            return next(false);
+            return next(plugin._err);


I can't comment on the exact line, but I think this file here needs to create the error inline to get a proper stack trace (rather than creating it ahead of time).

DonutEspresso · 2018-02-05T22:44:57Z

lib/server.js

-    argumentsToChain(handlers).forEach(function forEach(h) {
-        self.before.push(h);
+    argumentsToChain(handlers).forEach(function forEach(handler) {
+        handler._name = handler.name || 'pre-' + self.preChain.count();


Isn't this already happening in router?

Router, pre, and use are registered separately with a different prefix.

DonutEspresso · 2018-02-05T22:47:20Z

lib/server.js

+//         3.2. _afterRoute (runs after route handlers are finised,
+//                          triggers use)
+//          4.1 _runUse
+//            4.2. _afterUse


I know we chatted about this before, are we changing the pre -> use -> route order? Looks like this is breaking from 6.x.

No, it's the same, the doc was wrong, fixed.

DonutEspresso · 2018-02-05T22:50:56Z

lib/server.js

-
-    req.timers = [];
+    // Preserve handler err for finish event
+    res.err = res.err || err;


I didn't see where this is initially set - what's the use case for storing it on the response directly?

It's used when the request succeeds but the response is an error:
https://github.com/restify/node-restify/blob/feat/new-router/lib/server.js#L1093

This is how it's ensured that error is always emitted in after.
It's not an elegant solution decorating the res object, but in the earlier version it was way to complex, I like that now it's based on the response events.

DonutEspresso · 2018-02-05T22:53:52Z

lib/server.js

+        res.removeListener('finish', onFinish);
+        self._finishReqResCycle(req, res, err);
+    }
+    res.once('finish', onFinish);


Is this a breaking change from 6.x? IIRC in 6.x we consider a request finished once it has reached the end of the handler chain. Using this pattern, it won't fire until the request is completely done.

I have to think about whether this is better/worse/different, but definitely has an impact on how we might view metrics. cc @yunong

I didn't know that we fire it before the response is finished. What's the reason behind it?

DonutEspresso · 2018-02-05T22:54:48Z

lib/server.js

+
+    // after event has signature of function(req, res, route, err) {...}
+    if (!res.finished && !req.closed()) {
+        res.once('finish', function resFinished() {


Since finishReqResCycle() doesn't get triggered until finish event fires, is this scenario possible anymore?

Good catch!

DonutEspresso · 2018-02-05T23:03:52Z

Great work! Love that we added benchmarks - thanks for digging in and getting those perf numbers. 💯 Left some comments - mostly minor, the two big things for me are:

~~1) 6.x order is pre->use->route, order here looks like pre->route->use. Did we agree to a breaking change on that?~~ EDIT: I can't read, this is fine now. Just needs update on the JSDoc.
2) In 6.x a request is considered "complete" (i.e., causing audit log and metrics plugin to fire) when reaching the end of the next chain. "Completion" is synonymous with the 'after' event, where audit log and metrics are triggered. With this PR, "completion" gets delayed until the request object's finish event is fired. Not sure if this is good/bad yet but it is definitely different and may have an impact on how we interpret metrics. Thoughts from the rest of the team? cc @yunong @retrohacker

hekike · 2018-02-09T23:22:40Z

We discussed the request "complete" topic in person with @DonutEspresso and we decided that the new behavior is acceptable and even better in some use cases like load shedding calculations where you really want to know when the request doesn't use your resources anymore.

To have the correct timing about handler categories like pre, use and router execution durations a new timing object will be introduced in the next version of restify, related issue: #1603

cc @yunong @retrohacker

hekike · 2018-02-13T16:17:16Z

@DonutEspresso I added the new request timings and explained the change in the migration guide in a separate commit.

hekike · 2018-02-15T18:59:34Z

We discussed in person that we need two latencies one when the request is flushed and one when all handlers are finished. The after event and inflight request counter will wait for both request flushing and handler finish.

DonutEspresso · 2018-02-23T08:21:42Z

lib/plugins/metrics.js

@@ -39,7 +39,7 @@ function createMetrics(opts, callback) {
            // REST verb
            method: req.method,
            // overall request latency
-            latency: hrTimeDurationInMs(req._time, process.hrtime()),
+            latency: hrTimeDurationInMs(req._time, req._timeFlushed),


This looks great!

I was thinking there might be one more timer would be useful - one that is started _onRequest and finishes in _finishReqResCycle (when both res._flushed and res._handlersFinished are true). This would probably be the closest "end to end" time view of a request we see in our system. Maybe something like totalLatency?

Minus this last timer I think we are good to go!

hekike · 2018-02-23T16:28:00Z

@DonutEspresso totalLatency added! 1acc1be

…lugin

…handler is finished

BREAKING CHANGE: - Server returns `RequestCloseError` instead of `RequestAbortedError` - Non-strict routing is gone - Different `RegExp` usage in router path and wildcards - Remove already deprecated `next.ifError` - Disable DTrace probes by default - Change in calling `next` multiple times - Router versioning and content type as a separate plugin: `conditionalHandler` - After event fires when both request is flushed and the last handler is finished - Metrics plugin latency logic changes and new latencies were added For more info see the `/guides/6to7guide.md`.

hekike added Do Not Merge Needs Discussion Unconfirmed labels Nov 9, 2017

hekike changed the title ~~Performance improvements pt2: new router and middleware system~~ [WIP] Performance improvements pt2: new router and middleware system Nov 9, 2017

retrohacker reviewed Nov 9, 2017

View reviewed changes

hekike force-pushed the feat/new-router branch 5 times, most recently from bd2c358 to 4b2c8fb Compare November 15, 2017 15:50

hekike changed the title ~~[WIP] Performance improvements pt2: new router and middleware system~~ 7.x: new router and middleware system Nov 15, 2017

hekike removed Do Not Merge Unconfirmed Needs Discussion labels Nov 15, 2017

hekike force-pushed the feat/new-router branch from 8d255c6 to 0da8219 Compare November 18, 2017 08:47

hekike requested review from yunong and DonutEspresso November 19, 2017 08:47

hekike force-pushed the feat/new-router branch from c4202e4 to b7d4e5f Compare November 20, 2017 12:24

hekike mentioned this pull request Nov 20, 2017

server _routeErrorResponse avoiding uncaughtException by only sending response when not sent #1568

Merged

hekike force-pushed the feat/new-router branch from b7d4e5f to 23b2aed Compare November 21, 2017 07:40

DonutEspresso requested changes Nov 22, 2017

View reviewed changes

hekike changed the base branch from master to next February 1, 2018 20:53

DonutEspresso requested changes Feb 5, 2018

View reviewed changes

retrohacker mentioned this pull request Feb 8, 2018

.get does not identify valid route request after it returned correct response #1581

Closed

hekike force-pushed the feat/new-router branch 2 times, most recently from 4e0bc45 to b30396f Compare February 9, 2018 00:18

hekike force-pushed the feat/new-router branch from 3ffa6c3 to 3dfdcbf Compare February 13, 2018 16:16

hekike force-pushed the feat/new-router branch 2 times, most recently from f9f91e8 to 891e737 Compare February 13, 2018 16:27

DonutEspresso reviewed Feb 23, 2018

View reviewed changes

DonutEspresso approved these changes Feb 23, 2018

View reviewed changes

hekike force-pushed the next branch from 51bd490 to 194a2fe Compare February 23, 2018 16:29

hekike and others added 3 commits February 23, 2018 09:13

feat(server): new router and middleware system

99123d1

feat(plugins): add pre, use and route handlers latencies to metrics p…

f9ed7ed

…lugin

feat(server): emit after event when both request is flushed and last …

f7cfba1

…handler is finished

hekike force-pushed the feat/new-router branch 2 times, most recently from 844ccbe to c43d236 Compare February 23, 2018 18:51

feat(plugins): add totalLatency to metrics plugin

3616028

hekike force-pushed the feat/new-router branch from c43d236 to 3616028 Compare February 23, 2018 19:12

hekike merged commit 785d7a6 into next Feb 23, 2018

hekike deleted the feat/new-router branch February 23, 2018 19:20

dependabot-preview bot mentioned this pull request Mar 21, 2018

Update restify requirement to ^7.0.0 javimudi/pm2-deploy-rest-interface#21

Closed

renovate bot mentioned this pull request Apr 9, 2018

Update dependency restify to v7 [reopen please] mozilla/ensemble-transposer#49

Closed


		## Breaking Changes

		### Server throws `RequestCloseError` instead of `RequestAbortedError`

7.x: new router and middleware system #1561

7.x: new router and middleware system #1561

Conversation

hekike commented Nov 9, 2017 • edited

Changes

TODO

Breaking Changes

Results

Result: dumb server

Result: middleware

Result: heavy router

hekike commented Nov 9, 2017 • edited

retrohacker left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

hekike Nov 9, 2017 • edited

Choose a reason for hiding this comment

hekike commented Nov 10, 2017

hekike commented Nov 10, 2017

hekike commented Nov 11, 2017 • edited

DonutEspresso commented Nov 15, 2017

hekike commented Nov 16, 2017

yunong commented Nov 17, 2017

DonutEspresso commented Nov 17, 2017

hekike commented Nov 18, 2017

DonutEspresso left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

DonutEspresso commented Feb 5, 2018 • edited

hekike commented Feb 9, 2018 • edited

hekike commented Feb 13, 2018

hekike commented Feb 15, 2018

Choose a reason for hiding this comment

Choose a reason for hiding this comment

hekike commented Feb 23, 2018

hekike commented Nov 9, 2017 •

edited

hekike commented Nov 9, 2017 •

edited

hekike Nov 9, 2017 •

edited

hekike commented Nov 11, 2017 •

edited

DonutEspresso commented Feb 5, 2018 •

edited

hekike commented Feb 9, 2018 •

edited