Closed Bug 481347 Opened 16 years ago Closed 15 years ago

First Sync Fails repeatedly for bookmarks

Categories

(Firefox :: Sync, defect, P2)

Product:
Firefox
Component:
Sync
Type:
defect

Tracking

()

Status:
RESOLVED FIXED

People

(Reporter: blackdenim, Assigned: hello)

References

(
URL
)

Details

(Keywords: relnote)

Attachments

(1 file)

Upload records in chunks
3.32 KB, patch
Mardak
: review+
Details | Diff | Splinter Review
User-Agent: Mozilla/5.0 (Windows; U; Windows NT 5.1; en-US; rv:1.9.1b2) Gecko/20081201 Firefox/3.1b2 Build Identifier: Mozilla/5.0 (Windows; U; Windows NT 5.1; en-US; rv:1.9.1b2) Gecko/20081201 Firefox/3.1b2 I've set up Weave on my XP Home SP2 desktop running Firefox 3.1beta2 with Weave0.2.108 downloaded today from http://releases.mozilla.org/pub/mozilla.org/addons/10868/weave-0.2.108-fx+tb+fn.xpi but the bookmarks (and passwords, but that's a separate issue) will not sync to the Weave server Reproducible: Always Steps to Reproduce: 1. Install Firefox 3.1beta2 2. Install Weave-.2.108 3. Try initial sync -- NOTE: my places.sqlite is 29mb Actual Results: 2009-03-03 16:46:45 Service.Main INFO Logs reinitialized 2009-03-03 16:46:45 Store.Clients.Store DEBUG Wiping local clients store 2009-03-03 16:46:45 Store.Clients.Store DEBUG Saving client list to disk 2009-03-03 16:46:45 Store.Tabs.Store DEBUG Reading in from file... 2009-03-03 16:46:45 Store.Tabs.Store DEBUG Wipe called. Clearing cache of remote client tabs. 2009-03-03 16:46:45 Service.Main INFO Client metadata wiped, deleting server data 2009-03-03 16:46:45 Net.Resource DEBUG DELETE request for https://sj-weave01.services.mozilla.com/0.3/user/geoapps/bookmarks/ 2009-03-03 16:46:45 Net.Resource DEBUG DELETE request successful (200) 2009-03-03 16:46:45 Engine.Bookmarks DEBUG Resetting bookmarks last sync time 2009-03-03 16:46:45 Net.Resource DEBUG DELETE request for https://sj-weave01.services.mozilla.com/0.3/user/geoapps/history/ 2009-03-03 16:46:45 Net.Resource DEBUG DELETE request successful (200) 2009-03-03 16:46:45 Engine.History DEBUG Resetting history last sync time 2009-03-03 16:46:46 Net.Resource DEBUG DELETE request for https://sj-weave01.services.mozilla.com/0.3/user/geoapps/passwords/ 2009-03-03 16:46:46 Net.Resource DEBUG DELETE request successful (200) 2009-03-03 16:46:46 Engine.Passwords DEBUG Resetting passwords last sync time 2009-03-03 16:46:46 Net.Resource DEBUG DELETE request for https://sj-weave01.services.mozilla.com/0.3/user/geoapps/tabs/ 2009-03-03 16:46:46 Net.Resource DEBUG DELETE request successful (200) 2009-03-03 16:46:46 Engine.Tabs DEBUG Resetting tabs last sync time 2009-03-03 16:46:46 Net.Resource DEBUG DELETE request for https://sj-weave01.services.mozilla.com/0.3/user/geoapps/clients/ 2009-03-03 16:46:46 Net.Resource DEBUG DELETE request successful (200) 2009-03-03 16:46:46 Engine.Clients DEBUG Resetting clients last sync time 2009-03-03 16:46:47 Net.Resource DEBUG DELETE request for https://sj-weave01.services.mozilla.com/0.3/user/geoapps/keys/ 2009-03-03 16:46:47 Net.Resource DEBUG DELETE request successful (200) 2009-03-03 16:46:47 Net.Resource DEBUG DELETE request for https://sj-weave01.services.mozilla.com/0.3/user/geoapps/crypto/ 2009-03-03 16:46:47 Net.Resource DEBUG DELETE request successful (200) 2009-03-03 16:46:47 Service.Main DEBUG Uploading new metadata record 2009-03-03 16:46:47 Service.Main DEBUG Setting meta payload storage version to 0.2.108 2009-03-03 16:46:47 Net.Resource DEBUG PUT request for https://sj-weave01.services.mozilla.com/0.3/user/geoapps/meta/global 2009-03-03 16:46:47 Net.Resource DEBUG PUT request successful (200) 2009-03-03 16:46:47 Service.Main INFO Metadata record not found, server wiped to ensure consistency. 2009-03-03 16:46:47 PubKeyManager TRACE Importing record: https://sj-weave01.services.mozilla.com/0.3/user/geoapps/keys/pubkey 2009-03-03 16:46:47 Net.Resource DEBUG GET request for https://sj-weave01.services.mozilla.com/0.3/user/geoapps/keys/pubkey 2009-03-03 16:46:47 Net.Resource DEBUG GET request failed (404) 2009-03-03 16:46:47 Net.Resource DEBUG Error response: "record not found" 2009-03-03 16:46:47 PubKeyManager DEBUG Failed to import record: Could not GET resource https://sj-weave01.services.mozilla.com/0.3/user/geoapps/keys/pubkey (404) 2009-03-03 16:46:47 PubKeyManager DEBUG Generating RSA keypair 2009-03-03 16:46:50 PubKeyManager DEBUG Generating RSA keypair... done 2009-03-03 16:46:51 Net.Resource DEBUG PUT request for https://sj-weave01.services.mozilla.com/0.3/user/geoapps/keys/pubkey 2009-03-03 16:46:51 Net.Resource DEBUG PUT request successful (200) 2009-03-03 16:46:51 Net.Resource DEBUG PUT request for https://sj-weave01.services.mozilla.com/0.3/user/geoapps/keys/privkey 2009-03-03 16:46:51 Net.Resource DEBUG PUT request successful (200) 2009-03-03 16:46:51 Service.Main DEBUG Refreshing client list 2009-03-03 16:46:51 Engine.Clients DEBUG Event: weave:engine:sync:start 2009-03-03 16:46:51 Engine.Clients DEBUG Ensuring server crypto records are there 2009-03-03 16:46:51 RecordMgr TRACE Importing record: https://sj-weave01.services.mozilla.com/0.3/user/geoapps/crypto/clients 2009-03-03 16:46:51 Net.Resource DEBUG GET request for https://sj-weave01.services.mozilla.com/0.3/user/geoapps/crypto/clients 2009-03-03 16:46:51 Net.Resource DEBUG GET request failed (404) 2009-03-03 16:46:51 Net.Resource DEBUG Error response: "record not found" 2009-03-03 16:46:51 RecordMgr DEBUG Failed to import record: Could not GET resource https://sj-weave01.services.mozilla.com/0.3/user/geoapps/crypto/clients (404) 2009-03-03 16:46:51 PubKeyManager TRACE Importing record: https://sj-weave01.services.mozilla.com/0.3/user/geoapps/keys/pubkey 2009-03-03 16:46:52 Net.Resource DEBUG GET request for https://sj-weave01.services.mozilla.com/0.3/user/geoapps/keys/pubkey 2009-03-03 16:46:52 Net.Resource DEBUG GET request successful (200) 2009-03-03 16:46:52 Net.Resource DEBUG PUT request for https://sj-weave01.services.mozilla.com/0.3/user/geoapps/crypto/clients 2009-03-03 16:46:52 Net.Resource DEBUG PUT request successful (200) 2009-03-03 16:46:52 Engine.Clients INFO First sync, uploading all items 2009-03-03 16:46:52 ClientTracker DEBUG Clearing changed ID list 2009-03-03 16:46:52 ClientTracker DEBUG Saving changed IDs to disk 2009-03-03 16:46:52 Engine.Clients INFO 1 outgoing items pre-reconciliation 2009-03-03 16:46:52 Engine.Clients DEBUG Downloading & applying server changes 2009-03-03 16:46:52 Collection DEBUG GET request for https://sj-weave01.services.mozilla.com/0.3/user/geoapps/clients/?full=1&sort=depthindex 2009-03-03 16:46:52 Collection DEBUG GET request successful (200) 2009-03-03 16:46:52 Engine.Clients INFO Applied 0 records, reconciled 0 records 2009-03-03 16:46:52 Engine.Clients DEBUG Preparing 1 outgoing records 2009-03-03 16:46:52 Engine.Clients INFO Uploading 1 records + 0 index/depth records) 2009-03-03 16:46:53 Collection DEBUG POST request for https://sj-weave01.services.mozilla.com/0.3/user/geoapps/clients/ 2009-03-03 16:46:53 Collection DEBUG POST request successful (200) 2009-03-03 16:46:53 ClientTracker DEBUG Clearing changed ID list 2009-03-03 16:46:53 ClientTracker DEBUG Saving changed IDs to disk 2009-03-03 16:46:53 Engine.Clients DEBUG Finishing up sync 2009-03-03 16:46:53 Engine.Clients DEBUG Event: weave:engine:sync:finish 2009-03-03 16:46:53 Engine.Bookmarks DEBUG Event: weave:engine:sync:start 2009-03-03 16:46:53 Engine.Bookmarks DEBUG Ensuring server crypto records are there 2009-03-03 16:46:53 RecordMgr TRACE Importing record: https://sj-weave01.services.mozilla.com/0.3/user/geoapps/crypto/bookmarks 2009-03-03 16:46:53 Net.Resource DEBUG GET request for https://sj-weave01.services.mozilla.com/0.3/user/geoapps/crypto/bookmarks 2009-03-03 16:46:53 Net.Resource DEBUG GET request failed (404) 2009-03-03 16:46:53 Net.Resource DEBUG Error response: "record not found" 2009-03-03 16:46:53 RecordMgr DEBUG Failed to import record: Could not GET resource https://sj-weave01.services.mozilla.com/0.3/user/geoapps/crypto/bookmarks (404) 2009-03-03 16:46:53 Net.Resource DEBUG PUT request for https://sj-weave01.services.mozilla.com/0.3/user/geoapps/crypto/bookmarks 2009-03-03 16:46:53 Net.Resource DEBUG PUT request successful (200) 2009-03-03 16:46:53 Engine.Bookmarks INFO First sync, uploading all items 2009-03-03 16:46:53 BmkTracker DEBUG Clearing changed ID list 2009-03-03 16:46:53 BmkTracker DEBUG Saving changed IDs to disk 2009-03-03 16:46:54 Engine.Bookmarks INFO 5537 outgoing items pre-reconciliation 2009-03-03 16:46:54 Engine.Bookmarks DEBUG Downloading & applying server changes 2009-03-03 16:46:54 Collection DEBUG GET request for https://sj-weave01.services.mozilla.com/0.3/user/geoapps/bookmarks/?full=1&sort=depthindex 2009-03-03 16:46:54 Collection DEBUG GET request successful (200) 2009-03-03 16:46:54 Engine.Bookmarks INFO Applied 0 records, reconciled 0 records 2009-03-03 16:46:54 Engine.Bookmarks DEBUG Preparing 5537 outgoing records 2009-03-03 16:46:54 PrivKeyManager TRACE Importing record: https://sj-weave01.services.mozilla.com/0.3/user/geoapps/keys/privkey 2009-03-03 16:46:54 Net.Resource DEBUG GET request for https://sj-weave01.services.mozilla.com/0.3/user/geoapps/keys/privkey 2009-03-03 16:46:54 Net.Resource DEBUG GET request successful (200) 2009-03-03 16:46:54 RecordMgr TRACE Importing record: https://sj-weave01.services.mozilla.com/0.3/user/geoapps/crypto/bookmarks 2009-03-03 16:46:55 Net.Resource DEBUG GET request for https://sj-weave01.services.mozilla.com/0.3/user/geoapps/crypto/bookmarks 2009-03-03 16:46:55 Net.Resource DEBUG GET request successful (200) 2009-03-03 16:50:23 Service.Main TRACE Skipping scheduled sync; local operation in progress 2009-03-03 16:51:45 Engine.Bookmarks INFO Uploading 5537 records + 0 index/depth records) 2009-03-03 16:52:18 Collection DEBUG POST request for https://sj-weave01.services.mozilla.com/0.3/user/geoapps/bookmarks/ 2009-03-03 16:52:18 Collection DEBUG POST request successful (200) 2009-03-03 16:52:18 Engine.Bookmarks WARN Sync failed 2009-03-03 16:52:18 Engine.Bookmarks DEBUG Event: weave:engine:sync:error 2009-03-03 16:52:18 FaultTolerance DEBUG Original exception: Component returned failure code: 0x80004005 (NS_ERROR_FAILURE) [nsIJSON.decode] (JS frame :: file:///C:/Documents%20and%20Settings/Angus/Application%20Data/Mozilla/Firefox/Profiles/g95nqhq6.Firefox2/extensions/%7B340c2bbc-ce74-4362-90b5-7c26312808ef%7D/modules/resource.js :: JsonFilter_afterGET :: line 353) Async stack trace: module:engines.js:144 :: Engine_sync module:service.js:809 :: WeaveSvc__syncEngine module:service.js:709 :: WeaveSvc__sync module:util.js:501 :: EL_notify Last callback created at module:wrap.js:92 :: NotifyWrap Expected Results: Sync Additional logs are available if needed.
Version: unspecified → 0.2
Blocks: 468694
OS: Windows XP → All
Priority: -- → P2
Hardware: x86 → All
Target Milestone: -- → 0.3
Version: 0.2 → 0.3
Pushing to 0.4. The reason for the failure is likely the number of bookmarks (~5500). Average is <500/user, so this bug will not affect most users.
No longer blocks: 468694
Target Milestone: 0.3 → 0.4
A workaround: 1) backup all bookmarks, 2) delete all bookmarks, 3) perform a bookmark sync with Weave, 4) restore bookmarks from the backup, 5) re-perform a bookmark sync with Weave. In this way I was able to let weave sync with over 5000 bookmark, but I must redo all these steps every time a weave update is installed. Another problem is the slowness of Firefox during deletion and restore of the bookmarks.
Flags: blocking-weave1.0+
Target Milestone: 0.4 → 1.0
Status: UNCONFIRMED → NEW
Ever confirmed: true
Keywords: relnote
Component: Weave → General
Product: Mozilla Labs → Weave
Version: 0.3 → unspecified
QA Contact: weave → general
Let's move this into 0.5, we should figure out why this is, and what we can do to avoid it, earlier rather than later.
Assignee: nobody → edilee
Component: General → Sync
QA Contact: general → sync
Target Milestone: 1.0 → 0.5
I'd be happy to help debug since I am affected. I love Weave and bookmark sync is the biggest reason I use it. FYI: it seems like it fails almost instantly. As you can see, there isn't much debug information. I could post my "verbose" log, but I don't think it will help since, like I said, it just fails straightaway. Again, please let me know if there is anything I can do to help. I am quite tehhnically inclined, so I'm not afraid to "get my hands dirty" to help debug. Cheers!
Marty, thanks for your offer to help! Make sure to report back here anything you find. Somehow it seems to be choking on the first upload, the POST succeeds but we fail to parse the response. Perhaps if you could save the POST response we could look at it and see if it's wrong somehow, or maybe it's getting truncated or something.
I am experiencing a similar problem, my (first) bookmark doesn't work either. For me, this is a blocker. The verbose log shows the following: 2009-07-01 15:21:54 Service.Main DEBUG 2009-07-01 15:21:54 Service.Main DEBUG Caught exception: Could not POST resource https://sj-weave01.services.mozilla.com/0.3/user/myusername/clients/ (400) (JS frame :: file:///C:/Documents%20and%20Settings/myusername/Application%20Data/Mozilla/Firefox/Profiles/ykr6fffc.default/extensions/%7B340c2bbc-ce74-4362-90b5-7c26312808ef%7D/modules/resource.js :: Res__request :: line 291) 2009-07-01 15:21:54 Service.Main DEBUG Event: weave:service:sync:error 2009-07-01 15:21:54 Engine.Clients DEBUG Event: weave:engine:sync:error 2009-07-01 15:21:54 Engine.Clients WARN Sync failed 2009-07-01 15:21:54 Collection DEBUG Error response: 2009-07-01 15:21:54 Collection DEBUG POST request failed (400) 2009-07-01 15:21:54 Collection DEBUG POST request for https://sj-weave01.services.mozilla.com/0.3/user/myusername/clients/ 2009-07-01 15:21:53 Engine.Clients INFO Uploading 1 records + 0 index/depth records) 2009-07-01 15:21:53 Engine.Clients DEBUG Preparing 1 outgoing records 2009-07-01 15:21:53 Engine.Clients INFO Applied 0 records, reconciled 0 records
Patric, that looks like a different problem. You are getting a 400 response. Not sure what the problem is, either, but it looks different from the other log in this bug.
Dan, thanks for the info. In the meanwhile, I tried the same procedure on another machine - with the same result, the same error. Because of the SSL encryption I cannot sniff the traffic. Are there any other possibilities to get more info on this issue? Is it possible that you have a look at your server logs to see what went wrong?
You can enable extra debugging output by going to about:config and setting the extensions.weave.log.logger.network.resources pref to "Trace", and restarting Firefox. That will print out the actual data being transmitted, which could be useful. Can you open a new bug for your issue? It doesn't seem to be the same as this bug.
I opened bug 501899 for the issue I am experiencing.
Mine never even makes it to the POST part of the process. I see GETs to: http://[myserver]/0.3/user/[me]/meta/global http://[myserver]/0.3/user/[me]/clients/?newer=1246395440.56&modified=1246395440.56&full=1&sort=depthindex http://[myserver]/0.3/user/[me]/bookmarks/?newer=1246550254.53&modified=1246550254.53&full=1&sort=depthindex http://[myserver]/0.3/user/[me]/forms/?newer=1246573582.11&modified=1246573582.11&full=1&sort=depthindex http://[myserver]/0.3/user/[me]/history/?newer=1246576882.12&modified=1246576882.12&full=1&sort=depthindex Then a DELETE to: http://[myserver]/0.3/user/[me]/history/?older=1245972082.12 Then GETs to: http://[myserver]/0.3/user/[me]/passwords/?newer=1246564881.46&modified=1246564881.46&full=1&sort=depthindex http://[myserver]/0.3/user/[me]/prefs/?newer=1246494303.49&modified=1246494303.49&full=1&sort=depthindex http://[myserver]/0.3/user/[me]/tabs/?newer=1246576883.29&modified=1246576883.29&full=1&sort=depthindex Then a POST to: http://[myserver]/0.3/user/[me]/tabs/ And the log for this event is: 2009-07-02 17:24:36 Service.Main WARN Some engines did not sync correctly 2009-07-02 17:24:35 Engine.Tabs INFO Uploading 1 records + 0 index/depth records) 2009-07-02 17:24:35 Engine.Tabs INFO Applied 0 records, reconciled 0 records 2009-07-02 17:24:35 Engine.Tabs INFO 1 outgoing items pre-reconciliation 2009-07-02 17:24:35 Engine.Prefs INFO Applied 0 records, reconciled 0 records 2009-07-02 17:24:35 Engine.Prefs INFO 0 outgoing items pre-reconciliation 2009-07-02 17:24:35 Engine.Passwords INFO Applied 0 records, reconciled 0 records 2009-07-02 17:24:35 Engine.Passwords INFO 0 outgoing items pre-reconciliation 2009-07-02 17:24:35 Engine.InputEngine WARN Sync failed 2009-07-02 17:24:35 Engine.InputEngine INFO First sync, uploading all items 2009-07-02 17:24:35 Engine.History INFO Applied 0 records, reconciled 0 records 2009-07-02 17:24:35 Engine.History INFO 0 outgoing items pre-reconciliation 2009-07-02 17:24:35 Engine.Forms INFO Applied 0 records, reconciled 0 records 2009-07-02 17:24:35 Engine.Forms INFO 0 outgoing items pre-reconciliation 2009-07-02 17:24:33 Engine.Bookmarks WARN Sync failed 2009-07-02 17:24:33 Engine.Bookmarks INFO Applied 0 records, reconciled 0 records 2009-07-02 17:24:33 Engine.Bookmarks INFO 734 outgoing items pre-reconciliation 2009-07-02 17:24:33 Engine.Clients INFO Applied 0 records, reconciled 0 records 2009-07-02 17:24:33 Engine.Clients INFO 0 outgoing items pre-reconciliation The GET stream for bookmarks is as such: " GET /0.3/user/[me]/bookmarks/?newer=1246550254.53&modified=1246550254.53&full=1&sort=depthindex HTTP/1.1 Host: [myserver] User-Agent: Mozilla/5.0 (Windows; U; Windows NT 5.1; en-US; rv:1.9.1) Gecko/20090624 Firefox/3.5 GTB5 (.NET CLR 3.5.30729) Accept: text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8 Accept-Language: en-us,en;q=0.5 Accept-Encoding: gzip,deflate Accept-Charset: ISO-8859-1,utf-8;q=0.7,*;q=0.7 Keep-Alive: 300 Connection: keep-alive Content-Type: text/plain Authorization: Basic bW9icmllbjExODpmbGlnaHQx Cookie: __utma=38826943.97208388.1233781868.1237229659.1242783024.11; __utmz=38826943.1233781869.1.1.utmccn=(direct)|utmcsr=(direct)|utmcmd=(none) Pragma: no-cache Cache-Control: no-cache " And the response is: " HTTP/1.1 200 OK Date: Thu, 02 Jul 2009 23:24:33 GMT Server: Apache/2.2.11 (Ubuntu) PHP/5.2.6-3ubuntu4.1 with Suhosin-Patch mod_python/3.3.1 Python/2.6.2 mod_perl/2.0.4 Perl/v5.10.0 X-Powered-By: PHP/5.2.6-3ubuntu4.1 Content-Length: 2 Keep-Alive: timeout=15, max=98 Connection: Keep-Alive Content-Type: application/json [] " The reason I'm getting the first upload again is because, for some reason, the sync wiped out all of the bookmarks on this system last night. So strange. Luckily, I had a backup. Bookmark sync has a lot to work on. Maybe I'll also take a peek at the source code and see if there's anything that jumps out at me.
Hrm.. It doesn't seem right that it's a POST response decoding issue because there's too many "response parts". I just synced almost 6k form entries, and it was able to handle that fine. I wonder if the server is actually complaining about too big of a payload? Bookmark records are going to be bigger than Forms.
Angus: Could you try running Weave 0.5pre1 with Firefox 3.5? https://people.mozilla.com/~cbeard/weave/dist/latest-weave.xpi I've been trying to recreate this problem, but Weave seems to sync okay for me using 0.5pre1 with 3.5. "Okay" in that it actually syncs, but the browser basically hangs for that whole time. The bookmarks portion of my verbose log for 6880 records is as follows: 2009-07-14 00:44:10 Engine.Bookmarks DEBUG Event: weave:engine:sync:start 2009-07-14 00:44:10 Engine.Bookmarks DEBUG Ensuring server crypto records are there 2009-07-14 00:44:10 RecordMgr TRACE Importing record: https://sj-weave01.services.mozilla.com/0.3/user/EdTest2/crypto/bookmarks 2009-07-14 00:44:11 Net.Resource DEBUG GET request for https://sj-weave01.services.mozilla.com/0.3/user/EdTest2/crypto/bookmarks 2009-07-14 00:44:11 Net.Resource DEBUG GET request failed (404) 2009-07-14 00:44:11 Net.Resource DEBUG Error response: "record not found" 2009-07-14 00:44:11 RecordMgr DEBUG Failed to import record: Could not GET resource https://sj-weave01.services.mozilla.com/0.3/user/EdTest2/crypto/bookmarks (404) 2009-07-14 00:44:11 Net.Resource DEBUG PUT request for https://sj-weave01.services.mozilla.com/0.3/user/EdTest2/crypto/bookmarks 2009-07-14 00:44:11 Net.Resource DEBUG PUT request successful (200) 2009-07-14 00:44:11 Engine.Bookmarks INFO First sync, uploading all items 2009-07-14 00:44:11 BmkTracker DEBUG Clearing changed ID list 2009-07-14 00:44:11 BmkTracker DEBUG Saving json to disk: weave/changes/bookmarks.json 2009-07-14 00:44:13 Engine.Bookmarks INFO 6880 outgoing items pre-reconciliation 2009-07-14 00:44:13 Engine.Bookmarks DEBUG Downloading & applying server changes 2009-07-14 00:44:13 Collection DEBUG GET request for https://sj-weave01.services.mozilla.com/0.3/user/EdTest2/bookmarks/?full=1&sort=depthindex 2009-07-14 00:44:13 Collection DEBUG GET request successful (200) 2009-07-14 00:44:13 Engine.Bookmarks INFO Applied 0 records, reconciled 0 records 2009-07-14 00:44:13 Engine.Bookmarks DEBUG Preparing 6880 outgoing records 2009-07-14 00:44:13 PrivKeyManager TRACE Importing record: https://sj-weave01.services.mozilla.com/0.3/user/EdTest2/keys/privkey 2009-07-14 00:44:14 Net.Resource DEBUG GET request for https://sj-weave01.services.mozilla.com/0.3/user/EdTest2/keys/privkey 2009-07-14 00:44:14 Net.Resource DEBUG GET request successful (200) 2009-07-14 00:44:14 RecordMgr TRACE Importing record: https://sj-weave01.services.mozilla.com/0.3/user/EdTest2/crypto/bookmarks 2009-07-14 00:44:14 Net.Resource DEBUG GET request for https://sj-weave01.services.mozilla.com/0.3/user/EdTest2/crypto/bookmarks 2009-07-14 00:44:14 Net.Resource DEBUG GET request successful (200) 2009-07-14 00:55:16 Engine.Bookmarks INFO Uploading 6880 records + 0 index/depth records) 2009-07-14 00:55:16 Service.Main DEBUG Skipping scheduled sync: already locked for sync 2009-07-14 00:55:26 Collection DEBUG POST request for https://sj-weave01.services.mozilla.com/0.3/user/EdTest2/bookmarks/ 2009-07-14 00:55:27 Collection DEBUG POST request successful (200) 2009-07-14 00:55:27 BmkTracker DEBUG Clearing changed ID list 2009-07-14 00:55:27 BmkTracker DEBUG Saving json to disk: weave/changes/bookmarks.json 2009-07-14 00:55:27 Engine.Bookmarks DEBUG Finishing up sync 2009-07-14 00:55:27 Engine.Bookmarks DEBUG Event: weave:engine:sync:finish So it takes about 11 minutes to generate 6880 records, and the actual POST upload is about 10 seconds. During the 11 minutes of record preparation, I sampled a little bit with Shark and the top sampled functions by time were sqlite related: 10.5% libsqlite3.dylib sqlite3_blob_open 10.3% libsqlite3.dylib sqlite3_randomness 10.1% libsqlite3.dylib sqlite3_enable_shared_cache 3.8% libsqlite3.dylib sqlite3_config 3.8% libmozjs.dylib JS_CompareValues 3.5% libsqlite3.dylib sqlite3_sql 3.1% libSystem.B.dylib __spin_lock 2.9% libSystem.B.dylib __memcpy 2.4% libsqlite3.dylib sqlite3_result_value 2.3% libSystem.B.dylib szone_free
So, I decided to try making the UI more responsive (instead of totally hang for 11 minutes) by adding a Sync.sleep(0) after encrypting each record. And it turns out the UI is totally responsive. Slightly slow because of 100% CPU, but no different from another program using high CPU and slowing down Firefox. Before, the code would run in a single for loop and never break for the UI, and it took.. 2009-07-14 00:44:14 Net.Resource DEBUG GET request successful (200) 2009-07-14 00:55:16 Engine.Bookmarks INFO Uploading 6880 records + 0 index/depth records) 2009-07-14 00:55:16 Service.Main DEBUG Skipping scheduled sync: already locked for sync 11 minutes and 2 seconds. And in the process, prevented any timers from running (scheduled sync only ran after the encrypt-record loop finished). After just adding a single Sync.sleep(0) at the bottom of the loop: 2009-07-14 01:15:21 Net.Resource DEBUG GET request successful (200) 2009-07-14 01:19:56 Service.Main DEBUG Skipping scheduled sync: already locked for sync 2009-07-14 01:24:56 Service.Main DEBUG Skipping scheduled sync: already locked for sync 2009-07-14 01:26:49 Engine.Bookmarks INFO Uploading 6880 records + 0 index/depth records) 11 minutes and 28 seconds. I'm actually somewhat confused, because I thought the lowest resolution for timers is 10ms, which I would calculate as a total of 68800ms of sleeping. But Sync.sleep(0) was only slower by 26 seconds. And that might have been because I was loading tabs and scrolling to see how things performed. I'll probably just land the Sync.sleep(0) in a separate bug for UI responsiveness when uploading. There's probably a related one for download/decrypt too.
Just for comparison, I ran this test with 0.4.0 and it didn't fail for bookmarks.. 2009-07-14 10:21:32 Net.Resource DEBUG GET request successful (200) 2009-07-14 10:25:48 Service.Main DEBUG Skipping scheduled sync: already locked for sync 2009-07-14 10:30:48 Service.Main DEBUG Skipping scheduled sync: already locked for sync 2009-07-14 10:33:38 Engine.Bookmarks INFO Uploading 6880 records + 0 index/depth records) So that took 12 minutes and 6 seconds. Maybe I should try making each payload bigger but not have as many records..
I tried again to reproduce this issue but this time using fatter bookmarks than just lots of bookmarks. Now the server is giving back 500 when I do a POST with a body of ~10.5MB? 2009-07-14 12:04:30 Engine.Bookmarks DEBUG Preparing 1156 outgoing records 2009-07-14 12:05:30 Engine.Bookmarks INFO Uploading 1156 records + 1 index/depth records) 2009-07-14 12:05:30 Collection DEBUG POST Length: 11064606 2009-07-14 12:05:38 Collection DEBUG POST request for https://sj-weave01.services.mozilla.com/0.3/user/EdTest2/bookmarks/ 2009-07-14 12:05:38 Collection DEBUG POST request failed (500) 2009-07-14 12:05:38 Engine.Bookmarks WARN Sync failed 2009-07-14 12:05:38 Engine.Bookmarks DEBUG Event: weave:engine:sync:error 2009-07-14 12:05:38 FaultTolerance DEBUG Could not POST resource https://sj-weave01.services.mozilla.com/0.3/user/EdTest2/bookmarks/ (500)
Depends on: 504177
Assignee: edilee → thunder
Proposed patch v1 also removes obsolete KEEP_DELTAS constant.
Attachment #389631 - Flags: review?(edilee)
Attachment #389631 - Flags: review?(edilee) → review+
Comment on attachment 389631 [details] [diff] [review] Upload records in chunks >+++ b/source/modules/constants.js.in Mon Jul 20 23:51:14 2009 -0700 >+// How many records to upload in a single POST >+// If there are more, multiple POST calls will be made >+const MAX_UPLOAD_RECORDS = 100; Perhaps include how 100 was picked in terms of max upload and max record size >+++ b/source/modules/engines.js Mon Jul 20 23:51:14 2009 -0700 >@@ -474,22 +488,21 @@ >+ let count2 = 0; call it miniCount? > for each (let obj in meta) { or metaCount? r=Mardak Looks good and seems to work for me.
http://hg.mozilla.org/labs/weave/rev/809c80ec79ac
Status: NEW → RESOLVED
Closed: 15 years ago
Resolution: --- → FIXED
Blocks: 505906
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.

Attachment

General

Creator:
Created:
Updated:
Size: