Closed Bug 1755312 Opened 2 years ago Closed 2 years ago

geckodriver fails to connect to Marionette if an older MarionetteActivePort file is in the profile

Categories

(Testing :: geckodriver, defect, P2)

Product:
Testing
Component:
geckodriver
Version:
Default
Type:
defect
Points:
2

Tracking

(firefox-esr91 unaffected, firefox97 unaffected, firefox98 wontfix, firefox99 wontfix, firefox100 fixed)

Status:
RESOLVED FIXED
Milestone:
100 Branch
Tracking Flags:
Tracking Status
firefox-esr91 --- unaffected
firefox97 --- unaffected
firefox98 --- wontfix
firefox99 --- wontfix
firefox100 --- fixed

People

(Reporter: whimboo, Assigned: whimboo)

References

(Regression)

Details

(Keywords: regression, Whiteboard: [bidi-m3-mvp])

Attachments

(2 files, 2 obsolete files)

Bug 1755312 - [geckodriver] Account for an already existing MarionetteActivePort file.
48 bytes, text/x-phabricator-request
Details | Review
Bug 1755312 - [geckodriver] Clippy and rustfmt fixes.
48 bytes, text/x-phabricator-request
Details | Review

There is a regression from bug 1421766 which causes geckodriver to not connect to Marionette if an old and outdated MarionetteActivePort file is found in the profile:

https://treeherder.mozilla.org/logviewer?job_id=367772032&repo=autoland&lineNumber=3137-3157

[task 2022-02-14T06:18:08.885Z] 06:18:08     INFO - STDOUT: tests/web-platform/tests/webdriver/tests/bidi/errors/errors.py::test_unknown_command[invalid module] 
[task 2022-02-14T06:18:08.889Z] 06:18:08     INFO - PID 7904 | 1644819488887	webdriver::server	DEBUG	-> POST /session {"capabilities": {"alwaysMatch": {"moz:firefoxOptions": {"args": ["--profile", "C:\\Users\\task_164481859927852\\AppData\\Local\\Temp\\tmp10k83yzp.mozrunner"], "binary": "Z:\\task_164481859927852\\build\\application\\firefox\\firefox.exe"}, "webSocketUrl": true}}}
[task 2022-02-14T06:18:08.890Z] 06:18:08     INFO - PID 7904 | 1644819488888	geckodriver::capabilities	DEBUG	Trying to read firefox version from ini files
[task 2022-02-14T06:18:08.890Z] 06:18:08     INFO - PID 7904 | 1644819488889	geckodriver::capabilities	DEBUG	Found version 99.0a1
[task 2022-02-14T06:18:08.891Z] 06:18:08     INFO - PID 7904 | 1644819488889	geckodriver::browser	DEBUG	Backing up prefs to "C:\\Users\\task_164481859927852\\AppData\\Local\\Temp\\tmp10k83yzp.mozrunner\\user.geckodriver_backup_1"
[task 2022-02-14T06:18:08.904Z] 06:18:08     INFO - PID 7904 | 1644819488903	mozrunner::runner	INFO	Running command: "Z:\\task_164481859927852\\build\\application\\firefox\\firefox.exe" "--marionette" "--profile" "C:\\Users\\task_164481859927852\\AppData\\Local\\Temp\\tmp10k83yzp.mozrunner" "--remote-debugging-port" "9222" "-no-remote"
[task 2022-02-14T06:18:08.906Z] 06:18:08     INFO - PID 7904 | 1644819488905	geckodriver::marionette	DEBUG	Waiting 60s to connect to browser on 127.0.0.1
[task 2022-02-14T06:18:08.907Z] 06:18:08     INFO - PID 7904 | Read port: 50073
[task 2022-02-14T06:18:08.967Z] 06:18:08     INFO - PID 7904 | *** You are running in headless mode.
[task 2022-02-14T06:18:09.095Z] 06:18:09     INFO - PID 7904 | 1644819489107	RemoteAgent	DEBUG	WebDriver BiDi enabled
[task 2022-02-14T06:18:09.109Z] 06:18:09     INFO - PID 7904 | 1644819489107	RemoteAgent	DEBUG	CDP enabled
[task 2022-02-14T06:18:09.110Z] 06:18:09     INFO - PID 7904 | 1644819489107	Marionette	INFO	Marionette enabled
[task 2022-02-14T06:18:09.405Z] 06:18:09     INFO - PID 7904 | [GFX1-]: RenderCompositorSWGL failed mapping default framebuffer, no dt
[task 2022-02-14T06:18:09.892Z] 06:18:09     INFO - PID 7904 | 1644819489904	RemoteAgent	TRACE	Received observer notification remote-startup-requested
[task 2022-02-14T06:18:09.908Z] 06:18:09     INFO - PID 7904 | 1644819489911	Marionette	TRACE	Received observer notification marionette-startup-requested
[task 2022-02-14T06:18:09.912Z] 06:18:09     INFO - PID 7904 | 1644819489911	Marionette	TRACE	Waiting until startup recorder finished recording startup scripts...
[task 2022-02-14T06:18:09.913Z] 06:18:09     INFO - PID 7904 | DevTools listening on ws://localhost:9222/devtools/browser/fed4cf86-5ede-41a3-8dd6-41a3b05a1490
[task 2022-02-14T06:18:09.916Z] 06:18:09     INFO - PID 7904 | WebDriver BiDi listening on ws://localhost:9222
[task 2022-02-14T06:18:09.992Z] 06:18:09     INFO - PID 7904 | 1644819489995	Marionette	TRACE	All scripts recorded.
[task 2022-02-14T06:18:09.997Z] 06:18:09     INFO - PID 7904 | 1644819489996	Marionette	INFO	Listening on port 50316
[task 2022-02-14T06:18:09.997Z] 06:18:09     INFO - PID 7904 | 1644819489997	Marionette	DEBUG	Marionette is listening
[task 2022-02-14T06:18:10.933Z] 06:18:10     INFO - PID 7904 | 1644819490932	geckodriver::marionette	TRACE	Retrying in 100ms
[..]
[task 2022-02-14T06:18:36.482Z] 06:18:36     INFO - PID 7904 | 1644819516482	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2022-02-14T06:18:38.527Z] 06:18:38     INFO - TEST-UNEXPECTED-TIMEOUT | /webdriver/tests/bidi/errors/errors.py | expected OK

As the log above shows we read the port once from the file and keep it set while trying to connect. But the file will be overwritten with the updated port by Marionette once it's listening. And this port is missed.

Set release status flags based on info from the regressing bug 1421766

status-firefox97: --- → unaffected
status-firefox98: --- → affected
status-firefox99: --- → affected
status-firefox-esr91: --- → unaffected
Has Regression Range: --- → yes
Assignee: nobody → hskupin
Status: NEW → ASSIGNED
Severity: -- → S3
Points: --- → 2
Priority: -- → P3
Whiteboard: [bidi-m3-mvp]
Priority: P3 → P2
Depends on: 1750689
Blocks: 1758627
Pushed by hskupin@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/4bb6093b4db3
[geckodriver] Account for an already existing MarionetteActivePort file. r=webdriver-reviewers,jgraham
https://hg.mozilla.org/integration/autoland/rev/6c795bd3f3d4
[geckodriver] Clippy and rustfmt fixes. r=webdriver-reviewers,jgraham

Backed out for causing wd failures on marionette_port.py.

Push with failures
Push where the failures first appeared

Failure log

Backout link

[task 2022-03-22T15:44:17.629Z] 15:44:17     INFO - TEST-START | /_mozilla/webdriver/protocol/marionette_port.py
[task 2022-03-22T15:44:17.677Z] 15:44:17     INFO - STDOUT: ============================= test session starts =============================
[task 2022-03-22T15:44:17.692Z] 15:44:17     INFO - STDOUT: platform win32 -- Python 3.9.5, pytest-6.1.1, py-1.5.2, pluggy-unknown -- Z:\task_164796097424198\build\venv\Scripts\python.exe
[task 2022-03-22T15:44:17.693Z] 15:44:17     INFO - STDOUT: rootdir: Z:\task_164796097424198\build
[task 2022-03-22T15:44:17.694Z] 15:44:17     INFO - STDOUT: plugins: asyncio-0.14.0
[task 2022-03-22T15:44:17.694Z] 15:44:17     INFO - STDOUT: collecting ... 
[task 2022-03-22T15:44:17.754Z] 15:44:17     INFO - STDOUT: collected 2 items
[task 2022-03-22T15:44:17.756Z] 15:44:17     INFO - STDOUT: tests/web-platform/mozilla/tests/webdriver/protocol/marionette_port.py::test_marionette_port[system allocated] 
[task 2022-03-22T15:45:37.637Z] 15:45:37     INFO - TEST-UNEXPECTED-TIMEOUT | /_mozilla/webdriver/protocol/marionette_port.py | expected OK
[task 2022-03-22T15:45:37.637Z] 15:45:37     INFO - TEST-INFO took 80010ms
[task 2022-03-22T15:45:37.651Z] 15:45:37  WARNING - Firefox didn't exit cleanly, not processing leak logs
[task 2022-03-22T15:45:47.659Z] 15:45:47  WARNING - Forcibly terminating runner process
[task 2022-03-22T15:45:48.197Z] 15:45:48     INFO - PID 7664 | 1647963947686	geckodriver	INFO	Listening on 127.0.0.1:49821
[task 2022-03-22T15:45:48.199Z] 15:45:48     INFO - Starting runner
[task 2022-03-22T15:45:48.779Z] 15:45:48     INFO - TEST-START | /_mozilla/webdriver/protocol/request.py
Flags: needinfo?(hskupin)
Attachment #9264185 - Attachment is obsolete: true

The underlying issue here was that we weren't processing the piped stdout from the geckodriver process. As such both geckodriver and Firefox were hanging. New patches are on the way and I will upload when the following try build is successful:

https://treeherder.mozilla.org/jobs?repo=try&revision=2a72502d2507a620abeb75bdee99672350ab9e70

Flags: needinfo?(hskupin)
Blocks: 1759994
Pushed by hskupin@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/866230ba45ae
[geckodriver] Account for an already existing MarionetteActivePort file. r=webdriver-reviewers,jgraham,jdescottes
https://hg.mozilla.org/integration/autoland/rev/9882f0d750ef
[geckodriver] Clippy and rustfmt fixes. r=webdriver-reviewers,jgraham

https://hg.mozilla.org/mozilla-central/rev/866230ba45ae
https://hg.mozilla.org/mozilla-central/rev/9882f0d750ef

Status: ASSIGNED → RESOLVED
Closed: 2 years ago
status-firefox100: --- → fixed
Resolution: --- → FIXED
Target Milestone: --- → 100 Branch

Our geckodriver releases are getting built out of mozilla-central. As such there is no need for an uplift.

status-firefox98: affected → wontfix
status-firefox99: affected → wontfix

Comment on attachment 9269342 [details]
Bug 1755312 - [wdspec] Re-organize Browser and Geckodriver classes for Mozilla specific tests.

Revision D142029 was moved to bug 1761436. Setting attachment 9269342 [details] to obsolete.

Attachment #9269342 - Attachment is obsolete: true
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: