Closed Bug 634441 Opened 9 years ago Closed 9 years ago

Illegal value in nsILivemarkService::createLivemark

Categories

(Firefox :: Sync, defect)

defect
Not set

Tracking

()

RESOLVED FIXED

People

(Reporter: rnewman, Assigned: rnewman)

Details

(Whiteboard: [fixed in fx-sync][fixed in services])

Attachments

(3 files, 2 obsolete files)

Attached file Error log.
User reported this on the mailing list.

I'm going to have to transcribe the record itself, as it was sent in as a screenshot.
Attached file Bad record.
I believe this is an accurate transcription of http://imagebin.org/136377 .
The only way I've found (so far) to cause this error is to pass an invalid parent ID (e.g., 0 or -1) to createLivemark. I can see by inspection that the other arguments are fine: the others are all constant for this record, with only the parent variable by virtue of depending on the context of insertion.

Sure would be nice if we logged that.

The odd thing is that the code apparently doesn't allow a non-positive parent ID at this point.

This perhaps suggests that some other mechanism exists for causing the parent ID to be invalid. Still looking.
This happened again on a different record:

2011-02-20 11:43:32	Engine.Bookmarks     INFO	0 outgoing items pre-reconciliation
2011-02-20 11:43:36	Store.Bookmarks      WARN	Failed to apply incoming record WOJggJtjso_2
2011-02-20 11:43:36	Store.Bookmarks      WARN	Encountered exception: 'Illegal value' when calling method: [nsILivemarkService::createLivemark] Stack trace: BStore_create()@resource://services-sync/engines/bookmarks.js:703 < Store_applyIncoming()@resource://services-sync/engines.js:217 < BStore_applyIncoming()@resource://services-sync/engines/bookmarks.js:580 < resource://services-sync/engines.js:203 < applyIncomingBatch()@resource://services-sync/engines.js:209 < doApplyBatch()@resource://services-sync/engines.js:676 < resource://services-sync/engines.js:742 < innerBind()@resource://services-sync/util.js:1486 < resource://services-sync/record.js:801 < Channel_onDataAvail()@resource://services-sync/resource.js:530
2011-02-20 11:43:36	Collection           DEBUG	GET success 200 https://phx-sync352.services.mozilla.com/1.0/henrik/storage/bookmarks?full=1&ids=WOJggJtjso_2
2011-02-20 11:43:36	Engine.Bookmarks     DEBUG	Records that failed to apply: WOJggJtjso_2
2011-02-20 11:43:36	Service.Main         DEBUG	bookmarks failed to apply some records.
2011-02-20 11:43:36	Engine.Bookmarks     INFO	Records: 1 applied, 1 failed to apply, 0 reconciled.

Here's the record http://dl.dropbox.com/u/1087529/weave/WOJggJtjso_2.png

(The previous record is at http://dl.dropbox.com/u/1087529/weave/1lnZZXfB8nC7.png -- it disappeared from imagebin.  Why can't I copy text from the error console, I wonder..?)
(In reply to comment #3)

> Why can't I copy text from the error console, I wonder..?

You can. Click on the entry and hit the keyboard shortcut for Copy, or open the context menu and choose "Copy".
No, I cannot.  The context meny entry is greyed out: http://dl.dropbox.com/u/1087529/weave/cannot-copy.png

As a side note, which might be helpful for others:

Here's a link to the original mail thread, by the way: https://groups.google.com/group/mozilla-labs-weave/browse_frm/thread/de65ab4061bbdc83  

It contains a guide on how to decrypt a weave bookmark entry.
(In reply to comment #3)

> Here's the record http://dl.dropbox.com/u/1087529/weave/WOJggJtjso_2.png

This record also looks fine to me. Thanks for the additional report; I'm going to be cogitating some more this week, see if I can get to the bottom of this.

No idea why the copying operation is disabled…!
Assignee: nobody → rnewman
Status: NEW → ASSIGNED
Attached patch Tests. v1 (obsolete) — Splinter Review
These tests don't fail, which aligns with the fact that we can't repro the problem :)

However, it's good to have them, if only as a basis for further modifications to try to get them to break...

These are in my queue on top of the patch in Bug 632287.
Attachment #514302 - Flags: review?(philipp)
Attached patch Improvements. v1 (obsolete) — Splinter Review
This patch does the following:

* Adds logging to Store.applyIncoming. If an operation throws an error, it gets logged and rethrown. This might not be the best place for this, but right now we don't seem to have enough logging, and this is better than putting log-catches around individual 'constructor' calls that might fail.

* Adds logging of the link between record ID and parent ID prior to hitting the guts of BStore_create. This should help us track down the problem, if the createLivemark error is due to a parent issue.

* Adds checking for known-bad Livemark values (such as a parent which is a Livemark, or no feed URI). Better to catch these here and drop the record rather than get an exception in createLivemark.

* Uses createLivemarkFolderOnly instead of createLivemark. This will prevent nsLivemarkService from attempting to update the livemark during our sync. (Also handily avoids background errors during test termination.)

* Log the record ID when livemark created.

* Adds a "noCreate" option to GUIDForId. Without it it's kinda hard to write tests that check whether an ID has a GUID...

* Switch a 'var' to a 'let'.
Attachment #514306 - Flags: review?(philipp)
Comment on attachment 514302 [details] [diff] [review]
Tests. v1

>+// Clean up after other tests. Only necessary in XULRunner.
>+store.wipe();

I wonder if it's a good idea to put that at global scope rather than inside the run_test() functinon. Also, we should really just fix bug 620473.

>+function makeLivemark(p) {
>+  let b = new Livemark("bookmarks", p.id);
>+  for each (let x in ["siteUri", "feedUri", "description", "title",
>+                      "children", "hasDupe", "parentid", "parentName",
>+                      "type"]) {
>+    _("Copying " + x);
>+    b[x] = p[x];
>+  }

How about b.cleartext = p instead of that loop?

>+  return b;
>+}
>+
>+function test_bug634441() {
>+  // Put it in the menu.
>+  record634441.parentid = kSpecialIds.specialGUIDForId(kSpecialIds.menu);

record634441.parentid = "menu" ???

>+  let siteURI = null;
>+  let record = makeLivemark(record634441);
>+
>+  // noCreate option to idForGUID => no parent ID yet.
>+  let parentId = store.idForGUID(record.parentid, true);
>+  //do_check_eq(null, parentId);

Left over comment?

>+  if (parentId > 0) {
>+    // Save the parent id for modifying the bookmark later
>+    record._parent = parentId;
>+    record._orphan = false;
>+  } else {
>+    _("Record " + record.id +
>+      " is an orphan: could not find parent " + record.parentid);
>+    record._orphan = true;
>+  }
>+  _("Parent: " + record._parent);
>+  if (!record._parent) {
>+    record._parent = Svc.Bookmark.unfiledBookmarksFolder;
>+  }
>+  _("Parent: " + record._parent);
>+  if (record.siteUri != null)
>+    siteURI = Utils.makeURI(record.siteUri);
>+
>+  let newId;
>+  try {
>+    let ls = store._ls;
>+    newId = ls.createLivemarkFolderOnly(record._parent, record.title,
>+                                        siteURI,
>+                                        Utils.makeURI(record.feedUri),
>+                                        Svc.Bookmark.DEFAULT_INDEX);
>+  } catch(ex) {
>+    _("Got exception in createLivemarkFolderOnly: " + Utils.exceptionStr(ex));
>+  }
>+  _("newId is " + newId);
>+  do_check_true(newId > 0);
>+  do_check_true(store._ls.isLivemark(newId));

What parts of the bookmark engine are we testing here exactly? This test seems to be mostly copypasta from the engine itself rather than exercising its code...


>+function test_bug631361() {

Nit: please choose a descriptive function name. We can ref bug 631361 in a comment, but having to go look up a bug just to figure out what the test is supposed to exercise is unnecessary indirection.

>+  let record = record631361.payload;
>+  function doRecord(r) {
>+    let err = null;
>+    try {
>+      store._childrenToOrder = {};
>+      store.applyIncoming(r);
>+      store._orderChildren();
>+      delete store._childrenToOrder;
>+    } catch (ex) {
>+      err = ex;
>+    }
>+    do_check_true(!err);

No need to catch exceptions here. They will bubble up, the test runner will catch them and abort the test. Unless of course you're in an async callback, in which case you want to do_throw(ex) in the catch clause rather than catching it and checking that it's not truthy.

>+  // Attempt to provoke an error by messing around with the description.
>+  record.description = null;
>+  doRecord(makeLivemark(record));
>+  record.description = "";
>+  doRecord(makeLivemark(record));
>+  
>+  // Attempt to provoke an error by adding a bad description anno.
>+  let id = store.idForGUID(record.id);
>+  let err = null;
>+  try {
>+    Utils.anno(id, DESCRIPTION_ANNO, "");
>+  } catch (ex) {
>+    err = ex;
>+  }
>+  do_check_eq(null, err);

Same as above: no need for explicit catch.

>+function sleep(delay, fn) {
>+  let timer = Cc["@mozilla.org/timer;1"].createInstance(Ci.nsITimer);
>+  let callback = {
>+    notify: function notify() {
>+      // This line actually just keeps a reference to timer (prevent GC)
>+      timer = null;
>+      _("Timer fired.");
>+      fn();
>+    }
>+  }
>+  timer.initWithCallback(callback, delay, Ci.nsITimer.TYPE_ONE_SHOT);
>+}
...
>+  sleep(0, do_test_finished);

Simpler:

  Utils.delay(do_test_finished, 0);

>+function run_test() {
>+  do_test_pending();
>+  initTestLogging("Trace");
>+  Log4Moz.repository.getLogger("Engine.Bookmarks").level = Log4Moz.Level.Trace;
>+  Log4Moz.repository.getLogger("Store.Bookmarks").level  = Log4Moz.Level.Trace;
>+
>+  test_bug631361();
>+  test_bug634441();
>+  
>+  // Wait here so that Livemarks gets a chance to finish what it's doing.
>+  // asyncChain doesn't seem to work...

Huh? Livemarks is doing some async stuff despite its synchronous API? Why does asyncChain not work? I imagine this is what you did:?

  function test_foobar(next) {
    // test test test

    // Clear event loop
    Utils.delay(next, 0);
  }

  function run_test() {
    do_test_pending();
    Utils.asyncChain(test_foobar,
                     do_test_finished)();
  }


r- for now since we need a new patch
Attachment #514302 - Flags: review?(philipp) → review-
Comment on attachment 514306 [details] [diff] [review]
Improvements. v1

>   applyIncoming: function Store_applyIncoming(record) {
>-    if (record.deleted)
>-      this.remove(record);
>-    else if (!this.itemExists(record.id))
>-      this.create(record);
>-    else
>-      this.update(record);
>+    try {
>+      if (record.deleted)
>+        this.remove(record);
>+      else if (!this.itemExists(record.id))
>+        this.create(record);
>+      else
>+        this.update(record);
>+    } catch(ex) {
>+      this._log.debug("Caught exception in Store.applyIncoming: " +
>+                      Utils.exceptionStr(ex));
>+      this._log.trace("Record: " + JSON.stringify(record));
>+      throw ex;
>+    }

CryptoWrappers have a toString() method that actually produces nice output, so you could just do

      this._log.trace("Record: " + record);

But even that seems unnecessary because when you've got that engine's log on Trace level, it will already print out that exact thing [1]. Furthermore, the exception should already be logged by store.applyIncomingBatch() [2], so I don't really see the point of introducing this try+except clause at all. (Note that the latter is missing from 1.6.x which might explain the lack of exception traces in logs provided by users.)

[1] https://mxr.mozilla.org/mozilla-central/source/services/sync/modules/engines.js#884
[2] https://mxr.mozilla.org/mozilla-central/source/services/sync/modules/engines.js#205


>       let siteURI = null;
>+      if (!record.feedUri) {
>+        this._log.debug("No feed URI: skipping livemark record " + record.id);
>+        return;
>+      }
>+      if (!record._parent || this._ls.isLivemark(record._parent)) {
>+        this._log.debug("Invalid parent: skipping livemark record " + record.id);
>+        return;
>+      }
>+

Yay! But where are the tests?

>       if (record.siteUri != null)
>         siteURI = Utils.makeURI(record.siteUri);
> 
>-      newId = this._ls.createLivemark(record._parent, record.title, siteURI,
>-                                      Utils.makeURI(record.feedUri),
>-                                      Svc.Bookmark.DEFAULT_INDEX);
>+      // Use createLivemarkFolderOnly, not createLivemark, to avoid it
>+      // automatically updating during a sync.
>+      newId = this._ls.createLivemarkFolderOnly(record._parent, record.title,
>+                                                siteURI,
>+                                                Utils.makeURI(record.feedUri),
>+                                                Svc.Bookmark.DEFAULT_INDEX);

Nice!

>-  GUIDForId: function GUIDForId(id) {
>+  GUIDForId: function GUIDForId(id, noCreate) {

You mentioned that this helps writing tests but I see no such tests. I think we should wait with these changes until we actually implement those tests...

>     // Give the uri a GUID if it doesn't have one
>-    return this._setGUID(id);
>+    return noCreate ? null : this._setGUID(id);

Ick. Please spell this out:

  if (noCreate)
    return null;
  return this._setGUID(id);

(Though this comment is obsolete given the previous comment.)


r- for now because we need a new patch. It should contain just the improvements wrt livemark robustness (+ tests).
Attachment #514306 - Flags: review?(philipp) → review-
(In reply to comment #9)

> I wonder if it's a good idea to put that at global scope rather than inside the
> run_test() functinon. Also, we should really just fix bug 620473.

Indeed.

That was copied from another test, so I make no claim to whether it's the best approach or not :D

> How about b.cleartext = p instead of that loop?

I'll check whether that is equivalent for all of the accessors. If so, much nicer!

> record634441.parentid = "menu" ???

You say "tomato", I say globalConstant.lookupStringFor("tomato") :D
 
> Left over comment?

Commented-out test; see the noCreate stuff. Things got a little juggled as I rearranged patch queue items for easy review. Will fix this.


> What parts of the bookmark engine are we testing here exactly? This test seems
> to be mostly copypasta from the engine itself rather than exercising its
> code...

It's not directly testing the bookmark engine: it's testing the assumptions upon which the bookmark engine rests. Not ideal, but it's the best way to attack this particular bug.

I'm not averse to refactoring these into tests that call through the engine itself, but I'd only want to do that once we figure out exactly what's going wrong.

Like I said: this is a first step.


> Nit: please choose a descriptive function name.

Gotcha.


> Simpler:
> 
>   Utils.delay(do_test_finished, 0);

Thanks!
 

> Huh? Livemarks is doing some async stuff despite its synchronous API? Why does
> asyncChain not work? I imagine this is what you did:?

Livemarks was updating its records, doing HTTP fetches, etc. in the background. That caused leak notifications (e.g., for allocated URIs) and so forth to occur after do_test_finished. Switching to createLivemarkFolderOnly might have got rid of all of these, but I haven't tested on all platforms, so I left the delay in place.

When I used asyncChain, it seemed to block on the event loop. I didn't use Utils.delay (always something new to learn!), so that might do the trick. Will test.
(In reply to comment #10)

> don't really see the point of introducing this try+except clause at all. (Note
> that the latter is missing from 1.6.x which might explain the lack of exception
> traces in logs provided by users.)

Ah, that would explain it. Yes, my thought process was "hmm, I ain't never seen a user's log worth a damn at figuring out which record failed; better add more logging!".
This should suck less. Furthermore, it directly exercises this bug: the check at the start of BStore_create() was invalid, and would cause createLivemark to throw an error whenever a livemark was encountered before its parent.

We're lucky that most people don't use livemarks, and those that exist are typically top-level items...
Attachment #514302 - Attachment is obsolete: true
Attachment #514306 - Attachment is obsolete: true
Attachment #514917 - Flags: review?(philipp)
Comment on attachment 514917 [details] [diff] [review]
Just the good bits. v1

>   create: function BStore_create(record) {
>-    // Default to unfiled if we don't have the parent yet
>-    if (!record._parent) {
>+    // Default to unfiled if we don't have the parent yet.
>+    if (!(record._parent > 0)) {

I understand why this isn't equivalent to record._parent <= 0 but the casual reader might not (undefined > 0 is false just as much as undefined <= 0 is). Add a comment?

>+  try {
>+    // Attempt to provoke an error by messing around with the description.
>+    record.description = null;
>+    doRecord(makeLivemark(record));
>+    record.description = "";
>+    doRecord(makeLivemark(record));
>+    
>+    // Attempt to provoke an error by adding a bad description anno.
>+    let id = store.idForGUID(record.id);
>+    Utils.anno(id, DESCRIPTION_ANNO, "");
>+  } catch (ex) {
>+    do_throw(ex);
>+  }

No need for this try+catch+do_throw dance if you use asyncChainTests() below.

>+  Utils.asyncChain(

Use asyncChainTests() here.

r=me. 100 tests w0000t!
Attachment #514917 - Flags: review?(philipp) → review+
Comment on attachment 514917 [details] [diff] [review]
Just the good bits. v1

Risks: negligible. Could conceivably alter livemark refreshing schedules, but not too worried about that.

Rewards: no more sync errors downloading livemarks!
Attachment #514917 - Flags: approval2.0?
Whiteboard: [has patch][has review]
Comment on attachment 514917 [details] [diff] [review]
Just the good bits. v1

a=beltzner
Attachment #514917 - Flags: approval2.0? → approval2.0+
Pushed to fx-sync.

  http://hg.mozilla.org/services/fx-sync/rev/bb1d109d50e7

mconnor, philiKON: are we planning another 1.6.x release? If not, then I shan't bother transplanting the commit...
Whiteboard: [has patch][has review] → [has patch][has review][fixed in fx-sync]
Hold up, just got something weird overlaying the addon on a nightly:

[Exception... "'[JavaScript Error: "aURI is null" {file: "chrome://browser/content/browser.js" line: 3493}]' when calling method: [nsINavBookmarkObserver::onItemAdded]"  nsresult: "0x80570021 (NS_ERROR_XPC_JAVASCRIPT_ERROR_WITH_DETAILS)"  location: "JS frame :: file:///Users/rnewman/moz/hg/services-central/obj-ff-dbg/dist/MinefieldDebug.app/Contents/MacOS/components/nsLivemarkService.js :: LS__createFolder :: line 371"  data: yes]

Investigating.
(In reply to comment #18)
> Hold up, just got something weird overlaying the addon on a nightly:
> 
> [Exception... "'[JavaScript Error: "aURI is null" {file:
> "chrome://browser/content/browser.js" line: 3493}]' when calling method:
> [nsINavBookmarkObserver::onItemAdded]"  nsresult: "0x80570021
> (NS_ERROR_XPC_JAVASCRIPT_ERROR_WITH_DETAILS)"  location: "JS frame ::
> file:///Users/rnewman/moz/hg/services-central/obj-ff-dbg/dist/MinefieldDebug.app/Contents/MacOS/components/nsLivemarkService.js
> :: LS__createFolder :: line 371"  data: yes]
> 
> Investigating.

Nothing in the sync-log, which is why I didn't notice this before. Apparently browser.js is naïve in the case of a Livemark folder being added:

  // nsINavBookmarkObserver
  onItemAdded:
  function PSB_onItemAdded(aItemId, aFolder, aIndex, aItemType, aURI)
  {
    if (!this._starIcon) {
      return;
    }

    if (aURI.equals(this._uri)) {
      // If a new bookmark has been added to the tracked uri, register it.
      if (this._itemIds.indexOf(aItemId) == -1) {
        this._itemIds.push(aItemId);
        this._updateStateInternal();
      }
    }
  },

*sigh*
OK, nothing to worry about. Existing bug, which I filed and have a r+ patch for: Bug 636828.

New livemarks don't get their icon until they're refreshed, apparently: Bug 387138. I've been advised that having Sync kick off a livemark refresh would be a bad thing, because refreshes block the UI. So we're done here, and should fix Bug 387138 to get things looking right.
Merged to s-c: http://hg.mozilla.org/services/services-central/rev/c600993a7b03
Whiteboard: [has patch][has review][fixed in fx-sync] → [fixed in fx-sync][fixed in services]
Merged to m-c: http://hg.mozilla.org/mozilla-central/rev/c600993a7b03
Status: ASSIGNED → RESOLVED
Closed: 9 years ago
Resolution: --- → FIXED
Component: Firefox Sync: Backend → Sync
Product: Cloud Services → Firefox
You need to log in before you can comment on or make changes to this bug.