1397277 - Batch upload failure in minimal mobile bookmarks uploader due to server rejecting empty POST bodies

Status: VERIFIED FIXED

(Firefox for iOS :: Sync, defect)

Description

[Catalin Suciu [:csuciu]]

master 98a9f16ea
iPhone 6 Plus (10.3.3)

1. Sign into sync with the same FxA
2. On mobile side, bookmark a few web pages
3. Sync on mobile => Sync on desktop
4. Check the bookmarks section on desktop

Result: The mobile bookmarks are not displayed in the "Mobile Bookmarks" folder on desktop.

Note: Desktop bookmarks are correctly synced to mobile. Also, I've checked that history items are correctly synced from mobile to desktop.    


https://pastebin.mozilla.org/9031596

Comment 1

[Stefan Arentz | :st3fan | ⏰ EST | he/him]

2017-09-06 16:19:57.844 [Debug] [BookmarksSynchronizer.swift:197] synchronizeBookmarksToStorage(_:usingBuffer:withServer:info:greenLight:remoteClientsAndTabs:) > Validating completed buffer download.
2017-09-06 16:19:58.090 [Debug] [StorageClient.swift:381] failFromResponse > Status code: 202.
2017-09-06 16:19:58.302 [Debug] [StorageClient.swift:381] failFromResponse > Status code: 400.
2017-09-06 16:19:58.303 [Debug] [StorageClient.swift:402] failFromResponse > BadRequestError.
2017-09-06 16:19:58.304 [Info] [BookmarksSynchronizer.swift:260] synchronizeBookmarksToStorage(_:usingBuffer:withServer:info:greenLight:remoteClientsAndTabs:) > Bookmark mirroring took 463870µs. Result was Completed

Comment 2

[Richard Newman [:rnewman]]

Bob, did the batch API just get turned on?

Comment 3

[Richard Newman [:rnewman]]

Stefan does not see this on a server that returns 200 in response to ?batch=true.

Comment 4

[Richard Newman [:rnewman]]

I think this is the bug:

    fileprivate func start() -> DeferredResponse {
        let postRecordCount = self.postRecords
        let postBytesCount = self.postBytes
        let lines = freezePost()
        return self.uploader(lines, self.ifUnmodifiedSince, [batchQueryParamWithValue("true")])
             >>== effect(moveForward)

…

    fileprivate func moveForward(_ response: StorageResponse<POSTResult>) {
        let lastModified = response.metadata.lastModifiedMilliseconds
        self.ifUnmodifiedSince = lastModified
        _ = self.onCollectionUploaded(response.value, lastModified)
    }

We advance `iUS` on `moveForward`, and we do so in `start`. We should not -- we should only call `moveForward` in `commit` (which is already in the code) and if a batch token was not returned.

This will cause the commit to fail, because we'll pass the server modified time from the last request as XIUS, not the current modification time of the collection.

Comment 5

[Richard Newman [:rnewman]]

Bob confirms that we're at 50% batch enabled.

Comment 6

[Stefan Arentz | :st3fan | ⏰ EST | he/him]

Marking this as a 9.0 blocker.

Comment 7

[Stefan Arentz | :st3fan | ⏰ EST | he/him]

>> GET https://sync-542-us-west-2.sync.services.mozilla.com/1.5/82820557/info/collections
       ← 200 application/json 227b 152ms
   GET https://sync-542-us-west-2.sync.services.mozilla.com/1.5/82820557/storage/clients?full=1&newer=0.00
       ← 200 application/json 2.42k 141ms
   GET https://sync-542-us-west-2.sync.services.mozilla.com/1.5/82820557/storage/passwords?full=1&newer=1504708343.15
       ← 200 application/json 2b 168ms
   POST https://sync-542-us-west-2.sync.services.mozilla.com/1.5/82820557/storage/bookmarks?batch=true
        ← 202 application/json 86b 143ms
   POST https://sync-542-us-west-2.sync.services.mozilla.com/1.5/82820557/storage/bookmarks?batch=MTUwNDcxMzg4MjU0Nw%3D%3D&commit=true
        ← 400 application/json 1b 157ms
   POST https://sync-542-us-west-2.sync.services.mozilla.com/1.5/82820557/storage/history
        ← 200 application/json 70b 192ms
   POST https://incoming.telemetry.mozilla.org/submit/telemetry/E8402E57-71F1-49A0-87C0-1E136BDE2B64/sync/Fennec/8.0/developer/1
        ← 200 text/plain 2b 137ms


Here are the two failed requests:


Request:

Host:                   sync-542-us-west-2.sync.services.mozilla.com
Content-Type:           application/newlines
X-If-Unmodified-Since:  1504709019.14
Accept:                 */*
Connection:             keep-alive
Content-Length:         949
User-Agent:             Firefox-iOS-Sync/8.0b1 (iPhone; iPhone OS 10.3.3) (Fennec (sarentz))
Accept-Language:        en-CA;q=1.0, nl-CA;q=0.9, de-CA;q=0.8, fr-CA;q=0.7
Authorization:          ... redacted ...
Accept-Encoding:        gzip;q=1.0, compress;q=0.5

batch: true

Response:

Server:             openresty/1.9.7.3
Date:               Wed, 06 Sep 2017 16:04:42 GMT
Content-Type:       application/json; charset=UTF-8
Content-Length:     86
Connection:         keep-alive
X-Last-Modified:    1504709019.14
X-Weave-Timestamp:  1504713882.54

{
    "batch": "MTUwNDcxMzg4MjU0Nw==",
    "failed": {},
    "success": [
        "mobile",
        "OEnknMVWdLra"
    ]
}



Request:

Host:                   sync-542-us-west-2.sync.services.mozilla.com
Content-Type:           application/newlines
X-If-Unmodified-Since:  1504709019.14
Content-Length:         0
Connection:             keep-alive
Accept:                 */*
User-Agent:             Firefox-iOS-Sync/8.0b1 (iPhone; iPhone OS 10.3.3) (Fennec (sarentz))
Accept-Language:        en-CA;q=1.0, nl-CA;q=0.9, de-CA;q=0.8, fr-CA;q=0.7
Authorization:          ... redacted ...
Accept-Encoding:        gzip;q=1.0, compress;q=0.5

batch:  MTUwNDcxMzg4MjU0Nw==
commit: true

Response:

Server:             openresty/1.9.7.3
Date:               Wed, 06 Sep 2017 16:04:42 GMT
Content-Type:       application/json; charset=UTF-8
Content-Length:     1
Connection:         keep-alive
X-Weave-Timestamp:  1504713882.79

6



The response of this last call is just the character 6 (0x36) and nothing else.

Comment 8

[Richard Newman [:rnewman]]

`6` means JSON parse failure. We send a Content-Length of 0.

Comment 9

[Aaron Train [:aaronmt]]

Was 8.x good here?

Comment 10

[Richard Newman [:rnewman]]

(In reply to Aaron Train [:aaronmt] from comment #9)
> Was 8.x good here?

Yes; it's not a client-side bug.

Testing and verifying would be good; I expect Bug 1396849 to do that implicitly.

Comment 11

[Catalin Suciu [:csuciu]]

I was able to verify this issue as fixed in stage env.
Tested on beta 9.0(5893)/latest Nightly on desktop.

Will change the status of the bug once it is verified in production also.

Comment 12

[Richard Newman [:rnewman]]

Marking as unaffected 'cos this was a server-side issue.