Frequent toolkit/modules/tests/xpcshell/test_firstStartup.js | single tracking bug
Categories
(Toolkit :: Find Toolbar, defect, P5)
Tracking
()
Tracking | Status | |
---|---|---|
firefox117 | --- | fixed |
People
(Reporter: intermittent-bug-filer, Assigned: mconley)
References
Details
(Keywords: intermittent-failure, intermittent-testcase)
Attachments
(1 file)
Filed by: imoraru [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer?job_id=404903386&repo=autoland
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/FVyhetckTbWi5MubU4E7nQ/runs/0/artifacts/public/logs/live_backing.log
[task 2023-02-07T18:26:49.002Z] 18:26:49 INFO - TEST-START | toolkit/modules/tests/xpcshell/test_Region_geocoding.js
[task 2023-02-07T18:27:07.120Z] 18:27:07 INFO - TEST-PASS | toolkit/modules/tests/xpcshell/test_Region_geocoding.js | took 18119ms
[task 2023-02-07T18:27:07.135Z] 18:27:07 INFO - Retrying tests that failed when run in parallel.
[task 2023-02-07T18:27:07.137Z] 18:27:07 INFO - TEST-START | toolkit/modules/tests/xpcshell/test_firstStartup.js
[task 2023-02-07T18:27:18.749Z] 18:27:18 WARNING - TEST-UNEXPECTED-FAIL | toolkit/modules/tests/xpcshell/test_firstStartup.js | xpcshell return code: 0
[task 2023-02-07T18:27:18.761Z] 18:27:18 INFO - TEST-INFO took 11612ms
[task 2023-02-07T18:27:18.761Z] 18:27:18 INFO - >>>>>>>
[task 2023-02-07T18:27:18.761Z] 18:27:18 INFO - (xpcshell/head.js) | test MAIN run_test pending (1)
[task 2023-02-07T18:27:18.761Z] 18:27:18 INFO - (xpcshell/head.js) | test run_next_test 0 pending (2)
[task 2023-02-07T18:27:18.762Z] 18:27:18 INFO - (xpcshell/head.js) | test MAIN run_test finished (2)
[task 2023-02-07T18:27:18.762Z] 18:27:18 INFO - running event loop
[task 2023-02-07T18:27:18.762Z] 18:27:18 INFO - toolkit/modules/tests/xpcshell/test_firstStartup.js | Starting test_success
[task 2023-02-07T18:27:18.762Z] 18:27:18 INFO - (xpcshell/head.js) | test test_success pending (2)
[task 2023-02-07T18:27:18.763Z] 18:27:18 INFO - PID 6688 | console.error: (new Error("Unexpected content-type \\"text/plain;charset=US-ASCII\\"", "resource://services-settings/Utils.jsm", 407))
[task 2023-02-07T18:27:18.763Z] 18:27:18 INFO - PID 6688 | console.error: (new Error("Unexpected content-type \\"text/plain;charset=US-ASCII\\"", "resource://services-settings/Utils.jsm", 407))
[task 2023-02-07T18:27:18.763Z] 18:27:18 INFO - PID 6688 | console.error: (new Error("Unexpected content-type \\"text/plain;charset=US-ASCII\\"", "resource://services-settings/Utils.jsm", 407))
[task 2023-02-07T18:27:18.764Z] 18:27:18 INFO - TEST-PASS | toolkit/modules/tests/xpcshell/test_firstStartup.js | test_success - [test_success : 19] 3 == 3
[task 2023-02-07T18:27:18.764Z] 18:27:18 INFO - (xpcshell/head.js) | test run_next_test 0 finished (2)
[task 2023-02-07T18:27:18.764Z] 18:27:18 INFO - (xpcshell/head.js) | test run_next_test 1 pending (2)
[task 2023-02-07T18:27:18.764Z] 18:27:18 INFO - (xpcshell/head.js) | test test_success finished (2)
[task 2023-02-07T18:27:18.764Z] 18:27:18 INFO - toolkit/modules/tests/xpcshell/test_firstStartup.js | Starting test_timeout
[task 2023-02-07T18:27:18.765Z] 18:27:18 INFO - (xpcshell/head.js) | test test_timeout pending (2)
[task 2023-02-07T18:27:18.765Z] 18:27:18 INFO - TEST-PASS | toolkit/modules/tests/xpcshell/test_firstStartup.js | test_timeout - [test_timeout : 31] 2 == 2
[task 2023-02-07T18:27:18.765Z] 18:27:18 INFO - (xpcshell/head.js) | test run_next_test 1 finished (2)
[task 2023-02-07T18:27:18.765Z] 18:27:18 INFO - (xpcshell/head.js) | test run_next_test 2 pending (2)
[task 2023-02-07T18:27:18.765Z] 18:27:18 INFO - (xpcshell/head.js) | test test_timeout finished (2)
[task 2023-02-07T18:27:18.766Z] 18:27:18 INFO - (xpcshell/head.js) | test run_next_test 2 finished (1)
[task 2023-02-07T18:27:18.766Z] 18:27:18 INFO - exiting test
[task 2023-02-07T18:27:18.767Z] 18:27:18 INFO - "CONSOLE_MESSAGE: (error) [JavaScript Error: "IndexedDB UnknownErr: ActorsParent.cpp:9566"]"
[task 2023-02-07T18:27:18.767Z] 18:27:18 INFO - "CONSOLE_MESSAGE: (error) [JavaScript Error: "IndexedDB UnknownErr: ActorsParent.cpp:10263"]"
[task 2023-02-07T18:27:18.767Z] 18:27:18 INFO - PID 6688 | *** UTM:SVC TimerManager:registerTimer called after profile-before-change notification. Ignoring timer registration for id: recipe-client-addon-run
[task 2023-02-07T18:27:18.768Z] 18:27:18 INFO - "CONSOLE_MESSAGE: (error) [JavaScript Error: "1675794438692 app.normandy.bootstrap ERROR Failed to initialize addon rollouts:: AbortError: A request was aborted, for example through a call to IDBTransaction.abort. No traceback available" {file: "resource://gre/modules/Log.sys.mjs" line: 723}]
[task 2023-02-07T18:27:18.768Z] 18:27:18 INFO - append@resource://gre/modules/Log.sys.mjs:723:12
[task 2023-02-07T18:27:18.768Z] 18:27:18 INFO - log@resource://gre/modules/Log.sys.mjs:377:16
[task 2023-02-07T18:27:18.768Z] 18:27:18 INFO - error@resource://gre/modules/Log.sys.mjs:385:10
[task 2023-02-07T18:27:18.769Z] 18:27:18 INFO - finishInit@resource://normandy/Normandy.jsm:172:11
[task 2023-02-07T18:27:18.769Z] 18:27:18 INFO - _execute_test@Z:\\task_167579070795972\\build\\tests\\xpcshell\\head.js:702:23
[task 2023-02-07T18:27:18.769Z] 18:27:18 INFO - @-e:1:1
[task 2023-02-07T18:27:18.769Z] 18:27:18 INFO - "
[task 2023-02-07T18:27:18.770Z] 18:27:18 INFO - "CONSOLE_MESSAGE: (error) [JavaScript Error: "1675794438692 app.normandy.bootstrap ERROR Failed to initialize addon rollouts:: AbortError: A request was aborted, for example through a call to IDBTransaction.abort. No traceback available" {file: "resource://gre/modules/Log.sys.mjs" line: 723}]
[task 2023-02-07T18:27:18.770Z] 18:27:18 INFO - append@resource://gre/modules/Log.sys.mjs:723:12
[task 2023-02-07T18:27:18.770Z] 18:27:18 INFO - log@resource://gre/modules/Log.sys.mjs:377:16
[task 2023-02-07T18:27:18.770Z] 18:27:18 INFO - error@resource://gre/modules/Log.sys.mjs:385:10
[task 2023-02-07T18:27:18.771Z] 18:27:18 INFO - finishInit@resource://normandy/Normandy.jsm:172:11
[task 2023-02-07T18:27:18.771Z] 18:27:18 INFO - _execute_test@Z:\\task_167579070795972\\build\\tests\\xpcshell\\head.js:702:23
[task 2023-02-07T18:27:18.771Z] 18:27:18 INFO - @-e:1:1
[task 2023-02-07T18:27:18.771Z] 18:27:18 INFO - "
[task 2023-02-07T18:27:18.771Z] 18:27:18 INFO - "CONSOLE_MESSAGE: (error) [JavaScript Error: "1675794438692 app.normandy.bootstrap ERROR Failed to initialize addon rollouts:: AbortError: A request was aborted, for example through a call to IDBTransaction.abort. No traceback available" {file: "resource://gre/modules/Log.sys.mjs" line: 723}]
[task 2023-02-07T18:27:18.772Z] 18:27:18 INFO - append@resource://gre/modules/Log.sys.mjs:723:12
[task 2023-02-07T18:27:18.772Z] 18:27:18 INFO - log@resource://gre/modules/Log.sys.mjs:377:16
[task 2023-02-07T18:27:18.772Z] 18:27:18 INFO - error@resource://gre/modules/Log.sys.mjs:385:10
[task 2023-02-07T18:27:18.772Z] 18:27:18 INFO - finishInit@resource://normandy/Normandy.jsm:172:11
[task 2023-02-07T18:27:18.773Z] 18:27:18 INFO - _execute_test@Z:\\task_167579070795972\\build\\tests\\xpcshell\\head.js:702:23
[task 2023-02-07T18:27:18.773Z] 18:27:18 INFO - @-e:1:1
[task 2023-02-07T18:27:18.773Z] 18:27:18 INFO - "
[task 2023-02-07T18:27:18.773Z] 18:27:18 INFO - "CONSOLE_MESSAGE: (error) [JavaScript Error: "1675794438693 app.normandy.bootstrap ERROR Failed to initialize preference experiments:: Error: Data is not ready.(resource://gre/modules/JSONFile.sys.mjs:184:13) JS Stack trace: get data@sys.mjs:184:13
[task 2023-02-07T18:27:18.773Z] 18:27:18 INFO - getAllActive@PreferenceExperiments.jsm:924:5
[task 2023-02-07T18:27:18.774Z] 18:27:18 INFO - _execute_test@Z:\\task_167579070795972\\build\\tests\\xpcshell\\head.js:702:23
[task 2023-02-07T18:27:18.774Z] 18:27:18 INFO - @-e:1:1" {file: "resource://gre/modules/Log.sys.mjs" line: 723}]
[task 2023-02-07T18:27:18.775Z] 18:27:18 INFO - append@resource://gre/modules/Log.sys.mjs:723:12
[task 2023-02-07T18:27:18.775Z] 18:27:18 INFO - log@resource://gre/modules/Log.sys.mjs:377:16
[task 2023-02-07T18:27:18.775Z] 18:27:18 INFO - error@resource://gre/modules/Log.sys.mjs:385:10
[task 2023-02-07T18:27:18.775Z] 18:27:18 INFO - finishInit@resource://normandy/Normandy.jsm:178:11
[task 2023-02-07T18:27:18.775Z] 18:27:18 INFO - _execute_test@Z:\\task_167579070795972\\build\\tests\\xpcshell\\head.js:702:23
[task 2023-02-07T18:27:18.775Z] 18:27:18 INFO - @-e:1:1
[task 2023-02-07T18:27:18.776Z] 18:27:18 INFO - "
[task 2023-02-07T18:27:18.776Z] 18:27:18 INFO - "CONSOLE_MESSAGE: (error) [JavaScript Error: "1675794438693 app.normandy.bootstrap ERROR Failed to initialize preference experiments:: Error: Data is not ready.(resource://gre/modules/JSONFile.sys.mjs:184:13) JS Stack trace: get data@sys.mjs:184:13
[task 2023-02-07T18:27:18.776Z] 18:27:18 INFO - getAllActive@PreferenceExperiments.jsm:924:5
[task 2023-02-07T18:27:18.776Z] 18:27:18 INFO - _execute_test@Z:\\task_167579070795972\\build\\tests\\xpcshell\\head.js:702:23
[task 2023-02-07T18:27:18.777Z] 18:27:18 INFO - @-e:1:1" {file: "resource://gre/modules/Log.sys.mjs" line: 723}]
[task 2023-02-07T18:27:18.777Z] 18:27:18 INFO - append@resource://gre/modules/Log.sys.mjs:723:12
[task 2023-02-07T18:27:18.777Z] 18:27:18 INFO - log@resource://gre/modules/Log.sys.mjs:377:16
[task 2023-02-07T18:27:18.777Z] 18:27:18 INFO - error@resource://gre/modules/Log.sys.mjs:385:10
[task 2023-02-07T18:27:18.777Z] 18:27:18 INFO - finishInit@resource://normandy/Normandy.jsm:178:11
[task 2023-02-07T18:27:18.778Z] 18:27:18 INFO - _execute_test@Z:\\task_167579070795972\\build\\tests\\xpcshell\\head.js:702:23
[task 2023-02-07T18:27:18.778Z] 18:27:18 INFO - @-e:1:1
[task 2023-02-07T18:27:18.778Z] 18:27:18 INFO - "
[task 2023-02-07T18:27:18.778Z] 18:27:18 INFO - "CONSOLE_MESSAGE: (error) [JavaScript Error: "1675794438693 app.normandy.bootstrap ERROR Failed to initialize preference experiments:: Error: Data is not ready.(resource://gre/modules/JSONFile.sys.mjs:184:13) JS Stack trace: get data@sys.mjs:184:13
[task 2023-02-07T18:27:18.779Z] 18:27:18 INFO - getAllActive@PreferenceExperiments.jsm:924:5
[task 2023-02-07T18:27:18.779Z] 18:27:18 INFO - _execute_test@Z:\\task_167579070795972\\build\\tests\\xpcshell\\head.js:702:23
[task 2023-02-07T18:27:18.779Z] 18:27:18 INFO - @-e:1:1" {file: "resource://gre/modules/Log.sys.mjs" line: 723}]
[task 2023-02-07T18:27:18.779Z] 18:27:18 INFO - append@resource://gre/modules/Log.sys.mjs:723:12
[task 2023-02-07T18:27:18.779Z] 18:27:18 INFO - log@resource://gre/modules/Log.sys.mjs:377:16
[task 2023-02-07T18:27:18.780Z] 18:27:18 INFO - error@resource://gre/modules/Log.sys.mjs:385:10
[task 2023-02-07T18:27:18.780Z] 18:27:18 INFO - finishInit@resource://normandy/Normandy.jsm:178:11
[task 2023-02-07T18:27:18.780Z] 18:27:18 INFO - _execute_test@Z:\\task_167579070795972\\build\\tests\\xpcshell\\head.js:702:23
[task 2023-02-07T18:27:18.780Z] 18:27:18 INFO - @-e:1:1
[task 2023-02-07T18:27:18.780Z] 18:27:18 INFO - "
[task 2023-02-07T18:27:18.781Z] 18:27:18 INFO - "CONSOLE_MESSAGE: (info) UTM:SVC TimerManager:registerTimer called after profile-before-change notification. Ignoring timer registration for id: recipe-client-addon-run"
[task 2023-02-07T18:27:18.782Z] 18:27:18 INFO - PID 6688 | JavaScript error: , line 0: AbortError: A request was aborted, for example through a call to IDBTransaction.abort.
[task 2023-02-07T18:27:18.782Z] 18:27:18 INFO - "CONSOLE_MESSAGE: (error) [JavaScript Error: "AbortError: A request was aborted, for example through a call to IDBTransaction.abort."]"
[task 2023-02-07T18:27:18.782Z] 18:27:18 WARNING - TEST-UNEXPECTED-FAIL | toolkit/modules/tests/xpcshell/test_firstStartup.js | test_timeout - [test_timeout : 266] A promise chain failed to handle a rejection: A request was aborted, for example through a call to IDBTransaction.abort. - stack: (No stack available.)
[task 2023-02-07T18:27:18.783Z] 18:27:18 INFO - Rejection date: Tue Feb 07 2023 18:27:18 GMT+0000 (Greenwich Mean Time) - false == true
[task 2023-02-07T18:27:18.783Z] 18:27:18 INFO - resource://testing-common/PromiseTestUtils.sys.mjs:assertNoUncaughtRejections:266
[task 2023-02-07T18:27:18.783Z] 18:27:18 INFO - Z:\task_167579070795972\build\tests\xpcshell\head.js:_execute_test:711
[task 2023-02-07T18:27:18.783Z] 18:27:18 INFO - -e:null:1
[task 2023-02-07T18:27:18.783Z] 18:27:18 INFO - exiting test
[task 2023-02-07T18:27:18.784Z] 18:27:18 INFO - PID 6688 | JavaScript error: Z:\\task_167579070795972\\build\\tests\\xpcshell\\head.js, line 863: NS_ERROR_ABORT:
[task 2023-02-07T18:27:18.784Z] 18:27:18 INFO - <<<<<<<
[task 2023-02-07T18:27:18.784Z] 18:27:18 INFO - TEST-START | toolkit/components/antitracking/test/xpcshell/test_purge_trackers.js
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment 3•2 years ago
|
||
The Bugbug bot thinks this bug should belong to the 'Toolkit::Find Toolbar' component, and is moving the bug to that component. Please correct in case you think the bot is wrong.
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment 15•2 years ago
|
||
Hi Mike! Can you please take a look at this? This seems to have started with the landing of Bug 1841138.
This is now frequently failing with this failure line TEST-UNEXPECTED-FAIL | toolkit/modules/tests/xpcshell/test_firstStartup.js | test_timeout - [test_timeout : 78] false == true
Recent failure log: https://treeherder.mozilla.org/logviewer?job_id=421532251&repo=autoland&lineNumber=6568
Thank you!
Updated•2 years ago
|
Assignee | ||
Updated•2 years ago
|
Assignee | ||
Comment 16•2 years ago
|
||
This is because sometimes these timings will be less than 1 millisecond, and we
were coercing those fractional numbers to a uint which caused it to become 0.
This patch causes us to round up to the nearest uint instead.
It also adds the AppConstants.MOZ_NORMANDY condition for recording the timing
value for Normandy init, which I'd somehow missed the first time.
Comment 17•2 years ago
|
||
Comment 18•2 years ago
|
||
bugherder |
Comment hidden (Intermittent Failures Robot) |
Comment 20•2 years ago
|
||
Nice! I was hitting this frequently while working on something totally different. Time to rebase my patches. Thanks!
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Description
•