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

(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"}}

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.

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"}}]}}

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

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.

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.

: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)

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.

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?

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.

You are correct.

Comment on attachment 8584881 [details] [diff] [review] patch v2 Review of attachment 8584881 [details] [diff] [review]: ----------------------------------------------------------------- LGTM!

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

Hi Drew, can you provide a point value.

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?

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?

(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.