1347373 - bookmark repair fails if we can't find any items locally

Status: RESOLVED FIXED

(Firefox :: Sync, defect, P1)

Description

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

In my logs:

> Sync.Engine.Bookmarks.Repair	DEBUG	repair request to upload items that don't exist locally: ["lBX8pyjeaaBG"]
> Sync.Collection	DEBUG	mesg: GET fail 400 https://sync-367-us-west-2.sync.services.mozilla.com/1.5/51345796/storage/bookmarks?ids=
> Sync.Collection	DEBUG	GET fail 400 https://sync-367-us-west-2.sync.services.mozilla.com/1.5/51345796/storage/bookmarks?ids=
> Sync.Collection	WARN	GET request to https://sync-367-us-west-2.sync.services.mozilla.com/1.5/51345796/storage/bookmarks?ids= failed with status 400
> Sync.Engine.Clients	ERROR	Failed to handle a repair request: TypeError: JSON.parse(...) is not iterable 

2 problems here:

* We got a 400, but still charge ahead as if it worked.

* The requested item doesn't appear locally, so we have an empty set of items to check the server for, thus we create a malformed url, then get upset. We should skip this part of the repair so we immediately write a response saying "nope, sorry"

Comment 1

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

Attachment: Bug 1347373 - better handling of requests that have only non-existing items and of errors.

This patch has ended up fairly large:

* The key issue in this bug is a result of the test HTTP server behaving
  differently than the real sync servers. The test server would happy accept
  a request that ends with |?ids=| and return 200 with an empty array, while
  the real sync server rejects this request with a 400. Changing the test HTTP
  server to do the same exposed the initial bug.

* These kinds of bugs didn't record telememtry, so we would remain oblivious to
  them - so this patch also adds better handling of errors - we now report the
  failure in telemetry with a description of the error. To try and be
  consistent with how we report such errors, Telemetry.jsm now exposes the
  previously private |transformError| function via the SyncTelemetry object,
  and is used by this error handling.

* I ended up rewriting the logic for working out which of the requested
  IDs we should upload - so gone are all the insane sets and set operations,
  and now we have a much simpler loop that earier to rationalize about - but
  this makes the patch larger than it otherwise would have been - but I feel
  much better about this new version, partly because...

* ... this exposed a different bug - we would previously upload a tombstone for
  all left-pane items we discovered, whether they were requested or not. This
  isn't what we intend - only items explicitly requested should get tombstones.
  As a result of this, test_non_syncable() has changed to reflect that - the
  test unfortunately relied on the previous buggy behaviour :(

Review commit: https://reviewboard.mozilla.org/r/120970/diff/#index_header
See other reviews: https://reviewboard.mozilla.org/r/120970/

Comment 2

[Lina Butler [:lina]]

Comment on attachment 8848017 [details]
Bug 1347373 - better handling of requests that have only non-existing items and of errors.

https://reviewboard.mozilla.org/r/120970/#review123138

Much better! I noted a few nits and concerns, but this LGTM.

::: services/sync/modules/bookmark_repair.js:605
(Diff revision 1)
> +      this._currentState.failureReason = SyncTelemetry.transformError(ex);
> +      this._finishRepair();
> +    }
> +  }
> +
> +  async _fetchItemsToUpload(request) {

Excellent cleanup and comments! This makes the logic so much easier to reason about.

::: services/sync/modules/bookmark_repair.js:661
(Diff revision 1)
> +        // and doesn't exist on the server.
> +        if (syncable && !existRemotely.has(id)) {
> +          log.debug(`repair request found related item '${id}' which isn't on the server`);
> +          toUpload.add(id);
> +        } else {
> +          log.debug(`repair request found related item '${id}' which we will not upload`);

What if a related non-syncable item exists on the server, but wasn't explicitly requested? On the one hand, I wonder if we might as well upload the tombstone, since that item should never have been uploaded in the first place.

On the other, it's inconsistent with our rule for related syncable items, which we *won't* upload if they weren't explicitly requested. (Try saying that five times fast, eh?)

I can be convinced either way, but it's something to think about.

::: services/sync/modules/bookmark_repair.js:698
(Diff revision 1)
>        numIDs: response.ids.length.toString(),
>      }
> +    if (this._currentState.failureReason) {
> +      // *sob* - recording this in "extra" means the value must be a string of
> +      // max 85 chars.
> +      eventExtra.failureReason = JSON.stringify(this._currentState.failureReason).substring(0, 85)

That's really unfortunate. Does the telemetry server treat "extra" as an opaque string, or will it try to expand it into a struct, and fail if the string is truncated?

If the former, will we ever want to query by specific failure reasons, or is this more informational? If the latter, could truncating to invalid JSON cause the server to discard the event?

::: services/sync/tests/unit/test_bookmark_repair_responder.js:111
(Diff revision 1)
> +    { object: "repairResponse",
> +      method: "failed",
> +      value: undefined,
> +      extra: { flowID: request.flowID,
> +               numIDs: "0",
> +               failureReason: '{"name":"unexpectederror","error":"Error: oh no!"}',

Nit: In theory, object properties are unordered, so I wonder if this could fail intermittently if `error` comes first. But maybe Firefox is guaranteed to iterate over properties in the order they're set, and this is fine in practice?

Comment 3

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

(In reply to Kit Cambridge [:kitcambridge] from comment #2)
> What if a related non-syncable item exists on the server, but wasn't
> explicitly requested? On the one hand, I wonder if we might as well upload
> the tombstone, since that item should never have been uploaded in the first
> place.
> 
> On the other, it's inconsistent with our rule for related syncable items,
> which we *won't* upload if they weren't explicitly requested. (Try saying
> that five times fast, eh?)
> 
> I can be convinced either way, but it's something to think about.

Yeah, I think you are probably right - there's really no good reason to not delete items we happen to discover shouldn't be on the server, so I made that change.

> That's really unfortunate. Does the telemetry server treat "extra" as an
> opaque string, or will it try to expand it into a struct, and fail if the
> string is truncated?

It's an opaque string.

> If the former, will we ever want to query by specific failure reasons, or is
> this more informational?

It's really just informational - we'll probably want to know the top reasons - and even when truncated, I expect many would still be the same string value. Our ad-hoc analysis could probably try and parse it, and append |"}" if it fails :)

> Nit: In theory, object properties are unordered, so I wonder if this could
> fail intermittently if `error` comes first. But maybe Firefox is guaranteed
> to iterate over properties in the order they're set, and this is fine in
> practice?

This winds up as an Assert.deepEqual() call, so I suspect if that breaks there'd be hell to pay anyway :)

Thanks!

Comment 4

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

Comment on attachment 8848017 [details]
Bug 1347373 - better handling of requests that have only non-existing items and of errors.

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/120970/diff/1-2/

Comment 5

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/d533ad7c74ea
better handling of requests that have only non-existing items and of errors. r=kitcambridge

Comment 6

[Carsten Book [:Tomcat]]

https://hg.mozilla.org/mozilla-central/rev/d533ad7c74ea

Comment 7

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

Comment on attachment 8848017 [details]
Bug 1347373 - better handling of requests that have only non-existing items and of errors.

Approval Request Comment
[Feature/Bug causing the regression]: bug 1317223
[User impact if declined]: Attempted repair of their bookmarks may fail.
[Is this code covered by automated tests?]: Yes
[Has the fix been verified in Nightly?]: Manually
[Needs manual test from QE? If yes, steps to reproduce]: No
[List of other uplifts needed for the feature/fix]: None
[Is the change risky?]: Low risk, limited to sync
[Why is the change risky/not risky?]:
[String changes made/needed]: None

Comment 8

[Gerry Chang [:gchang]]

Comment on attachment 8848017 [details]
Bug 1347373 - better handling of requests that have only non-existing items and of errors.

Fix a bookmark repair handling issue. Aurora54+.

Comment 9

[Carsten Book [:Tomcat]]

https://hg.mozilla.org/releases/mozilla-aurora/rev/dd7871655d03