442927 - Service.FormSync: "ERROR Remote command has GUID that already exists locally. Dropping command."

Status: RESOLVED WONTFIX

(Cloud Services :: General, defect)

Description

[Jeff Billimek]

User-Agent:       Mozilla/5.0 (Windows; U; Windows NT 5.1; en-US; rv:1.9) Gecko/2008052906 Firefox/3.0
Build Identifier: Weave 0.2

This is with Weave 0.2

The first client (FF 3.0 release running sync 0.2 on XP) syncs all engines without complaint

The second client (FF 3.0 release running sync 0.2 on Vista) syncs all engines without complaint except for the forms engine.  When I add the forms engnie data type, during sync the following occurs:

2008-07-01 10:51:59     Service.FormEngine      INFO    Beginning sync
2008-07-01 10:51:59     Service.DAV     DEBUG   GET request for user-data/
2008-07-01 10:52:00     Service.DAV     DEBUG   GET request for user-data/forms/
2008-07-01 10:52:00     Service.DAV     DEBUG   GET request for user-data/forms/deltas/
2008-07-01 10:52:01     Service.RemoteStore     DEBUG   Downloading status file
2008-07-01 10:52:01     Service.DAV     DEBUG   GET request for user-data/forms/status.json
2008-07-01 10:52:02     Service.Resource        DEBUG   GET request successful
2008-07-01 10:52:02     Service.JsonFilter      DEBUG   Decoding JSON data
2008-07-01 10:52:02     Service.RemoteStore     DEBUG   Downloading status file... done
2008-07-01 10:52:02     Service.FormEngine      DEBUG   Remote/local sync GUIDs do not match.  Forcing initial sync.
2008-07-01 10:52:02     Service.FormEngine      INFO    Local snapshot version: -1
2008-07-01 10:52:02     Service.FormEngine      INFO    Server maxVersion: 0
2008-07-01 10:52:02     Service.DAV     DEBUG   GET request for user-data/forms/keys.json
2008-07-01 10:52:02     Service.Resource        DEBUG   GET request successful
2008-07-01 10:52:02     Service.JsonFilter      DEBUG   Decoding JSON data
2008-07-01 10:52:02     Service.RemoteStore     TRACE   Getting latest from snap --> scratch
2008-07-01 10:52:02     Service.RemoteStore     INFO    Downloading all server data from scratch
2008-07-01 10:52:02     Service.DAV     DEBUG   GET request for user-data/forms/snapshot.json
2008-07-01 10:52:07     Service.Resource        DEBUG   GET request successful
2008-07-01 10:52:07     Service.CryptoFilter    DEBUG   Decrypting data
2008-07-01 10:52:07     Service.JsonFilter      DEBUG   Decoding JSON data
2008-07-01 10:52:13     Service.FormEngine      INFO    Reconciling client/server updates
2008-07-01 10:52:13     Service.FormSync        DEBUG   Reconciling 9318 against 4590 commands
2008-07-01 10:52:13     Service.FormSync        ERROR   Remote command has GUID that already exists locally. Dropping command.
<above line repeated 605 times>
2008-07-01 10:52:43     Service.Main    INFO    Running scheduled sync
2008-07-01 10:52:43     Async.Generator ERROR   Exception: Could not acquire lock (lock already held)
2008-07-01 10:52:43     Async.Generator DEBUG   Stack trace:
No traceback available.
This exception was raised by an asynchronous coroutine.
Initial async stack trace:
unknown (async) :: WeaveLockWrapper-1610
module:wrap.js:92 :: WeaveNotifyWrapper
module:service.js:271 :: WeaveSvc__onSchedule
module:util.js:399 :: innerBind
module:util.js:439 :: EL_notify
<the above “Running scheduled sync” section repeats every minute indefinitely>

Firefox is responsive and it's running at about 35-40% CPU constantly during the sync activity (the weave icon is spinning this entire time).  There isn't any forms file in the weave/snapshot directory under the firefox profile on the second client.  On the first client where forms data successfully syncs, there exists a 422k forms.json file in the weave/snapshot directory.

Reproducible: Always

Steps to Reproduce:
1. Select "Saved Form Data" from the datatypes to sync
2. Initiate a sync
Actual Results:  
Sync never completes

Expected Results:  
Sync should complete syncing forms data

Comment 1

[Jeff Billimek]

This may not be an issue after all.  It looks like it took 2 hours and 8 minutes to process the FormData from the server against client #2: 

From the verbose log after attempting (and failing) to do an autosync every 60 seconds for the next 128 minutes, this happened:

2008-07-01 13:00:43     Service.Main    INFO    Running scheduled sync
2008-07-01 13:00:43     Async.Generator ERROR   Exception: Could not acquire lock (lock already held)
2008-07-01 13:00:43     Async.Generator DEBUG   Stack trace:
No traceback available. 
This exception was raised by an asynchronous coroutine.
Initial async stack trace:
unknown (async) :: WeaveLockWrapper-1866
module:wrap.js:92 :: WeaveNotifyWrapper
module:service.js:271 :: WeaveSvc__onSchedule
module:util.js:399 :: innerBind
module:util.js:439 :: EL_notify
2008-07-01 13:01:35     Service.FormEngine      INFO    Changes for client: 3985
2008-07-01 13:01:35     Service.FormEngine      INFO    Predicted changes for server: 9318
2008-07-01 13:01:35     Service.FormEngine      INFO    Client conflicts: 0
2008-07-01 13:01:35     Service.FormEngine      INFO    Server conflicts: 0
2008-07-01 13:01:37     Service.FormEngine      INFO    Applying changes locally
2008-07-01 13:01:37     Service.SnapStore       TRACE   Processing command: {"action":"create","GUID":"4892e8a95f67f38d545d5d03408537a6b12e7cf1","depth":0,"parents":[],"data":{"name":"searchbar-history","value":"iphone ipod \"sound check\" setting"}}

<then similar Service.SnapStore entries for the next 4073 lines>

2008-07-01 13:01:40     Service.FormStore       TRACE   Processing command: {"action":"create","GUID":"4892e8a95f67f38d545d5d03408537a6b12e7cf1","depth":0,"parents":[],"data":{"name":"searchbar-history","value":"iphone ipod \"sound check\" setting"}}

<then similar Service.FormStore entries for the next 3985 lines>
2008-07-01 13:02:30     Service.FormStore       INFO    FormStore got createCommand: [object Object]
2008-07-01 13:02:38     Service.SnapStore       INFO    Saving snapshot to disk

<now after that, it looks like it did a scheduled sync followed by this:>

2008-07-01 13:03:46     Service.DAV     DEBUG   UNLOCK request for lock
2008-07-01 13:03:46     Service.DAV     WARN    _makeRequest: got status 400
2008-07-01 13:03:46     Async.Generator WARN    Async method 'DC_unlock-1986' may have yielded without an outstanding callback.
2008-07-01 13:04:43     Service.Main    INFO    Running scheduled sync
2008-07-01 13:04:43     Async.Generator ERROR   Exception: Could not acquire lock (lock already held)

<And now every minute the following happens:>
2008-07-01 13:15:43     Service.Main    INFO    Running scheduled sync
2008-07-01 13:15:43     Async.Generator ERROR   Exception: Could not acquire lock (lock already held)
2008-07-01 13:15:43     Async.Generator DEBUG   Stack trace:
No traceback available.
This exception was raised by an asynchronous coroutine.
Initial async stack trace:
unknown (async) :: WeaveLockWrapper-2011
module:wrap.js:92 :: WeaveNotifyWrapper
module:service.js:271 :: WeaveSvc__onSchedule
module:util.js:399 :: innerBind
module:util.js:439 :: EL_notify

It appears that the sync is 'completed' at this time as the spinning icon stopped.  I didn't mess with weave during this time so it looks like it worked itself into a locked state.  Client #1 will still sync correctly.  Attempting to close down client #2 results in the closed sync dialgoue staying indefinitely and the following in the log:
2008-07-01 13:18:05     Chrome.Window   INFO    Sync window closed
2008-07-01 13:18:06     Sync.Status     INFO    waiting for current action to finish
2008-07-01 13:18:43     Service.Main    INFO    Running scheduled sync
2008-07-01 13:18:43     Async.Generator ERROR   Exception: Could not acquire lock (lock already held)

Restarting Firefox appears to clear out that condition and client 2 now syncs correctly.

So bottom line after meandering through all of that is that the form data eventually synced on client #2 after 2 hours of processing but it seemed to get itself into a locked state that was cleared only after a browser restart.

Comment 2

[Dan Mills [:thunder]]

Form sync is currently unimplemented for the 0.3 client, and the 0.2 client is no longer supported.  Closing as wontfix.