472480 - Engine exception: TypeError: this._findURLByGUID(oldID) is null | some fixes for history sync

Status: RESOLVED FIXED

(Cloud Services :: General, defect)

Description

[Markus Doits]

User-Agent:       Mozilla/5.0 (X11; U; Linux i686 (x86_64); en-US; rv:1.9.1b2) Gecko/20081201 Firefox/3.1b2
Build Identifier: 0.2.96

like some other people on the mozilla forum (https://labs.mozilla.com/forum/comments.php?DiscussionID=4919) suddenly i've got this in my log:

2009-01-07 13:56:56	Service.Main	WARN	Engine exception: TypeError: this._findURLByGUID(oldID) is null
2009-01-07 13:56:56	FaultTolerance	DEBUG	
Original exception: this._findURLByGUID(oldID) is null (module:history.js:282 :: TypeError)
Async stack trace:
module:engines.js:212 :: Engine_sync
module:service.js:648 :: WeaveSvc__syncEngine
module:wrap.js:94 :: WeaveNotifyWrapper
module:service.js:576 :: WeaveSvc__sync
module:util.js:475 :: EL_notify
Last callback created at module:engines.js:511 :: SyncEngine__sync

some syncs worked fine, then this error appeared. maybe it should be stated i am using a sqlite-database-server now and i did not have this on mysql before using it for few days, with sqlite after half a day (but maybe that's not related to the problem)

i've workaround for this error below, but it should be looked why the function is returning null (which should not be the case). but when the source of the problem is not easy to find, the patch can make it working for now.

Reproducible: Always

Steps to Reproduce:
not known, it simply appeared
Actual Results:  
history sync not working


diff -r 4d702f39c061 modules/engines/history.js
--- a/modules/engines/history.js	Sat Jan 03 01:41:07 2009 -0800
+++ b/modules/engines/history.js	Wed Jan 07 14:14:34 2009 +0100
@@ -279,8 +279,13 @@
   },
 
   changeItemID: function HStore_changeItemID(oldID, newID) {
-    let uri = Utils.makeURI(this._findURLByGUID(oldID).uri);
-    this._anno.setPageAnnotation(uri, "weave/guid", newID, 0, 0);
+    var temp = this._findURLByGUID(oldID);
+    if (temp) {
+      let uri = Utils.makeURI(this._findURLByGUID(oldID).uri);
+      this._anno.setPageAnnotation(uri, "weave/guid", newID, 0, 0);
+    } else {
+      this._log.trace("changeItemID: this._findURLByGUID(oldID) is null");
+    }
   },

Comment 1

[Markus Doits]

Attachment: second version of the patch

here's a further version, which handles some more errors.

i created some errors by deleting the last history sync timestamp (which simulates initial sync with a new client, right?) and fixed them afterwards with this patch.

deleting last bookmark sync timestamp does work well, though - no fix needed

Comment 2

[Markus Doits]

Attachment: third version + one more fix

third version, i should drink more coffee...

this fixes one additionally error i encountered (and forgot to include in the patch) and corrects the previous patch.

this patch is now also based on the latest weave snapshot ba6949bae813 (though not 0.9.97 since sources are not available)

Comment 3

[Markus Doits]

damn it, i mean 0.2.97 in #2 of course...

btw., i wonder what you say to my patch-tryouts - i'm sure i'm not fixing it "the right way", so i am waiting for how you guys will fix it to learn from it and to make it better next time :)

Comment 4

[Dan Mills [:thunder]]

Thanks Markus!

While your fix is good, it doesn't actually fix the root cause (as you pointed out).  changeItemID should not get called for non-existent IDs.  This is the only time changeItemID gets called:

http://hg.mozilla.org/labs/weave/file/tip/modules/engines.js#l364

One thought is that recordLike might be considering deleted items to be alike.  That would be incorrect, only existing records should be considered.

Comment 5

[Dan Mills [:thunder]]

Fix to recordLike:

http://hg.mozilla.org/labs/weave/rev/c086899f4b7e

And also a modified version of your util.js change:

http://hg.mozilla.org/labs/weave/rev/e2c7d49c46be

Comment 6

[Dan Mills [:thunder]]

I decided to implement a more simplistic version of the changeItemID check.  This patch I committed simply catches any exception and prints it:

http://hg.mozilla.org/labs/weave/rev/d6dc5a90a635

This change and the ones from comment #5 should fix the problem.  Please reopen if something's still wrong... and thanks again!

Comment 7

[Markus Doits]

allright, that fixes it. try n error does not give any information why it went wrong, but since it should never go wrong, that's the best solution, i see :)

so the source was an incoming entry with empty "cleartext"? is cleartext the entry itself (i.e. "www.google.de", without any other information of the playload - https://wiki.mozilla.org/Labs/Weave/0.3/API#Payloads does not have information about this yet)? 

and deleted entries are simply stored as "" on the server, right? if so, how can a client know an entry was deleted when the local ID was another than the one on the server (e.g. adding the same bookmarks on different clients without syncing, delete the bookmark from one of them, sync this one, sync the other one - will the bookmark get deleted from the latter, which it should, since server wins)?

trying to understand the whole process.

Comment 8

[Dan Mills [:thunder]]

the try/catch should give a little bit of info - just enough to know to look in there if something isn't working.  I think it's enough.

The 'cleartext' property contains the encrypted payload after decryption.  Its contents depend on the data type--in the case of history it's something like:

{URI: "http://foo.com",
 title: "blah blah",
 visits: [{date: 2342342, type: 5}, {..},...]}

Or in the case of a deleted item, null.  That is how a remote profile would distinguish between a new item and a deleted item.

If you add the same item on two profiles, then delete it on one profile, recordLike() will never get a chance to reconcile the ID between the two profiles, so you'll end up with two records on the server, one of them deleted (and eventually the item will reappear on the profile you deleted it in).

Does that make sense?

Comment 9

[Markus Doits]

okey, i mixed up that the ID is saved unencrypted (at least not encrypted with the passphrase), so it's not in the playload --> if playload is null it still can be compared with id. makes sense.

i mixed up http://hg.mozilla.org/labs/weave/file/d6dc5a90a635/modules/engines.js#l338 too - i had "server wins" in my mind, which means exactly the opposite as written there :) so right now it works like it is written there.

it would be more reasonable to know when the item was updated/deleted on client side (a local timestamp or so), then the latest one could win. because if i change something on two clients, i will change it to what i want it to be and to stay, not to something like "i'll change the entry but i know it will be overwritten if i sync in wrong order by an old change (which may be outdated already) i made before".

but this would depend on the client-time, which is a possible source of error. also this would only work changed/deleted items with the same ID - newly created items would never know they are the same and that their local timestamps have to be compared. this could be fixed by comparing some keys of the entry (e.g. the url and parentid/place where it is) and seeing they are the same despite of different id, ... 

so having it the way it is now is at least consistent in the way changes are handled. and this should be a rare case, too.

Comment 10

[Markus Doits]

... so my conclusion is: this change requires some work and it's benefits are noticed in rare cases - so handle this as low low priority (if at all).

Comment 11

[Dan Mills [:thunder]]

We don't use local timestamps because (as you point out) differences in time will cause unpredictable behavior.  I feel that predictability is more important.

I have thought about changing the behavior to be the opposite, though (server wins).  It has some nice upsides.