1657253 - Intermittent TEST-UNEXPECTED-TIMEOUT | toolkit/components/search/tests/xpcshell/searchconfigs/test_amazon.js | Test timed out

Status: RESOLVED FIXED

(Firefox :: Search, defect, P2)

Description

[Treeherder Bug Filer]

Filed by: btara [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer.html#?job_id=312065375&repo=mozilla-central
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/LE3HGe6MSSyw2fCzoKsLsQ/runs/0/artifacts/public/logs/live_backing.log

---

[task 2020-08-05T00:32:09.179Z] 00:32:09     INFO -  TEST-START | xpcshell.ini:toolkit/components/search/tests/xpcshell/searchconfigs/test_amazon.js
[task 2020-08-05T00:37:09.190Z] 00:37:09  WARNING -  TEST-UNEXPECTED-TIMEOUT | xpcshell.ini:toolkit/components/search/tests/xpcshell/searchconfigs/test_amazon.js | Test timed out
[task 2020-08-05T00:37:09.190Z] 00:37:09     INFO -  TEST-INFO took 300000ms
[task 2020-08-05T00:37:09.190Z] 00:37:09     INFO -  >>>>>>>
[task 2020-08-05T00:37:09.190Z] 00:37:09     INFO -  PID 24426 | [CodeCoverage] Setting handlers for process 24426.
[task 2020-08-05T00:37:09.190Z] 00:37:09     INFO -  (xpcshell/head.js) | test MAIN run_test pending (1)
[task 2020-08-05T00:37:09.190Z] 00:37:09     INFO -  (xpcshell/head.js) | test run_next_test 0 pending (2)
[task 2020-08-05T00:37:09.190Z] 00:37:09     INFO -  (xpcshell/head.js) | test MAIN run_test finished (2)
[task 2020-08-05T00:37:09.190Z] 00:37:09     INFO -  running event loop
[task 2020-08-05T00:37:09.190Z] 00:37:09     INFO -  xpcshell.ini:toolkit/components/search/tests/xpcshell/searchconfigs/test_amazon.js | Starting setup
[task 2020-08-05T00:37:09.190Z] 00:37:09     INFO -  (xpcshell/head.js) | test setup pending (2)
[task 2020-08-05T00:37:09.190Z] 00:37:09     INFO -  "CONSOLE_MESSAGE: (info) 1596587529822	addons.manager	DEBUG	Application has been upgraded"
[task 2020-08-05T00:37:09.191Z] 00:37:09     INFO -  "CONSOLE_MESSAGE: (info) 1596587529823	addons.manager	DEBUG	Loaded provider scope for resource://gre/modules/addons/XPIProvider.jsm: ["XPIProvider", "XPIInternal"]"
[task 2020-08-05T00:37:09.191Z] 00:37:09     INFO -  "CONSOLE_MESSAGE: (info) 1596587529840	addons.manager	DEBUG	Loaded provider scope for resource://gre/modules/addons/GMPProvider.jsm"
[task 2020-08-05T00:37:09.191Z] 00:37:09     INFO -  "CONSOLE_MESSAGE: (info) 1596587529848	addons.manager	DEBUG	Loaded provider scope for resource://gre/modules/addons/PluginProvider.jsm"
[task 2020-08-05T00:37:09.191Z] 00:37:09     INFO -  "CONSOLE_MESSAGE: (info) 1596587529848	addons.manager	DEBUG	Starting provider: XPIProvider"
[task 2020-08-05T00:37:09.192Z] 00:37:09     INFO -  "CONSOLE_MESSAGE: (info) 1596587529849	addons.xpi	DEBUG	startup"
[task 2020-08-05T00:37:09.192Z] 00:37:09     INFO -  "CONSOLE_MESSAGE: (info) 1596587529850	addons.xpi	INFO	SystemAddonLocation directory is missing"
[task 2020-08-05T00:37:09.192Z] 00:37:09     INFO -  "CONSOLE_MESSAGE: (info) 1596587529895	addons.xpi	INFO	Removing all system add-on upgrades."
[task 2020-08-05T00:37:09.193Z] 00:37:09     INFO -  "CONSOLE_MESSAGE: (info) 1596587529896	addons.xpi	DEBUG	checkForChanges"
[task 2020-08-05T00:37:09.194Z] 00:37:09     INFO -  "CONSOLE_MESSAGE: (info) 1596587529896	addons.xpi	DEBUG	Loaded add-on state: ${}"
[task 2020-08-05T00:37:09.194Z] 00:37:09     INFO -  "CONSOLE_MESSAGE: (info) 1596587529899	addons.xpi	DEBUG	scanForChanges changed: false, state: {}"
[task 2020-08-05T00:37:09.195Z] 00:37:09     INFO -  "CONSOLE_MESSAGE: (info) 1596587529901	addons.xpi	DEBUG	Empty XPI database, setting schema version preference to 32"
[task 2020-08-05T00:37:09.195Z] 00:37:09     INFO -  "CONSOLE_MESSAGE: (info) 1596587529901	addons.xpi	DEBUG	No changes found"
[task 2020-08-05T00:37:09.195Z] 00:37:09     INFO -  "CONSOLE_MESSAGE: (info) 1596587529946	addons.xpi-utils	DEBUG	Synchronously loading the add-ons database"
[task 2020-08-05T00:37:09.195Z] 00:37:09     INFO -  "CONSOLE_MESSAGE: (info) 1596587529947	addons.xpi-utils	DEBUG	Starting async load of XPI database /tmp/xpc-profile-5B4obJ/extensions.json"
[task 2020-08-05T00:37:09.195Z] 00:37:09     INFO -  (xpcshell/head.js) | test run_next_test 0 finished (2)
[task 2020-08-05T00:37:09.195Z] 00:37:09     INFO -  "CONSOLE_MESSAGE: (info) 1596587530060	addons.xpi-utils	DEBUG	Rebuilding XPI database with no extensions"
[task 2020-08-05T00:37:09.196Z] 00:37:09     INFO -  "CONSOLE_MESSAGE: (info) 1596587530067	addons.manager	DEBUG	Registering shutdown blocker for XPIProvider"
[task 2020-08-05T00:37:09.196Z] 00:37:09     INFO -  "CONSOLE_MESSAGE: (info) 1596587530067	addons.manager	DEBUG	Provider finished startup: XPIProvider"
[task 2020-08-05T00:37:09.196Z] 00:37:09     INFO -  "CONSOLE_MESSAGE: (info) 1596587530067	addons.manager	DEBUG	Starting provider: PluginProvider"
[task 2020-08-05T00:37:09.196Z] 00:37:09     INFO -  "CONSOLE_MESSAGE: (info) 1596587530067	addons.manager	DEBUG	Registering shutdown blocker for PluginProvider"
[task 2020-08-05T00:37:09.197Z] 00:37:09     INFO -  "CONSOLE_MESSAGE: (info) 1596587530068	addons.manager	DEBUG	Provider finished startup: PluginProvider"
[task 2020-08-05T00:37:09.197Z] 00:37:09     INFO -  "CONSOLE_MESSAGE: (info) 1596587530068	addons.manager	DEBUG	Completed startup sequence"
[task 2020-08-05T00:37:09.197Z] 00:37:09     INFO -  PID 24426 | console.error: SearchCache: "_readCacheFile: Error reading cache file:" (new Error("", "(unknown module)"))
[task 2020-08-05T00:37:09.197Z] 00:37:09     INFO -  "CONSOLE_MESSAGE: (info) 1596587530678	addons.xpi-utils	DEBUG	Make addon app-builtin:[e-mail] visible"
[task 2020-08-05T00:37:09.197Z] 00:37:09     INFO -  "CONSOLE_MESSAGE: (info) 1596587530678	addons.xpi	DEBUG	XPIStates adding add-on [e-mail] in {"addons":{},"staged":{}}: null"
...
[task 2020-08-05T00:37:09.215Z] 00:37:09     INFO -  "CONSOLE_MESSAGE: (info) 1596587531022	addons.xpi	DEBUG	Calling bootstrap method startup on [e-mail] version 1.0"
[task 2020-08-05T00:37:09.215Z] 00:37:09     INFO -  TEST-PASS | xpcshell.ini:toolkit/components/search/tests/xpcshell/searchconfigs/test_amazon.js | setup - [setup : 1] Should have correctly initialized the search service - true == true
[task 2020-08-05T00:37:09.215Z] 00:37:09     INFO -  (xpcshell/head.js) | test run_next_test 1 pending (2)
[task 2020-08-05T00:37:09.215Z] 00:37:09     INFO -  (xpcshell/head.js) | test setup finished (2)
[task 2020-08-05T00:37:09.215Z] 00:37:09     INFO -  xpcshell.ini:toolkit/components/search/tests/xpcshell/searchconfigs/test_amazon.js | Starting test_searchConfig_amazon
[task 2020-08-05T00:37:09.215Z] 00:37:09     INFO -  (xpcshell/head.js) | test test_searchConfig_amazon pending (2)
[task 2020-08-05T00:37:09.215Z] 00:37:09     INFO -  (xpcshell/head.js) | test run_next_test 1 finished (2)
[task 2020-08-05T00:37:09.215Z] 00:37:09     INFO -  "CONSOLE_MESSAGE: (info) 1596587531178	addons.xpi-utils	DEBUG	Make addon app-builtin:[e-mail] visible"
[task 2020-08-05T00:37:09.215Z] 00:37:09     INFO -  "CONSOLE_MESSAGE: (info) 1596587531178	addons.xpi	DEBUG	XPIStates adding add-on [e-mail] in {"addons":{"[e-mail]":{"dependencies":[],"enabled":true,"loader":null,"path":null,"rootURI":"resource://search-extensions/google/","runInSafeMode":true,"signedDate":null,"telemetryKey":"google%40search.mozilla.org:1.0","version":"1.0"},"[e-mail]":{"dependencies":[],"enabled":true,"loader":null,"path":null,"rootURI":"resource://search-extensions/amazondotcom/","runInSafeMode":true,"signedDate":null,"telemetryKey":"amazondotcom%40search.mozilla.org:1.1","version":"1.1"},"[e-mail]":{"dependencies":[],"enabled":true,"loader":null,"path":null,"rootURI":"resource://search-extensions/wikipedia/","runInSafeMode":true,"signedDate":null,"telemetryKey":"wikipedia%40search.mozilla.org:1.0","version":"1.0"},"[e-mail]":{"dependencies":[],"enabled":true,"loader":null,"path":null,"rootURI":"resource://search-extensions/bing/","runInSafeMode":true,"signedDate":null,"telemetryKey":"bing%40search.mozilla.org:1.1","version":"1.1"},"[e-mail]":{"dependencies":[],"enabled":true,"loader":null,"path":null,"rootURI":"resource://search-extensions/ddg/","runInSafeMode":true,"signedDate":null,"telemetryKey":"ddg%40search.mozilla.org:1.0","version":"1.0"}},"staged":{}}: null"
...
[task 2020-08-05T00:37:09.772Z] 00:37:09     INFO -  "CONSOLE_MESSAGE: (info) 1596587535302	addons.xpi	DEBUG	Calling bootstrap method startup on [e-mail] version 1.0"
[task 2020-08-05T00:37:09.772Z] 00:37:09     INFO -  <<<<<<<
[task 2020-08-05T00:37:09.772Z] 00:37:09     INFO -  xpcshell return code: None
[task 2020-08-05T00:37:09.772Z] 00:37:09     INFO -  xpcshell.ini:toolkit/components/search/tests/xpcshell/searchconfigs/test_amazon.js | Process still running after test!
[task 2020-08-05T00:37:09.788Z] 00:37:09     INFO -  TEST-START | xpcshell.ini:toolkit/components/search/tests/xpcshell/searchconfigs/test_baidu.js
[task 2020-08-05T00:42:07.878Z] 00:42:07     INFO -  TEST-PASS | xpcshell.ini:toolkit/components/search/tests/xpcshell/searchconfigs/test_baidu.js | took 298086ms
[task 2020-08-05T00:42:07.879Z] 00:42:07     INFO -  TEST-START | xpcshell.ini:toolkit/components/search/tests/xpcshell/searchconfigs/test_bing.js
[task 2020-08-05T00:47:07.889Z] 00:47:07  WARNING -  TEST-UNEXPECTED-TIMEOUT | xpcshell.ini:toolkit/components/search/tests/xpcshell/searchconfigs/test_bing.js | Test timed out
[task 2020-08-05T00:47:07.889Z] 00:47:07     INFO -  TEST-INFO took 300000ms
[task 2020-08-05T00:47:07.890Z] 00:47:07     INFO -  >>>>>>>
[task 2020-08-05T00:47:07.890Z] 00:47:07     INFO -  PID 24495 | [CodeCoverage] Setting handlers for process 24495.
[task 2020-08-05T00:47:07.890Z] 00:47:07     INFO -  (xpcshell/head.js) | test MAIN run_test pending (1)
[task 2020-08-05T00:47:07.891Z] 00:47:07     INFO -  (xpcshell/head.js) | test run_next_test 0 pending (2)
[task 2020-08-05T00:47:07.891Z] 00:47:07     INFO -  (xpcshell/head.js) | test MAIN run_test finished (2)
[task 2020-08-05T00:47:07.891Z] 00:47:07     INFO -  running event loop
[task 2020-08-05T00:47:07.891Z] 00:47:07     INFO -  xpcshell.ini:toolkit/components/search/tests/xpcshell/searchconfigs/test_bing.js | Starting setup
[task 2020-08-05T00:47:07.892Z] 00:47:07     INFO -  (xpcshell/head.js) | test setup pending (2)
[task 2020-08-05T00:47:07.892Z] 00:47:07     INFO -  "CONSOLE_MESSAGE: (info) 1596588128517	addons.manager	DEBUG	Application has been upgraded"
[task 2020-08-05T00:47:07.892Z] 00:47:07     INFO -  "CONSOLE_MESSAGE: (info) 1596588128518	addons.manager	DEBUG	Loaded provider scope for resource://gre/modules/addons/XPIProvider.jsm: ["XPIProvider", "XPIInternal"]"
[task 2020-08-05T00:47:07.893Z] 00:47:07     INFO -  "CONSOLE_MESSAGE: (info) 1596588128535	addons.manager	DEBUG	Loaded provider scope for resource://gre/modules/addons/GMPProvider.jsm"
[task 2020-08-05T00:47:07.893Z] 00:47:07     INFO -  "CONSOLE_MESSAGE: (info) 1596588128542	addons.manager	DEBUG	Loaded provider scope for resource://gre/modules/addons/PluginProvider.jsm"
[task 2020-08-05T00:47:07.893Z] 00:47:07     INFO -  "CONSOLE_MESSAGE: (info) 1596588128543	addons.manager	DEBUG	Starting provider: XPIProvider"
...
...
...

Comment 1

[Mark Banner (:standard8)]

Taking, I think it is possibly worth having these as part of code coverage for now. We just need to bump the timeout for a little bit.

Comment 3

[Mark Banner (:standard8)]

Attachment: Bug 1657253 - Allow a little longer for searchconfig tests to complete. r?daleharvey!

Comment 4

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/0be468d23dee
Allow a little longer for searchconfig tests to complete. r=daleharvey

Comment 5

[Cristian Brindusan [:cbrindusan]]

https://hg.mozilla.org/mozilla-central/rev/0be468d23dee

Comment 6

[Intermittent Failures Robot]

6 failures in 4618 pushes (0.001 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-central: 6

Platform breakdown:

• linux1804-64-ccov: 6

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1657253&startday=2020-08-03&endday=2020-08-09&tree=all