685944 - Sync resource.js, rest.js: warn if response bodies don't match Content-Length etc. headers

Status: RESOLVED FIXED

(Firefox :: Sync, defect)

Description

[Richard Newman [:rnewman]]

11:08:49 <@atoll> the interesting thing is
11:08:52 <@atoll> if we returned 206 byts
11:09:02 <@atoll> you should have a Content-Length mismatch in the response
11:09:12 <@atoll> can you write something that warns when response length != header stated length?
11:09:31 <@atoll> dunno if our stuff sends C-L or not, but it'd be a useful warning of some sort

Comment 1

[Josh Matthews [:jdm]]

Richard, could you give some pointers for any new contributors who wish to look into this bug?

Comment 2

[Richard Newman [:rnewman]]

(In reply to Josh Matthews [:jdm] from comment #1)
> Richard, could you give some pointers for any new contributors who wish to
> look into this bug?

Sure.

Two (or more) parts:

* Amend services/sync/modules/record.js, WBORecord::fetch and WBORecord::deserialize, to examine response headers (currently resource.js, eventually rest.js). The code currently just *tries* JSON deserialization; this should really be forced if the returned Content-Type is JSON, and should fail noisily.

* Test the behavior of rest.js and resource.js when the server returns a Content-Type that disagrees with the length of the returned body. Ensure that we at least log a warning; this is also a possible cause for JSON deserialization errors, so we could also log a "why".

Comment 3

[Richard Newman [:rnewman]]

See the horror in Bug 691257.

Comment 4

[Rajesh Veeranki]

Attachment: Modified Deserialize function

Need help in finding response header length

Comment 5

[Josh Matthews [:jdm]]

Comment on attachment 795065 [details] [diff] [review]
Modified Deserialize function

For that, you want to set the feedback flag to ? and give a name. review+ is for patches that have been fully reviewed.

Comment 6

[Richard Newman [:rnewman]]

Comment on attachment 795065 [details] [diff] [review]
Modified Deserialize function

Review of attachment 795065 [details] [diff] [review]:
-----------------------------------------------------------------

You'll need to alter logic in `deserialize`'s call sites, not inside that method. Where we get the response is where we can see Content-Length.

Ideally you can actually work this into `AsyncResource` and `RESTRequest`, rather than in `Record` -- at the HTTP layer we know exactly how many bytes we've seen, and what the Content-Length header said.

::: services/sync/modules/record.js
@@ +78,5 @@
> +    // var header_length=json.constructor.toString() == String ? JSON.parse(json).ContentLength : json.ContentLength;
> +    if(json.constructor.toString()!=String) json=JSON.stringify(json);
> +    else {}
> +    var len = json.length;
> +    if(len!=header_length){

Please follow the coding style in the rest of the file:

* Braces around every conditional
* Spaces around operators and before/after parentheticals
* `let`, not `var`.

Comment 7

[Mark Hammond [:markh] [:mhammond]]

At first glance, this seems trickier than expected.  We actually apply the records as the data comes in from the network - *not* after the entire response has been received.  Thus, we will not know about a mismatch until after we've applied the records we *did* see.  This is true for both content-length and X-Weave-Records (sp?).

Comment 8

[Richard Newman [:rnewman]]

Two options. I suggest doing both.

* Look at the Content-Length prior to processing the body -- we should be able to see the headers first, even if it needs a small change to resource.js. If it's small, buffer records before applying. (This will also fix some bookmarks bugs.)

* After processing, don't fast-forward timestamps (and don't upload records!) if we haven't downloaded everything we expected to.

Comment 9

[Stephen Gowan]

Attachment: bug685944.patch - rest.js & resource.js log a warning when there is a content-length mismatch

Hi Richard,

I'm interested in squashing this bug.  The patch I submitted attempts to address your second bullet point from comment 2:

> * Test the behavior of rest.js and resource.js when the server returns a
> Content-Type that disagrees with the length of the returned body. Ensure that
> we at least log a warning; this is also a possible cause for JSON
> deserialization errors, so we could also log a "why".

Does it seem like it's headed in the right direction?

Comment 10

[Richard Newman [:rnewman]]

Comment on attachment 8502822 [details] [diff] [review]
bug685944.patch - rest.js & resource.js log a warning when there is a content-length mismatch

Review of attachment 8502822 [details] [diff] [review]:
-----------------------------------------------------------------

Excellent work!

::: services/sync/modules/resource.js
@@ +301,5 @@
>        if (success && headers["x-weave-quota-remaining"]) {
>          Observers.notify("weave:service:quota:remaining",
>                           parseInt(headers["x-weave-quota-remaining"], 10));
>        }
> +      let contentLength = headers["content-length"];

Newline before.

@@ +302,5 @@
>          Observers.notify("weave:service:quota:remaining",
>                           parseInt(headers["x-weave-quota-remaining"], 10));
>        }
> +      let contentLength = headers["content-length"];
> +      if (success && contentLength && contentLength !== data.length.toString()) {

Can data ever be null or undefined?

::: services/sync/modules/rest.js
@@ +90,5 @@
> +
> +  onProgress: function onProgress() {
> +    RESTRequest.prototype.onProgress.call(this);
> +    let resp = this.response;
> +    if (!resp) {

resp should always be truthy, no? It's set near the end of onStartRequest.

@@ +98,5 @@
> +    let contentLength = resp.headers["content-length"];
> +
> +    if (resp.success && contentLength &&
> +                        contentLength !== resp.body.length.toString()) {
> +      this._log.warn("The response body's length of: " + resp.body.length +

onProgress is called multiple times -- it's invoked once on each onDataAvailable call from the channel.

If you do this work in onProgress, you'll report a warning each time until completion.

You probably want to override onStopRequest, call the super implementation, check this.status == this.COMPLETED, and *then* examine the response.

::: services/sync/tests/unit/test_bug685944.js
@@ +1,1 @@
> +/* Any copyright is dedicated to the Public Domain.

We turned away from doing test_bugNumber as a naming convention a few years ago, because it makes figuring out what the test does pretty hard.

Let's go for test_warn_on_truncated_response.

@@ +15,5 @@
> +const BODY = "response body";
> +// contentLength needs to be longer than the response body
> +// length in order to get a mismatch between what is sent in
> +// the response and the content-length header value.
> +let contentLength = BODY.length + 1;

This raises the interesting question of bytes versus characters.

@@ +29,5 @@
> +  let warnMessages = [];
> +  let warn = log.warn;
> +  log.warn = function (message) {
> +    let regEx = /The response body\'s length of: \d+ doesn\'t match the header\'s content-length of: \d+/i
> +    if(message.match(regEx)) {

Nit: space between `if` and `(`.

@@ +77,5 @@
> +  // Setting this affects how received data is read from the underlying
> +  // nsIHttpChannel in rest.js.  If it's left as UTF-8 (the default) an
> +  // nsIConverterInputStream is used and the data read from channel's stream
> +  // isn't truncated at the null byte mark (\u0000). Therefore the
> +  // content-length mismatch being tested for doesn't occurr.  Setting it to

'occur'

Comment 11

[Stephen Gowan]

Attachment: rest.js & resource.js warn on truncated response

This patch addresses the issues found in the last submission.  

@@ +302,5 @@
>          Observers.notify("weave:service:quota:remaining",
>                           parseInt(headers["x-weave-quota-remaining"], 10));
>        }
> +      let contentLength = headers["content-length"];
> +      if (success && contentLength && contentLength !== data.length.toString()) {
> 
> Can data ever be null or undefined?

I wasn't sure if this was a rhetorical question, but I figured I would answer it anyway. :-)

Yes, if no data is received from the channel or the response body is an empty string, then onStopRequest will set this._data = null and pass it to _OnComplete. I added a check to the if statement to make sure that data is truthy.

> onProgress is called multiple times -- it's invoked once on each onDataAvailable call 
> from the channel.
> If you do this work in onProgress, you'll report a warning each time until completion.
> You probably want to override onStopRequest, call the super implementation, check 
> this.status == this.COMPLETED, and *then* examine the response.

I tackled this in a slightly different manner.  I overrode onStopRequest, but I put the call to the super implementation last since it will call onComplete before it returns.  Since the test performs its assertions in the onComplete method, the warning message needs to be logged before onComplete is called. Since I put the super call last I also check for this.status != this.ABORTED instead.

@@ +15,5 @@
> +const BODY = "response body";
> +// contentLength needs to be longer than the response body
> +// length in order to get a mismatch between what is sent in
> +// the response and the content-length header value.
> +let contentLength = BODY.length + 1;
> 
>This raises the interesting question of bytes versus characters.

I *think* just checking the response body's string length and not its byte length is OK, since only a warn level message is being logged when there is a mismatch. To me that level indicates, "the thing that was logged may not be a problem, but it's something to keep an eye on."

Comment 12

[Richard Newman [:rnewman]]

Comment on attachment 8504880 [details] [diff] [review]
rest.js & resource.js warn on truncated response

Looks good. If the tests pass, and everyday syncing operations aren't dumping warnings in the log, let's land!

Comment 13

[Stephen Gowan]

Awesome, thanks for the quick feedback! I'll keep my fingers crossed.

Comment 14

[Richard Newman [:rnewman]]

Stephen: has this passed the services/ xpcshell-tests on your machine, and do syncs work with your build?

Let me know.

Comment 15

[Stephen Gowan]

*double facepalm*

Sorry for the delay on this Richard, I didn't realize by "if the tests pass" you meant the local xpcshell-tests passing.  I got a ahead of myself and for some reason assumed you were talking about the tests passing on the try server--my bad. 

Well, it's a good thing you were talking about the tests passing locally, because after running "./mach xpcshell-test services" I had 5 failures.  It looks like all 5 failures came from /services/sync/tests/unit/test_service_getStorageInfo.js. 

The problem appears to be stemming from my implementation of onStopRequest in /services/sync/modules/rest.js.  The headers property on response can be null, so I need to make the change below and check it before checking for the value of content-length.

>      let contentLength = resp.headers ? resp.headers["content-length"] : "";
>
>      if (resp.success && contentLength &&
>                          contentLength !== resp.body.length.toString()) {

I'll verify this is the issue, make sure this change makes all the tests pass, and then see how syncs work with my local build.

Comment 16

[Stephen Gowan]

Attachment: rest.js & resource.js warn on truncated response

The 5 failures I saw yesterday were not all from the same file.  I misunderstood the test output.  test_service_getStorageInfo.js only accounts for one of those failures, and this latest patch corrects that failure. It includes the fix mentioned in comment 15.

tl;dr - Do I need to disconnect from the internet when running xpcshell tests?

It took me a while to figure this out, but failures occur whenever I'm connected to my home network.  If I disconnect my machine and disable wireless, then all tests pass.  It doesn't matter if my patch is applied or if I pop it off, the tests will fail while connected to the internet and will pass while disconnected.  I haven't verified this is the case for all the failures, but the last failure I can see in the console output looks like this:

 7:00.64 Sync.Service DEBUG Caching URLs under storage user base: http://dummy:9000/1.1/broken.wipe/
 7:00.64 Sync.Service DEBUG Fetching unlocked auth state returned success.status_ok
 7:00.64 FATAL ERROR: Non-local network connections are disabled and a connection attempt to dummy (198.105.254.228) was made.
 7:00.64 You should only access hostnames available via the test networking proxy (if running mochitests) or from a test-specific httpd.js server (if running xpcshell tests). Browser services should be disabled or redirected to a local server.
 7:00.64 Hit MOZ_CRASH(Attempting to connect to non-local address!) at /Users/gowansg/mozilla-central/netwerk/base/src/nsSocketTransport2.cpp:1215

What's going on here? Is my ISP trying to resolve that hostname?

Also, do you know of a way to get the names of all the tests that failed?  I didn't see an option that I could pass to xpcshell-test to do so.  I wanted to verify they all fail with a similar message.

And just prove to myself that I'm not crazy, I ran a hg pull -u about an hour ago and then ran the tests. I saw the following:

7:49.15 INFO | Passed: 157
7:49.15 INFO | Failed: 6
7:49.15 INFO | Todo: 0
7:49.15 INFO | Retried: 7

Next, I applied my patch, reran the tests, and saw:

10:27.88 INFO | Result summary:
10:27.88 INFO | Passed: 158
10:27.88 INFO | Failed: 6
10:27.88 INFO | Todo: 0
10:27.88 INFO | Retried: 9

Finally, I disconnected my computer, ran the tests again, and saw:

10:06.93 INFO | Result summary:
10:06.93 INFO | Passed: 164
10:06.93 INFO | Failed: 0
10:06.93 INFO | Todo: 0
10:06.93 INFO | Retried: 2

Comment 17

[Richard Newman [:rnewman]]

(In reply to Stephen Gowan from comment #16)

> tl;dr - Do I need to disconnect from the internet when running xpcshell
> tests?

You shouldn't. I don't. But sometimes things happen, and I've seen ISP fallback pages do weird things.

> Also, do you know of a way to get the names of all the tests that failed?  I
> didn't see an option that I could pass to xpcshell-test to do so.  I wanted
> to verify they all fail with a similar message.

I normally just search the console output for UNEXPECTED-FAIL.

Comment 18

[Richard Newman [:rnewman]]

Comment on attachment 8510533 [details] [diff] [review]
rest.js & resource.js warn on truncated response

Review of attachment 8510533 [details] [diff] [review]:
-----------------------------------------------------------------

Looks good! Just nits.

When you upload an updated patch, please set the r= in the commit message; it'll make it easier for someone to check in for you.

::: services/sync/modules/resource.js
@@ +304,5 @@
>        }
> +
> +      let contentLength = headers["content-length"];
> +      if (success && contentLength && data &&
> +                                      contentLength !== data.length.toString()) {

Nit: align the 'contentLength' with 'success' on the line above.

Also you should be able to rely on JS's coercion here:

  data.length == contentLength

which avoids a garbage string.

(Yes, this also allows for craziness like Content-Length: 0x42.)

::: services/sync/modules/rest.js
@@ +93,5 @@
> +      let resp = this.response;
> +      let contentLength = resp.headers ? resp.headers["content-length"] : "";
> +
> +      if (resp.success && contentLength &&
> +                          contentLength !== resp.body.length.toString()) {

Same two comments apply here. "" == 0, handily.

::: services/sync/tests/unit/test_warn_on_truncated_response.js
@@ +36,5 @@
> +    warn.call(log, message);
> +  }
> +  return warnMessages;
> +}
> +add_test(function test_resource_logs_content_length_mismatch() {

Newline before add_test.

Comment 19

[Stephen Gowan]

Attachment: bug685944.patch - rest.js & resource.js log a warning when there is a content-length mismatch

I've addressed the issues from the last submission.

All services/ xpcshell-tests are passing, and syncs are working with my build.

Comment 20

[Stephen Gowan]

Richard, I just wanted to send you a quick review ping; mostly I just want to make sure you're not waiting on anything else from me.

Comment 21

[Richard Newman [:rnewman]]

Nope, just swamped! Will get to this.

Comment 22

[Stephen Gowan]

Thanks and no need to rush on my behalf.

Comment 23

[Richard Newman [:rnewman]]

Comment on attachment 8511701 [details] [diff] [review]
bug685944.patch - rest.js & resource.js log a warning when there is a content-length mismatch

Review of attachment 8511701 [details] [diff] [review]:
-----------------------------------------------------------------

Looks excellent! Thanks for getting this done.

Comment 24

[Richard Newman [:rnewman]]

https://hg.mozilla.org/integration/fx-team/rev/46f851f9fc43

Comment 25

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/mozilla-central/rev/46f851f9fc43