Closed Bug 410895 Opened 17 years ago Closed 17 years ago

Failure to Synch Bookmarks with exception: "this._data[command.GUID] is undefined"

Categories

(Cloud Services :: General, defect)

Product:
Cloud Services
Component:
General
Platform:
PowerPC
macOS
Type:
defect
Priority:
Not set
Severity:
major

Tracking

(Not tracked)

Status:
VERIFIED FIXED

People

(Reporter: abillings, Unassigned)

Details

My bookmarks are failing to synch between two machines running the same version of Weave now. (My history is failing to but that seems to be a different and longer standing issue.) The log shows the following when I try to synch bookmarks: 2008-01-05 00:59:15 Service.Main DEBUG Service lock acquired 2008-01-05 00:59:15 Service.Main DEBUG Resetting server lock 2008-01-05 00:59:15 Service.DAV INFO Forcibly releasing any server locks 2008-01-05 00:59:15 Service.DAV INFO Getting active lock token 2008-01-05 00:59:15 Service.DAV DEBUG Creating PROPFIND request for https://services.mozilla.com/user/dfba9baf82ab25da08625aa27370c44fb46cdf5a/ 2008-01-05 00:59:15 Service.DAV DEBUG HTTP Header Content-type: text/xml; charset="utf-8" 2008-01-05 00:59:15 Service.DAV DEBUG HTTP Header Depth: 0 2008-01-05 00:59:15 Service.DAV DEBUG HTTP Header Authorization: ***** (suppressed) 2008-01-05 00:59:15 Service.DAV DEBUG HTTP Header If: 2008-01-05 00:59:15 Service.EventHandler DEBUG Handling event load 2008-01-05 00:59:15 Service.DAV ERROR Exception caught: token is null 2008-01-05 00:59:15 Service.DAV DEBUG No active lock token found 2008-01-05 00:59:15 Service.DAV INFO No server lock found 2008-01-05 00:59:15 Service.DAV DEBUG Lock released 2008-01-05 00:59:15 Service.Main DEBUG Server lock reset successful 2008-01-05 00:59:15 Service.Main DEBUG Service lock released 2008-01-05 00:59:20 Service.Main DEBUG Service lock acquired 2008-01-05 00:59:20 Service.BmkEngine INFO Beginning sync 2008-01-05 00:59:20 Service.DAV INFO Acquiring lock 2008-01-05 00:59:20 Service.DAV DEBUG Creating LOCK request for https://services.mozilla.com/user/dfba9baf82ab25da08625aa27370c44fb46cdf5a/ 2008-01-05 00:59:20 Service.DAV DEBUG HTTP Header Content-type: text/xml; charset="utf-8" 2008-01-05 00:59:20 Service.DAV DEBUG HTTP Header Depth: infinity 2008-01-05 00:59:20 Service.DAV DEBUG HTTP Header Timeout: Second-600 2008-01-05 00:59:20 Service.DAV DEBUG HTTP Header Authorization: ***** (suppressed) 2008-01-05 00:59:20 Service.DAV DEBUG HTTP Header If: 2008-01-05 00:59:20 Service.EventHandler DEBUG Handling event load 2008-01-05 00:59:20 Service.DAV INFO Lock acquired 2008-01-05 00:59:20 Service.BmkEngine INFO Lock acquired 2008-01-05 00:59:20 Service.DAV DEBUG Creating GET request for https://services.mozilla.com/user/dfba9baf82ab25da08625aa27370c44fb46cdf5a/user-data/ 2008-01-05 00:59:20 Service.DAV DEBUG HTTP Header Authorization: ***** (suppressed) 2008-01-05 00:59:20 Service.DAV DEBUG HTTP Header Content-type: text/plain 2008-01-05 00:59:20 Service.DAV DEBUG HTTP Header If: <https://services.mozilla.com/user/dfba9baf82ab25da08625aa27370c44fb46cdf5a/> (<opaquelocktoken:83f9ba3d-138d-4c84-807c-f41b1858416b>) 2008-01-05 00:59:20 Service.EventHandler DEBUG Handling event load 2008-01-05 00:59:20 Service.DAV DEBUG Skipping creation of path user-data (got status 200) 2008-01-05 00:59:20 Service.DAV DEBUG Creating GET request for https://services.mozilla.com/user/dfba9baf82ab25da08625aa27370c44fb46cdf5a/user-data/bookmarks/ 2008-01-05 00:59:20 Service.DAV DEBUG HTTP Header Authorization: ***** (suppressed) 2008-01-05 00:59:20 Service.DAV DEBUG HTTP Header Content-type: text/plain 2008-01-05 00:59:20 Service.DAV DEBUG HTTP Header If: <https://services.mozilla.com/user/dfba9baf82ab25da08625aa27370c44fb46cdf5a/> (<opaquelocktoken:83f9ba3d-138d-4c84-807c-f41b1858416b>) 2008-01-05 00:59:20 Service.EventHandler DEBUG Handling event load 2008-01-05 00:59:21 Service.DAV DEBUG Skipping creation of path user-data/bookmarks (got status 200) 2008-01-05 00:59:21 Service.BmkEngine DEBUG Getting status file from server 2008-01-05 00:59:21 Service.DAV DEBUG Creating GET request for https://services.mozilla.com/user/dfba9baf82ab25da08625aa27370c44fb46cdf5a/user-data/bookmarks/status.json 2008-01-05 00:59:21 Service.DAV DEBUG HTTP Header Authorization: ***** (suppressed) 2008-01-05 00:59:21 Service.DAV DEBUG HTTP Header Content-type: text/plain 2008-01-05 00:59:21 Service.DAV DEBUG HTTP Header If: <https://services.mozilla.com/user/dfba9baf82ab25da08625aa27370c44fb46cdf5a/> (<opaquelocktoken:83f9ba3d-138d-4c84-807c-f41b1858416b>) 2008-01-05 00:59:21 Service.EventHandler DEBUG Handling event load 2008-01-05 00:59:21 Service.BmkEngine INFO Got status file from server 2008-01-05 00:59:21 Service.BmkEngine INFO Downloading server deltas 2008-01-05 00:59:21 Service.DAV DEBUG Creating GET request for https://services.mozilla.com/user/dfba9baf82ab25da08625aa27370c44fb46cdf5a/user-data/bookmarks/deltas.json 2008-01-05 00:59:21 Service.DAV DEBUG HTTP Header Authorization: ***** (suppressed) 2008-01-05 00:59:21 Service.DAV DEBUG HTTP Header Content-type: text/plain 2008-01-05 00:59:21 Service.DAV DEBUG HTTP Header If: <https://services.mozilla.com/user/dfba9baf82ab25da08625aa27370c44fb46cdf5a/> (<opaquelocktoken:83f9ba3d-138d-4c84-807c-f41b1858416b>) 2008-01-05 00:59:21 Service.EventHandler DEBUG Handling event load 2008-01-05 00:59:21 Service.Crypto DEBUG Decrypting data 2008-01-05 00:59:29 Service.Crypto DEBUG Done decrypting data 2008-01-05 00:59:29 Service.SnapStore DEBUG Processing command: ({action:"edit", GUID:"{57ef7428-c78f-3549-ac91-a3e67dd0f795}355", depth:1, parents:["{57ef7428-c78f-3549-ac91-a3e67dd0f795}0"], data:{index:57}}) 2008-01-05 00:59:29 Service.SnapStore DEBUG Processing command: ({action:"edit", GUID:"{8129d1fa-d3a1-9f43-8de2-91adb318e9d5}361", depth:1, parents:["{57ef7428-c78f-3549-ac91-a3e67dd0f795}0"], data:{index:58}}) 2008-01-05 00:59:29 Service.SnapStore DEBUG Processing command: ({action:"edit", GUID:"{6e9db0b6-639e-8746-b2b6-053e3c5a5106}1", depth:1, parents:["{57ef7428-c78f-3549-ac91-a3e67dd0f795}0"], data:{index:59}}) 2008-01-05 00:59:29 Service.BmkEngine ERROR Exception caught: this._data[command.GUID] is undefined 2008-01-05 00:59:29 Service.BmkEngine INFO Local snapshot version: 25 2008-01-05 00:59:29 Service.BmkEngine INFO Server status: -1 2008-01-05 00:59:29 Service.BmkEngine INFO Server maxVersion: null 2008-01-05 00:59:29 Service.BmkEngine INFO Server snapVersion: null 2008-01-05 00:59:29 Service.BmkEngine FATAL Sync error: could not get server status, or initial upload failed. Aborting sync. 2008-01-05 00:59:29 Service.DAV INFO Releasing lock 2008-01-05 00:59:29 Service.DAV DEBUG Creating UNLOCK request for https://services.mozilla.com/user/dfba9baf82ab25da08625aa27370c44fb46cdf5a/ 2008-01-05 00:59:29 Service.DAV DEBUG HTTP Header Lock-Token: <opaquelocktoken:83f9ba3d-138d-4c84-807c-f41b1858416b> 2008-01-05 00:59:29 Service.DAV DEBUG HTTP Header Authorization: ***** (suppressed) 2008-01-05 00:59:29 Service.DAV DEBUG HTTP Header Content-type: text/plain 2008-01-05 00:59:29 Service.DAV DEBUG HTTP Header If: <https://services.mozilla.com/user/dfba9baf82ab25da08625aa27370c44fb46cdf5a/> (<opaquelocktoken:83f9ba3d-138d-4c84-807c-f41b1858416b>) 2008-01-05 00:59:29 Service.EventHandler DEBUG Handling event load 2008-01-05 00:59:29 Service.DAV INFO Lock released (or we didn't have one)
Interesting, it looks like your snapshot and deltas file are inconsistent: you seem to have a delta with an "edit" command for an item that doesn't exist in your snapshot (nor created in a previous delta). This seems quite broken, but I don't know how to reproduce this. Any tips?
Severity: normal → major
I can reproduce it at will. I just try to synch bookmarks from my home computer. My work laptop, unfortunately, doesn't have the problem. My log from just a minute ago: 2008-01-08 14:39:03 Service.Main INFO Running scheduled sync 2008-01-08 14:39:03 Service.Main DEBUG Service lock acquired 2008-01-08 14:39:03 Service.BmkEngine INFO Beginning sync 2008-01-08 14:39:03 Service.DAV INFO Acquiring lock 2008-01-08 14:39:03 Service.DAV DEBUG Creating LOCK request for https://services.mozilla.com/user/dfba9baf82ab25da08625aa27370c44fb46cdf5a/ 2008-01-08 14:39:03 Service.DAV DEBUG HTTP Header Content-type: text/xml; charset="utf-8" 2008-01-08 14:39:03 Service.DAV DEBUG HTTP Header Depth: infinity 2008-01-08 14:39:03 Service.DAV DEBUG HTTP Header Timeout: Second-600 2008-01-08 14:39:03 Service.DAV DEBUG HTTP Header Authorization: ***** (suppressed) 2008-01-08 14:39:03 Service.DAV DEBUG HTTP Header If: 2008-01-08 14:39:04 Service.EventHandler DEBUG Handling event load 2008-01-08 14:39:04 Service.DAV INFO Lock acquired 2008-01-08 14:39:04 Service.BmkEngine INFO Lock acquired 2008-01-08 14:39:04 Service.DAV DEBUG Creating GET request for https://services.mozilla.com/user/dfba9baf82ab25da08625aa27370c44fb46cdf5a/user-data/ 2008-01-08 14:39:04 Service.DAV DEBUG HTTP Header Authorization: ***** (suppressed) 2008-01-08 14:39:04 Service.DAV DEBUG HTTP Header Content-type: text/plain 2008-01-08 14:39:04 Service.DAV DEBUG HTTP Header If: <https://services.mozilla.com/user/dfba9baf82ab25da08625aa27370c44fb46cdf5a/> (<opaquelocktoken:4e415b1c-1010-43a1-a1f4-fef60db459c8>) 2008-01-08 14:39:04 Service.EventHandler DEBUG Handling event load 2008-01-08 14:39:04 Service.DAV DEBUG Skipping creation of path user-data (got status 200) 2008-01-08 14:39:04 Service.DAV DEBUG Creating GET request for https://services.mozilla.com/user/dfba9baf82ab25da08625aa27370c44fb46cdf5a/user-data/bookmarks/ 2008-01-08 14:39:04 Service.DAV DEBUG HTTP Header Authorization: ***** (suppressed) 2008-01-08 14:39:04 Service.DAV DEBUG HTTP Header Content-type: text/plain 2008-01-08 14:39:04 Service.DAV DEBUG HTTP Header If: <https://services.mozilla.com/user/dfba9baf82ab25da08625aa27370c44fb46cdf5a/> (<opaquelocktoken:4e415b1c-1010-43a1-a1f4-fef60db459c8>) 2008-01-08 14:39:04 Service.EventHandler DEBUG Handling event load 2008-01-08 14:39:04 Service.DAV DEBUG Skipping creation of path user-data/bookmarks (got status 200) 2008-01-08 14:39:04 Service.BmkEngine DEBUG Getting status file from server 2008-01-08 14:39:04 Service.DAV DEBUG Creating GET request for https://services.mozilla.com/user/dfba9baf82ab25da08625aa27370c44fb46cdf5a/user-data/bookmarks/status.json 2008-01-08 14:39:04 Service.DAV DEBUG HTTP Header Authorization: ***** (suppressed) 2008-01-08 14:39:04 Service.DAV DEBUG HTTP Header Content-type: text/plain 2008-01-08 14:39:04 Service.DAV DEBUG HTTP Header If: <https://services.mozilla.com/user/dfba9baf82ab25da08625aa27370c44fb46cdf5a/> (<opaquelocktoken:4e415b1c-1010-43a1-a1f4-fef60db459c8>) 2008-01-08 14:39:04 Service.EventHandler DEBUG Handling event load 2008-01-08 14:39:04 Service.BmkEngine INFO Got status file from server 2008-01-08 14:39:04 Service.BmkEngine INFO Downloading server deltas 2008-01-08 14:39:04 Service.DAV DEBUG Creating GET request for https://services.mozilla.com/user/dfba9baf82ab25da08625aa27370c44fb46cdf5a/user-data/bookmarks/deltas.json 2008-01-08 14:39:04 Service.DAV DEBUG HTTP Header Authorization: ***** (suppressed) 2008-01-08 14:39:04 Service.DAV DEBUG HTTP Header Content-type: text/plain 2008-01-08 14:39:04 Service.DAV DEBUG HTTP Header If: <https://services.mozilla.com/user/dfba9baf82ab25da08625aa27370c44fb46cdf5a/> (<opaquelocktoken:4e415b1c-1010-43a1-a1f4-fef60db459c8>) 2008-01-08 14:39:06 Service.EventHandler DEBUG Handling event load 2008-01-08 14:39:06 Service.Crypto DEBUG Decrypting data 2008-01-08 14:39:09 Service.Crypto DEBUG Done decrypting data 2008-01-08 14:39:09 Service.SnapStore DEBUG Processing command: ({action:"edit", GUID:"{57ef7428-c78f-3549-ac91-a3e67dd0f795}355", depth:1, parents:["{57ef7428-c78f-3549-ac91-a3e67dd0f795}0"], data:{index:57}}) 2008-01-08 14:39:09 Service.SnapStore DEBUG Processing command: ({action:"edit", GUID:"{8129d1fa-d3a1-9f43-8de2-91adb318e9d5}361", depth:1, parents:["{57ef7428-c78f-3549-ac91-a3e67dd0f795}0"], data:{index:58}}) 2008-01-08 14:39:09 Service.SnapStore DEBUG Processing command: ({action:"edit", GUID:"{6e9db0b6-639e-8746-b2b6-053e3c5a5106}1", depth:1, parents:["{57ef7428-c78f-3549-ac91-a3e67dd0f795}0"], data:{index:59}}) 2008-01-08 14:39:09 Service.BmkEngine ERROR Exception caught: this._data[command.GUID] is undefined 2008-01-08 14:39:09 Service.BmkEngine INFO Local snapshot version: 25 2008-01-08 14:39:09 Service.BmkEngine INFO Server status: -1 2008-01-08 14:39:09 Service.BmkEngine INFO Server maxVersion: null 2008-01-08 14:39:09 Service.BmkEngine INFO Server snapVersion: null 2008-01-08 14:39:09 Service.BmkEngine FATAL Sync error: could not get server status, or initial upload failed. Aborting sync. 2008-01-08 14:39:09 Service.DAV INFO Releasing lock 2008-01-08 14:39:09 Service.DAV DEBUG Creating UNLOCK request for https://services.mozilla.com/user/dfba9baf82ab25da08625aa27370c44fb46cdf5a/ 2008-01-08 14:39:09 Service.DAV DEBUG HTTP Header Lock-Token: <opaquelocktoken:4e415b1c-1010-43a1-a1f4-fef60db459c8> 2008-01-08 14:39:09 Service.DAV DEBUG HTTP Header Authorization: ***** (suppressed) 2008-01-08 14:39:09 Service.DAV DEBUG HTTP Header Content-type: text/plain 2008-01-08 14:39:09 Service.DAV DEBUG HTTP Header If: <https://services.mozilla.com/user/dfba9baf82ab25da08625aa27370c44fb46cdf5a/> (<opaquelocktoken:4e415b1c-1010-43a1-a1f4-fef60db459c8>) 2008-01-08 14:39:09 Service.EventHandler DEBUG Handling event load 2008-01-08 14:39:09 Service.DAV INFO Lock released (or we didn't have one)
This is why QA has a job. :-)
;-) Interesting, only one machine errors out that way? Hmm. I think it might still be an inconsistency with the data on the server. If I'm right, you should see the problem with a fresh profile. Can you? The problem is that, if I'm correct, the real question is not how to reproduce the error you're seeing now. It's being able to reproduce the actions that cause Weave to leave inconsistent data on the server...
I do not see the problem with a fresh profile. The fresh profile synchs (well, I get the other history bug still...) and get the bookmark data that matches what my laptop has... So, my primary home profile (which I recreated about two or three weeks ago from scratch) cannot send its bookmarks up via weave and synch. Only my laptop's profile or a clean and fresh profile on my desktop can synch. The existing profile on my desktop does not work. Following the successful synch with the new profile, I logged into the old profile and synched. I get the same "this._data[command.GUID] is undefined" error in the log.
Ok, clearly my earlier analysis is incorrect. But I think I understand the problem now: your local snapshot is invalid somehow. It's not failing when trying to apply deltas to the server snapshot, it's failing when applying deltas to your *local* snapshot. I'll need to think a little about how that could happen... One possibility: you deleted a bookmark while a sync was running. That might cause what you see. I do have a workaround: delete <profile>/weave/snapshots/bookmarks-engine.json But that will cause a resync (a merge, as if you'd never synced before).
If you try the workaround, it'd be good for me if you could move the file rather than deleting it. Maybe tomorrow I'll write some debugging tools and have you run them to try to gather some data.
Doh, I saw the second message too late and already deleted the files. Sorry about that, Dan.
Oh well, it's okay. Did the workaround do the trick?
Yes, it worked. I am synching now (except for the 404 error in history).
Status: NEW → RESOLVED
Closed: 17 years ago
Resolution: --- → FIXED
Status: RESOLVED → VERIFIED
Component: Weave → General
Product: Mozilla Labs → Weave
Target Milestone: -- → ---
QA Contact: weave → general
You need to log in before you can comment on or make changes to this bug.