480270 - Update wipes up server data multiple times

Status: RESOLVED FIXED

(Cloud Services :: General, defect, P1)

Description

[Peter Staev]

User-Agent:       Mozilla/5.0 (Windows; U; Windows NT 6.0; en-US; rv:1.9.1b2) Gecko/20081201 Firefox/3.1b2 (.NET CLR 3.5.30729)
Build Identifier: 0.2.105

After the upgrade to 0.2.105 each computer does a server wipe data, and this is incorrect. 

Reproducible: Always

Steps to Reproduce:
1. Upgrade Computer1 to 0.2.105
2. After FF restart, do a sync
3. Weave on Computer1 does a server wipe data calls (OK)
4. After sync finishes, upgrade Copmuter2
5. After restart Weave on Copmuter2 does a server wipe data againg, although Computer1 already done so. (not OK)
Actual Results:  
As a result of the two time wiping, the client list gets inconsistent. On Copmuter1 you have both Computer1 and Computer2 listed, and on Computer2 client list consist of only Computer2. Also I suspect on the server files only Computer2 is in the client list, because after Computer2 wiped the data, the record for Computer1 was lost, and the client on that computer does not reconize this. 

Expected Results:  
Weave should wipe server data, only after the upgrade of the first client. Each other client upgraded after that should just wipe client data, and do a full sync from server to client

Comment 1

[Dan Mills [:thunder]]

> 5. After restart Weave on Copmuter2 does a server wipe data againg, although
Computer1 already done so. (not OK)

That would be very bad indeed.  Can you look at the verbose log, near the top, and see what the reason for the wipe is?

Comment 2

[Peter Staev]

Here is the start of the Verbose log on Computer2:

2009-02-26 09:50:42	Service.Main	INFO	Logs reinitialized
2009-02-26 09:50:42	Store.Clients.Store	DEBUG	Wiping local clients store
2009-02-26 09:50:42	Store.Clients.Store	DEBUG	Saving client list to disk
2009-02-26 09:50:42	Store.Tabs.Store	DEBUG	Wipe called.  Clearing cache of remote client tabs.
2009-02-26 09:50:42	Store.Tabs.Store	DEBUG	Writing out to file...
2009-02-26 09:50:42	Service.Main	INFO	Client metadata wiped, deleting server data
2009-02-26 09:50:44	Net.Resource	DEBUG	DELETE request for https://sj-weave01.services.mozilla.com/0.3/user/peter.staev/bookmarks/
2009-02-26 09:50:44	Net.Resource	DEBUG	DELETE request successful (200)
2009-02-26 09:50:44	Engine.Bookmarks	DEBUG	Resetting bookmarks last sync time
2009-02-26 09:50:44	Net.Resource	DEBUG	DELETE request for https://sj-weave01.services.mozilla.com/0.3/user/peter.staev/history/
2009-02-26 09:50:44	Net.Resource	DEBUG	DELETE request successful (200)
2009-02-26 09:50:44	Engine.History	DEBUG	Resetting history last sync time
2009-02-26 09:50:45	Net.Resource	DEBUG	DELETE request for https://sj-weave01.services.mozilla.com/0.3/user/peter.staev/tabs/
2009-02-26 09:50:45	Net.Resource	DEBUG	DELETE request successful (200)
2009-02-26 09:50:45	Engine.Tabs	DEBUG	Resetting tabs last sync time
2009-02-26 09:50:46	Net.Resource	DEBUG	DELETE request for https://sj-weave01.services.mozilla.com/0.3/user/peter.staev/clients/
2009-02-26 09:50:46	Net.Resource	DEBUG	DELETE request successful (200)
2009-02-26 09:50:46	Engine.Clients	DEBUG	Resetting clients last sync time
2009-02-26 09:50:47	Net.Resource	DEBUG	DELETE request for https://sj-weave01.services.mozilla.com/0.3/user/peter.staev/keys/
2009-02-26 09:50:47	Net.Resource	DEBUG	DELETE request successful (200)
2009-02-26 09:50:48	Net.Resource	DEBUG	DELETE request for https://sj-weave01.services.mozilla.com/0.3/user/peter.staev/crypto/
2009-02-26 09:50:48	Net.Resource	DEBUG	DELETE request successful (200)
2009-02-26 09:50:48	Service.Main	DEBUG	Uploading new metadata record
2009-02-26 09:50:49	Net.Resource	DEBUG	PUT request for https://sj-weave01.services.mozilla.com/0.3/user/peter.staev/meta/global
2009-02-26 09:50:49	Net.Resource	DEBUG	PUT request successful (200)
2009-02-26 09:50:49	Service.Main	INFO	Server data wiped to ensure consistency due to missing keys
2009-02-26 09:50:49	PubKeyManager	DEBUG	Generating RSA keypair
2009-02-26 09:50:54	PubKeyManager	DEBUG	Generating RSA keypair... done
2009-02-26 09:50:55	Net.Resource	DEBUG	PUT request for https://sj-weave01.services.mozilla.com/0.3/user/peter.staev/keys/pubkey
2009-02-26 09:50:55	Net.Resource	DEBUG	PUT request successful (200)
2009-02-26 09:50:56	Net.Resource	DEBUG	PUT request for https://sj-weave01.services.mozilla.com/0.3/user/peter.staev/keys/privkey
2009-02-26 09:50:56	Net.Resource	DEBUG	PUT request successful (200)
2009-02-26 09:50:56	Service.Main	DEBUG	Refreshing client list
2009-02-26 09:50:56	Engine.Clients	DEBUG	Event: weave:engine:sync:start
2009-02-26 09:50:56	Engine.Clients	DEBUG	Ensuring server crypto records are there
2009-02-26 09:50:56	RecordMgr	TRACE	Importing record: https://sj-weave01.services.mozilla.com
/0.3/user/peter.staev/crypto/clients
2009-02-26 09:50:56	Net.Resource	DEBUG	GET request for https://sj-weave01.services.mozilla.com/0.3/user/peter.staev/crypto/clients
2009-02-26 09:50:56	Net.Resource	DEBUG	GET request failed (404)
2009-02-26 09:50:56	Net.Resource	DEBUG	Error response: 
"record not found"
2009-02-26 09:50:56	RecordMgr	DEBUG	Failed to import record: Could not GET resource https://sj-weave01.services.mozilla.com/0.3/user/peter.staev/crypto/clients (404)
2009-02-26 09:50:56	PubKeyManager	TRACE	Importing record: https://sj-weave01.services.mozilla.com
/0.3/user/peter.staev/keys/pubkey
2009-02-26 09:50:57	Net.Resource	DEBUG	GET request for https://sj-weave01.services.mozilla.com/0.3/user/peter.staev/keys/pubkey
2009-02-26 09:50:57	Net.Resource	DEBUG	GET request successful (200)
2009-02-26 09:50:58	Net.Resource	DEBUG	PUT request for https://sj-weave01.services.mozilla.com/0.3/user/peter.staev/crypto/clients
2009-02-26 09:50:58	Net.Resource	DEBUG	PUT request successful (200)
2009-02-26 09:50:58	Engine.Clients	INFO	First sync, uploading all items

Comment 3

[Dan Mills [:thunder]]

Please attach the log in the future, it makes discussion easier.

2009-02-26 09:50:49    Service.Main    INFO    Server data wiped to ensure
consistency due to missing keys

That would imply that the first client did not successfully upload keys.  Can you verify?

Comment 4

[Peter Staev]

Sorry about the log, will attach in the future. 

Sadly it seems that after Computer2 did a full resync and then Computer1 synced, the logs got reintialized, so i cannot check whether Computer1 has successfully uploaded the crypto keys. The first record in Copmuter1 log is:

2009-02-26 09:51:57    Service.Main    INFO    Logs reinitalized

Do you keep a backup copy of the old logs, before reinitalization, so i can look at them?

Comment 5

[Dan Mills [:thunder]]

no, they get cleared.

Why did Computer1 reinitialize the logs?  Also because the keys weren't there?

Something is fishy...

Comment 6

[Peter Staev]

Well, i don't have an idea why they got cleared :) All i know is when i updated Computer1, in the status bar Weave started circling. After a minute it raise error Sync Failed. Pressed Sync now and the popup dialog showed with the progress of syncing Clients, Bookmarks, History, Tabs. After a couple of minutes it said Sync Finished Closing...

After that i updated Computer2, and the above happened.

Comment 7

[Jono Xia]

This has been happening for me for a while.  I did some debugging work on it yesterday.

I believe the server wipe is happening before "Logs reinitialized"; you can watch what's happening by setting extensions.weave.log.appender.dump to debug and then watching the terminal.  When I do that, I find that the wipe is happening in services.js in WeaveSvc.freshStart(), which is called from WeaveSvc._remoteSetup() when meta.payload.storageVersion is less than MIN_SERVER_STORAGE_VERSION.  When I print those values out, I get:

2009-02-26 00:41:30	Service.Main	DEBUG	Min server storage version is 0.2.105
2009-02-26 00:41:30	Service.Main	DEBUG	payload storage version is 0.2.103

This is after I've synced SEVERAL times from two 0.2.105 clients, so the version on the server should definitely be 0.2.105.

In fact, when I directly download the file:
https://sjweave01.services.mozilla.com/0.3/user/jono/meta/global
which is the url of the meta record that it's getting, I find this:

{"id":"global","modified":1235689030,"payload":"{\"storageVersion\":\"0.2.105\",\"syncID\":\"c496d50f-dddd-454c-a0a3-29a5851395ad\"}"}

So the version on the server IS 0.2.105.  This makes me think that the client is writing the version number correctly, but is reading it wrong.  Perhaps it's reading a cached version number instead of the fresh one?

Comment 8

[Dan Mills [:thunder]]

It could be Firefox caching the value, because Weave does attempt to issue another GET request (we call Records.import() instead of Records.get() which would use a cached version).

Comment 9

[Peter Staev]

With the update to 0.2.106 i the second wiping is gone. So this is resolved for me...

Comment 10

[Jono Xia]

The second wiping is NOT gone for me in 0.2.106.  It's still thinking that the version on the server is 0.2.103.  There's some kind of weird cache problem...

Changing Resource._createRequest() to always validate the cache (i.e. use flag nsIRequest.VALIDATE_ALWAYS) seems to fix the problem -- but only on Firefox.  The same change on Fennec seems to do nothing, as Fennec still thinks the version is 0.2.103 half the time and 0.2.106 the other half the time.

Comment 11

[Dan Mills [:thunder]]

Dave, any advice?  We did some debugging using

http://www.mozilla.org/projects/netlib/http/http-debugging.html

and didn't see anything particularly noteworthy, but maybe we didn't know what to look for.

Comment 13

[Jono Xia]

Seems to be fixed on the client in http://hg.mozilla.org/labs/weave/rev/875c20caefac by using LOAD_BYPASS_CACHE, and making sure that Fennec updates extensions.weave.lastversion.  Leaving this bug open because there may still be a caching bug on the server, for which LOAD_BYPASS_CACHE is merely a workaround.

Comment 14

[Ed Lee :Mardak]

Shouldn't the server be able to set a flag to tell the client to never cache? Necko should be obeying those.. otherwise we have bigger problems ;)

Comment 15

[Dan Mills [:thunder]]

(In reply to comment #14)
> Shouldn't the server be able to set a flag to tell the client to never cache?
> Necko should be obeying those.. otherwise we have bigger problems ;)

Yes.  We have a ticket open with IT to try to figure this out.

Comment 16

[Dan Mills [:thunder]]

I think our current workaround is fine, we may even leave it there going forward, as we probably don't want to cache regardless of what the server says, since we do our own caching.  Marking as fixed.