Last Comment Bug 806460 - NS_ERROR_ILLEGAL_VALUE in nsINavBookmarksService.insertBookmark while inserting query
: NS_ERROR_ILLEGAL_VALUE in nsINavBookmarksService.insertBookmark while inserti...
[verified in services][qa+]
Product: Cloud Services
Classification: Client Software
Component: Firefox Sync: Backend (show other bugs)
: unspecified
: All All
: P1 normal with 1 vote (vote)
: mozilla19
Assigned To: Richard Newman [:rnewman]
Depends on: 806656
Blocks: 806087
  Show dependency treegraph
Reported: 2012-10-29 11:01 PDT by Richard Newman [:rnewman]
Modified: 2014-02-19 13:13 PST (History)
3 users (show)
ryanvm: in‑testsuite+
See Also:
Crash Signature:
QA Whiteboard:
Iteration: ---
Points: ---

Band-Aid. v1 (3.15 KB, patch)
2012-10-29 15:11 PDT, Richard Newman [:rnewman]
gps: review+
Details | Diff | Splinter Review
Part 0: modernize test. (Mechanical change.) (8.75 KB, patch)
2012-10-29 15:25 PDT, Richard Newman [:rnewman]
rnewman: review+
lukasblakk+bugs: approval‑mozilla‑aurora+
lukasblakk+bugs: approval‑mozilla‑beta+
Details | Diff | Splinter Review
Part 1: nits addressed. v2 (2.21 KB, patch)
2012-10-29 15:26 PDT, Richard Newman [:rnewman]
no flags Details | Diff | Splinter Review
Part 1: revised. v3 (3.06 KB, patch)
2012-10-29 17:51 PDT, Richard Newman [:rnewman]
lukasblakk+bugs: approval‑mozilla‑aurora+
lukasblakk+bugs: approval‑mozilla‑beta+
Details | Diff | Splinter Review

Description Richard Newman [:rnewman] 2012-10-29 11:01:31 PDT
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] 2012-10-29 11:03:01 PDT
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] 2012-10-29 11:16:34 PDT
I will look at this today.
Comment 3 Richard Newman [:rnewman] 2012-10-29 13:29:32 PDT
Trivial failing test:

function test_empty_query() {
  let record = new BookmarkQuery("bookmarks", "8xoDGqKrXf1P");
  record.folderName    = "";
  record.queryId       = "";
  record.parentName    = "Toolbar";
  record.parentid      = "toolbar";
Comment 4 Richard Newman [:rnewman] 2012-10-29 13:32:51 PDT
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] 2012-10-29 15:11:41 PDT
Created attachment 676347 [details] [diff] [review]
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] 2012-10-29 15:14:52 PDT
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");


@@ +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] 2012-10-29 15:25:36 PDT
Created attachment 676358 [details] [diff] [review]
Part 0: modernize test. (Mechanical change.)
Comment 8 Richard Newman [:rnewman] 2012-10-29 15:26:35 PDT
Created attachment 676360 [details] [diff] [review]
Part 1: nits addressed. v2

Nits addressed. Uploaded for landing approval.
Comment 10 Richard Newman [:rnewman] 2012-10-29 17:51:19 PDT
Created attachment 676417 [details] [diff] [review]
Part 1: revised. v3

Busted another test. Made this a little more nuanced!
Comment 11 Richard Newman [:rnewman] 2012-10-29 17:51:46 PDT
Fix was here:
Comment 12 Richard Newman [:rnewman] 2012-10-29 22:18:33 PDT

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] 2012-10-30 07:36:18 PDT
Yes, I will check this against s-c build from this morning.
Comment 15 Tracy Walker [:tracy] 2012-10-30 10:03:00 PDT
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] 2012-10-30 13:13:49 PDT
Thanks, Tracy, that's fantastic.
Comment 17 Richard Newman [:rnewman] 2012-10-30 13:15:50 PDT
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: 
Comment 18 Richard Newman [:rnewman] 2012-10-30 13:16:37 PDT
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 2012-10-30 13:40:01 PDT
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

Note You need to log in before you can comment on or make changes to this bug.