geckodriver fails to connect to Marionette if an older MarionetteActivePort file is in the profile
Categories
(Testing :: geckodriver, defect, P2)
Tracking
(firefox-esr91 unaffected, firefox97 unaffected, firefox98 wontfix, firefox99 wontfix, firefox100 fixed)
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)
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.
Updated•3 years ago
|
Comment 1•3 years ago
|
||
Set release status flags based on info from the regressing bug 1421766
Updated•3 years ago
|
Assignee | ||
Comment 2•3 years ago
|
||
Updated•3 years ago
|
Assignee | ||
Updated•3 years ago
|
Updated•3 years ago
|
Assignee | ||
Comment 3•3 years ago
|
||
Assignee | ||
Comment 4•3 years ago
|
||
Depends on D141358
Comment 6•3 years ago
|
||
Backed out for causing wd failures on marionette_port.py.
Push with failures
Push where the failures first appeared
[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
Updated•3 years ago
|
Assignee | ||
Comment 7•3 years ago
|
||
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
Assignee | ||
Comment 8•3 years ago
|
||
Comment 10•3 years ago
|
||
bugherder |
https://hg.mozilla.org/mozilla-central/rev/866230ba45ae
https://hg.mozilla.org/mozilla-central/rev/9882f0d750ef
Assignee | ||
Comment 11•3 years ago
|
||
Our geckodriver releases are getting built out of mozilla-central. As such there is no need for an uplift.
Comment 12•3 years ago
|
||
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.
Description
•