Closed Bug 1758627 Opened 2 years ago Closed 2 years ago

Intermittent TEST-UNEXPECTED-TIMEOUT | /webdriver/tests/new_session/websocket_url.py | expected OK

Tracking

(firefox100 fixed)

Status:

RESOLVED FIXED

Milestone:

100 Branch

Tracking Flags:

Tracking

Status

firefox100

---

fixed

People

(Reporter: intermittent-bug-filer, Assigned: whimboo)

References

Details

(Keywords: intermittent-failure)

Treeherder Bug Filer

Reporter

Description

•

2 years ago

treeherder

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

[task 2022-03-09T05:41:48.329Z] 05:41:48     INFO - TEST-START | /webdriver/tests/new_session/websocket_url.py
[task 2022-03-09T05:41:48.610Z] 05:41:48     INFO - STDOUT: ============================= test session starts ==============================
[task 2022-03-09T05:41:48.611Z] 05:41:48     INFO - STDOUT: platform linux -- Python 3.6.9, pytest-6.1.1, py-1.5.2, pluggy-unknown -- /builds/worker/workspace/build/venv/bin/python
[task 2022-03-09T05:41:48.612Z] 05:41:48     INFO - STDOUT: rootdir: /builds/worker/workspace/build
[task 2022-03-09T05:41:48.613Z] 05:41:48     INFO - STDOUT: plugins: asyncio-0.14.0
[task 2022-03-09T05:41:48.613Z] 05:41:48     INFO - STDOUT: collecting ... 
[task 2022-03-09T05:41:48.625Z] 05:41:48     INFO - STDOUT: collected 1 item
[task 2022-03-09T05:41:48.626Z] 05:41:48     INFO - STDOUT: tests/web-platform/tests/webdriver/tests/new_session/websocket_url.py::test_websocket_url 
[task 2022-03-09T05:41:48.627Z] 05:41:48     INFO - PID 6938 | 1646804508624	webdriver::server	DEBUG	-> POST /session {"capabilities": {"alwaysMatch": {"moz:firefoxOptions": {"args": ["--profile", "/tmp/tmp9spe5rhm.mozrunner"], "binary": "/builds/worker/workspace/build/application/firefox/firefox"}, "webSocketUrl": true}}}
[task 2022-03-09T05:41:48.628Z] 05:41:48     INFO - PID 6938 | 1646804508624	geckodriver::capabilities	DEBUG	Trying to read firefox version from ini files
[task 2022-03-09T05:41:48.628Z] 05:41:48     INFO - PID 6938 | 1646804508624	geckodriver::capabilities	DEBUG	Found version 100.0a1
[task 2022-03-09T05:41:48.629Z] 05:41:48     INFO - PID 6938 | 1646804508625	geckodriver::browser	DEBUG	Backing up prefs to "/tmp/tmp9spe5rhm.mozrunner/user.geckodriver_backup_1"
[task 2022-03-09T05:41:48.633Z] 05:41:48     INFO - PID 6938 | 1646804508632	mozrunner::runner	INFO	Running command: "/builds/worker/workspace/build/application/firefox/firefox" "--marionette" "--profile" "/tmp/tmp9spe5rhm.mozrunner" "--remote-debugging-port" "9222" "-no-remote"
[task 2022-03-09T05:41:48.635Z] 05:41:48     INFO - PID 6938 | 1646804508632	geckodriver::marionette	DEBUG	Waiting 60s to connect to browser on 127.0.0.1
[task 2022-03-09T05:41:48.635Z] 05:41:48     INFO - PID 6938 | Read port: 39163
[task 2022-03-09T05:41:48.635Z] 05:41:48     INFO - PID 6938 | 1646804508632	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2022-03-09T05:41:48.734Z] 05:41:48     INFO - PID 6938 | 1646804508733	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2022-03-09T05:41:48.834Z] 05:41:48     INFO - PID 6938 | 1646804508833	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2022-03-09T05:41:48.934Z] 05:41:48     INFO - PID 6938 | 1646804508933	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2022-03-09T05:41:49.034Z] 05:41:49     INFO - PID 6938 | 1646804509033	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2022-03-09T05:41:49.134Z] 05:41:49     INFO - PID 6938 | 1646804509134	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2022-03-09T05:41:49.235Z] 05:41:49     INFO - PID 6938 | 1646804509234	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2022-03-09T05:41:49.335Z] 05:41:49     INFO - PID 6938 | 1646804509334	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2022-03-09T05:41:49.435Z] 05:41:49     INFO - PID 6938 | 1646804509434	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2022-03-09T05:41:49.535Z] 05:41:49     INFO - PID 6938 | 1646804509534	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2022-03-09T05:41:49.636Z] 05:41:49     INFO - PID 6938 | 1646804509635	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2022-03-09T05:41:49.736Z] 05:41:49     INFO - PID 6938 | 1646804509735	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2022-03-09T05:41:49.836Z] 05:41:49     INFO - PID 6938 | 1646804509835	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2022-03-09T05:41:49.936Z] 05:41:49     INFO - PID 6938 | 1646804509935	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2022-03-09T05:41:50.036Z] 05:41:50     INFO - PID 6938 | 1646804510035	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2022-03-09T05:41:50.137Z] 05:41:50     INFO - PID 6938 | 1646804510136	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2022-03-09T05:41:50.237Z] 05:41:50     INFO - PID 6938 | 1646804510236	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2022-03-09T05:41:50.337Z] 05:41:50     INFO - PID 6938 | 1646804510336	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2022-03-09T05:41:50.437Z] 05:41:50     INFO - PID 6938 | 1646804510436	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2022-03-09T05:41:50.538Z] 05:41:50     INFO - PID 6938 | 1646804510536	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2022-03-09T05:41:50.638Z] 05:41:50     INFO - PID 6938 | 1646804510637	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2022-03-09T05:41:50.738Z] 05:41:50     INFO - PID 6938 | 1646804510737	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2022-03-09T05:41:50.764Z] 05:41:50     INFO - PID 6938 | 1646804510763	RemoteAgent	DEBUG	WebDriver BiDi enabled
[task 2022-03-09T05:41:50.766Z] 05:41:50     INFO - PID 6938 | 1646804510765	RemoteAgent	DEBUG	CDP enabled
[task 2022-03-09T05:41:50.767Z] 05:41:50     INFO - PID 6938 | 1646804510765	Marionette	INFO	Marionette enabled
[task 2022-03-09T05:41:50.838Z] 05:41:50     INFO - PID 6938 | 1646804510837	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2022-03-09T05:41:50.938Z] 05:41:50     INFO - PID 6938 | 1646804510937	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2022-03-09T05:41:51.038Z] 05:41:51     INFO - PID 6938 | 1646804511038	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2022-03-09T05:41:51.139Z] 05:41:51     INFO - PID 6938 | 1646804511138	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2022-03-09T05:41:51.239Z] 05:41:51     INFO - PID 6938 | 1646804511238	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2022-03-09T05:41:51.339Z] 05:41:51     INFO - PID 6938 | 1646804511338	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2022-03-09T05:41:51.439Z] 05:41:51     INFO - PID 6938 | 1646804511438	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2022-03-09T05:41:51.540Z] 05:41:51     INFO - PID 6938 | 1646804511539	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2022-03-09T05:41:51.640Z] 05:41:51     INFO - PID 6938 | 1646804511639	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2022-03-09T05:41:51.740Z] 05:41:51     INFO - PID 6938 | 1646804511739	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2022-03-09T05:41:51.840Z] 05:41:51     INFO - PID 6938 | 1646804511839	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2022-03-09T05:41:51.941Z] 05:41:51     INFO - PID 6938 | 1646804511939	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2022-03-09T05:41:52.041Z] 05:41:52     INFO - PID 6938 | 1646804512040	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2022-03-09T05:41:52.141Z] 05:41:52     INFO - PID 6938 | 1646804512140	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2022-03-09T05:41:52.241Z] 05:41:52     INFO - PID 6938 | 1646804512240	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2022-03-09T05:41:52.342Z] 05:41:52     INFO - PID 6938 | 1646804512340	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2022-03-09T05:41:52.442Z] 05:41:52     INFO - PID 6938 | 1646804512441	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2022-03-09T05:41:52.542Z] 05:41:52     INFO - PID 6938 | 1646804512541	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2022-03-09T05:41:52.642Z] 05:41:52     INFO - PID 6938 | 1646804512641	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2022-03-09T05:41:52.742Z] 05:41:52     INFO - PID 6938 | 1646804512741	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2022-03-09T05:41:52.843Z] 05:41:52     INFO - PID 6938 | 1646804512841	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2022-03-09T05:41:52.943Z] 05:41:52     INFO - PID 6938 | 1646804512942	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2022-03-09T05:41:53.043Z] 05:41:53     INFO - PID 6938 | 1646804513042	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2022-03-09T05:41:53.143Z] 05:41:53     INFO - PID 6938 | 1646804513142	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2022-03-09T05:41:53.243Z] 05:41:53     INFO - PID 6938 | 1646804513242	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2022-03-09T05:41:53.344Z] 05:41:53     INFO - PID 6938 | 1646804513343	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2022-03-09T05:41:53.444Z] 05:41:53     INFO - PID 6938 | 1646804513443	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2022-03-09T05:41:53.544Z] 05:41:53     INFO - PID 6938 | 1646804513543	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2022-03-09T05:41:53.644Z] 05:41:53     INFO - PID 6938 | 1646804513643	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2022-03-09T05:41:53.745Z] 05:41:53     INFO - PID 6938 | 1646804513743	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2022-03-09T05:41:53.845Z] 05:41:53     INFO - PID 6938 | 1646804513844	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2022-03-09T05:41:53.945Z] 05:41:53     INFO - PID 6938 | 1646804513944	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2022-03-09T05:41:54.045Z] 05:41:54     INFO - PID 6938 | 1646804514044	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2022-03-09T05:41:54.145Z] 05:41:54     INFO - PID 6938 | 1646804514144	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2022-03-09T05:41:54.246Z] 05:41:54     INFO - PID 6938 | 1646804514245	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2022-03-09T05:41:54.346Z] 05:41:54     INFO - PID 6938 | 1646804514345	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2022-03-09T05:41:54.446Z] 05:41:54     INFO - PID 6938 | 1646804514445	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2022-03-09T05:41:54.546Z] 05:41:54     INFO - PID 6938 | 1646804514545	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2022-03-09T05:41:54.646Z] 05:41:54     INFO - PID 6938 | 1646804514645	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2022-03-09T05:41:54.747Z] 05:41:54     INFO - PID 6938 | 1646804514746	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2022-03-09T05:41:54.847Z] 05:41:54     INFO - PID 6938 | 1646804514846	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2022-03-09T05:41:54.947Z] 05:41:54     INFO - PID 6938 | 1646804514946	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2022-03-09T05:41:55.047Z] 05:41:55     INFO - PID 6938 | 1646804515046	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2022-03-09T05:41:55.148Z] 05:41:55     INFO - PID 6938 | 1646804515147	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2022-03-09T05:41:55.248Z] 05:41:55     INFO - PID 6938 | 1646804515247	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2022-03-09T05:41:55.348Z] 05:41:55     INFO - PID 6938 | 1646804515347	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2022-03-09T05:41:55.449Z] 05:41:55     INFO - PID 6938 | 1646804515447	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2022-03-09T05:41:55.549Z] 05:41:55     INFO - PID 6938 | 1646804515548	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2022-03-09T05:41:55.649Z] 05:41:55     INFO - PID 6938 | 1646804515648	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2022-03-09T05:41:55.749Z] 05:41:55     INFO - PID 6938 | 1646804515748	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2022-03-09T05:41:55.850Z] 05:41:55     INFO - PID 6938 | 1646804515848	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2022-03-09T05:41:55.950Z] 05:41:55     INFO - PID 6938 | 1646804515948	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2022-03-09T05:41:56.050Z] 05:41:56     INFO - PID 6938 | 1646804516049	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2022-03-09T05:41:56.150Z] 05:41:56     INFO - PID 6938 | 1646804516149	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2022-03-09T05:41:56.250Z] 05:41:56     INFO - PID 6938 | 1646804516249	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2022-03-09T05:41:56.351Z] 05:41:56     INFO - PID 6938 | 1646804516350	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2022-03-09T05:41:56.451Z] 05:41:56     INFO - PID 6938 | 1646804516450	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2022-03-09T05:41:56.551Z] 05:41:56     INFO - PID 6938 | 1646804516550	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2022-03-09T05:41:56.652Z] 05:41:56     INFO - PID 6938 | 1646804516650	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2022-03-09T05:41:56.694Z] 05:41:56     INFO - PID 6938 | 1646804516692	RemoteAgent	TRACE	Received observer notification remote-startup-requested
[task 2022-03-09T05:41:56.752Z] 05:41:56     INFO - PID 6938 | 1646804516751	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2022-03-09T05:41:56.762Z] 05:41:56     INFO - PID 6938 | 1646804516761	Marionette	TRACE	Received observer notification marionette-startup-requested
[task 2022-03-09T05:41:56.764Z] 05:41:56     INFO - PID 6938 | 1646804516761	Marionette	TRACE	Waiting until startup recorder finished recording startup scripts...
[task 2022-03-09T05:41:56.767Z] 05:41:56     INFO - PID 6938 | DevTools listening on ws://localhost:9222/devtools/browser/39330ca4-62e0-4ebf-bd73-11feffc87934
[task 2022-03-09T05:41:56.802Z] 05:41:56     INFO - PID 6938 | WebDriver BiDi listening on ws://localhost:9222
[task 2022-03-09T05:41:56.852Z] 05:41:56     INFO - PID 6938 | 1646804516851	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2022-03-09T05:41:56.870Z] 05:41:56     INFO - PID 6938 | 1646804516868	Marionette	TRACE	All scripts recorded.
[task 2022-03-09T05:41:56.875Z] 05:41:56     INFO - PID 6938 | 1646804516874	Marionette	INFO	Listening on port 37845
<...>
[task 2022-03-09T05:42:48.460Z] 05:42:48     INFO - PID 6938 | 1646804568460	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2022-03-09T05:42:48.561Z] 05:42:48     INFO - PID 6938 | 1646804568560	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2022-03-09T05:43:08.332Z] 05:43:08     INFO - TEST-UNEXPECTED-TIMEOUT | /webdriver/tests/new_session/websocket_url.py | expected OK
[task 2022-03-09T05:43:08.332Z] 05:43:08     INFO - TEST-INFO took 80003ms
[task 2022-03-09T05:43:08.336Z] 05:43:08     INFO - Restarting browser for new test group
[task 2022-03-09T05:43:08.524Z] 05:43:08     INFO - Closing logging queue
[task 2022-03-09T05:43:08.524Z] 05:43:08     INFO - queue closed
[task 2022-03-09T05:43:08.531Z] 05:43:08     INFO - PID 7157 | 1646804588528	geckodriver	INFO	Listening on 127.0.0.1:60970
[task 2022-03-09T05:43:08.532Z] 05:43:08     INFO - Starting runner
[task 2022-03-09T05:43:08.859Z] 05:43:08     INFO - TEST-START | /webdriver/tests/permissions/set.py

Henrik Skupin [:whimboo][⌚️UTC+1]

Assignee

Comment 1

•

2 years ago

geckodriver tries to connect to the wrong Marionette port because it read an outdated MarionetteActivePort file.

Depends on: 1755312

Comment hidden (Intermittent Failures Robot)

Henrik Skupin [:whimboo][⌚️UTC+1]

Assignee

Comment 3

•

2 years ago

Fixed by the patch on bug 1755312.

Assignee: nobody → hskupin

Status: NEW → RESOLVED

Closed: 2 years ago

status-firefox100: --- → fixed

Resolution: --- → FIXED

Target Milestone: --- → 100 Branch

Comment hidden (Intermittent Failures Robot)

BMO Automation

Comment 5

•

1 year ago

Moving bug to Remote Protocol::Marionette component per bug 1815831.

Component: geckodriver → Marionette

Product: Testing → Remote Protocol

You need to log in before you can comment on or make changes to this bug.

Bugzilla

Quick Search

Intermittent TEST-UNEXPECTED-TIMEOUT | /webdriver/tests/new_session/websocket_url.py | expected OK

Categories

(Remote Protocol :: Marionette, defect, P5)

Tracking

(firefox100 fixed)

People

(Reporter: intermittent-bug-filer, Assigned: whimboo)

References

Details

(Keywords: intermittent-failure)

Crash Data

Security

(public)

User Story

Description

Comment 1

Comment 2

Comment 3

Comment 4

Comment 5