1148201 - Fix desktop reading list client's use of Last-Modified, If-Unmodified-Since, If-Modified-Since headers

Status: VERIFIED FIXED

(Firefox Graveyard :: Reading List, defect)

Description

[Edwin Wong [:edwong]]

STR:
1. On FxNightly, add items to RL
2. sign into sync
3. open new profile of FxNightly
4. sign into sync

actual:
https://edwong.pastebin.mozilla.org/8827306

expected:
it should sync

adw and I were IRC'ing and he said RL sync is working on dev-stable but not Prod. 
[16:09]  <adw> they're handling If-Unmodified-Since differently
[16:09]  <adw> the production server seems broken to me
[16:11]  <adw> i'm uploading a new item that doesn't exist on the server with an If-Unmodified-Since whose value is that Last-Modified from a previous sync. the prod server sends back a 412 in response for the item

Comment 1

[Drew Willcoxon :adw]

(In reply to Edwin Wong [:edwong] from comment #0)
> [16:11]  <adw> i'm uploading a new item that doesn't exist on the server
> with an If-Unmodified-Since whose value is that Last-Modified from a
> previous sync. the prod server sends back a 412 in response for the item

Some clarification: I should have said "the Last-Modified", not "that Last-Modified".

I can reproduce like this:

1. Create a new profile
2. Sign in to an existing FxA account
3. Restart the browser
4. Click the Sync now menu item
5. Add an item to your reading list

After step 5, you can see the unexpected 412 in your terminal:

1427416011428	readinglist.sync	WARN	Unexpected response uploading a new item: {"status":412,"path":"/v1/articles","body":{"errno":999,"message":"Failed batch subrequest","code":412,"error":"Precondition Failed"},"headers":{"Last-Modified":"1427416010973","Content-Length":"90","Content-Type":"application/json; charset=UTF-8"}}

Comment 2

[Drew Willcoxon :adw]

Some more clarification: This is happening when we do a POST /batch with an If-Unmodified-Since header (whose value is the last Last-Modified header received from the server) that contains a POST /articles sub-request.

Comment 3

[Drew Willcoxon :adw]

My STR in comment 1 aren't quite right.  At least I can reproduce by creating a new FxA account in step 2 instead of signing in to an existing account.  Here's the HTTP traffic in one example:

1427418235508	readinglist.sync	DEBUG	Sending request: {"method":"GET","path":"/articles","headers":{}}

1427418236143	readinglist.sync	DEBUG	Received response: {"status":200,"headers":{"date":"Fri, 27 Mar 2015 01:03:55 GMT","content-type":"application/json; charset=UTF-8","content-length":"12","connection":"keep-alive","last-modified":"1427418235365","total-records":"0","access-control-expose-headers":"Backoff, Retry-After, Alert, Next-Page, Total-Records, Last-Modified","backoff":"None","access-control-allow-credentials":"true","access-control-allow-methods":"GET, POST, OPTIONS","access-control-max-age":"1728000","access-control-allow-headers":"DNT,X-Mx-ReqToken,Keep-Alive,User-Agent,X-Requested-With,If-Modified-Since,Cache-Control,Content-Type,Authorization,X-Conditions-Accepted"},"body":{"items":[]}}

1427418244294	readinglist.sync	DEBUG	Sending request: {"method":"POST","path":"/batch","body":{"defaults":{"method":"POST","path":"/articles"},"requests":[{"body":{"url":"https://search.yahoo.com/web?fr=yhs-invalid","title":"Yahoo Search - Web Search","resolved_url":"https://search.yahoo.com/web?fr=yhs-invalid","resolved_title":null,"excerpt":"The search engine that helps you find exactly what you're looking for. Find the most relevant information, video, images, and answers from all across the Web.","favorite":null,"is_article":null,"word_count":null,"unread":null,"added_by":"adw's Nightly on fourside","added_on":1427418244277,"marked_read_by":null,"marked_read_on":null,"read_position":null,"preview":"https://s.yimg.com/kx/yucs/uh3s/promo-ff/1/images/ff_icon-compressed.png"}}]},"headers":{"If-Unmodified-Since":"1427418235365"}}

1427418244546	readinglist.sync	DEBUG	Received response: {"status":200,"headers":{"date":"Fri, 27 Mar 2015 01:04:03 GMT","content-type":"application/json; charset=UTF-8","content-length":"268","connection":"keep-alive","access-control-expose-headers":"Backoff, Retry-After, Alert","backoff":"None","access-control-allow-credentials":"true","access-control-allow-methods":"GET, POST, OPTIONS","access-control-max-age":"1728000","access-control-allow-headers":"DNT,X-Mx-ReqToken,Keep-Alive,User-Agent,X-Requested-With,If-Modified-Since,Cache-Control,Content-Type,Authorization,X-Conditions-Accepted"},"body":{"responses":[{"status":412,"path":"/v1/articles","body":{"errno":999,"message":"Failed batch subrequest","code":412,"error":"Precondition Failed"},"headers":{"Last-Modified":"1427418243761","Content-Length":"90","Content-Type":"application/json; charset=UTF-8"}}]}}

Comment 4

[Edwin Wong [:edwong]]

tracking this for server visibility - https://github.com/mozilla-services/readinglist/issues/225

Comment 5

[Mathieu Leplatre [:leplatrem]]

Thanks for reporting this.


In the current implementation, we copy the batch request headers to the subrequests.

It is not always relevant. For example, if in batch the first subrequest creates an item, the precondition "if-unmodified" is not true anymore for the second one.

I believe we should change it so that precondition headers (I-Modified-S, I-Unmodified-S) of the original batch request do not apply to subrequests.

If a precondition has to be introduced for some operations within the batch, then headers can be specified in the subrequests headers list.

Does it make sense ?

Thanks for your feedback !

Comment 6

[Rémy Hubscher (:natim)]

Your batch request seems broken to me because you add a precondition on articles creation. What are you trying to achieve?

What it means is that no other articles or action should have happened on the collection during the article creation but we do not have conflict on article creation.

As soon as the first entry of your batch is executed, the collection timestamp changes and then the other one fails (as explained by Mathieu).

We should be cautious on how we handle this precondition headers and make sure that we need them.

For the readinglist it makes sense only if we are updating the title, all the other conflicts are handled on the server side.

So you shouldn't need it on DELETE and CREATION, nor when changing the read status or the read_position.

Comment 7

[Richard Newman [:rnewman]]

Yeah, this doesn't seem like a sane place to be adding If-Unmodified-Since. You're basically trying to say "don't apply this batch if anything has changed on the server since I last downloaded". That defeats the point of doing server-based reconciling for new items. You should upload new articles without I-U-S.

Comment 8

[Richard Newman [:rnewman]]

FWIW, Android basically doesn't use I-U-S at all, relying instead on our small conflict area.

Comment 9

[Edwin Wong [:edwong]]

:adw is aware and working on a fix today - if you need to test - please use dev-stable (which is out of date but still works)

Comment 10

[Drew Willcoxon :adw]

Thanks guys.  No surprise I'm doing it wrong.  I'll morph this bug into fixing the desktop client instead of filing a new one, hope that's OK.  Feel free to drop off as you'd like.

Comment 11

[Drew Willcoxon :adw]

Attachment: patch

Still not sure I'm handling Last-Modified right.  I still set _serverLastModifiedHeader to the Last-Modified of *every* response, no matter what the request was.  _serverLastModifiedHeader is then used as the _since param in the download-modified-items phase.  Should I be setting it only for responses to certain requests?

Comment 12

[Richard Newman [:rnewman]]

Assuming I'm understanding you correctly: you're advancing your server-seen point on every request you do.

That's not right: you should advance it only when fetching (i.e., GET /articles).

If you advance it only when you fetch, then you'll see every record you uploaded come back down; that's OK, because you'll discard those dupes by comparing their modified time to the version in the DB.

If you advance it on every request, then you will suffer races where you miss changes simply because you did a write.

Without solving that problem (which is filed as <https://github.com/mozilla-services/readinglist/issues/68>), we'd rather see the same data twice than not see some data once.


You can see what we do with timestamps on Android here:

https://github.com/mozilla-services/android-sync/blob/develop/src/main/java/org/mozilla/gecko/reading/ReadingListSynchronizer.java#L785


Note that the download completion handler is the only place we ever look at the response modified time, and we explicitly choose when to advance our high water mark.

This is separate from the individual record modified time, which lives in the DB.

Comment 13

[Drew Willcoxon :adw]

Attachment: patch v2

You are correct.

Comment 14

[Richard Newman [:rnewman]]

Comment on attachment 8584881 [details] [diff] [review]
patch v2

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

LGTM!

Comment 15

[Drew Willcoxon :adw]

Attachment: landed patch

Bug 1148217 bitrotted my local tree and the previous patch a little.  Here's the landed patch.

https://hg.mozilla.org/integration/fx-team/rev/5fde3c10ff01

Comment 16

[Drew Willcoxon :adw]

https://hg.mozilla.org/releases/mozilla-aurora/rev/42c16678844c

Comment 17

[Marco Mucci [:MarcoM]]

Hi Drew, can you provide a point value.

Comment 18

[Nick Alexander :nalexander [he/him]]

https://hg.mozilla.org/mozilla-central/rev/5fde3c10ff01

Comment 19

[Edwin Wong [:edwong]]

Sync'd RL is working on nightly. Thanks for the quick fix Drew!

Comment 20

[Ada [:adalucinet]]

Reproduced with Nightly 2015-03-26 on OS X 10.9.5.
With Firefox 38 beta 2 and latest Developer Edition 39.0a2, under Windows 7 64-bit, Mac OSX 10.9.5 and Ubuntu 14.04 32-bit, this issue is no longer reproducible when using str from comment 1 and comment 3; Although, intermittently, with str from comment 0 - the sync is not working and no errors are present. Any ideas?

Comment 21

[Drew Willcoxon :adw]

Thanks, Alexandra.  It's probably not related to this bug, and without any logs it's really hard to say what the problem is.  Could you please file a new bug and attach logs, even if they don't appear helpful?

Comment 22

[Ada [:adalucinet]]

(In reply to Drew Willcoxon :adw from comment #21)
> Thanks, Alexandra.  It's probably not related to this bug, and without any
> logs it's really hard to say what the problem is.  Could you please file a
> new bug and attach logs, even if they don't appear helpful?

No luck in reproducing the issue mentioned in comment 20, but I'll keep an eye on it though.
Changing the status accordingly.