Closed Bug 646910 Opened 9 years ago Closed 9 years ago

Intermittent failure in services/sync/tests/unit/test_clients_engine.js | test failed (with xpcshell return code: 0), see following log: (xpcshell/h‌ead.js) | 2147746065

Categories

(Firefox :: Sync, defect)

x86
Windows XP
defect
Not set

Tracking

()

RESOLVED FIXED
mozilla6

People

(Reporter: ehsan, Assigned: rnewman)

References

Details

(Keywords: intermittent-failure, Whiteboard: [qa-])

Attachments

(1 file, 1 obsolete file)

+++ This bug was initially created as a clone of Bug #629664 +++

http://tinderbox.mozilla.org/showlog.cgi?log=Cedar/1301589446.1301590192.6527.gz
Rev3 MacOSX Leopard 10.5.8 cedar opt test xpcshell on 2011/03/31 09:37:26

TEST-INFO | /Users/cltbld/talos-slave/test/build/xpcshell/tests/services/sync/tests/unit/test_clients_engine.js | running test ...
TEST-UNEXPECTED-FAIL | /Users/cltbld/talos-slave/test/build/xpcshell/tests/services/sync/tests/unit/test_clients_engine.js | test failed (with xpcshell return code: 0), see following log:
>>>>>>>
Setting the identity for passphrase
TEST-INFO | (xpcshell/head.js) | test 1 pending
Ensure that Clients engine deletes corrupt records.
TEST-INFO | (xpcshell/head.js) | test 2 pending
Service.Main	DEBUG	Caching URLs under storage user base: http://localhost:8080/1.0/foo/
Service.Main	INFO	Logging in user foo
Engine.Clients	TRACE	Saving json to disk: weave/toFetch/clients.json
Net.Resource	DEBUG	GET success 200 http://localhost:8080/1.0/foo/info/collections
Service.Main	DEBUG	Fetching global metadata record
RecordMgr	TRACE	Importing record: http://localhost:8080/1.0/foo/storage/meta/global
Net.Resource	DEBUG	GET success 200 http://localhost:8080/1.0/foo/storage/meta/global
Service.Main	DEBUG	Weave Version: 1.7 Local Storage: 5 Remote Storage: 
Service.Main	INFO	One of: no meta, no meta storageVersion, or no meta syncID. Fresh start needed.
Service.Main	WARN	No sync id, server wipe needed
Service.Main	INFO	Wiping server data
Service.Main	INFO	Fresh start. Resetting client and considering key upgrade.
Service.Main	INFO	Service reset.
Engine.Clients	TRACE	Event: weave:engine:reset-client:start
Engine.Clients	DEBUG	Resetting clients last sync time
Engine.Clients	TRACE	Event: weave:engine:reset-client:finish
Engine.Bookmarks	DEBUG	Resetting bookmarks last sync time
Engine.Forms	DEBUG	Resetting forms last sync time
Engine.History	DEBUG	Resetting history last sync time
Engine.Passwords	DEBUG	Resetting passwords last sync time
Engine.Prefs	DEBUG	Resetting prefs last sync time
Engine.Tabs	DEBUG	Resetting tabs last sync time
CollectionKeys	INFO	Clearing CollectionKeys...
Service.Main	INFO	Sync key is up-to-date: no need to upgrade.
Service.Main	DEBUG	New metadata record: {"syncID":"EPAvJuAc8L1O","storageVersion":5}
Net.Resource	DEBUG	PUT Length: 78
Engine.Clients	TRACE	Saving json to disk: weave/toFetch/clients.json
Net.Resource	DEBUG	PUT success 200 http://localhost:8080/1.0/foo/storage/meta/global
Net.Resource	DEBUG	DELETE success 200 http://localhost:8080/1.0/foo/storage/clients
Net.Resource	DEBUG	DELETE fail 404 http://localhost:8080/1.0/foo/storage/bookmarks
Net.Resource	DEBUG	DELETE fail 404 http://localhost:8080/1.0/foo/storage/forms
Net.Resource	DEBUG	DELETE fail 404 http://localhost:8080/1.0/foo/storage/history
Net.Resource	DEBUG	DELETE fail 404 http://localhost:8080/1.0/foo/storage/passwords
Net.Resource	DEBUG	DELETE fail 404 http://localhost:8080/1.0/foo/storage/prefs
Net.Resource	DEBUG	DELETE fail 404 http://localhost:8080/1.0/foo/storage/tabs
Service.Main	INFO	Generating new keys....
BulkKeyBundle	INFO	BulkKeyBundle being created for [default]
Service.Main	INFO	Encrypting new key bundle. Modified time is 1301589795.23
Service.Main	INFO	Uploading...
Net.Resource	DEBUG	PUT Length: 402
Net.Resource	DEBUG	PUT success 200 http://localhost:8080/1.0/foo/storage/crypto/keys
Service.Main	INFO	Got status 200
Service.Main	INFO	Wiped server; incompatible metadata: 
BulkKeyBundle	INFO	BulkKeyBundle being created for [default]
First sync, client record is uploaded
TEST-PASS | /Users/cltbld/talos-slave/test/build/xpcshell/tests/services/sync/tests/unit/test_clients_engine.js | [test_bad_hmac : 54] 0 == 0
TEST-PASS | /Users/cltbld/talos-slave/test/build/xpcshell/tests/services/sync/tests/unit/test_clients_engine.js | [test_bad_hmac : 55] 0 == 0
Engine.Clients	TRACE	Event: weave:engine:sync:start
Engine.Clients	DEBUG	Old engine data: ,1
Net.Resource	DEBUG	DELETE success 200 http://localhost:8080/1.0/foo/storage/clients
Engine.Clients	DEBUG	Resetting clients last sync time
Engine.Clients	DEBUG	First sync, uploading all items
Engine.Clients	INFO	1 outgoing items pre-reconciliation
Engine.Clients	TRACE	Downloading & applying server changes
Engine.Clients	TRACE	Saving json to disk: weave/toFetch/clients.json
Collection	DEBUG	GET success 200 http://localhost:8080/1.0/foo/storage/clients?full=1
Engine.Clients	INFO	Records: 0 applied, 0 failed to apply, 0 reconciled.
Engine.Clients	TRACE	Uploading local changes to server.
Engine.Clients	TRACE	Preparing 1 outgoing records
Engine.Clients	TRACE	Outgoing: { id: Vga3TxKs6wV8
  index: 0
  modified: undefined
  ttl: 1814400
  payload: {"id":"Vga3TxKs6wV8","name":"cltbld's Minefield on Intel Mac OS X 10.5","type":"desktop"}
  collection: clients }
CollectionKeys	TRACE	keyForCollection: clients. Default is not null.
Engine.Clients	INFO	Uploading all of 1 records
Collection	DEBUG	POST Length: 313
Creating WBO "Vga3TxKs6wV8" on the fly.
Collection	DEBUG	POST success 200 http://localhost:8080/1.0/foo/storage/clients
Engine.Clients	TRACE	Finishing up sync
Engine.Clients	TRACE	Event: weave:engine:sync:finish
TEST-PASS | /Users/cltbld/talos-slave/test/build/xpcshell/tests/services/sync/tests/unit/test_clients_engine.js | [test_bad_hmac : 57] 1 == 1
TEST-PASS | /Users/cltbld/talos-slave/test/build/xpcshell/tests/services/sync/tests/unit/test_clients_engine.js | [test_bad_hmac : 58] true == true
Records now: ["Vga3TxKs6wV8"]
Change our keys and our client ID, reupload keys.
Engine.Clients	TRACE	Event: weave:engine:reset-client:start
Engine.Clients	DEBUG	Resetting clients last sync time
Engine.Clients	TRACE	Event: weave:engine:reset-client:finish
BulkKeyBundle	INFO	BulkKeyBundle being created for [default]
Net.Resource	DEBUG	PUT Length: 402
Engine.Clients	TRACE	Saving json to disk: weave/toFetch/clients.json
Net.Resource	DEBUG	PUT success 200 http://localhost:8080/1.0/foo/storage/crypto/keys
TEST-PASS | /Users/cltbld/talos-slave/test/build/xpcshell/tests/services/sync/tests/unit/test_clients_engine.js | [test_bad_hmac : 68] true == true
Sync.
TEST-PASS | /Users/cltbld/talos-slave/test/build/xpcshell/tests/services/sync/tests/unit/test_clients_engine.js | [test_bad_hmac : 71] true == true
Engine.Clients	TRACE	Event: weave:engine:sync:start
Engine.Clients	DEBUG	First sync, uploading all items
Engine.Clients	INFO	1 outgoing items pre-reconciliation
Engine.Clients	TRACE	Downloading & applying server changes
CollectionKeys	TRACE	keyForCollection: clients. Default is not null.
Engine.Clients	DEBUG	Handling HMAC mismatch for Vga3TxKs6wV8
Service.Main	INFO	Bad HMAC event detected. Attempting recovery or signaling to other clients.
Net.Resource	DEBUG	GET success 200 http://localhost:8080/1.0/foo/storage/crypto/keys
CollectionKeys	INFO	Updating collection keys...
CollectionKeys	INFO	Setting CollectionKeys contents. Our last modified: 1301589795.26, input modified: 1301589795.262.
BulkKeyBundle	INFO	BulkKeyBundle being created for [default]
CollectionKeys	INFO	Processing downloaded per-collection keys.
CollectionKeys	INFO	New keys are the same as our old keys! Bumping local modified time and returning.
CollectionKeys	INFO	Bumping last modified to 1301589795.262
CollectionKeys	INFO	Collection keys updated.
Net.Resource	DEBUG	PUT Length: 403
Net.Resource	DEBUG	PUT success 200 http://localhost:8080/1.0/foo/storage/crypto/keys
Service.Main	INFO	Successfully re-uploaded keys. Continuing sync.
Engine.Clients	DEBUG	Bad client record detected. Scheduling for deletion.
Engine.Clients	WARN	Error decrypting record: Record SHA256 HMAC mismatch: should be fd87858bc3fee9aaebf9136ca7dd90db94f150f7c229e03c480eb878f6bee092, is dd5882ba48af8b296967577aa9ab268da178d29dc3cedf906288b33cb4276ca8 No traceback available
Collection	DEBUG	GET success 200 http://localhost:8080/1.0/foo/storage/clients?full=1
Engine.Clients	DEBUG	Records that failed to apply: Vga3TxKs6wV8
Service.Main	DEBUG	clients failed to apply some records.
Engine.Clients	INFO	Records: 0 applied, 1 failed to apply, 0 reconciled.
Engine.Clients	TRACE	Uploading local changes to server.
Engine.Clients	TRACE	Preparing 1 outgoing records
Engine.Clients	TRACE	Outgoing: { id: 8PAtur_2ZLrq
  index: 0
  modified: undefined
  ttl: 1814400
  payload: {"id":"8PAtur_2ZLrq","name":"cltbld's Minefield on Intel Mac OS X 10.5","type":"desktop"}
  collection: clients }
CollectionKeys	TRACE	keyForCollection: clients. Default is not null.
Engine.Clients	TRACE	Saving json to disk: weave/toFetch/clients.json
Engine.Clients	INFO	Uploading all of 1 records
Collection	DEBUG	POST Length: 313
Creating WBO "8PAtur_2ZLrq" on the fly.
Collection	DEBUG	POST success 200 http://localhost:8080/1.0/foo/storage/clients
Engine.Clients	TRACE	Finishing up sync
Deleting {"id":"Vga3TxKs6wV8","payload":"{\"ciphertext\":\"nwGUWkA8Xut8jW7oCD+YFUgMA4oFk018Q/5h8QkveFVOoJLdWNaALZylHrvvN012bpcdWt0P7L7WDYxuGPgklixsNIVV45d8OSRaQiahWxEckGOX8pqsLiMUrOk6iMKU\",\"IV\":\"IEAKl4pr66ehi3E0YDqPig==\",\"hmac\":\"fd87858bc3fee9aaebf9136ca7dd90db94f150f7c229e03c480eb878f6bee092\"}","modified":1301589795.253}
Collection	DEBUG	DELETE success 200 http://localhost:8080/1.0/foo/storage/clients?ids=Vga3TxKs6wV8
Engine.Clients	TRACE	Event: weave:engine:sync:finish
Old record was deleted, new one uploaded.
TEST-PASS | /Users/cltbld/talos-slave/test/build/xpcshell/tests/services/sync/tests/unit/test_clients_engine.js | [test_bad_hmac : 75] true == true
TEST-PASS | /Users/cltbld/talos-slave/test/build/xpcshell/tests/services/sync/tests/unit/test_clients_engine.js | [test_bad_hmac : 76] 1 == 1
Records now: ["8PAtur_2ZLrq"]
Test lastRecordUpload property
TEST-PASS | /Users/cltbld/talos-slave/test/build/xpcshell/tests/services/sync/tests/unit/test_clients_engine.js | [test_properties : 89] undefined == undefined
TEST-PASS | /Users/cltbld/talos-slave/test/build/xpcshell/tests/services/sync/tests/unit/test_clients_engine.js | [test_properties : 90] 0 == 0
TEST-PASS | /Users/cltbld/talos-slave/test/build/xpcshell/tests/services/sync/tests/unit/test_clients_engine.js | [test_properties : 94] 1301589795 == 1301589795
Ensure that Clients engine uploads a new client record once a week.
BulkKeyBundle	INFO	BulkKeyBundle being created for [default]
TEST-UNEXPECTED-FAIL | (xpcshell/head.js) | 2147746065
Service.Main	DEBUG	Clearing sync triggers.
<<<<<<<
Summary: Intermittent failure in services/sync/tests/unit/test_clients_engine.js | test failed (with xpcshell return code: 0), see following log: (xpcshell/head.js) | 2147746065 → Intermittent failure in services/sync/tests/unit/test_clients_engine.js | test failed (with xpcshell return code: 0), see following log: (xpcshell/h‌ead.js) | 2147746065
Attached patch Proposed patch. v1 (obsolete) — Splinter Review
This appears to be the test harness cleaning up parts of our prefs system between the two tests. Here's a patch that pulls do_test_pending calls apart a bit, and reorders the non-HTTP test to come first. Bit of a stab in the dark, but hey.
Assignee: nobody → rnewman
Status: NEW → ASSIGNED
Attachment #527061 - Flags: review?(philipp)
Comment on attachment 527061 [details] [diff] [review]
Proposed patch. v1

Would prefer that we use run_next_test here instead of do_test_pending/do_test_finished. That way we don't start the next test until the server has actually shut down.
Attachment #527061 - Flags: review?(philipp) → review-
I believe this is a correct recasting into add_test/run_next_test... philikon?
Attachment #527061 - Attachment is obsolete: true
Attachment #527062 - Flags: review?(philipp)
Attachment #527062 - Flags: review?(philipp) → review+
Pushed to s-c:

https://hg.mozilla.org/services/services-central/rev/dc16d00fe382

(This isn't a frequent orange, so not landing on m-c just yet.)
Whiteboard: [orange] → [orange][fixed in services]
(In reply to comment #10)
> Pushed to s-c:
> 
> https://hg.mozilla.org/services/services-central/rev/dc16d00fe382
> 
> (This isn't a frequent orange, so not landing on m-c just yet.)

Would it be too hard for you guys to do a merge so that we get this on mozilla-central, and all the other branches synced to it?
(In reply to comment #11)

> Would it be too hard for you guys to do a merge so that we get this on
> mozilla-central, and all the other branches synced to it?

I can do a merge about 6:30pm, if Philipp or someone else with a checkout doesn't get to it first.
(In reply to comment #12)
> (In reply to comment #11)
> 
> > Would it be too hard for you guys to do a merge so that we get this on
> > mozilla-central, and all the other branches synced to it?
> 
> I can do a merge about 6:30pm, if Philipp or someone else with a checkout
> doesn't get to it first.

According to our new process, we can't just merge s-c to m-c. Not without a QA sign off at least. If you guys want the fixed urgently, I suggest Richard double lands them on m-c. hg transplant is easy enough :)
(In reply to comment #11)

> Would it be too hard for you guys to do a merge so that we get this on
> mozilla-central, and all the other branches synced to it?

tbpl is red from Jetpack failures, and lsblakk is still trying to figure the cause. Rather than land on red, I'll transplant this tomorrow morning.
Transplanted to m-c:

  http://hg.mozilla.org/mozilla-central/rev/91d31a1edceb
Status: ASSIGNED → RESOLVED
Closed: 9 years ago
Resolution: --- → FIXED
Whiteboard: [orange][fixed in services] → [orange]
Thanks!
Whiteboard: [orange] → [orange][qa-]
Target Milestone: --- → mozilla6
Whiteboard: [orange][qa-] → [qa-]
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.