Closed Bug 1058703 Opened 10 years ago Closed 7 years ago

test_fxa_startOver.js | Test timed out on OS X 10.9

Categories

(Firefox :: Sync, defect)

Product:
Firefox
Component:
Sync
Platform:
x86_64
Linux
Type:
defect
Priority:
Not set
Severity:
normal

Tracking

()

Status:
RESOLVED WORKSFORME

People

(Reporter: gbrown, Unassigned)

References

Details

This test consistently times out on OS X 10.9 Opt and Debug. Note that 10.9 tests are currently only running on the Cedar branch, but we want to green them up and run them elsewhere as soon as possible. https://tbpl.mozilla.org/php/getParsedLog.php?id=46751324&tree=Cedar&full=1#error0 00:30:59 INFO - TEST-INFO | /builds/slave/talos-slave/test/build/tests/xpcshell/tests/services/sync/tests/unit/test_fxa_startOver.js | running test ... 00:35:59 WARNING - TEST-UNEXPECTED-FAIL | /builds/slave/talos-slave/test/build/tests/xpcshell/tests/services/sync/tests/unit/test_fxa_startOver.js | Test timed out 00:35:59 WARNING - TEST-UNEXPECTED-FAIL | /builds/slave/talos-slave/test/build/tests/xpcshell/tests/services/sync/tests/unit/test_fxa_startOver.js | test failed (with xpcshell return code: 5), see following log: 00:35:59 INFO - >>>>>>> 00:35:59 INFO - TEST-INFO | (xpcshell/head.js) | test MAIN run_test pending (1) 00:35:59 INFO - TEST-INFO | (xpcshell/head.js) | test run_next_test 0 pending (2) 00:35:59 INFO - TEST-INFO | (xpcshell/head.js) | test MAIN run_test finished (2) 00:35:59 INFO - TEST-INFO | (xpcshell/head.js) | running event loop 00:35:59 INFO - TEST-INFO | /builds/slave/talos-slave/test/build/tests/xpcshell/tests/services/sync/tests/unit/test_fxa_startOver.js | Starting test_startover 00:35:59 INFO - TEST-INFO | (xpcshell/head.js) | test test_startover pending (2) 00:35:59 INFO - Sync.Identity INFO Username changed. Removing stored credentials. 00:35:59 INFO - Sync.Identity INFO Basic password has no value. Removing. 00:35:59 INFO - Sync.Identity INFO Sync Key has no value. Deleting. 00:35:59 INFO - Sync.Identity INFO Basic password being updated. 00:35:59 INFO - Sync.Identity INFO Sync Key being updated. 00:35:59 INFO - Sync.SyncKeyBundle INFO SyncKeyBundle being created. 00:35:59 INFO - TEST-INFO | (xpcshell/head.js) | test run_next_test 0 finished (2) 00:35:59 INFO - TEST-PASS | /builds/slave/talos-slave/test/build/tests/xpcshell/tests/services/sync/tests/unit/test_fxa_startOver.js | [test_startover : 25] true == true 00:35:59 INFO - TEST-PASS | /builds/slave/talos-slave/test/build/tests/xpcshell/tests/services/sync/tests/unit/test_fxa_startOver.js | [test_startover : 29] true == true 00:35:59 INFO - Sync.Service DEBUG Caching URLs under storage user base: https://localhost/1.1/johndoe/ 00:35:59 INFO - Sync.Status DEBUG Status.service: service.client_not_configured => success.status_ok 00:35:59 INFO - Sync.Status DEBUG Status.service: success.status_ok => success.status_ok 00:35:59 INFO - Sync.Tracker.Clients WARN Changed IDs file clients contains non-object value. 00:35:59 INFO - Sync.Service INFO Logging in the user. 00:35:59 INFO - Sync.Service DEBUG Caching URLs under storage user base: https://localhost/1.1/johndoe/ 00:35:59 INFO - Sync.Service DEBUG Fetching unlocked auth state returned success.status_ok 00:35:59 INFO - Sync.Tracker.Bookmarks WARN Changed IDs file bookmarks contains non-object value. 00:35:59 INFO - Sync.Tracker.Forms WARN Changed IDs file forms contains non-object value. 00:35:59 INFO - Sync.Tracker.History WARN Changed IDs file history contains non-object value. 00:35:59 INFO - Sync.Tracker.Passwords WARN Changed IDs file passwords contains non-object value. 00:35:59 INFO - Sync.Tracker.Addons WARN Changed IDs file addons contains non-object value. 00:35:59 INFO - Sync.Service DEBUG verifyLogin failed: Error: NS_ERROR_CONNECTION_REFUSED (resource://services-sync/resource.js:394:18) JS Stack trace: Res_get@resource.js:414:12 < verifyLogin@service.js:715:18 < onNotify@service.js:992:12 < WrappedNotify@util.js:148:21 < WrappedLock@util.js:103:16 < WrappedCatch@util.js:77:16 < login@service.js:1003:12 < test_startover@test_fxa_startOver.js:34:3 < TaskImpl_run@Task.jsm:314:40 < Handler.prototype.process@Promise-backend.js:865:23 < this.PromiseWalker.walkerLoop@Promise-backend.js:744:7 < _do_main@head.js:191:5 < _execute_test@head.js:405:5 < @-e:1:1 00:35:59 INFO - Sync.Status DEBUG Status.login: error.login.reason.no_username => error.login.reason.network 00:35:59 INFO - Sync.Status DEBUG Status.service: success.status_ok => error.login.failed 00:35:59 INFO - Sync.Status DEBUG Status.login: error.login.reason.network => error.login.reason.network 00:35:59 INFO - Sync.Status DEBUG Status.service: error.login.failed => error.login.failed 00:35:59 INFO - Sync.SyncScheduler DEBUG Clearing sync triggers and the global score. 00:35:59 INFO - Sync.SyncScheduler DEBUG Next sync in 3600000 ms. 00:35:59 INFO - Sync.ErrorHandler DEBUG Flushing file log. 00:35:59 INFO - Sync.Service DEBUG Exception: Login failed: error.login.reason.network No traceback available 00:35:59 INFO - TEST-PASS | /builds/slave/talos-slave/test/build/tests/xpcshell/tests/services/sync/tests/unit/test_fxa_startOver.js | [test_startover : 36] true == true 00:35:59 INFO - Sync.Status INFO Resetting Status. 00:35:59 INFO - Sync.Status DEBUG Status.service: error.login.failed => success.status_ok 00:35:59 INFO - Sync.ErrorHandler DEBUG Log cleanup threshold time: 1408174355541 00:35:59 INFO - Sync.ErrorHandler DEBUG No logs to clean up. 00:35:59 INFO - Sync.Service WARN Deleting client data for clients failed:Error: NS_ERROR_CONNECTION_REFUSED (resource://services-sync/resource.js:394:18) JS Stack trace: Res_delete@resource.js:435:12 < removeClientData@clients.js:168:5 < startOver@service.js:882:11 < test_startover@test_fxa_startOver.js:47:3 < TaskImpl_run@Task.jsm:314:40 < Handler.prototype.process@Promise-backend.js:865:23 < this.PromiseWalker.walkerLoop@Promise-backend.js:744:7 < _do_main@head.js:191:5 < _execute_test@head.js:405:5 < @-e:1:1 00:35:59 INFO - <<<<<<< 00:35:59 INFO - mozcrash INFO | Downloading symbols from: https://ftp-ssl.mozilla.org/pub/mozilla.org/firefox/tinderbox-builds/cedar-macosx64/1408998475/firefox-34.0a1.en-US.mac.crashreporter-symbols.zip 00:36:20 INFO - mozcrash INFO | Saved minidump as /builds/slave/talos-slave/test/build/blobber_upload_dir/BAF7BCC7-5B0F-4A48-9429-018295F16F40.dmp 00:36:20 INFO - mozcrash INFO | Saved app info as /builds/slave/talos-slave/test/build/blobber_upload_dir/BAF7BCC7-5B0F-4A48-9429-018295F16F40.extra 00:36:20 WARNING - PROCESS-CRASH | /builds/slave/talos-slave/test/build/tests/xpcshell/tests/services/sync/tests/unit/test_fxa_startOver.js | application crashed [@ libsystem_kernel.dylib + 0x11a1a] 00:36:20 INFO - Crash dump filename: /var/folders/r_/0w__4rrn4d98ybr8qdz97n2000000w/T/tmp5XAORI/BAF7BCC7-5B0F-4A48-9429-018295F16F40.dmp 00:36:20 INFO - Operating system: Mac OS X 00:36:20 INFO - 10.9.0 13A603 00:36:20 INFO - CPU: amd64 00:36:20 INFO - family 6 model 42 stepping 7 00:36:20 INFO - 8 CPUs 00:36:20 INFO - Crash reason: EXC_SOFTWARE / SIGABRT 00:36:20 INFO - Crash address: 0x7fff8f056a1a 00:36:20 INFO - Thread 0 (crashed) 00:36:20 INFO - 0 libsystem_kernel.dylib + 0x11a1a 00:36:20 INFO - rbx = 0x0000000007000006 r12 = 0x0000000000000c00 00:36:20 INFO - r13 = 0x0000000000000000 r14 = 0x00007fff5fbf1860 00:36:20 INFO - r15 = 0x0000000000001d03 rip = 0x00007fff8f056a1a 00:36:20 INFO - rsp = 0x00007fff5fbf1728 rbp = 0x00007fff5fbf1770 00:36:20 INFO - Found by: given as instruction pointer in context 00:36:20 INFO - 1 libsystem_kernel.dylib + 0x10d17 00:36:20 INFO - rip = 0x00007fff8f055d18 rsp = 0x00007fff5fbf1730 00:36:20 INFO - rbp = 0x00007fff5fbf1770 00:36:20 INFO - Found by: stack scanning 00:36:20 INFO - 2 CoreFoundation + 0x71314 00:36:20 INFO - rip = 0x00007fff8e377315 rsp = 0x00007fff5fbf1780 00:36:20 INFO - rbp = 0x00007fff5fbf17d0 00:36:20 INFO - Found by: stack scanning 00:36:20 INFO - 3 CoreFoundation + 0x70938 00:36:20 INFO - rip = 0x00007fff8e376939 rsp = 0x00007fff5fbf17e0 00:36:20 INFO - rbp = 0x00007fff5fbf2590 00:36:20 INFO - Found by: stack scanning
https://tbpl.mozilla.org/php/getParsedLog.php?id=46731395&tree=Cedar&full=1#error0 17:44:09 INFO - TEST-INFO | /builds/slave/talos-slave/test/build/tests/xpcshell/tests/services/sync/tests/unit/test_fxa_startOver.js | running test ... 17:49:09 WARNING - TEST-UNEXPECTED-FAIL | /builds/slave/talos-slave/test/build/tests/xpcshell/tests/services/sync/tests/unit/test_fxa_startOver.js | Test timed out 17:49:09 WARNING - TEST-UNEXPECTED-FAIL | /builds/slave/talos-slave/test/build/tests/xpcshell/tests/services/sync/tests/unit/test_fxa_startOver.js | test failed (with xpcshell return code: 5), see following log: 17:49:09 INFO - >>>>>>> 17:49:09 INFO - DMD[4987] $DMD = '(null)' 17:49:09 INFO - DMD[4987] DMD is not enabled 17:49:09 INFO - [4987] WARNING: Couldn't get the user appdata directory. Crash events may not be produced.: file /builds/slave/ced-osx64-d-000000000000000000/build/src/toolkit/crashreporter/nsExceptionHandler.cpp, line 2189 17:49:09 INFO - System JS : ERROR (null):0 - uncaught exception: 2147500037 17:49:09 INFO - System JS : ERROR (null):0 - uncaught exception: 2147500037 17:49:09 INFO - System JS : ERROR (null):0 - uncaught exception: 2147500037 17:49:09 INFO - System JS : ERROR (null):0 - uncaught exception: 2147500037 17:49:09 INFO - System JS : ERROR (null):0 - uncaught exception: 2147500037 17:49:09 INFO - System JS : ERROR (null):0 - uncaught exception: 2147500037 17:49:09 INFO - System JS : WARNING resource://testing-common/httpd.js:2857 - in strict mode code, functions may be declared only at top level or immediately within another function 17:49:09 INFO - System JS : WARNING resource://gre/modules/Preferences.jsm:378 - mutating the [[Prototype]] of an object will cause your code to run very slowly; instead create the object with the correct initial [[Prototype]] value using Object.create 17:49:09 INFO - TEST-INFO | (xpcshell/head.js) | test MAIN run_test pending (1) 17:49:09 INFO - System JS : WARNING resource://testing-common/services/common/logging.js:30 - mutating the [[Prototype]] of an object will cause your code to run very slowly; instead create the object with the correct initial [[Prototype]] value using Object.create 17:49:09 INFO - TEST-INFO | (xpcshell/head.js) | test run_next_test 0 pending (2) 17:49:09 INFO - TEST-INFO | (xpcshell/head.js) | test MAIN run_test finished (2) 17:49:09 INFO - TEST-INFO | (xpcshell/head.js) | running event loop 17:49:09 INFO - TEST-INFO | /builds/slave/talos-slave/test/build/tests/xpcshell/tests/services/sync/tests/unit/test_fxa_startOver.js | Starting test_startover 17:49:09 INFO - TEST-INFO | (xpcshell/head.js) | test test_startover pending (2) 17:49:09 INFO - Sync.Identity INFO Username changed. Removing stored credentials. 17:49:09 INFO - Sync.Identity INFO Basic password has no value. Removing. 17:49:09 INFO - Sync.Identity INFO Sync Key has no value. Deleting. 17:49:09 INFO - Sync.Identity INFO Basic password being updated. 17:49:09 INFO - Sync.Identity INFO Sync Key being updated. 17:49:09 INFO - Sync.SyncKeyBundle INFO SyncKeyBundle being created. 17:49:09 INFO - System JS : WARNING resource://services-common/utils.js:304 - reference to undefined property ret[rOffset] 17:49:09 INFO - TEST-INFO | (xpcshell/head.js) | test run_next_test 0 finished (2) 17:49:09 INFO - TEST-PASS | /builds/slave/talos-slave/test/build/tests/xpcshell/tests/services/sync/tests/unit/test_fxa_startOver.js | [test_startover : 25] true == true 17:49:09 INFO - TEST-PASS | /builds/slave/talos-slave/test/build/tests/xpcshell/tests/services/sync/tests/unit/test_fxa_startOver.js | [test_startover : 29] true == true 17:49:09 INFO - Sync.Service DEBUG Caching URLs under storage user base: https://localhost/1.1/johndoe/ 17:49:09 INFO - Sync.Status DEBUG Status.service: service.client_not_configured => success.status_ok 17:49:09 INFO - Sync.Status DEBUG Status.service: success.status_ok => success.status_ok 17:49:09 INFO - Sync.Tracker.Clients WARN Changed IDs file clients contains non-object value. 17:49:09 INFO - Sync.Service INFO Logging in the user. 17:49:09 INFO - Sync.Service DEBUG Caching URLs under storage user base: https://localhost/1.1/johndoe/ 17:49:09 INFO - Sync.Service DEBUG Fetching unlocked auth state returned success.status_ok 17:49:09 INFO - Sync.Tracker.Bookmarks WARN Changed IDs file bookmarks contains non-object value. 17:49:09 INFO - Sync.Tracker.Forms WARN Changed IDs file forms contains non-object value. 17:49:09 INFO - Sync.Tracker.History WARN Changed IDs file history contains non-object value. 17:49:09 INFO - Sync.Tracker.Passwords WARN Changed IDs file passwords contains non-object value. 17:49:09 INFO - Sync.Tracker.Addons WARN Changed IDs file addons contains non-object value. 17:49:09 INFO - Sync.Service DEBUG verifyLogin failed: Error: NS_ERROR_CONNECTION_REFUSED (resource://services-sync/resource.js:394:18) JS Stack trace: Res_get@resource.js:414:12 < verifyLogin@service.js:715:18 < onNotify@service.js:992:12 < WrappedNotify@util.js:148:21 < WrappedLock@util.js:103:16 < WrappedCatch@util.js:77:16 < login@service.js:1003:12 < test_startover@test_fxa_startOver.js:34:3 < TaskImpl_run@Task.jsm:314:40 < Handler.prototype.process@Promise-backend.js:865:23 < this.PromiseWalker.walkerLoop@Promise-backend.js:744:7 < _do_main@head.js:191:5 < _execute_test@head.js:405:5 < @-e:1:1 17:49:09 INFO - Sync.Status DEBUG Status.login: error.login.reason.no_username => error.login.reason.network 17:49:09 INFO - Sync.Status DEBUG Status.service: success.status_ok => error.login.failed 17:49:09 INFO - Sync.Status DEBUG Status.login: error.login.reason.network => error.login.reason.network 17:49:09 INFO - Sync.Status DEBUG Status.service: error.login.failed => error.login.failed 17:49:09 INFO - Sync.SyncScheduler DEBUG Clearing sync triggers and the global score. 17:49:09 INFO - Sync.SyncScheduler DEBUG Next sync in 3600000 ms. 17:49:09 INFO - Sync.ErrorHandler DEBUG Flushing file log. 17:49:09 INFO - Sync.Service DEBUG Exception: Login failed: error.login.reason.network No traceback available 17:49:09 INFO - TEST-PASS | /builds/slave/talos-slave/test/build/tests/xpcshell/tests/services/sync/tests/unit/test_fxa_startOver.js | [test_startover : 36] true == true 17:49:09 INFO - Sync.Status INFO Resetting Status. 17:49:09 INFO - Sync.Status DEBUG Status.service: error.login.failed => success.status_ok 17:49:09 INFO - Sync.ErrorHandler DEBUG Log cleanup threshold time: 1408149967042 17:49:09 INFO - Sync.ErrorHandler DEBUG No logs to clean up. 17:49:09 INFO - Sync.Service WARN Deleting client data for clients failed:Error: NS_ERROR_CONNECTION_REFUSED (resource://services-sync/resource.js:394:18) JS Stack trace: Res_delete@resource.js:435:12 < removeClientData@clients.js:168:5 < startOver@service.js:882:11 < test_startover@test_fxa_startOver.js:47:3 < TaskImpl_run@Task.jsm:314:40 < Handler.prototype.process@Promise-backend.js:865:23 < this.PromiseWalker.walkerLoop@Promise-backend.js:744:7 < _do_main@head.js:191:5 < _execute_test@head.js:405:5 < @-e:1:1 17:49:09 INFO - <<<<<<< 17:49:25 INFO - mozcrash INFO | Saved minidump as /builds/slave/talos-slave/test/build/blobber_upload_dir/E0700397-B653-4448-89D6-1D9500FA249F.dmp 17:49:25 INFO - mozcrash INFO | Saved app info as /builds/slave/talos-slave/test/build/blobber_upload_dir/E0700397-B653-4448-89D6-1D9500FA249F.extra 17:49:25 WARNING - PROCESS-CRASH | /builds/slave/talos-slave/test/build/tests/xpcshell/tests/services/sync/tests/unit/test_fxa_startOver.js | application crashed [@ libsystem_kernel.dylib + 0x10a76] 17:49:25 INFO - Crash dump filename: /var/folders/d5/wc5442yn6wb6lfks763bctxc00000w/T/tmp1QnvxO/E0700397-B653-4448-89D6-1D9500FA249F.dmp 17:49:25 INFO - Operating system: Mac OS X 17:49:25 INFO - 10.9.0 13A476u 17:49:25 INFO - CPU: amd64 17:49:25 INFO - family 6 model 42 stepping 7 17:49:25 INFO - 8 CPUs 17:49:25 INFO - Crash reason: EXC_SOFTWARE / SIGABRT 17:49:25 INFO - Crash address: 0x7fff90a33a76 17:49:25 INFO - Thread 0 (crashed) 17:49:25 INFO - 0 libsystem_kernel.dylib + 0x10a76 17:49:25 INFO - rbx = 0x0000000007000006 r12 = 0x0000000000000c00 17:49:25 INFO - r13 = 0x0000000000000000 r14 = 0x00007fff5fbf01e0 17:49:25 INFO - r15 = 0x0000000000001d03 rip = 0x00007fff90a33a76 17:49:25 INFO - rsp = 0x00007fff5fbf00a8 rbp = 0x00007fff5fbf00f0 17:49:25 INFO - Found by: given as instruction pointer in context
FTR, the NS_ERROR_CONNECTION_REFUSED messages are "expected" - it's the crash that isn't! These tests are all exercising pure javascript, so it shouldn't be possible for these tests to crash the process even if it wanted to. Are there any other "unexplained" crashes on cedar?
Note that the logs show a SIGABRT following a time out: 00:35:59 WARNING - TEST-UNEXPECTED-FAIL | /builds/slave/talos-slave/test/build/tests/xpcshell/tests/services/sync/tests/unit/test_fxa_startOver.js | Test timed out ... 00:36:20 INFO - Crash reason: EXC_SOFTWARE / SIGABRT I believe the test harness aborts (kill -6) the process when a test times out. The crash reporter then kicks in and dumps a report. It looks to me like this isn't really crashing -- just hanging / timing out. To see what is passing and what is failing, you can check https://tbpl.mozilla.org/?tree=Cedar&jobname=.*10.9.*&rev=d1c507305848, for instance. Bug 947089 tracks most known failures.
Ah - I was looking at the output above, which shows, eg: 00:35:59 INFO - Sync.Service WARN Deleting client data ... 00:35:59 INFO - <<<<<<< 00:35:59 INFO - mozcrash INFO | Downloading symbols from: ... 00:36:20 INFO - mozcrash INFO | Saved minidump as ... Which makes it look like the crash was detected while the test was running. But I see now this is just an artifact of how xpcshell handles test output.
Haven't seen this for 3 years now.
Status: NEW → RESOLVED
Closed: 7 years ago
Resolution: --- → WORKSFORME
You need to log in before you can comment on or make changes to this bug.