806460 - NS_ERROR_ILLEGAL_VALUE in nsINavBookmarksService.insertBookmark while inserting query

Status: RESOLVED FIXED

(Firefox :: Sync, defect, P1)

Description

[Richard Newman [:rnewman]]

Sync.Store.Bookmarks	TRACE	Number of rows matching GUID AAAAAAAAAAAA: 0
	Sync.Engine.Bookmarks	TRACE	Reconciling AAAAAAAAAAAA. exists=false; modified=false; local age=null; incoming age=35772.10000014305
	Sync.Engine.Bookmarks	TRACE	Finding mapping: All Bookmarks, bundefined:undefined
	Sync.Engine.Bookmarks	TRACE	No parent => no dupe.
	Sync.Engine.Bookmarks	TRACE	No duplicate found for incoming item: AAAAAAAAAAAA
	Sync.Engine.Bookmarks	TRACE	Applying incoming because local item does not exist and was not deleted.
	Sync.Store.Bookmarks	TRACE	Number of rows matching GUID BBBBBBBBBBBB: 1
	Sync.Store.Bookmarks	TRACE	Number of rows matching GUID AAAAAAAAAAAA: 0
	Sync.Store.Bookmarks	WARN	Failed to apply incoming record AAAAAAAAAAAA
	Sync.Store.Bookmarks	WARN	Encountered exception: Component returned failure code: 0x80070057 (NS_ERROR_ILLEGAL_VALUE) [nsINavBookmarksService.insertBookmark] Stack trace: BStore_create()@resource://gre/modules/services-sync/engines/bookmarks.js:635 < Store_applyIncoming()@resource://services-sync/engines.js:250 < BStore_applyIncoming()@resource://gre/modules/services-sync/engines/bookmarks.js:523 < applyIncomingBatch()@resource://services-sync/engines.js:218 < doApplyBatch()@resource://services-sync/engines.js:782 < resource://services-sync/engines.js:893 < resource://gre/modules/services-sync/record.js:625 < Channel_onDataAvail()@resource://gre/modules/services-sync/resource.js:524 < <file:unknown>

Comment 1

[Richard Newman [:rnewman]]

Record is:

 Sync.Engine.Bookmarks	TRACE	Incoming: { id: AAAAAAAAAAAA  index: 0  modified: 1351468990.35  ttl: undefined  payload: {"id":"AAAAAAAAAAAA","folderName":"","parentid":"BBBBBBBBBBBB","title":"Downloads","queryId":"","type":"query","parentName":""}  collection: bookmarks }


Happens to a bunch of records in this log.

Comment 2

[Richard Newman [:rnewman]]

I will look at this today.

Comment 3

[Richard Newman [:rnewman]]

Trivial failing test:

function test_empty_query() {
  let record = new BookmarkQuery("bookmarks", "8xoDGqKrXf1P");
  record.folderName    = "";
  record.queryId       = "";
  record.parentName    = "Toolbar";
  record.parentid      = "toolbar";
  store.applyIncoming(record);
}

Comment 4

[Richard Newman [:rnewman]]

If we introduce a bmkUri:

0.91 TEST-UNEXPECTED-FAIL| xpcshell/head.js | [Exception... "'Illegal value' when calling method: [nsITaggingService::tagURI]"  nsresult: "0x80070057 (NS_ERROR_ILLEGAL_VALUE)"  location: "JS frame :: resource://services-sync/engines/bookmarks.js :: preprocessTagQuery :: line 455"  data: no]

If we introduce a title (still no queryId), it passes.

So somehow a query record is being created on the server without a URI (which causes the primary bug), and without a non-empty title (which would cause a different error).

Let's filter these out for sanity, and figure out how they're happening…

Comment 5

[Richard Newman [:rnewman]]

Attachment: Band-Aid. v1

This patch skips malformed query records. The traditional Sync solution to this is to throw, as we do for bad parent IDs, but that will cause clients to perpetually refetch the failed record (and report a failure, too).

I think it's better to quietly skip, until a client uploads a correct one (which will be fetched then due to its new timestamp).

Test included.

I kept this small, because I want to get it in ALL THE CHANNELS.

Comment 6

[Gregory Szorc [:gps]]

Comment on attachment 676347 [details] [diff] [review]
Band-Aid. v1

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

Code looks good. See nits.

::: services/sync/tests/unit/test_bookmark_store.js
@@ +4,5 @@
>  Cu.import("resource://services-sync/engines.js");
>  Cu.import("resource://services-sync/engines/bookmarks.js");
>  Cu.import("resource://services-sync/service.js");
>  Cu.import("resource://services-sync/util.js");
> +Cu.import("resource://services-common/utils.js");

Why?

@@ +377,5 @@
> +  record.folderName    = "";
> +  record.queryId       = "";
> +  record.parentName    = "Toolbar";
> +  record.parentid      = "toolbar";
> +  

Trailing whitespace.

@@ +397,5 @@
>    test_reparentOrphans();
>    if (engine._tracker._lazySave) {
>      engine._tracker._lazySave.clear();
>    }
> +  test_empty_query_doesnt_die();

Would you mind adding the new test with add_test() and calling run_next_test()? I know it breaks convention in this file but I'd rather not add more engineering debt.

Comment 7

[Richard Newman [:rnewman]]

Attachment: Part 0: modernize test. (Mechanical change.)

Comment 8

[Richard Newman [:rnewman]]

Attachment: Part 1: nits addressed. v2

Nits addressed. Uploaded for landing approval.

Comment 9

[Richard Newman [:rnewman]]

https://hg.mozilla.org/services/services-central/rev/e9418e7f4ab5
https://hg.mozilla.org/services/services-central/rev/8bc890ed3683

Comment 10

[Richard Newman [:rnewman]]

Attachment: Part 1: revised. v3

Busted another test. Made this a little more nuanced!

Comment 11

[Richard Newman [:rnewman]]

Fix was here:

https://hg.mozilla.org/services/services-central/rev/424592561c43

Comment 12

[Richard Newman [:rnewman]]

   https://hg.mozilla.org/integration/mozilla-inbound/rev/ea46051fdc77
   https://hg.mozilla.org/integration/mozilla-inbound/rev/561c637077fa

This affects all released versions; handling of malformed records has been poor back to Firefox 4.

I'd like to land this fix in Aurora and Beta, once we've had some verification on Nightly, because this will affect users who've been using Firefox for Android for a while.

Tracy, would you mind verifying with a services-central build (rather than waiting for Nightly)?

Things to check:

* Ordinary syncing between two profiles. Make sure that queries -- "Recent" etc. -- work, and there are no errors. (Do a "Sync Now" to make sure they get reported.)

* Syncing to Android.


Precise STR:

* Once you've synced with Android, quit desktop and delete all of your data from the Sync server (from another browser). You should be able to do this through Account Portal; if not, an HTTP DELETE to the storage URL will do the trick.

* Now force a sync on Android: Settings > Accounts & sync > your account > Menu > Sync Now. Wait for it to finish. This'll put bad data on the server.

* Now set up a new desktop profile. Delete all of your bookmarks, turn on logOnSuccess, then pair with your phone. Sync. An older release will fail; with this fix, you'll see log messages in the success log:

  Skipping malformed query bookmark: <some ID>

and those queries won't appear (e.g., smart bookmarks on your toolbar won't appear).


After Bug 806656 lands, those queries should sync successfully.

Comment 13

[Tracy Walker [:tracy]]

Yes, I will check this against s-c build from this morning.

Comment 14

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/mozilla-central/rev/ea46051fdc77
https://hg.mozilla.org/mozilla-central/rev/561c637077fa

Comment 15

[Tracy Walker [:tracy]]

Ah, there wasn't a build from this morning but the last s-c build of 1029 had this apparently picked up this fix.  

I reproduced on an older build first, so I'd be sure to know what I was verifying here.  With this fix I see success log with 

Skipping malformed query bookmark: <some ID>

as expected.

good to go for uplift to other channels.

Comment 16

[Richard Newman [:rnewman]]

Thanks, Tracy, that's fantastic.

Comment 17

[Richard Newman [:rnewman]]

Comment on attachment 676417 [details] [diff] [review]
Part 1: revised. v3

[Approval Request Comment]
Bug caused by (feature/regressing bug #): 
  Combination of long-term lack of robustness (< Fx4) and Bug 806634, which generated bad records.

User impact if declined: 
  Failure to sync bookmarks in some circumstances.

Testing completed (on m-c, etc.): 
  QA verified on s-c.

Risk to taking this patch (and alternatives if risky): 
  Essentially 0.

String or UUID changes made by this patch: 
  None.

Comment 18

[Richard Newman [:rnewman]]

Comment on attachment 676358 [details] [diff] [review]
Part 0: modernize test. (Mechanical change.)

Should be a rubberstamp approval; routine test modernization as a prerequisite for Part 1.

Comment 19

[Lukas Blakk [:lsblakk] use ?needinfo]

Comment on attachment 676358 [details] [diff] [review]
Part 0: modernize test. (Mechanical change.)

go ahead and uplift to branches now so this gets into 17 b4

Comment 20

[Richard Newman [:rnewman]]

   https://hg.mozilla.org/releases/mozilla-beta/rev/ec9a0c5f41ca
   https://hg.mozilla.org/releases/mozilla-beta/rev/e23a57ca75a9

   https://hg.mozilla.org/releases/mozilla-aurora/rev/018df0692d6a
   https://hg.mozilla.org/releases/mozilla-aurora/rev/cab03de92c7e