Closed
Bug 1473547
Opened 6 years ago
Closed 2 years ago
Intermittent toolkit/components/places/tests/unit/test_origins.js | changeBookmarks - [changeBookmarks : 1268]
Categories
(Toolkit :: Places, defect, P2)
Toolkit
Places
Tracking
()
RESOLVED
DUPLICATE
of bug 1760067
People
(Reporter: intermittent-bug-filer, Unassigned)
References
Details
(Keywords: intermittent-failure, Whiteboard: [TV-bf pass:pass])
Filed by: aciure [at] mozilla.com https://treeherder.mozilla.org/logviewer.html#?job_id=186572894&repo=mozilla-central https://queue.taskcluster.net/v1/task/ZsJ-okflQZSYnmQGUSW1MQ/runs/0/artifacts/public/logs/live_backing.log [task 2018-07-05T10:50:49.039Z] INFO - TEST-START | toolkit/components/places/tests/unit/test_origins.js [task 2018-07-05T10:50:53.934Z] WARNING - TEST-UNEXPECTED-FAIL | toolkit/components/places/tests/unit/test_origins.js | xpcshell return code: 0 [task 2018-07-05T10:50:53.935Z] INFO - TEST-INFO took 4896ms [task 2018-07-05T10:50:53.936Z] INFO - >>>>>>> [task 2018-07-05T10:50:53.937Z] INFO - (xpcshell/head.js) | test MAIN run_test pending (1) [task 2018-07-05T10:50:53.939Z] INFO - (xpcshell/head.js) | test run_next_test 0 pending (2) [task 2018-07-05T10:50:53.940Z] INFO - (xpcshell/head.js) | test MAIN run_test finished (2) [task 2018-07-05T10:50:53.941Z] INFO - running event loop [task 2018-07-05T10:50:53.942Z] INFO - toolkit/components/places/tests/unit/test_origins.js | Starting visit [task 2018-07-05T10:50:53.943Z] INFO - (xpcshell/head.js) | test visit pending (2) [task 2018-07-05T10:50:53.944Z] INFO - (xpcshell/head.js) | test run_next_test 0 finished (2) [task 2018-07-05T10:50:53.945Z] INFO - TEST-PASS | toolkit/components/places/tests/unit/test_origins.js | visit - [visit : 1268] [] deepEqual [] [task 2018-07-05T10:50:53.946Z] INFO - TEST-PASS | toolkit/components/places/tests/unit/test_origins.js | visit - [visit : 1282] 0 == 0 [task 2018-07-05T10:50:53.947Z] INFO - TEST-PASS | toolkit/components/places/tests/unit/test_origins.js | visit - [visit : 1286] 0 == 0 [task 2018-07-05T10:50:53.948Z] INFO - TEST-PASS | toolkit/components/places/tests/unit/test_origins.js | visit - [visit : 1290] 0 == 0 [task 2018-07-05T10:50:53.950Z] INFO - PID 8548 | JavaScript strict warning: resource://gre/modules/PlacesUtils.jsm, line 1064: ReferenceError: reference to undefined property "description" [task 2018-07-05T10:50:53.951Z] INFO - "CONSOLE_MESSAGE: (warn) [JavaScript Warning: "ReferenceError: reference to undefined property "description"" {file: "resource://gre/modules/PlacesUtils.jsm" line: 1064}]" [task 2018-07-05T10:50:53.952Z] INFO - TEST-PASS | toolkit/components/places/tests/unit/test_origins.js | visit - [visit : 1268] [["http://","example.com",100]] deepEqual [["http://","example.com",100]] [task 2018-07-05T10:50:53.953Z] INFO - TEST-PASS | toolkit/components/places/tests/unit/test_origins.js | visit - [visit : 1282] 1 == 1 [task 2018-07-05T10:50:53.954Z] INFO - TEST-PASS | toolkit/components/places/tests/unit/test_origins.js | visit - [visit : 1286] 100 == 100 [task 2018-07-05T10:50:53.957Z] INFO - TEST-PASS | toolkit/components/places/tests/unit/test_origins.js | visit - [visit : 1290] 10000 == 10000 [task 2018-07-05T10:50:53.959Z] INFO - TEST-PASS | toolkit/components/places/tests/unit/test_origins.js | visit - [visit : 1268] [] deepEqual [] [task 2018-07-05T10:50:53.960Z] INFO - TEST-PASS | toolkit/components/places/tests/unit/test_origins.js | visit - [visit : 1282] 0 == 0 [task 2018-07-05T10:50:53.961Z] INFO - TEST-PASS | toolkit/components/places/tests/unit/test_origins.js | visit - [visit : 1286] 0 == 0 [task 2018-07-05T10:50:53.962Z] INFO - TEST-PASS | toolkit/components/places/tests/unit/test_origins.js | visit - [visit : 1290] 0 == 0 [task 2018-07-05T10:50:53.963Z] INFO - (xpcshell/head.js) | test run_next_test 1 pending (2) [task 2018-07-05T10:50:53.965Z] INFO - (xpcshell/head.js) | test visit finished (2) [task 2018-07-05T10:50:53.966Z] INFO - toolkit/components/places/tests/unit/test_origins.js | Starting visitRepeatedly [task 2018-07-05T10:50:53.967Z] INFO - (xpcshell/head.js) | test visitRepeatedly pending (2) [task 2018-07-05T10:50:53.968Z] INFO - (xpcshell/head.js) | test run_next_test 1 finished (2) [task 2018-07-05T10:50:53.968Z] INFO - TEST-PASS | toolkit/components/places/tests/unit/test_origins.js | visitRepeatedly - [visitRepeatedly : 1268] [["http://","example.com",300]] deepEqual [["http://","example.com",300]] [task 2018-07-05T10:50:53.970Z] INFO - TEST-PASS | toolkit/components/places/tests/unit/test_origins.js | visitRepeatedly - [visitRepeatedly : 1282] 1 == 1 [task 2018-07-05T10:50:53.971Z] INFO - TEST-PASS | toolkit/components/places/tests/unit/test_origins.js | visitRepeatedly - [visitRepeatedly : 1286] 300 == 300 [task 2018-07-05T10:50:53.972Z] INFO - TEST-PASS | toolkit/components/places/tests/unit/test_origins.js | visitRepeatedly - [visitRepeatedly : 1290] 90000 == 90000 [task 2018-07-05T10:50:53.973Z] INFO - TEST-PASS | toolkit/components/places/tests/unit/test_origins.js | visitRepeatedly - [visitRepeatedly : 1268] [] deepEqual [] [task 2018-07-05T10:50:53.975Z] INFO - TEST-PASS | toolkit/components/places/tests/unit/test_origins.js | visitRepeatedly - [visitRepeatedly : 1282] 0 == 0 [task 2018-07-05T10:50:53.976Z] INFO - TEST-PASS | toolkit/components/places/tests/unit/test_origins.js | visitRepeatedly - [visitRepeatedly : 1286] 0 == 0 [task 2018-07-05T10:50:53.977Z] INFO - TEST-PASS | toolkit/components/places/tests/unit/test_origins.js | visitRepeatedly - [visitRepeatedly : 1290] 0 == 0 [task 2018-07-05T10:50:53.978Z] INFO - (xpcshell/head.js) | test run_next_test 2 pending (2) [task 2018-07-05T10:50:53.979Z] INFO - (xpcshell/head.js) | test visitRepeatedly finished (2) [task 2018-07-05T10:50:53.980Z] INFO - toolkit/components/places/tests/unit/test_origins.js | Starting visitRepeatedlySequential [task 2018-07-05T10:50:53.981Z] INFO - (xpcshell/head.js) | test visitRepeatedlySequential pending (2) [task 2018-07-05T10:50:53.982Z] INFO - (xpcshell/head.js) | test run_next_test 2 finished (2)
|
||
Comment 1•6 years ago
|
||
note: this is jsdcov specific failure. I did a backfill for test-verify: https://treeherder.mozilla.org/#/jobs?repo=mozilla-central&selectedJob=186597482&filter-searchStr=jsdcov%20verify&tochange=085cdfb90903d4985f0de1dc7786522d9fb45596&fromchange=1dad493abb2dc49890a5d6a23340afa0719efd96 This didn't reproduce in test-verify, so I suspect this is really just a low frequency intermittent or a random failure.
Whiteboard: [TV-bf pass:pass]
|
||
Comment 2•6 years ago
|
||
[task 2018-07-05T10:50:54.389Z] INFO - (xpcshell/head.js) | test changeBookmarks pending (2) [task 2018-07-05T10:50:54.391Z] INFO - (xpcshell/head.js) | test run_next_test 19 finished (2) [task 2018-07-05T10:50:54.392Z] WARNING - TEST-UNEXPECTED-FAIL | toolkit/components/places/tests/unit/test_origins.js | changeBookmarks - [changeBookmarks : 1268] [["http://","example.com",140],["http://","www.example.com",0]] deepEqual [["http://","example.com",140],["http://","www.example.com",140]] [task 2018-07-05T10:50:54.393Z] INFO - /builds/worker/workspace/build/tests/xpcshell/tests/toolkit/components/places/tests/unit/test_origins.js:checkDB:1268 [task 2018-07-05T10:50:54.394Z] INFO - exiting test [task 2018-07-05T10:50:54.395Z] INFO - Unexpected exception NS_ERROR_ABORT: [task 2018-07-05T10:50:54.396Z] INFO - _abort_failed_test@/builds/worker/workspace/build/tests/xpcshell/head.js:745:9 [task 2018-07-05T10:50:54.397Z] INFO - do_report_result@/builds/worker/workspace/build/tests/xpcshell/head.js:852:5 [task 2018-07-05T10:50:54.398Z] INFO - Assert<@/builds/worker/workspace/build/tests/xpcshell/head.js:55:5 [task 2018-07-05T10:50:54.399Z] INFO - proto.report@resource://testing-common/Assert.jsm:215:5 [task 2018-07-05T10:50:54.400Z] INFO - deepEqual@resource://testing-common/Assert.jsm:282:3 [task 2018-07-05T10:50:54.401Z] INFO - checkDB@/builds/worker/workspace/build/tests/xpcshell/tests/toolkit/components/places/tests/unit/test_origins.js:1268:3 [task 2018-07-05T10:50:54.402Z] INFO - async*changeBookmarks@/builds/worker/workspace/build/tests/xpcshell/tests/toolkit/components/places/tests/unit/test_origins.js:1112:9
Blocks: 1467627
Priority: P5 → P2
|
||
Comment 3•6 years ago
|
||
(In reply to Joel Maher ( :jmaher ) (UTC-4) from comment #1) > note: this is jsdcov specific failure. How can I try to reproduce this locally? I'm not familiar with jsdcov.
Flags: needinfo?(jmaher)
|
|
||
Comment 4•6 years ago
|
||
Line 1112 is the checkDB call in this snippet:
add_task(async function changeBookmarks() {
let bookmarks = [];
let urls = [
"http://example.com/",
"http://www.example.com/",
];
for (let url of urls) {
bookmarks.push(await PlacesUtils.bookmarks.insert({
url,
parentGuid: PlacesUtils.bookmarks.unfiledGuid,
}));
}
await checkDB([
["http://", "example.com", ["http://example.com/"]],
["http://", "www.example.com", ["http://www.example.com/"]],
]);
https://hg.mozilla.org/mozilla-central/file/5c31149518e3/toolkit/components/places/tests/unit/test_origins.js#l1112
So the test task isn't even doing anything complicated at this point.
Bug 1467627 changed how/when origin frecencies are calculated. Now we `DELETE FROM moz_updateoriginsupdate_temp` after changing the corresponding moz_places frecency. So I'd guess that the test happened to reach this checkDB call before the `DELETE FROM moz_updateoriginsupdate_temp` and the associated trigger ran for the http://www.example.com origin.
That DELETE call is here (I think this is the one, it's the only one in Bookmarks.jsm): https://hg.mozilla.org/mozilla-central/file/5c31149518e3/toolkit/components/places/Bookmarks.jsm#l2548
Unlike in the cpp code that deals with history, in Bookmarks.jsm we `await` each SQL query, so I'd guess that has something to do with it. The test needs to wait until the DELETE finishes for each origin it's testing.|
|
||
Comment 5•6 years ago
|
||
jsdcov is using devtools debugger to step through and get javascript code coverage. It is an edge case that a user wouldn't necessarily hit- which is why I called it out here. it looks like there is a potential solution that could be coded up, that might make the code/tests more reliable in general (although I think the places tests are pretty stable in general).
Flags: needinfo?(jmaher)
| Comment hidden (Intermittent Failures Robot) |
|
||
Updated•6 years ago
|
Summary: Intermittent toolkit/components/places/tests/unit/test_origins.js | xpcshell return code: 0 → Intermittent toolkit/components/places/tests/unit/test_origins.js | changeBookmarks - [changeBookmarks : 1268]
| Comment hidden (Intermittent Failures Robot) |
| Comment hidden (Intermittent Failures Robot) |
We are trying to build a tool to automatically classify intermittent failures, which would provide a starting point for fixing the bug, reducing the manual work for the developers.
We are collecting some feedback on the results, to see if they’re good enough and where we need to improve.
For this bug, the tool says that the intermittent failure is most likely a:
Concurrency Issue: This includes tests in which failures occur due to thread management issues (different threads or their outcomes depending on an implicit ordering), race conditions and/or deadlocks, and issues related to an asynchronous waits (e.g. a process trying to access an external resource or continuing before the external resource is available).
Once you’re done investigating and/or fixing the bug, could you tell me:
- Did the tool correctly recognize the type of intermittent failure?
- Did the information from the tool help your analysis, the bug fixing process, or anything in the process? (please also let us know how the tool was useful and/or what would improve the tool's usefulness for you)|
|
||
Updated•2 years ago
|
Status: NEW → RESOLVED
Closed: 2 years ago
Resolution: --- → DUPLICATE
You need to log in
before you can comment on or make changes to this bug.
Description
•