Closed
Bug 1317667
Opened 7 years ago
Closed 7 years ago
Intermittent services/sync/tests/unit/test_bookmark_duping.js | xpcshell return code: 0
Categories
(Firefox :: Sync, defect, P1)
Firefox
Sync
Tracking
()
RESOLVED
FIXED
Firefox 54
People
(Reporter: intermittent-bug-filer, Assigned: eoger)
References
Details
(Keywords: intermittent-failure, Whiteboard: [stockwell fixed])
Attachments
(1 file)
Filed by: tomcat [at] mozilla.com https://treeherder.mozilla.org/logviewer.html#?job_id=6644547&repo=autoland https://queue.taskcluster.net/v1/task/cQTgF9g_T3CRZrE82BmagQ/runs/0/artifacts/public%2Flogs%2Flive_backing.log
Comment 1•7 years ago
|
||
:markh, I see we only have one instance of this in the tree, but I have a case where this shows up consistently on linux64 debug when running in Ubuntu 16.04 (our tests now run in 12.04, we are trying to upgrade the OS to a more modern flavor): https://treeherder.mozilla.org/#/jobs?repo=try&revision=442aa421aa40a69a124413b6546c486210b728c1&selectedJob=65308509&group_state=expanded&filter-searchStr=xpcshell I see this in the log prior to the fail: [task 2016-12-29T21:09:09.419546Z] 21:09:09 INFO - TEST-PASS | services/sync/tests/unit/test_bookmark_duping.js | test_dupe_reparented_to_future_arriving_parent_bookmark - [test_dupe_reparented_to_future_arriving_parent_bookmark : 525] 8 == 8 [task 2016-12-29T21:09:09.421464Z] 21:09:09 INFO - PROCESS | 8476 | JavaScript strict warning: /home/worker/workspace/build/tests/xpcshell/tests/services/sync/tests/unit/test_bookmark_duping.js, line 526: ReferenceError: reference to undefined property "deleted" [task 2016-12-29T21:09:09.423505Z] 21:09:09 WARNING - TEST-UNEXPECTED-FAIL | services/sync/tests/unit/test_bookmark_duping.js | test_dupe_reparented_to_future_arriving_parent_bookmark - [test_dupe_reparented_to_future_arriving_parent_bookmark : 526] "undefined" == true :markh- if you have ideas on how to debug this, or get more information- do let me know- possibly you have an idea of how to fix this.
Flags: needinfo?(markh)
Comment 2•7 years ago
|
||
also in 2 of the 3 xpcshell-7 failure logs, there is a test-timeout on test_telemetry.js (I noticed it was also authored/reviewed primarily by :markh/:tcsc), this is after the previous failure, here is part of the message: [task 2016-12-29T21:15:19.830369Z] 21:15:19 INFO - TEST-PASS | services/sync/tests/unit/test_telemetry.js | - 1 == 1 [task 2016-12-29T21:15:19.838558Z] 21:15:19 INFO - PROCESS | 8551 | 1483045841065 Sync.Service DEBUG Exception calling anonymous function: TypeError: endpoint is null (resource://gre/modules/services-sync/browserid_identity.js:829:11) JS Stack trace: _findCluster/endPointFromIdentityToken<@browserid_identity.js:829:11 < process@Promise-backend.js:932:23 < walkerLoop@Promise-backend.js:813:7 < Promise*scheduleWalkerLoop@Promise-backend.js:744:11 < schedulePromise@Promise-backend.js:776:7 < Promise.prototype.then@Promise-backend.js:452:5 < _findCluster/promiseClusterURL<@browserid_identity.js:838:14 < _findCluster@browserid_identity.js:855:5 < setCluster@cluster.js:77:19 < sync@enginesync.js:61:38 < onNotify@service.js:1328:7 < WrappedNotify@util.js:166:21 < WrappedLock@util.js:121:16 < _lockedSync@service.js:1318:12 < sync/<@service.js:1310:14 < WrappedCatch@util.js:95:16 < sync@service.js:1298:5 < sync_and_validate_telem/<@head_helpers.js:353:30 < wait_for_ping/<@head_helpers.js:347:5 < wait_for_ping@head_helpers.js:330:10 < sync_and_validate_telem@head_helpers.js:353:10 < test_basic@test_telemetry.js:91:9 < _do_main@head.js:210:5 < _execute_test@head.js:545:5 < @-e:1:1 [task 2016-12-29T21:15:19.846415Z] 21:15:19 INFO - PROCESS | 8551 | 1483045841072 Sync.ErrorHandler DEBUG Addons installed: 0 [task 2016-12-29T21:15:19.848772Z] 21:15:19 INFO - PROCESS | 8551 | 1483045841080 Sync.LogManager DEBUG Flushing file log . . . [task 2016-12-29T21:15:19.920410Z] 21:15:19 INFO - PROCESS | 8551 | 1483045841713 Sync.LogManager DEBUG Log cleanup threshold time: 1482181841713 [task 2016-12-29T21:15:19.928213Z] 21:15:19 INFO - "CONSOLE_MESSAGE: (error) [JavaScript Error: "Sync encountered an error - see about:sync-log for the log file." {file: "resource://services-sync/policies.js" line: 731}] [task 2016-12-29T21:15:19.930950Z] 21:15:19 INFO - onComplete@resource://services-sync/policies.js:731:9 [task 2016-12-29T21:15:19.931401Z] 21:15:19 INFO - waitForSyncCallback@resource://services-common/async.js:98:7 [task 2016-12-29T21:15:19.941329Z] 21:15:19 INFO - Res__request@resource://services-sync/resource.js:386:14 [task 2016-12-29T21:15:19.941552Z] 21:15:19 INFO - Res_get@resource://services-sync/resource.js:415:12 [task 2016-12-29T21:15:19.941774Z] 21:15:19 INFO - RecordMgr_import@resource://services-sync/record.js:231:23 [task 2016-12-29T21:15:19.941990Z] 21:15:19 INFO - RecordMgr_get@resource://services-sync/record.js:255:12 [task 2016-12-29T21:15:19.942222Z] 21:15:19 INFO - _syncStartup@resource://services-sync/engines.js:911:22 [task 2016-12-29T21:15:19.942468Z] 21:15:19 INFO - _syncStart@resource://gre/modules/services-sync/engines/bookmarks.js:450:5 [task 2016-12-29T21:15:19.942668Z] 21:15:19 INFO - _sync@resource://services-sync/engines.js:1657:7 [task 2016-12-29T21:15:19.942909Z] 21:15:19 INFO - WrappedNotify@resource://services-sync/util.js:166:21 [task 2016-12-29T21:15:19.943155Z] 21:15:19 INFO - sync@resource://services-sync/engines.js:697:5 [task 2016-12-29T21:15:19.943501Z] 21:15:19 INFO - sync_engine_and_validate_telem/<@/home/worker/workspace/build/tests/xpcshell/tests/services/sync/tests/unit/head_helpers.js:427:7 [task 2016-12-29T21:15:19.946207Z] 21:15:19 INFO - sync_engine_and_validate_telem@/home/worker/workspace/build/tests/xpcshell/tests/services/sync/tests/unit/head_helpers.js:361:10 [task 2016-12-29T21:15:19.948389Z] 21:15:19 INFO - test_processIncoming_error@/home/worker/workspace/build/tests/xpcshell/tests/services/sync/tests/unit/test_telemetry.js:121:13 [task 2016-12-29T21:15:19.949761Z] 21:15:19 INFO - _do_main@/home/worker/workspace/build/tests/xpcshell/head.js:210:5 [task 2016-12-29T21:15:19.951229Z] 21:15:19 INFO - _execute_test@/home/worker/workspace/build/tests/xpcshell/head.js:545:5 [task 2016-12-29T21:15:19.952389Z] 21:15:19 INFO - @-e:1:1 [task 2016-12-29T21:15:19.952560Z] 21:15:19 INFO - " possibly the same root cause :)
Updated•7 years ago
|
Component: Bookmarks & History → Sync
Comment 3•7 years ago
|
||
Sorry for the delay here - I missed the needinfo request email :( This test is quite painful and does simulate many errors to ensure they are handled correctly. It's also slow :( I suspect a requestLongerTimeout() would be a good short-term solution, and there are probably a number of things we can do to speed it up in the medium term. Can you quickly try the requestLongerTimeout() hack to verify that it solves the immediate problem?
Flags: needinfo?(markh)
Comment 4•7 years ago
|
||
I realized these are xpcshell tests, not mochitest so there is no simple requestLongerTimeout(). The issue is: TEST-UNEXPECTED-FAIL | services/sync/tests/unit/test_bookmark_duping.js | test_dupe_reparented_to_future_arriving_parent_bookmark - [test_dupe_reparented_to_future_arriving_parent_bookmark : 526] "undefined" == true not sure if that is due to a timeout somewhere or not.
Comment hidden (Intermittent Failures Robot) |
Updated•7 years ago
|
Priority: -- → P2
Updated•7 years ago
|
Assignee: nobody → eoger
Priority: P2 → P1
Comment hidden (mozreview-request) |
Assignee | ||
Comment 7•7 years ago
|
||
This seems to resolve the problem *on my machine*.
Comment 8•7 years ago
|
||
mozreview-review |
Comment on attachment 8833413 [details] Bug 1317667 - Use dates further in the future in test_bookmark_duping. https://reviewboard.mozilla.org/r/109630/#review110702 Nice! Let's see if this helps. While you're here, could you please make `getFolderChildrenIDs` async, too? It looks like we don't actually care if they're IDs or GUIDs, so we could replace it with `PlacesSyncUtils.bookmarks.fetchChildSyncIds`.
Attachment #8833413 -
Flags: review?(kit) → review+
Comment hidden (mozreview-request) |
Assignee | ||
Comment 10•7 years ago
|
||
Patch amended, thanks kit!
Comment 12•7 years ago
|
||
bugherder |
https://hg.mozilla.org/mozilla-central/rev/3ad498e9416c
Status: NEW → RESOLVED
Closed: 7 years ago
status-firefox54:
--- → fixed
Resolution: --- → FIXED
Target Milestone: --- → Firefox 54
Updated•7 years ago
|
status-firefox52:
--- → affected
status-firefox53:
--- → affected
Comment 13•7 years ago
|
||
bugherder uplift |
https://hg.mozilla.org/releases/mozilla-aurora/rev/c6db1230ce23
Flags: in-testsuite+
Updated•7 years ago
|
Comment hidden (Intermittent Failures Robot) |
Comment 15•7 years ago
|
||
These are still happening :(
Flags: needinfo?(eoger)
Target Milestone: Firefox 54 → ---
Comment hidden (Intermittent Failures Robot) |
Updated•7 years ago
|
Status: RESOLVED → REOPENED
Resolution: FIXED → ---
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (mozreview-request) |
Assignee | ||
Comment 20•7 years ago
|
||
By throttling my CPU and launching all the sync unit tests are the same time (./mach xpcshell-test services/sync/tests/unit/), I have been able to reproduce once again the bug. I realized that in every test, we insert/update remote records in the "future" by setting their date to |Date.now() / 1000 + 10 (seconds)|. The problem is that the tests are executed so slowly that when we sync and actually get these remote records, this date is not in the future but in the past! I bumped the date in the future to 500 seconds (which should be more than enough).
Flags: needinfo?(eoger)
Comment 21•7 years ago
|
||
Pushed by eoger@mozilla.com: https://hg.mozilla.org/integration/autoland/rev/7d83ebea9020 Use dates further in the future in test_bookmark_duping. r=kitcambridge
Updated•7 years ago
|
Whiteboard: [stockwell fixed]
Comment 22•7 years ago
|
||
bugherder |
https://hg.mozilla.org/mozilla-central/rev/7d83ebea9020
Status: REOPENED → RESOLVED
Closed: 7 years ago → 7 years ago
Resolution: --- → FIXED
Target Milestone: --- → Firefox 54
Comment 23•7 years ago
|
||
bugherder uplift |
https://hg.mozilla.org/releases/mozilla-aurora/rev/514641af5ac4
Comment hidden (Intermittent Failures Robot) |
You need to log in
before you can comment on or make changes to this bug.
Description
•