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

VERIFIED FIXED in Firefox 38

Status

defect
VERIFIED FIXED
4 years ago
3 years ago

People

(Reporter: edwong, Assigned: adw)

Tracking

(Blocks 1 bug)

unspecified
Firefox 39
Dependency tree / graph
Bug Flags:
firefox-backlog +
qe-verify +

Firefox Tracking Flags

(firefox38+ verified, firefox39 verified)

Details

Attachments

(1 attachment, 2 obsolete attachments)

Reporter

Description

4 years ago
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
Assignee

Comment 1

4 years ago
(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"}}
Assignee

Comment 2

4 years ago
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.
Summary: ReadlingList server returns 412 response → ReadlingList server returns 412 response for POST /batch with If-Unmodified-Since containing POST /articles
Assignee

Comment 3

4 years ago
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"}}]}}
Reporter

Comment 4

4 years ago
tracking this for server visibility - https://github.com/mozilla-services/readinglist/issues/225
Assignee: tarek → mathieu
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 !
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.
Flags: needinfo?(adw)
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.
FWIW, Android basically doesn't use I-U-S at all, relying instead on our small conflict area.
Reporter

Comment 9

4 years ago
: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)
Assignee

Comment 10

4 years ago
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.
Assignee: mathieu → nobody
Status: NEW → ASSIGNED
Component: Server: ReadingList → Reading List
Flags: needinfo?(adw)
Product: Mozilla Services → Firefox
Summary: ReadlingList server returns 412 response for POST /batch with If-Unmodified-Since containing POST /articles → Fix desktop reading list client's use of Last-Modified, If-Unmodified-Since, If-Modified-Since headers
Assignee

Updated

4 years ago
Assignee: nobody → adw
Assignee

Comment 11

4 years ago
Posted patch patch (obsolete) — Splinter Review
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?
Attachment #8584857 - Flags: review?(rnewman)
Blocks: 1132074
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.
Assignee

Comment 13

4 years ago
Posted patch patch v2 (obsolete) — Splinter Review
You are correct.
Attachment #8584857 - Attachment is obsolete: true
Attachment #8584857 - Flags: review?(rnewman)
Attachment #8584881 - Flags: review?(rnewman)
Comment on attachment 8584881 [details] [diff] [review]
patch v2

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

LGTM!
Attachment #8584881 - Flags: review?(rnewman) → review+
Assignee

Comment 15

4 years ago
Posted patch landed patchSplinter Review
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
Attachment #8584881 - Attachment is obsolete: true
Attachment #8584890 - Flags: review+
Iteration: --- → 39.3 - 30 Mar
Flags: qe-verify?
Flags: firefox-backlog+
Hi Drew, can you provide a point value.
Flags: needinfo?(adw)
Assignee

Updated

4 years ago
Points: --- → 2
Flags: needinfo?(adw)
https://hg.mozilla.org/mozilla-central/rev/5fde3c10ff01
Status: ASSIGNED → RESOLVED
Closed: 4 years ago
Resolution: --- → FIXED
Target Milestone: --- → Firefox 39
Flags: qe-verify? → qe-verify+
QA Contact: andrei.vaida
Reporter

Comment 19

4 years ago
Sync'd RL is working on nightly. Thanks for the quick fix Drew!
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?
Flags: needinfo?(adw)
Assignee

Comment 21

4 years ago
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?
Flags: needinfo?(adw)
(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.
Status: RESOLVED → VERIFIED
Product: Firefox → Firefox Graveyard
You need to log in before you can comment on or make changes to this bug.