Closed Bug 1904919 Opened 1 year ago Closed 1 year ago

Intermittent [tier 2] TEST-UNEXPECTED-TIMEOUT | WD | expected OK | hang after Wait for initial navigation followed by "console.error: URLBar - QuickSuggest.SuggestBackendRust: "Ingest error: Error from Remote Settings: Error parsing URL: relative URL<...>

Categories

(Remote Protocol :: WebDriver BiDi, defect, P5)

Product:
Remote Protocol
Component:
WebDriver BiDi
Type:
defect

Tracking

(Not tracked)

Status:
RESOLVED DUPLICATE of bug 1791951

People

(Reporter: intermittent-bug-filer, Unassigned)

Details

(Keywords: intermittent-failure)

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

[task 2024-06-26T16:41:08.846Z] 16:41:08     INFO - TEST-START | /_mozilla/webdriver/bidi/storage/set_cookie/partition.py
[task 2024-06-26T16:41:09.107Z] 16:41:09     INFO - STDOUT: ============================= test session starts ==============================
[task 2024-06-26T16:41:09.107Z] 16:41:09     INFO - STDOUT: platform linux -- Python 3.8.0, pytest-8.2.1, pluggy-unknown -- /builds/worker/workspace/build/venv/bin/python
[task 2024-06-26T16:41:09.108Z] 16:41:09     INFO - STDOUT: rootdir: /builds/worker/workspace/build
[task 2024-06-26T16:41:09.109Z] 16:41:09     INFO - STDOUT: plugins: asyncio-0.19.0
[task 2024-06-26T16:41:09.109Z] 16:41:09     INFO - STDOUT: asyncio: mode=strict
[task 2024-06-26T16:41:09.109Z] 16:41:09     INFO - STDOUT: collecting ... 
[task 2024-06-26T16:41:09.129Z] 16:41:09     INFO - STDOUT: collected 3 items
[task 2024-06-26T16:41:09.129Z] 16:41:09     INFO - STDOUT: tests/web-platform/mozilla/tests/webdriver/bidi/storage/set_cookie/partition.py::test_partition_context 
[task 2024-06-26T16:41:09.133Z] 16:41:09     INFO - PID 31204 | 1719420069131	webdriver::server	DEBUG	-> POST /session {"capabilities": {"alwaysMatch": {"moz:firefoxOptions": {"args": ["--profile", "/tmp/tmppowd_v7v.mozrunner"] ... h=/builds/worker/workspace/build/application/firefox/llvm-symbolizer", "MOZ_WINDOW_OCCLUSION": "0"}}, "webSocketUrl": true}}}
[task 2024-06-26T16:41:09.133Z] 16:41:09     INFO - PID 31204 | 1719420069131	geckodriver::capabilities	DEBUG	Trying to read firefox version from ini files
[task 2024-06-26T16:41:09.133Z] 16:41:09     INFO - PID 31204 | 1719420069132	geckodriver::capabilities	DEBUG	Found version 129.0a1
[task 2024-06-26T16:41:09.134Z] 16:41:09     INFO - PID 31204 | 1719420069132	geckodriver::browser	DEBUG	Backing up prefs to "/tmp/tmppowd_v7v.mozrunner/user.geckodriver_backup"
[task 2024-06-26T16:41:09.140Z] 16:41:09     INFO - PID 31204 | 1719420069139	mozrunner::runner	INFO	Running command: MOZ_CRASHREPORTER="1" MOZ_CRASHREPORTER_NO_REPORT="1" MOZ_CRASHREPORTER_SHUTDOWN="1" MOZ_NO_REMOTE="1" "/bui ... te" "--profile" "/tmp/tmppowd_v7v.mozrunner" "--remote-debugging-port" "9222" "--remote-allow-hosts" "localhost" "-no-remote"
[task 2024-06-26T16:41:09.141Z] 16:41:09     INFO - PID 31204 | 1719420069139	geckodriver::marionette	DEBUG	Waiting 60s to connect to browser on 127.0.0.1
[task 2024-06-26T16:41:09.142Z] 16:41:09     INFO - PID 31204 | 1719420069139	geckodriver::browser	TRACE	Failed to open /tmp/tmppowd_v7v.mozrunner/MarionetteActivePort
[task 2024-06-26T16:41:09.142Z] 16:41:09     INFO - PID 31204 | 1719420069139	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2024-06-26T16:41:09.176Z] 16:41:09     INFO - PID 31204 | *** You are running in headless mode.
[task 2024-06-26T16:41:09.240Z] 16:41:09     INFO - PID 31204 | 1719420069239	geckodriver::browser	TRACE	Failed to open /tmp/tmppowd_v7v.mozrunner/MarionetteActivePort
[task 2024-06-26T16:41:09.241Z] 16:41:09     INFO - PID 31204 | 1719420069239	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2024-06-26T16:41:09.340Z] 16:41:09     INFO - PID 31204 | 1719420069340	geckodriver::browser	TRACE	Failed to open /tmp/tmppowd_v7v.mozrunner/MarionetteActivePort
[task 2024-06-26T16:41:09.341Z] 16:41:09     INFO - PID 31204 | 1719420069340	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2024-06-26T16:41:09.441Z] 16:41:09     INFO - PID 31204 | 1719420069440	geckodriver::browser	TRACE	Failed to open /tmp/tmppowd_v7v.mozrunner/MarionetteActivePort
[task 2024-06-26T16:41:09.442Z] 16:41:09     INFO - PID 31204 | 1719420069440	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2024-06-26T16:41:09.541Z] 16:41:09     INFO - PID 31204 | 1719420069540	geckodriver::browser	TRACE	Failed to open /tmp/tmppowd_v7v.mozrunner/MarionetteActivePort
[task 2024-06-26T16:41:09.541Z] 16:41:09     INFO - PID 31204 | 1719420069540	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2024-06-26T16:41:09.641Z] 16:41:09     INFO - PID 31204 | 1719420069640	geckodriver::browser	TRACE	Failed to open /tmp/tmppowd_v7v.mozrunner/MarionetteActivePort
[task 2024-06-26T16:41:09.641Z] 16:41:09     INFO - PID 31204 | 1719420069640	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2024-06-26T16:41:09.741Z] 16:41:09     INFO - PID 31204 | 1719420069740	geckodriver::browser	TRACE	Failed to open /tmp/tmppowd_v7v.mozrunner/MarionetteActivePort
[task 2024-06-26T16:41:09.741Z] 16:41:09     INFO - PID 31204 | 1719420069740	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2024-06-26T16:41:09.841Z] 16:41:09     INFO - PID 31204 | 1719420069840	geckodriver::browser	TRACE	Failed to open /tmp/tmppowd_v7v.mozrunner/MarionetteActivePort
[task 2024-06-26T16:41:09.842Z] 16:41:09     INFO - PID 31204 | 1719420069840	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2024-06-26T16:41:09.941Z] 16:41:09     INFO - PID 31204 | 1719420069940	geckodriver::browser	TRACE	Failed to open /tmp/tmppowd_v7v.mozrunner/MarionetteActivePort
[task 2024-06-26T16:41:09.942Z] 16:41:09     INFO - PID 31204 | 1719420069940	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2024-06-26T16:41:10.041Z] 16:41:10     INFO - PID 31204 | 1719420070040	geckodriver::browser	TRACE	Failed to open /tmp/tmppowd_v7v.mozrunner/MarionetteActivePort
[task 2024-06-26T16:41:10.042Z] 16:41:10     INFO - PID 31204 | 1719420070040	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2024-06-26T16:41:10.141Z] 16:41:10     INFO - PID 31204 | 1719420070141	geckodriver::browser	TRACE	Failed to open /tmp/tmppowd_v7v.mozrunner/MarionetteActivePort
[task 2024-06-26T16:41:10.142Z] 16:41:10     INFO - PID 31204 | 1719420070141	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2024-06-26T16:41:10.241Z] 16:41:10     INFO - PID 31204 | 1719420070241	geckodriver::browser	TRACE	Failed to open /tmp/tmppowd_v7v.mozrunner/MarionetteActivePort
[task 2024-06-26T16:41:10.242Z] 16:41:10     INFO - PID 31204 | 1719420070241	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2024-06-26T16:41:10.342Z] 16:41:10     INFO - PID 31204 | 1719420070341	geckodriver::browser	TRACE	Failed to open /tmp/tmppowd_v7v.mozrunner/MarionetteActivePort
[task 2024-06-26T16:41:10.342Z] 16:41:10     INFO - PID 31204 | 1719420070341	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2024-06-26T16:41:10.442Z] 16:41:10     INFO - PID 31204 | 1719420070441	geckodriver::browser	TRACE	Failed to open /tmp/tmppowd_v7v.mozrunner/MarionetteActivePort
[task 2024-06-26T16:41:10.442Z] 16:41:10     INFO - PID 31204 | 1719420070441	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2024-06-26T16:41:10.542Z] 16:41:10     INFO - PID 31204 | 1719420070541	geckodriver::browser	TRACE	Failed to open /tmp/tmppowd_v7v.mozrunner/MarionetteActivePort
[task 2024-06-26T16:41:10.543Z] 16:41:10     INFO - PID 31204 | 1719420070541	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2024-06-26T16:41:10.642Z] 16:41:10     INFO - PID 31204 | 1719420070641	geckodriver::browser	TRACE	Failed to open /tmp/tmppowd_v7v.mozrunner/MarionetteActivePort
[task 2024-06-26T16:41:10.643Z] 16:41:10     INFO - PID 31204 | 1719420070641	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2024-06-26T16:41:10.704Z] 16:41:10     INFO - PID 31204 | 1719420070703	RemoteAgent	DEBUG	Setting recommended pref browser.contentblocking.introCount to 99
[task 2024-06-26T16:41:10.706Z] 16:41:10     INFO - PID 31204 | 1719420070705	RemoteAgent	DEBUG	Setting recommended pref browser.search.update to false
[task 2024-06-26T16:41:10.706Z] 16:41:10     INFO - PID 31204 | 1719420070705	RemoteAgent	DEBUG	Setting recommended pref browser.tabs.remote.unloadDelayMs to 0
[task 2024-06-26T16:41:10.708Z] 16:41:10     INFO - PID 31204 | 1719420070706	RemoteAgent	DEBUG	Setting recommended pref browser.tabs.warnOnClose to false
[task 2024-06-26T16:41:10.708Z] 16:41:10     INFO - PID 31204 | 1719420070706	RemoteAgent	DEBUG	Setting recommended pref browser.tabs.warnOnCloseOtherTabs to false
[task 2024-06-26T16:41:10.708Z] 16:41:10     INFO - PID 31204 | 1719420070707	RemoteAgent	DEBUG	Setting recommended pref browser.tabs.warnOnOpen to false
[task 2024-06-26T16:41:10.708Z] 16:41:10     INFO - PID 31204 | 1719420070707	RemoteAgent	DEBUG	Setting recommended pref browser.usedOnWindows10.introURL to
[task 2024-06-26T16:41:10.709Z] 16:41:10     INFO - PID 31204 | 1719420070708	RemoteAgent	DEBUG	Setting recommended pref datareporting.policy.dataSubmissionPolicyAccepted to false
[task 2024-06-26T16:41:10.710Z] 16:41:10     INFO - PID 31204 | 1719420070709	RemoteAgent	DEBUG	Setting recommended pref dom.navigation.locationChangeRateLimit.count to 0
[task 2024-06-26T16:41:10.710Z] 16:41:10     INFO - PID 31204 | 1719420070709	RemoteAgent	DEBUG	Setting recommended pref dom.screenorientation.allow-lock to true
[task 2024-06-26T16:41:10.711Z] 16:41:10     INFO - PID 31204 | 1719420070710	RemoteAgent	DEBUG	Setting recommended pref network.connectivity-service.enabled to false
[task 2024-06-26T16:41:10.712Z] 16:41:10     INFO - PID 31204 | 1719420070711	RemoteAgent	DEBUG	Setting recommended pref privacy.trackingprotection.enabled to false
[task 2024-06-26T16:41:10.712Z] 16:41:10     INFO - PID 31204 | 1719420070711	RemoteAgent	DEBUG	Setting recommended pref remote.prefs.recommended.applied to true
[task 2024-06-26T16:41:10.713Z] 16:41:10     INFO - PID 31204 | 1719420070711	RemoteAgent	DEBUG	Setting recommended pref security.fileuri.strict_origin_policy to false
[task 2024-06-26T16:41:10.713Z] 16:41:10     INFO - PID 31204 | 1719420070712	RemoteAgent	DEBUG	Setting recommended pref signon.autofillForms to false
[task 2024-06-26T16:41:10.714Z] 16:41:10     INFO - PID 31204 | 1719420070713	RemoteAgent	DEBUG	Setting recommended pref widget.windows.window_occlusion_tracking.enabled to false
[task 2024-06-26T16:41:10.716Z] 16:41:10     INFO - PID 31204 | 1719420070715	RemoteAgent	DEBUG	WebDriver BiDi enabled
[task 2024-06-26T16:41:10.720Z] 16:41:10     INFO - PID 31204 | 1719420070719	Marionette	INFO	Marionette enabled
[task 2024-06-26T16:41:10.722Z] 16:41:10     INFO - PID 31204 | 1719420070721	Marionette	TRACE	Received observer notification final-ui-startup
[task 2024-06-26T16:41:10.725Z] 16:41:10     INFO - PID 31204 | 1719420070724	RemoteAgent	TRACE	Received observer notification final-ui-startup
[task 2024-06-26T16:41:10.742Z] 16:41:10     INFO - PID 31204 | 1719420070741	geckodriver::browser	TRACE	Failed to open /tmp/tmppowd_v7v.mozrunner/MarionetteActivePort
[task 2024-06-26T16:41:10.743Z] 16:41:10     INFO - PID 31204 | 1719420070741	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2024-06-26T16:41:10.842Z] 16:41:10     INFO - PID 31204 | 1719420070841	geckodriver::browser	TRACE	Failed to open /tmp/tmppowd_v7v.mozrunner/MarionetteActivePort
[task 2024-06-26T16:41:10.844Z] 16:41:10     INFO - PID 31204 | 1719420070841	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2024-06-26T16:41:10.845Z] 16:41:10     INFO - PID 31204 | 1719420070845	Marionette	INFO	Listening on port 38149
[task 2024-06-26T16:41:10.847Z] 16:41:10     INFO - PID 31204 | 1719420070846	Marionette	DEBUG	Marionette is listening
[task 2024-06-26T16:41:10.879Z] 16:41:10     INFO - PID 31204 | 1719420070878	RemoteAgent	TRACE	Available local IP addresses: 127.0.0.1, [::1]
[task 2024-06-26T16:41:10.888Z] 16:41:10     INFO - PID 31204 | 1719420070887	RemoteAgent	DEBUG	Setting recommended pref permissions.isolateBy.userContext to true
[task 2024-06-26T16:41:10.890Z] 16:41:10     INFO - PID 31204 | WebDriver BiDi listening on ws://127.0.0.1:9222
[task 2024-06-26T16:41:10.942Z] 16:41:10     INFO - PID 31204 | Read port: 38149
[task 2024-06-26T16:41:10.963Z] 16:41:10     INFO - PID 31204 | 1719420070962	Marionette	DEBUG	Accepted connection 0 from 127.0.0.1:56380
[task 2024-06-26T16:41:11.091Z] 16:41:11     INFO - PID 31204 | 1719420071090	geckodriver::marionette	DEBUG	Connection to Marionette established on 127.0.0.1:38149.
[task 2024-06-26T16:41:11.478Z] 16:41:11     INFO - PID 31204 | 1719420071477	Marionette	DEBUG	0 -> [0,1,"WebDriver:NewSession",{"webSocketUrl":true}]
[task 2024-06-26T16:41:11.490Z] 16:41:11     INFO - PID 31204 | 1719420071489	WebDriver BiDi	DEBUG	Registered session handler: /session/a7b797b0-01a4-406c-8c39-27fe61d34eeb
[task 2024-06-26T16:41:11.493Z] 16:41:11     INFO - PID 31204 | 1719420071489	WebDriver BiDi	DEBUG	Waiting for initial application window
[task 2024-06-26T16:41:12.762Z] 16:41:12     INFO - PID 31204 | Crash Annotation GraphicsCriticalError: |[0][GFX1-]: RenderCompositorSWGL failed mapping default framebuffer, no dt (t=3.611) [GFX1-]: RenderCompositorSWGL failed mapping default framebuffer, no dt
[task 2024-06-26T16:41:13.146Z] 16:41:13     INFO - PID 31204 | console.error: ({})
[task 2024-06-26T16:41:17.063Z] 16:41:17     INFO - PID 31204 | 1719420077062	Marionette	TRACE	Received observer notification browser-idle-startup-tasks-finished
[task 2024-06-26T16:41:17.063Z] 16:41:17     INFO - PID 31204 | 1719420077062	RemoteAgent	TRACE	Received observer notification browser-idle-startup-tasks-finished
[task 2024-06-26T16:41:17.065Z] 16:41:17     INFO - PID 31204 | 1719420077064	Marionette	DEBUG	Waiting for initial application window
[task 2024-06-26T16:41:17.082Z] 16:41:17     INFO - PID 31204 | 1719420077081	RemoteAgent	TRACE	[3] ProgressListener Start: expectNavigation=false resolveWhenStarted=false unloadTimeout=40000 waitForExplicitStart=false
[task 2024-06-26T16:41:17.082Z] 16:41:17     INFO - PID 31204 | 1719420077082	RemoteAgent	TRACE	[3] ProgressListener Document already loading about:blank
[task 2024-06-26T16:41:17.084Z] 16:41:17     INFO - PID 31204 | 1719420077083	RemoteAgent	TRACE	[3] ProgressListener Loading state: isStart=true isStop=false status=0x0, loadType=0x1
[task 2024-06-26T16:41:17.085Z] 16:41:17     INFO - PID 31204 | 1719420077083	RemoteAgent	TRACE	[3] ProgressListener Started loading about:blank
[task 2024-06-26T16:41:17.085Z] 16:41:17     INFO - PID 31204 | 1719420077083	RemoteAgent	TRACE	[3] Wait for initial navigation: isInitial=true, isLoadingDocument=true
[task 2024-06-26T16:41:17.089Z] 16:41:17     INFO - PID 31204 | [ERROR error_support::handling] suggest-unexpected: Error from Remote Settings: Error parsing URL: relative URL with a cannot-be-a-base base
[task 2024-06-26T16:41:17.090Z] 16:41:17     INFO - PID 31204 | console.error: URLBar - QuickSuggest.SuggestBackendRust: "Ingest error: Error from Remote Settings: Error parsing URL: relative URL with a cannot-be-a-base base"
[task 2024-06-26T16:44:33.849Z] 16:44:33     INFO - TEST-UNEXPECTED-TIMEOUT | /_mozilla/webdriver/bidi/storage/set_cookie/partition.py | expected OK
[task 2024-06-26T16:44:33.849Z] 16:44:33     INFO - TEST-INFO took 205003ms
[task 2024-06-26T16:44:33.859Z] 16:44:33     INFO - Restarting browser for new test group
[task 2024-06-26T16:44:39.898Z] 16:44:39     INFO - Closing logging queue
[task 2024-06-26T16:44:39.898Z] 16:44:39     INFO - queue closed
[task 2024-06-26T16:44:39.900Z] 16:44:39     INFO - Starting WebDriver: /builds/worker/fetches/geckodriver --host 127.0.0.1 --port 0 -vv --binary /builds/worker/workspace/build/application/firefox/firefox
[task 2024-06-26T16:44:39.908Z] 16:44:39     INFO - PID 31400 | 1719420279906	geckodriver	INFO	Listening on 127.0.0.1:39210
[task 2024-06-26T16:44:39.908Z] 16:44:39     INFO - Webdriver started successfully.
[task 2024-06-26T16:44:39.908Z] 16:44:39     INFO - Starting runner
[task 2024-06-26T16:44:40.169Z] 16:44:40     INFO - TEST-START | /_mozilla/webdriver/classic/perform_actions/wheel.py

This is basically waiting for the initial application window.

Status: NEW → RESOLVED
Closed: 1 year ago
Duplicate of bug: 1791951
Resolution: --- → DUPLICATE
You need to log in before you can comment on or make changes to this bug.