Closed Bug 1756541 Opened 3 years ago Closed 3 years ago

Intermittent [tier 2] TEST-UNEXPECTED-TIMEOUT | toolkit/components/extensions/test/xpcshell/test_proxy_failover.js | Test timed out

Categories

(WebExtensions :: General, defect, P5)

defect

Tracking

(Not tracked)

RESOLVED INCOMPLETE

People

(Reporter: intermittent-bug-filer, Unassigned)

Details

(Keywords: intermittent-failure)

Filed by: ctuns [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer?job_id=368699260&repo=autoland
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/BewJUFScT9iJdtdtaDcggw/runs/0/artifacts/public/logs/live_backing.log


[task 2022-02-22T07:43:20.048Z] 07:43:20     INFO -  TEST-START | xpcshell-remote.ini:toolkit/components/extensions/test/xpcshell/test_proxy_failover.js
[task 2022-02-22T07:48:20.051Z] 07:48:20  WARNING -  TEST-UNEXPECTED-TIMEOUT | xpcshell-remote.ini:toolkit/components/extensions/test/xpcshell/test_proxy_failover.js | Test timed out
[task 2022-02-22T07:48:20.051Z] 07:48:20     INFO -  TEST-INFO took 300000ms
[task 2022-02-22T07:48:20.052Z] 07:48:20     INFO -  >>>>>>>
[task 2022-02-22T07:48:20.059Z] 07:48:20     INFO -  PID 1958 | [Parent 1958, Main Thread] WARNING: Couldn't get the user appdata directory. Crash events may not be produced.: file /builds/worker/checkouts/gecko/toolkit/crashreporter/nsExceptionHandler.cpp:2965
[task 2022-02-22T07:48:20.060Z] 07:48:20     INFO -  (xpcshell/head.js) | test MAIN run_test pending (1)
[task 2022-02-22T07:48:20.060Z] 07:48:20     INFO -  (xpcshell/head.js) | test run_next_test 0 pending (2)
[task 2022-02-22T07:48:20.061Z] 07:48:20     INFO -  (xpcshell/head.js) | test MAIN run_test finished (2)
[task 2022-02-22T07:48:20.061Z] 07:48:20     INFO -  running event loop
[task 2022-02-22T07:48:20.062Z] 07:48:20     INFO -  xpcshell-remote.ini:toolkit/components/extensions/test/xpcshell/test_proxy_failover.js | Starting check_remote
[task 2022-02-22T07:48:20.062Z] 07:48:20     INFO -  (xpcshell/head.js) | test check_remote pending (2)
[task 2022-02-22T07:48:20.063Z] 07:48:20     INFO -  TEST-PASS | xpcshell-remote.ini:toolkit/components/extensions/test/xpcshell/test_proxy_failover.js | check_remote - [check_remote : 1] useRemoteWebExtensions matches - true == true
[task 2022-02-22T07:48:20.063Z] 07:48:20     INFO -  TEST-PASS | xpcshell-remote.ini:toolkit/components/extensions/test/xpcshell/test_proxy_failover.js | check_remote - [check_remote : 1] testing from extension process - false == false
[task 2022-02-22T07:48:20.063Z] 07:48:20     INFO -  (xpcshell/head.js) | test run_next_test 0 finished (2)
[task 2022-02-22T07:48:20.064Z] 07:48:20     INFO -  (xpcshell/head.js) | test run_next_test 1 pending (2)
[task 2022-02-22T07:48:20.065Z] 07:48:20     INFO -  (xpcshell/head.js) | test check_remote finished (2)
[task 2022-02-22T07:48:20.065Z] 07:48:20     INFO -  xpcshell-remote.ini:toolkit/components/extensions/test/xpcshell/test_proxy_failover.js | Starting setup
[task 2022-02-22T07:48:20.066Z] 07:48:20     INFO -  (xpcshell/head.js) | test setup pending (2)
[task 2022-02-22T07:48:20.066Z] 07:48:20     INFO -  (xpcshell/head.js) | test run_next_test 1 finished (2)
[task 2022-02-22T07:48:20.066Z] 07:48:20     INFO -  "CONSOLE_MESSAGE: (info) 1645515800360	addons.manager	DEBUG	Application has been upgraded"
[task 2022-02-22T07:48:20.067Z] 07:48:20     INFO -  "CONSOLE_MESSAGE: (info) 1645515800360	addons.manager	DEBUG	Loaded provider scope for resource://gre/modules/addons/XPIProvider.jsm: ["XPIProvider", "XPIInternal"]"
[task 2022-02-22T07:48:20.067Z] 07:48:20     INFO -  "CONSOLE_MESSAGE: (info) 1645515800365	addons.manager	DEBUG	Loaded provider scope for resource://gre/modules/addons/GMPProvider.jsm"
[task 2022-02-22T07:48:20.068Z] 07:48:20     INFO -  "CONSOLE_MESSAGE: (info) 1645515800366	addons.manager	DEBUG	Starting provider: XPIProvider"
[task 2022-02-22T07:48:20.068Z] 07:48:20     INFO -  "CONSOLE_MESSAGE: (info) 1645515800366	addons.xpi	DEBUG	startup"
[task 2022-02-22T07:48:20.069Z] 07:48:20     INFO -  "CONSOLE_MESSAGE: (info) 1645515800366	addons.xpi	DEBUG	List of built-in add-ons is missing or invalid.: [Exception... "Component returned failure code: 0xc1f30001 (NS_ERROR_NOT_INITIALIZED) [nsIXPCComponents_Utils.readUTF8URI]"  nsresult: "0xc1f30001 (NS_ERROR_NOT_INITIALIZED)"  location: "JS frame :: resource://gre/modules/addons/XPIProvider.jsm :: startup :: line 2456"  data: no] Stack trace: startup()@resource://gre/modules/addons/XPIProvider.jsm:2456
[task 2022-02-22T07:48:20.070Z] 07:48:20     INFO -  callProvider()@resource://gre/modules/AddonManager.jsm:222
[task 2022-02-22T07:48:20.070Z] 07:48:20     INFO -  _startProvider()@resource://gre/modules/AddonManager.jsm:528
[task 2022-02-22T07:48:20.070Z] 07:48:20     INFO -  startup()@resource://gre/modules/AddonManager.jsm:755
[task 2022-02-22T07:48:20.071Z] 07:48:20     INFO -  startup()@resource://gre/modules/AddonManager.jsm:3426
[task 2022-02-22T07:48:20.071Z] 07:48:20     INFO -  observe()@resource://gre/modules/addonManager.js:78
[task 2022-02-22T07:48:20.072Z] 07:48:20     INFO -  promiseStartupManager()@resource://testing-common/AddonTestUtils.jsm:900
[task 2022-02-22T07:48:20.072Z] 07:48:20     INFO -  setup()@/builds/worker/workspace/build/tests/xpcshell/tests/toolkit/components/extensions/test/xpcshell/test_proxy_failover.js:90
[task 2022-02-22T07:48:20.073Z] 07:48:20     INFO -  _run_next_test/<()@/builds/worker/workspace/build/tests/xpcshell/head.js:1727
[task 2022-02-22T07:48:20.073Z] 07:48:20     INFO -  _run_next_test()@/builds/worker/workspace/build/tests/xpcshell/head.js:1727
[task 2022-02-22T07:48:20.073Z] 07:48:20     INFO -  run()@/builds/worker/workspace/build/tests/xpcshell/head.js:819
[task 2022-02-22T07:48:20.074Z] 07:48:20     INFO -  _do_main()@/builds/worker/workspace/build/tests/xpcshell/head.js:240
[task 2022-02-22T07:48:20.074Z] 07:48:20     INFO -  _execute_test()@/builds/worker/workspace/build/tests/xpcshell/head.js:604
[task 2022-02-22T07:48:20.075Z] 07:48:20     INFO -  -e:1"
[task 2022-02-22T07:48:20.075Z] 07:48:20     INFO -  "CONSOLE_MESSAGE: (info) 1645515800370	addons.xpi	INFO	SystemAddonLocation directory is missing"
[task 2022-02-22T07:48:20.076Z] 07:48:20     INFO -  "CONSOLE_MESSAGE: (info) 1645515800386	addons.xpi	INFO	Removing all system add-on upgrades."
[task 2022-02-22T07:48:20.076Z] 07:48:20     INFO -  "CONSOLE_MESSAGE: (info) 1645515800387	addons.xpi	DEBUG	checkForChanges"
[task 2022-02-22T07:48:20.077Z] 07:48:20     INFO -  "CONSOLE_MESSAGE: (info) 1645515800388	addons.xpi	DEBUG	Loaded add-on state: ${}"
[task 2022-02-22T07:48:20.077Z] 07:48:20     INFO -  "CONSOLE_MESSAGE: (info) 1645515800390	addons.xpi	DEBUG	scanForChanges changed: false, state: {}"
[task 2022-02-22T07:48:20.078Z] 07:48:20     INFO -  "CONSOLE_MESSAGE: (info) 1645515800390	addons.xpi	DEBUG	Empty XPI database, setting schema version preference to 35"
[task 2022-02-22T07:48:20.079Z] 07:48:20     INFO -  "CONSOLE_MESSAGE: (info) 1645515800390	addons.xpi	DEBUG	No changes found"
[task 2022-02-22T07:48:20.080Z] 07:48:20     INFO -  "CONSOLE_MESSAGE: (info) 1645515800398	addons.manager	DEBUG	Registering shutdown blocker for XPIProvider"
[task 2022-02-22T07:48:20.080Z] 07:48:20     INFO -  "CONSOLE_MESSAGE: (info) 1645515800398	addons.manager	DEBUG	Provider finished startup: XPIProvider"
[task 2022-02-22T07:48:20.081Z] 07:48:20     INFO -  "CONSOLE_MESSAGE: (info) 1645515800399	addons.manager	DEBUG	Completed startup sequence"
[task 2022-02-22T07:48:20.081Z] 07:48:20     INFO -  (xpcshell/head.js) | test run_next_test 2 pending (2)
[task 2022-02-22T07:48:20.082Z] 07:48:20     INFO -  (xpcshell/head.js) | test setup finished (2)
[task 2022-02-22T07:48:20.082Z] 07:48:20     INFO -  xpcshell-remote.ini:toolkit/components/extensions/test/xpcshell/test_proxy_failover.js | Starting test_failover_content_direct
[task 2022-02-22T07:48:20.083Z] 07:48:20     INFO -  (xpcshell/head.js) | test test_failover_content_direct pending (2)
[task 2022-02-22T07:48:20.083Z] 07:48:20     INFO -  PID 1958 | [Parent 1958, Main Thread] WARNING: GLX_swap_control unsupported, ASAP mode may still block on buffer swaps.: file /builds/worker/checkouts/gecko/gfx/gl/GLContextProviderGLX.cpp:214
[task 2022-02-22T07:48:20.084Z] 07:48:20     INFO -  (xpcshell/head.js) | test run_next_test 2 finished (2)
[task 2022-02-22T07:48:20.084Z] 07:48:20     INFO -  PID 1958 | [Parent 1958, Main Thread] WARNING: NS_ENSURE_TRUE(rootFrame) failed: file /builds/worker/checkouts/gecko/dom/base/nsGlobalWindowOuter.cpp:4161
[task 2022-02-22T07:48:20.084Z] 07:48:20     INFO -  PID 1958 | [Parent 1958, Main Thread] WARNING: Couldn't get the user appdata directory, crash dumps will go in an unusual location: file /builds/worker/checkouts/gecko/toolkit/crashreporter/nsExceptionHandler.cpp:3024
[task 2022-02-22T07:48:20.085Z] 07:48:20     INFO -  PID 1958 | [Parent 1958, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, NS_ERROR_INVALID_ARG) failed with result 0x80520012 (NS_ERROR_FILE_NOT_FOUND): file /builds/worker/checkouts/gecko/intl/l10n/L10nRegistry.cpp:394
[task 2022-02-22T07:48:20.085Z] 07:48:20     INFO -  PID 1958 | [Parent 1958, GMPThread] WARNING: Failed to delete GMP storage directory: file /builds/worker/checkouts/gecko/dom/media/gmp/GMPServiceParent.cpp:1719
[task 2022-02-22T07:48:20.086Z] 07:48:20     INFO -  PID 1958 | [Child 1996, Main Thread] WARNING: could not set real-time limit in CubebUtils::InitLibrary: file /builds/worker/checkouts/gecko/dom/media/CubebUtils.cpp:693
[task 2022-02-22T07:48:20.087Z] 07:48:20     INFO -  "CONSOLE_MESSAGE: (info) 1645515800688	addons.manager	DEBUG	Starting provider: GMPProvider"
[task 2022-02-22T07:48:20.087Z] 07:48:20     INFO -  "CONSOLE_MESSAGE: (info) 1645515800692	addons.manager	DEBUG	Registering shutdown blocker for GMPProvider"
[task 2022-02-22T07:48:20.088Z] 07:48:20     INFO -  "CONSOLE_MESSAGE: (info) 1645515800693	addons.manager	DEBUG	Provider finished startup: GMPProvider"
[task 2022-02-22T07:48:20.089Z] 07:48:20     INFO -  PID 1958 | [Child 1996, Main Thread] WARNING: Fallback to BasicLayerManager: file /builds/worker/checkouts/gecko/dom/ipc/BrowserChild.cpp:2833
[task 2022-02-22T07:48:20.090Z] 07:48:20     INFO -  PID 1958 | [Parent 1958, Main Thread] WARNING: NS_ENSURE_TRUE(LoadIsPending()) failed: file /builds/worker/checkouts/gecko/netwerk/protocol/http/nsHttpChannel.cpp:5591
[task 2022-02-22T07:48:20.090Z] 07:48:20     INFO -  PID 1958 | [Child 1996, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, kKnownEsrVersion) failed with result 0x80070057 (NS_ERROR_ILLEGAL_VALUE): file /builds/worker/checkouts/gecko/toolkit/components/resistfingerprinting/nsRFPService.cpp:570
[task 2022-02-22T07:48:20.091Z] 07:48:20     INFO -  PID 1958 | [Parent 1958, Main Thread] WARNING: NS_ENSURE_TRUE(mSuspendCount > 0) failed: file /builds/worker/checkouts/gecko/netwerk/protocol/http/nsHttpChannel.cpp:5616
[task 2022-02-22T07:48:20.095Z] 07:48:20     INFO -  PID 1958 | [2022-02-22T07:43:20Z WARN  rkv::backend::impl_safe::environment] `load_ratio()` is irrelevant for this storage backend.
[task 2022-02-22T07:48:20.096Z] 07:48:20     INFO -  "CONSOLE_MESSAGE: (error) [JavaScript Error: "NetworkError: Network request failed" {file: "resource://services-settings/Utils.jsm" line: 137}]
[task 2022-02-22T07:48:20.096Z] 07:48:20     INFO -  fetch/</request.onerror@resource://services-settings/Utils.jsm:137:26
[task 2022-02-22T07:48:20.097Z] 07:48:20     INFO -  _do_main@/builds/worker/workspace/build/tests/xpcshell/head.js:240:6
[task 2022-02-22T07:48:20.097Z] 07:48:20     INFO -  _execute_test@/builds/worker/workspace/build/tests/xpcshell/head.js:604:5
[task 2022-02-22T07:48:20.097Z] 07:48:20     INFO -  @-e:1:1
[task 2022-02-22T07:48:20.098Z] 07:48:20     INFO -  "
[task 2022-02-22T07:48:20.099Z] 07:48:20     INFO -  "CONSOLE_MESSAGE: (error) [JavaScript Error: "NetworkError: Network request failed" {file: "resource://services-settings/Utils.jsm" line: 137}]
[task 2022-02-22T07:48:20.099Z] 07:48:20     INFO -  fetch/</request.onerror@resource://services-settings/Utils.jsm:137:26
[task 2022-02-22T07:48:20.100Z] 07:48:20     INFO -  _do_main@/builds/worker/workspace/build/tests/xpcshell/head.js:240:6
[task 2022-02-22T07:48:20.100Z] 07:48:20     INFO -  _execute_test@/builds/worker/workspace/build/tests/xpcshell/head.js:604:5
[task 2022-02-22T07:48:20.103Z] 07:48:20     INFO -  @-e:1:1
[task 2022-02-22T07:48:20.103Z] 07:48:20     INFO -  "
[task 2022-02-22T07:48:20.103Z] 07:48:20     INFO -  "CONSOLE_MESSAGE: (info) 1645515801413	addons.xpi-utils	DEBUG	Starting async load of XPI database /tmp/xpc-profile-nsl4hxyv/extensions.json"
[task 2022-02-22T07:48:20.104Z] 07:48:20     INFO -  "CONSOLE_MESSAGE: (info) 1645515801415	addons.xpi-utils	DEBUG	Rebuilding XPI database with no extensions"
[task 2022-02-22T07:48:20.104Z] 07:48:20     INFO -  "CONSOLE_MESSAGE: (info) 1645515801415	addons.xpi-utils	DEBUG	Make addon app-temporary:{b830f4ff-8b51-4aaa-a21f-dbd78811e9a9} visible"
[task 2022-02-22T07:48:20.105Z] 07:48:20     INFO -  "CONSOLE_MESSAGE: (info) 1645515801416	addons.xpi	DEBUG	XPIStates adding add-on {b830f4ff-8b51-4aaa-a21f-dbd78811e9a9} in {}: /tmp/xpc-profile-nsl4hxyv/temp/generated-extension.xpi"
[task 2022-02-22T07:48:20.106Z] 07:48:20     INFO -  "CONSOLE_MESSAGE: (info) 1645515801418	addons.xpi	DEBUG	Updating XPIState for {"id":"{b830f4ff-8b51-4aaa-a21f-dbd78811e9a9}","syncGUID":"{1af83b68-3667-4fbe-89e2-85008e3bb464}","version":"1.0","type":"extension","loader":null,"updateURL":null,"installOrigins":null,"manifestVersion":2,"optionsURL":null,"optionsType":null,"optionsBrowserStyle":true,"aboutURL":null,"defaultLocale":{"name":"Generated extension","creator":null,"developers":null,"translators":null,"contributors":null},"visible":true,"active":true,"userDisabled":false,"appDisabled":false,"embedderDisabled":false,"installDate":1645515801415,"applyBackgroundUpdates":1,"path":"/tmp/xpc-profile-nsl4hxyv/temp/generated-extension.xpi","skinnable":false,"sourceURI":null,"releaseNotesURI":null,"softDisabled":false,"foreignInstall":false,"strictCompatibility":true,"locales":[],"targetApplications":[{"id":"toolkit@mozilla.org","minVersion":null,"maxVersion":null}],"targetPlatforms":[],"signedState":4,"signedDate":null,"seen":true,"dependencies":[],"incognito":"spanning","userPermissions":{"permissions":["proxy"],"origins":["<all_urls>"]},"optionalPermissions":{"permissions":[],"origins":[]},"icons":{},"iconURL":null,"blocklistState":0,"blocklistURL":null,"startupData":null,"hidden":false,"installTelemetryInfo":null,"recommendationState":null,"rootURI":"jar:file:///tmp/xpc-profile-nsl4hxyv/temp/generated-extension.xpi!/","location":"app-temporary"}"
[task 2022-02-22T07:48:20.106Z] 07:48:20     INFO -  "CONSOLE_MESSAGE: (info) 1645515801419	addons.xpi	DEBUG	Loading bootstrap scope from jar:file:///tmp/xpc-profile-nsl4hxyv/temp/generated-extension.xpi!/"
[task 2022-02-22T07:48:20.107Z] 07:48:20     INFO -  "CONSOLE_MESSAGE: (info) 1645515801419	addons.xpi	DEBUG	Calling bootstrap method install on {b830f4ff-8b51-4aaa-a21f-dbd78811e9a9} version 1.0"
[task 2022-02-22T07:48:20.108Z] 07:48:20     INFO -  "CONSOLE_MESSAGE: (info) 1645515801419	addons.xpi	DEBUG	Calling bootstrap method startup on {b830f4ff-8b51-4aaa-a21f-dbd78811e9a9} version 1.0"
[task 2022-02-22T07:48:20.109Z] 07:48:20     INFO -  "Extension attached"
[task 2022-02-22T07:48:20.111Z] 07:48:20     INFO -  PID 1958 | [Parent 1958, Main Thread] WARNING: NS_ENSURE_TRUE(presShell) failed: file /builds/worker/checkouts/gecko/dom/base/nsGlobalWindowOuter.cpp:4159
[task 2022-02-22T07:48:20.111Z] 07:48:20     INFO -  "CONSOLE_MESSAGE: (info) 1645515801502	addons.xpi-utils	DEBUG	XPI Database saved, setting schema version preference to 35"
[task 2022-02-22T07:48:20.112Z] 07:48:20     INFO -  PID 1958 | [Child 2060, Main Thread] WARNING: could not set real-time limit in CubebUtils::InitLibrary: file /builds/worker/checkouts/gecko/dom/media/CubebUtils.cpp:693
[task 2022-02-22T07:48:20.112Z] 07:48:20     INFO -  PID 1958 | [Child 2060, Main Thread] WARNING: Fallback to BasicLayerManager: file /builds/worker/checkouts/gecko/dom/ipc/BrowserChild.cpp:2833
[task 2022-02-22T07:48:20.112Z] 07:48:20     INFO -  PID 1958 | [Child 2060, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, kKnownEsrVersion) failed with result 0x80070057 (NS_ERROR_ILLEGAL_VALUE): file /builds/worker/checkouts/gecko/toolkit/components/resistfingerprinting/nsRFPService.cpp:570
[task 2022-02-22T07:48:20.112Z] 07:48:20     INFO -  PID 1958 | [Child 2085, Main Thread] WARNING: could not set real-time limit in CubebUtils::InitLibrary: file /builds/worker/checkouts/gecko/dom/media/CubebUtils.cpp:693
[task 2022-02-22T07:48:20.112Z] 07:48:20     INFO -  PID 1958 | [Child 2085, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, kKnownEsrVersion) failed with result 0x80070057 (NS_ERROR_ILLEGAL_VALUE): file /builds/worker/checkouts/gecko/toolkit/components/resistfingerprinting/nsRFPService.cpp:570
[task 2022-02-22T07:48:20.112Z] 07:48:20     INFO -  "CONSOLE_MESSAGE: (info) 1645515801839	addons.xpi	DEBUG	Install of temporary addon in /tmp/xpc-profile-nsl4hxyv/temp/generated-extension.xpi completed."
[task 2022-02-22T07:48:20.113Z] 07:48:20     INFO -  PID 1958 | [Parent 1958, Main Thread] WARNING: NS_ENSURE_TRUE(rootFrame) failed: file /builds/worker/checkouts/gecko/dom/base/nsGlobalWindowOuter.cpp:4161
[task 2022-02-22T07:48:20.113Z] 07:48:20     INFO -  PID 1958 | [Child 2085, Main Thread] WARNING: Fallback to BasicLayerManager: file /builds/worker/checkouts/gecko/dom/ipc/BrowserChild.cpp:2833
[task 2022-02-22T07:48:20.113Z] 07:48:20     INFO -  PID 1958 | [Parent 1958, Main Thread] WARNING: NS_ENSURE_TRUE(LoadIsPending()) failed: file /builds/worker/checkouts/gecko/netwerk/protocol/http/nsHttpChannel.cpp:5591
[task 2022-02-22T07:48:20.113Z] 07:48:20     INFO -  PID 1958 | [Parent 1958, Main Thread] WARNING: NS_ENSURE_TRUE(mSuspendCount > 0) failed: file /builds/worker/checkouts/gecko/netwerk/protocol/http/nsHttpChannel.cpp:5616
[task 2022-02-22T07:48:20.113Z] 07:48:20     INFO -  TEST-PASS | xpcshell-remote.ini:toolkit/components/extensions/test/xpcshell/test_proxy_failover.js | test_failover_content_direct - [test_failover_content_direct : 136] fetch completed - "ok!" == "ok!"
Status: NEW → RESOLVED
Closed: 3 years ago
Resolution: --- → INCOMPLETE
You need to log in before you can comment on or make changes to this bug.