471960 - 0.9.96: sync fails with 0x80004005 (NS_ERROR_FAILURE) [IWeaveCrypto.decrypt] on other clients

Status: RESOLVED DUPLICATE of bug 471853

(Cloud Services :: General, defect)

Description

[Markus Doits]

User-Agent:       Mozilla/5.0 (Windows; U; Windows NT 5.1; de; rv:1.9.1b2) Gecko/20081201 Firefox/3.1b2
Build Identifier: 0.2.96

just tried the following after resetting server data on my server:

initial sync with linux client, works.

boot up windows, try to sync, error in summary. checked everything twice, passphrase is correct.

i'm using a passphrase with "@" and "+" in it, maybe that's a problem?

syncing linux-only clients works though.

oh and: the log states sync was successful, maybe that should be corrected too :)

Reproducible: Always

Steps to Reproduce:
1. sync linux client with windows one



2009-01-03 13:13:56	Engine.Bookmarks	INFO	First sync, uploading all items
2009-01-03 13:13:56	BmkTracker	DEBUG	Clearing changed ID list
2009-01-03 13:13:56	BmkTracker	DEBUG	Saving changed IDs to disk
2009-01-03 13:13:56	Engine.Bookmarks	INFO	4 outgoing items pre-reconciliation
2009-01-03 13:13:56	Engine.Bookmarks	DEBUG	Downloading & applying server changes
2009-01-03 13:13:56	Collection	DEBUG	GET request for https://coolphoenix.ath.cx:12328/0.3/user/coolphoenix/bookmarks/?full=1&sort=depthindex
2009-01-03 13:13:56	Collection	DEBUG	GET request successful (200)
2009-01-03 13:13:56	Engine.Bookmarks	WARN	Sync failed
2009-01-03 13:13:56	Service.Main	WARN	Engine exception: [Exception... "Component returned failure code: 0x80004005 (NS_ERROR_FAILURE) [IWeaveCrypto.decrypt]"  nsresult: "0x80004005 (NS_ERROR_FAILURE)"  location: "JS frame :: file:///C:/Documents%20and%20Settings/Markus/Application%20Data/Mozilla/Firefox/Profiles/default/extensions/%7B340c2bbc-ce74-4362-90b5-7c26312808ef%7D/modules/base_records/crypto.js :: CryptoWrap__decrypt :: line 120"  data: no]
2009-01-03 13:13:56	FaultTolerance	DEBUG	
Original exception: Component returned failure code: 0x80004005 (NS_ERROR_FAILURE) [IWeaveCrypto.decrypt] (JS frame :: file:///C:/Documents%20and%20Settings/Markus/Application%20Data/Mozilla/Firefox/Profiles/default/extensions/%7B340c2bbc-ce74-4362-90b5-7c26312808ef%7D/modules/base_records/crypto.js :: CryptoWrap__decrypt :: line 120)
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
2009-01-03 13:13:56	Service.Main	DEBUG	Event: weave:service:bookmarks-engine:sync:success
2009-01-03 13:13:56	Service.Main	DEBUG	Syncing engine history
2009-01-03 13:13:56	Service.Main	DEBUG	Event: weave:service:history-engine:sync:start
2009-01-03 13:13:56	Engine.History	DEBUG	Ensuring server crypto records are there
2009-01-03 13:13:56	Engine.History	INFO	First sync, uploading all items
2009-01-03 13:13:56	HistoryTracker	DEBUG	Clearing changed ID list
2009-01-03 13:13:56	HistoryTracker	DEBUG	Saving changed IDs to disk
2009-01-03 13:13:56	Engine.History	INFO	0 outgoing items pre-reconciliation
2009-01-03 13:13:56	Engine.History	DEBUG	Downloading & applying server changes
2009-01-03 13:13:57	Collection	DEBUG	GET request for https://coolphoenix.ath.cx:12328/0.3/user/coolphoenix/history/?full=1&sort=depthindex
2009-01-03 13:13:57	Collection	DEBUG	GET request successful (200)
2009-01-03 13:13:57	Engine.History	WARN	Sync failed
2009-01-03 13:13:57	Service.Main	WARN	Engine exception: [Exception... "Component returned failure code: 0x80004005 (NS_ERROR_FAILURE) [IWeaveCrypto.decrypt]"  nsresult: "0x80004005 (NS_ERROR_FAILURE)"  location: "JS frame :: file:///C:/Documents%20and%20Settings/Markus/Application%20Data/Mozilla/Firefox/Profiles/default/extensions/%7B340c2bbc-ce74-4362-90b5-7c26312808ef%7D/modules/base_records/crypto.js :: CryptoWrap__decrypt :: line 120"  data: no]
2009-01-03 13:13:57	FaultTolerance	DEBUG	
Original exception: Component returned failure code: 0x80004005 (NS_ERROR_FAILURE) [IWeaveCrypto.decrypt] (JS frame :: file:///C:/Documents%20and%20Settings/Markus/Application%20Data/Mozilla/Firefox/Profiles/default/extensions/%7B340c2bbc-ce74-4362-90b5-7c26312808ef%7D/modules/base_records/crypto.js :: CryptoWrap__decrypt :: line 120)
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
2009-01-03 13:13:57	Service.Main	DEBUG	Event: weave:service:history-engine:sync:success
2009-01-03 13:13:57	Service.Main	DEBUG	Sync complete
2009-01-03 13:13:57	Service.Main	DEBUG	Event: weave:service:sync:success

Comment 1

[Markus Doits]

i was a little bit too fast, now it fails on linux clients too. just deleted all data on my server again, initial sync worked, but second machine (linux or windows) cannot sync.

so the problem is: syncing between two machines not possible.

steps to reproduce:

initial sync on one machine, sync on other machine, error.

syncing one machine with itself works though.

Comment 2

[Markus Doits]

well i am confused.

i got it working now on some of my clients, but on the other ones it does not work.

right now i can sync one linux client and one windows client on different laptops. but when i try to sync another client, be it windows or linux, it does not work and gives me the error. maybe i should mention the others are installed on the same computer. 

to clarify this:

laptop A: windows, initial sync, works, further syncs, work
laptop B: linux, sync, works, further sync, work
laptop A: linux, always error
laptop B: windows, always error

so i can sync A/windows with B/linux, but the others do not work.

and this seems not to be the wrong passphrase, since on wrong passphrase i get this:

2009-01-03 14:57:50	Service.Main	WARN	Engine exception: [Exception... "Component returned failure code: 0x80004005 (NS_ERROR_FAILURE) [IWeaveCrypto.unwrapSymmetricKey]"  nsresult: "0x80004005 (NS_ERROR_FAILURE)"  location: "JS frame :: file:///C:/Documents%20and%20Settings/Markus/Application%20Data/Mozilla/Firefox/Profiles/default/extensions/%7B340c2bbc-ce74-4362-90b5-7c26312808ef%7D/modules/base_records/crypto.js :: CryptoMeta__getKey :: line 168"  data: no]

which is apperantly something different.

i am totally confused what is going on and why it fails.

Comment 3

[Igor Velkov]

did you clear last sync counters on 2 pc before try to sync? Try to clear it.

Comment 4

[Markus Doits]

yeah, that is what i did, too

but i think i found the problem, which was on my side at the end...

there was a third desktop pc running (which i wasn't able to access at the time i ran the tests), and there was still version 0.2.95 of weave installed. firefox was running, so it started scheduled syncs after i recreated my user on the server - and those syncs must have corrupted the database in a way.

that is what i found in the logs of the desktop-pc, just before 11:54 i must have cleared the user and then have created it again on the weave server:

2009-01-04 11:54:24	Service.Main	INFO	Running scheduled sync
2009-01-04 11:54:24	Service.Main	DEBUG	Event: weave:service:sync:start
2009-01-04 11:54:24	Service.Main	DEBUG	Syncing engine bookmarks
2009-01-04 11:54:24	Service.Main	DEBUG	Event: weave:service:bookmarks-engine:sync:start
2009-01-04 11:54:24	Engine.Bookmarks	DEBUG	Ensuring server crypto records are there
2009-01-04 11:54:24	Engine.Bookmarks	DEBUG	Downloading & applying server changes
2009-01-04 11:59:24	Service.Main	INFO	Skipping scheduled sync; local operation in progress
2009-01-04 12:04:24	Service.Main	INFO	Skipping scheduled sync; local operation in progress
2009-01-04 12:09:24	Service.Main	INFO	Skipping scheduled sync; local operation in progress
2009-01-04 12:13:30	Collection	DEBUG	GET request for https://coolphoenix.ath.cx:12328/0.3/user/coolphoenix/bookmarks/?modified=1230834770000&full=1&sort=depthindex
2009-01-04 12:13:30	Collection	DEBUG	GET request successful (200)
2009-01-04 12:13:30	Net.JsonFilter	TRACE	Decoding JSON data
2009-01-04 12:13:30	Net.JsonFilter	TRACE	Decoding JSON data
2009-01-04 12:13:30	Engine.Bookmarks	WARN	Sync failed
2009-01-04 12:13:30	Service.Main	WARN	Engine exception: ReferenceError: mem is not defined
2009-01-04 12:13:30	FaultTolerance	DEBUG	
Original exception: mem is not defined (module:engines.js:305 :: ReferenceError)
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:519 :: SyncEngine__sync
2009-01-04 12:13:30	Service.Main	DEBUG	Event: weave:service:bookmarks-engine:sync:success
2009-01-04 12:13:30	Service.Main	DEBUG	Sync complete
2009-01-04 12:13:30	Service.Main	DEBUG	Event: weave:service:sync:success
2009-01-04 12:14:24	Service.Main	INFO	Running scheduled sync
2009-01-04 12:14:24	Service.Main	DEBUG	Event: weave:service:sync:start
2009-01-04 12:14:24	Service.Main	DEBUG	Syncing engine bookmarks
2009-01-04 12:14:24	Service.Main	DEBUG	Event: weave:service:bookmarks-engine:sync:start
2009-01-04 12:14:24	Engine.Bookmarks	DEBUG	Ensuring server crypto records are there
2009-01-04 12:14:24	Engine.Bookmarks	DEBUG	Downloading & applying server changes
2009-01-04 12:14:25	Collection	DEBUG	GET request for https://coolphoenix.ath.cx:12328/0.3/user/coolphoenix/bookmarks/?modified=1230834770000&full=1&sort=depthindex
2009-01-04 12:14:25	Collection	DEBUG	GET request successful (200)
2009-01-04 12:14:25	Net.JsonFilter	TRACE	Decoding JSON data
2009-01-04 12:14:25	Net.JsonFilter	TRACE	Decoding JSON data
2009-01-04 12:14:25	Engine.Bookmarks	WARN	Sync failed
2009-01-04 12:14:25	Service.Main	WARN	Engine exception: ReferenceError: mem is not defined
2009-01-04 12:14:25	FaultTolerance	DEBUG	
Original exception: mem is not defined (module:engines.js:305 :: ReferenceError)
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:519 :: SyncEngine__sync
2009-01-04 12:14:25	Service.Main	DEBUG	Event: weave:service:bookmarks-engine:sync:success
2009-01-04 12:14:25	Service.Main	DEBUG	Sync complete
2009-01-04 12:14:25	Service.Main	DEBUG	Event: weave:service:sync:success

this goes on until i recreated the user again, starting again with the first sync, skipping some syncs and generating the error.


now i cannot access one of the laptops, but after installing 0.2.96 on my desktop-pc (and reacreating the user on the weave server, resetting timestamps of course) i can sync it with one of my laptops:

desktop A: linux, initial sync, works, further syncs, work
laptop B: linux, sync work
laptop B: windows, sync work

so hopefully laptop C will do the same like laptop B...

sorry for this mess, this was really weird. 
so in the end one can say: just update all clients to the latest version and do not forget one ;)

Comment 5

[Dan Mills [:thunder]]

Reopening for two reasons:

1) Weave should never get into this state, regardless of user interaction (short of messing with the server directly of course).
2) The log from your desktop doesn't actually say it uploaded any data to the server.  So your thesis, although sensible, doesn't seem to be correct.

I think what actually happened is that you didn't restart Firefox after clearing server data, and ended up with data on the server encrypted with a stale key:

https://labs.mozilla.com/forum/comments.php?DiscussionID=4910&page=1#Item_21

Comment 6

[Markus Doits]

this was indeed my first error (i did not report it, because at some point i noticed it), but then i restarted the laptops so often (to switch the OS) and remembered to restart firefox each time i change the passphrase so that this could not have been a further the problem.

also i tried a definitely wrong passphrase and the output was the one in comment #3 - "IWeaveCrypto.unwrapSymmetricKey" was the error, not "IWeaveCrypto.decrypt"

and you are right, data has never been sent by my desktop - only a "GET" was done. but weird before this get there was sometimes a "local operation in progress" - what could have weave been doing? (firefox wasn't touched since i was not at home)

if i happen to get the error again i'll report back, but now it works. 

your point 1) is right, but that should be the case after weave 0.3 is finally released to the broad mass - for now, this all is beta, so those kinds of errors (incompatible client versions - if that's really our case) are not fine but that's how it goes when changing a lot of code. the effort of tracing them back is too high for a beta-product in my opinion.

Comment 7

[Markus Doits]

the error-msg i mean is in comment #2, not #3

Comment 8

[Josh Triplett]

Comment #0 mentioned the use of @ and + in the passphrase; that suggests bug #471853 .

Comment 9

[Dan Mills [:thunder]]

Indeed, I suspect this is really bug 471853 after all.