Sails: Unskippable 50ms delay when making a POST/PUT/DELETE request with form-urlencoded or json data

[kevinburkeshyp]

If you make a request to Sails with any content-type that's not a multipart form upload, Sails's default body parser will sleep for 50 milliseconds before yielding control. You can verify this by checking out the latest upstream (2b908c9147039eb83cacea328a1d5431f6608371, at the time of writing) and running the following commands:

1. npm install
2. ./bin/sails.js new slow-body-parser
3. cd slow-body-parser
4. DEBUG=skipper ./node_modules/sails/bin/sails.js lift

and then making a POST request to localhost:1337, for example:

/usr/bin/time curl -iXPOST -H 'Content-Type: application/json' localhost:1337 -o output.html -vv

You will observe the following in your Sails log output:

  skipper multiparty form emitted error: +45m [Error: missing content-type header]
  skipper passed control to app because 50ms elapsed +52ms
  skipper waiting for any text params +0ms
  skipper Passing control to app... +7ms

(I'm not sure where the 45m comes from; it seems like the skipper output is measuring the amount of time since the last request, which was about 45 minutes ago, on my machine)

Anyway, here's the time output:

0.08 real         0.00 user         0.00 sys

And here's the time output if I do a GET request, say /usr/bin/time curl -i localhost:1337 -o output.html -vv. Note that the total time has decreased from 80ms to 30ms.

0.03 real         0.00 user         0.00 sys

I'm sure there's a good reason for doing this, but _it sure is unexpected_, and I'd expect this behavior to be called out in large type in the README. I also expect that the vast majority of POST/PUT requests are using form-urlencoded or JSON content types instead of multipart file upload, which makes it a bit bewildering that these are handled by delaying.

You may be saying to yourself "50ms isn't actually that long." Without this in place, the average test time for a controller test drops from 70-100ms to 20-50ms, about a 100% speed improvement. Eyeballing our request logs, an average POST request takes anywhere from 80 to 150ms; it would be a pretty significant performance increase if this dropped to 30-100ms. The delay also means the web node is holding open the request/tying up memory for the duration of the 50ms sleep.

It looks like the offending code is here - the comment there about why the value is hard coded to 50ms seemed like it was committed when only half-complete. https://github.com/balderdashy/skipper/blob/master/lib/Parser/prototype.parseReq.js#L132. I'm also confused about why the behavior is to _delay_ if the content-type is unknown, instead of just to hit the callback.

Anyway, I would appreciate advice on what I/we can do to mitigate this or work around it. Thanks!

[tjwebb]

You may be saying to yourself "50ms isn't actually that long."

I'm not saying that to myself. 50ms is a long time to waste on _each and every request_. I'll look into it. It smells like a workaround/hack that probably doesn't need to exist.

[kevinburkeshyp]

For the moment we're replacing these lines in config/http.js:

       'bodyParser',
       'handleBodyParserError',

with these

    [
       'jsonBodyParser',
       'formBodyParser',
    ],
    jsonBodyParser: bodyParser.json(),
    formBodyParser: bodyParser.urlencoded({extended: true}),

[sgress454]

This delay is covered in the FAQ for skipper. Its intent is to allow the body parser time to identity incoming file streams before passing control back to the controller. But, it should only need to do that for multipart requests; we should be able to avoid the delay for everything else. I'll look into it.

[sgress454]

Ok! Published a new version of Skipper that skips (no pun intended) the 50ms delay for non-multipart requests.

[kevinburkeshyp]

Thanks!

[RWOverdijk]

Sleeping to fix something? Are you being serious?

[AeroNotix]

The drama in node.js libraries never ceases to amaze. Good entertainment!

[sgress454]

Ha! To be clear though, this delay isn't "fixing" anything. You can look at it instead as guaranteeing that any request containing a file will pass control to app code in 50ms, versus having to possibly wait multiple seconds (minutes? hours?) for the file to upload (in the default Express bodyparser case, this meant buffering to disk/memory) before being able to run your code. If your code uses text params to determine whether or not to abort the upload, it sure is nice to only have to wait 50ms to do so! Obviously this didn't make sense for non-multipart requests, hence this issue, which is now fixed.

[mikermcneil]

@RWOverdijk I'm not sure I follow what you mean here, but I should reiterate that the 50ms timeout is not a hack-- it's intentional (more on that in a sec). Also, just to be clear, it is not a sleep because it does not block-- the Node process continues to handle requests.

@AeroNotix If performance patches for open-source modules aren't drama, I don't know what is. Maybe you could write a telenovela about this?

This is a closed issue that has been resolved with a fix published to NPM for over six months now, so I'm going to go ahead and wrap up:

You can choose to use any body parser you like in Sails-- like all of the other built-in middleware, it is completely configurable. As @sgress454 hinted at, our approach in the _default body parser_, Skipper, was a deliberate design decision I made in order to empower Sails apps to support terabyte file uploads instead of the original default behavior in Express and Sails, which left your app vulnerable to DoS attacks out of the box. The easy solution would have been to remove file upload support from core, which is what Express did (rightly IMO-- it's a different kind of framework). But I believed then (and still do now) that for Sails, that would be a cop-out.

What was _not_ a deliberate decision was that, if an incoming request did not include a content-type header that explicitly declared itself a multipart upload, the underlying bodyparser (multiparty) would emit an error event. This is not necessarily wrong, but _it sure was unexpected_, because it worked differently from the implementation of the multipart body parser in Connect at the time (as well as Connect's other body parsers), which call next() when they see an unrecognized content-type.)

Re: error handling in general, rather than expecting you to bind an error listener on the multiparty form instance yourself in your app code and risk you forgetting to do so, crashing the Node process and thus your app, we handle it for you in Skipper core. The only problem is that multiparty does not emit a close event if it ALSO emits an error event That sounds simple enough, right? But here's the thing: aside from the main error event on the multiparty form instance, each "part" from the multipart stream is actually a stream itself, which can also emit multiple error events-- importantly: more than one per part (hence the spinlock we implemented in Skipper). So, long story short, if a parse error is emitted, the 50ms timeout comes into play _for that specific request for which parsing failed_. Which is no problem.

As you've probably figured out, the real issue was we were using the approach that Express and Connect's body parser used at the time (and still use today), which was to _attempt_ to parse with each type of sub-parser. This relies on content-type headers to determine the appropriate behavior and, if the headers recognized by a particular parser are not sent, then that parser is skipped.... err... except for multiparty, which emits an error on its form stream, which Skipper handles to prevent from crashing the process-- but then close is not emitted, causing the upstream to time out after 50ms.

When replacing the built-in body parser with multiparty, we didn't notice the decrease in performance because it isn't visible to the naked eye. But luckily, at this point (Sep 2015), Shyp had scaled to the point where they making significant investment in performance anyway, and Kevin had a sharp eye. When profiling their Sails app, he noticed this and provided us with the excellent report above. After verifying that there wouldn't be any side-effects to compatibility, @sgress454 quickly published a patch that gave every Sails app a nice performance boost.

This was fixed in Skipper v0.5.7, so if you haven't run npm install in a while, be sure to do that to pick up the latest stable 0.5.x release of Skipper that includes this patch. If you are using Sails v0.10.2 or newer, this is taken care of automatically.

Thanks again for the help everyone.