1721011 - Intermittent TEST-UNEXPECTED-TIMEOUT | /webdriver/tests/bidi/new_session/connect.py | expected OK

Status: RESOLVED DUPLICATE of bug 1630162

(Remote Protocol :: Marionette, defect, P5)

Description

[Treeherder Bug Filer]

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

---

 INFO - TEST-START | /webdriver/tests/bidi/new_session/connect.py
[task 2021-07-17T11:53:18.657Z] 11:53:18     INFO - STDOUT: ============================= test session starts =============================
[task 2021-07-17T11:53:18.658Z] 11:53:18     INFO - STDOUT: platform win32 -- Python 3.6.5, pytest-6.1.1, py-1.5.2, pluggy-unknown -- Z:\task_1626522481\build\venv\Scripts\python.exe
[task 2021-07-17T11:53:18.659Z] 11:53:18     INFO - STDOUT: rootdir: Z:\task_1626522481\build
[task 2021-07-17T11:53:18.660Z] 11:53:18     INFO - STDOUT: plugins: asyncio-0.14.0
[task 2021-07-17T11:53:18.660Z] 11:53:18     INFO - STDOUT: collecting ... 
[task 2021-07-17T11:53:18.673Z] 11:53:18     INFO - STDOUT: collected 4 items
[task 2021-07-17T11:53:18.673Z] 11:53:18     INFO - STDOUT: tests/web-platform/tests/webdriver/tests/bidi/new_session/connect.py::test_websocket_url_connect[capabilities0] 
[task 2021-07-17T11:53:18.677Z] 11:53:18     INFO - PID 1852 | 1626522798676	webdriver::server	DEBUG	-> POST /session {"capabilities": {"alwaysMatch": {"moz:firefoxOptions": {"args": ["--profile", "C:\\Users\\task_1626522481\\AppData\\Local\\Temp\\tmpkw3nb0ki.mozrunner"], "binary": "Z:\\task_1626522481\\build\\application\\firefox\\firefox.exe"}, "webSocketUrl": true}}}
[task 2021-07-17T11:53:18.677Z] 11:53:18     INFO - PID 1852 | 1626522798676	geckodriver::capabilities	DEBUG	Trying to read firefox version from ini files
[task 2021-07-17T11:53:18.678Z] 11:53:18     INFO - PID 1852 | 1626522798677	geckodriver::capabilities	DEBUG	Found version 92.0a1
[task 2021-07-17T11:53:18.679Z] 11:53:18     INFO - PID 1852 | 1626522798678	geckodriver::browser	DEBUG	Backing up prefs to "C:\\Users\\task_1626522481\\AppData\\Local\\Temp\\tmpkw3nb0ki.mozrunner\\user.geckodriver_backup_1"
[task 2021-07-17T11:53:18.687Z] 11:53:18     INFO - PID 1852 | 1626522798686	mozrunner::runner	INFO	Running command: "Z:\\task_1626522481\\build\\application\\firefox\\firefox.exe" "--marionette" "--profile" "C:\\Users\\task_1626522481\\AppData\\Local\\Temp\\tmpkw3nb0ki.mozrunner" "--remote-debugging-port" "0" "-no-remote"
[task 2021-07-17T11:53:18.687Z] 11:53:18     INFO - PID 1852 | 1626522798687	geckodriver::marionette	DEBUG	Waiting 60s to connect to browser on 127.0.0.1:2828
[task 2021-07-17T11:53:18.950Z] 11:53:18     INFO - PID 1852 | DEBUG: Adding blocker OS.File: flush pending requests, warn about unclosed files, shut down service. for phase xpcom-will-shutdown
[task 2021-07-17T11:53:18.951Z] 11:53:18     INFO - PID 1852 | DEBUG: Adding blocker OS.File: flush I/O queued before profileBeforeChange for phase profile-before-change
[task 2021-07-17T11:53:18.952Z] 11:53:18     INFO - PID 1852 | DEBUG: Adding blocker AddonManager: shutting down. for phase profile-before-change
[task 2021-07-17T11:53:18.970Z] 11:53:18     INFO - PID 1852 | DEBUG: Adding blocker IOUtils Blocker (profile-before-change) for phase profile-before-change
[task 2021-07-17T11:53:18.970Z] 11:53:18     INFO - PID 1852 | DEBUG: Adding blocker IOUtils Blocker (xpcom-will-shutdown) for phase xpcom-will-shutdown
[task 2021-07-17T11:53:19.000Z] 11:53:19     INFO - PID 1852 | DEBUG: Adding blocker JSON store: writing data for phase AddonManager: Waiting for providers to shut down.
[task 2021-07-17T11:53:19.077Z] 11:53:19     INFO - PID 1852 | DEBUG: Adding blocker XPIProvider shutdown for phase quit-application-granted
[task 2021-07-17T11:53:19.079Z] 11:53:19     INFO - PID 1852 | DEBUG: Adding blocker XPIProvider for phase AddonManager: Waiting for providers to shut down.
[task 2021-07-17T11:53:19.080Z] 11:53:19     INFO - PID 1852 | DEBUG: Adding blocker ServiceWorkerRegistrar: Flushing data for phase profile-before-change
[task 2021-07-17T11:53:19.083Z] 11:53:19     INFO - PID 1852 | DEBUG: Adding blocker CrashMonitor: Writing notifications to file after receiving profile-before-change for phase IOUtils: waiting for profileBeforeChange IO to complete
[task 2021-07-17T11:53:19.113Z] 11:53:19     INFO - PID 1852 | DEBUG: Adding blocker TelemetryController: shutting down for phase profile-before-change-telemetry
[task 2021-07-17T11:53:19.148Z] 11:53:19     INFO - PID 1852 | DEBUG: Adding blocker EnvironmentAddonBuilder for phase AddonManager: Waiting to start provider shutdown.
[task 2021-07-17T11:53:19.168Z] 11:53:19     INFO - PID 1852 | DEBUG: Adding blocker RemoteSettingsClient - finish IDB access. for phase profile-before-change
[task 2021-07-17T11:53:19.174Z] 11:53:19     INFO - PID 1852 | 1626522799174	Marionette	INFO	Marionette enabled
<...>
INFO - PID 1852 | DEBUG: Adding blocker JSON store: writing data for phase profile-before-change
[task 2021-07-17T11:54:12.929Z] 11:54:12     INFO - PID 1852 | DEBUG: Adding blocker Remote Settings profile-before-change for phase profile-before-change
[task 2021-07-17T11:54:13.046Z] 11:54:13     INFO - PID 1852 | DEBUG: Adding blocker JSON store: writing data for phase AddonManager: Waiting for providers to shut down.
[task 2021-07-17T11:54:13.144Z] 11:54:13     INFO - PID 1852 | DEBUG: Adding blocker ContentParent: id=1657915d800 for phase xpcom-will-shutdown
[task 2021-07-17T11:54:13.145Z] 11:54:13     INFO - PID 1852 | DEBUG: Adding blocker ContentParent: id=1657915d800 for phase profile-before-change
[task 2021-07-17T11:54:13.146Z] 11:54:13     INFO - PID 1852 | DEBUG: Adding blocker ContentParent: id=16579156000 for phase xpcom-will-shutdown
[task 2021-07-17T11:54:13.147Z] 11:54:13     INFO - PID 1852 | DEBUG: Adding blocker ContentParent: id=16579156000 for phase profile-before-change
[task 2021-07-17T11:54:13.155Z] 11:54:13     INFO - PID 1852 | 1626522853153	Marionette	TRACE	Received observer notification marionette-startup-requested
[task 2021-07-17T11:54:13.156Z] 11:54:13     INFO - PID 1852 | 1626522853154	Marionette	TRACE	Waiting until startup recorder finished recording startup scripts...
[task 2021-07-17T11:54:13.189Z] 11:54:13     INFO - PID 1852 | 1626522853187	Marionette	TRACE	All scripts recorded.
[task 2021-07-17T11:54:13.192Z] 11:54:13     INFO - PID 1852 | 1626522853190	Marionette	INFO	Listening on port 2828
[task 2021-07-17T11:54:13.192Z] 11:54:13     INFO - PID 1852 | 1626522853191	Marionette	DEBUG	Marionette is listening
[task 2021-07-17T11:54:13.250Z] 11:54:13     INFO - PID 1852 | DEBUG: Adding blocker DownloadAutoSaveView: writing data for phase profile-before-change
[task 2021-07-17T11:54:13.256Z] 11:54:13     INFO - PID 1852 | ###!!! [Parent][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
[task 2021-07-17T11:54:13.361Z] 11:54:13     INFO - PID 1852 | DEBUG: Adding blocker ScriptPreloader: Saving bytecode cache for phase xpcom-will-shutdown
[task 2021-07-17T11:54:13.377Z] 11:54:13     INFO - PID 1852 | 1626522853376	Marionette	DEBUG	Accepted connection 0 from 127.0.0.1:50213
[task 2021-07-17T11:54:13.378Z] 11:54:13     INFO - PID 1852 | 1626522853377	geckodriver::marionette	DEBUG	Connection to Marionette established on 127.0.0.1:2828.
[task 2021-07-17T11:54:13.384Z] 11:54:13     INFO - PID 1852 | 1626522853383	Marionette	DEBUG	0 -> [0,1,"WebDriver:NewSession",{}]
[task 2021-07-17T11:54:13.412Z] 11:54:13     INFO - PID 1852 | 1626522853410	Marionette	DEBUG	0 <- [1,1,null,{"sessionId":"bf209027-376c-4a7b-be62-272d20b705aa","capabilities":{"browserName":"firefox","browserVersion":"92.0a ... i.mozrunner","moz:shutdownTimeout":60000,"moz:useNonSpecCompliantPointerOrigin":false,"moz:webdriverClick":true,"proxy":{}}}]
[task 2021-07-17T11:54:13.419Z] 11:54:13     INFO - PID 1852 | 1626522853415	webdriver::server	DEBUG	<- 200 OK {"value":{"sessionId":"bf209027-376c-4a7b-be62-272d20b705aa","capabilities":{"acceptInsecureCerts":false,"browserName":"firefox","browserVersion":"92.0a1","moz:accessibilityChecks":false,"moz:buildID":"20210717093616","moz:geckodriverVersion":"0.29.1","moz:headless":false,"moz:processID":1436,"moz:profile":"C:\\Users\\task_1626522481\\AppData\\Local\\Temp\\tmpkw3nb0ki.mozrunner","moz:shutdownTimeout":60000,"moz:useNonSpecCompliantPointerOrigin":false,"moz:webdriverClick":true,"pageLoadStrategy":"normal","platformName":"windows","platformVersion":"10.0","proxy":{},"setWindowRect":true,"strictFileInteractability":false,"timeouts":{"implicit":0,"pageLoad":300000,"script":30000},"unhandledPromptBehavior":"dismiss and notify"}}}
[task 2021-07-17T11:54:13.420Z] 11:54:13     INFO - PID 1852 | 1626522853417	webdriver::server	DEBUG	-> POST /session/bf209027-376c-4a7b-be62-272d20b705aa/window/rect {"width": 800, "height": 600}
[task 2021-07-17T11:54:13.421Z] 11:54:13     INFO - PID 1852 | 1626522853418	Marionette	DEBUG	0 -> [0,2,"WebDriver:SetWindowRect",{"height":600,"width":800}]
[task 2021-07-17T11:54:13.422Z] 11:54:13     INFO - TEST-UNEXPECTED-TIMEOUT | /webdriver/tests/bidi/new_session/connect.py | expected OK
[task 2021-07-17T11:54:13.422Z] 11:54:13     INFO - TEST-INFO took 55031ms
[task 2021-07-17T11:54:13.423Z] 11:54:13     INFO - Restarting browser for new test group
[task 2021-07-17T11:54:13.727Z] 11:54:13     INFO - PID 1852 | 1626522853419	Marionette	DEBUG	0 <- [1,2,null,{"x":100,"y":100,"width":800,"height":600}]
[task 2021-07-17T11:54:13.728Z] 11:54:13     INFO - PID 1852 | 1626522853420	webdriver::server	DEBUG	<- 200 OK {"value":{"x":100,"y":100,"width":800,"height":600}}
[task 2021-07-17T11:54:13.728Z] 11:54:13     INFO - PID 1852 | 1626522853422	webdriver::server	DEBUG	-> POST /session/bf209027-376c-4a7b-be62-272d20b705aa/window/rect {"x": 100, "y": 100}
[task 2021-07-17T11:54:13.729Z] 11:54:13     INFO - PID 1852 | 1626522853423	Marionette	DEBUG	0 -> [0,3,"WebDriver:SetWindowRect",{"x":100,"y":100}]
[task 2021-07-17T11:54:13.730Z] 11:54:13     INFO - Closing logging queue
[task 2021-07-17T11:54:13.730Z] 11:54:13     INFO - queue closed
[task 2021-07-17T11:54:13.732Z] 11:54:13     INFO - Starting runner
[task 2021-07-17T11:54:14.860Z] 11:54:14     INFO - PID 1860 | 1626522854361	geckodriver	INFO	Listening on 127.0.0.1:50221
[task 2021-07-17T11:54:14.861Z] 11:54:14     INFO - WebDriver HTTP server listening at http://127.0.0.1:50221/
[task 2021-07-17T11:54:14.862Z] 11:54:14     INFO - TEST-START | /webdriver/tests/delete_session/delete.py

Comment 1

[Intermittent Failures Robot]

2 failures in 2224 pushes (0.001 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-central: 2

Platform and build breakdown:

• windows10-64-ccov-qr: 2
  • opt: 2

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1721011&startday=2021-07-12&endday=2021-07-18&tree=all

Comment 2

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

Problem here is that there is no reply to the WebDriver:SetWindowRect command:

[task 2021-07-17T11:54:13.421Z] 11:54:13     INFO - PID 1852 | 1626522853418	Marionette	DEBUG	0 -> [0,2,"WebDriver:SetWindowRect",{"height":600,"width":800}]
[task 2021-07-17T11:54:13.422Z] 11:54:13     INFO - TEST-UNEXPECTED-TIMEOUT | /webdriver/tests/bidi/new_session/connect.py | expected OK

As such it is not related to bug 1721012.

Comment 3

[BugBot [:suhaib / :marco/ :calixte]]

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

Comment 4

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

And this is not a regression by this specific bug.

Comment 5

[Intermittent Failures Robot]

3 failures in 3131 pushes (0.001 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-central: 3

Platform and build breakdown:

• windows10-64-ccov-qr: 3
  • opt: 3

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1721011&startday=2021-07-26&endday=2021-08-01&tree=all

Comment 6

[Intermittent Failures Robot]

3 failures in 2829 pushes (0.001 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-central: 3

Platform and build breakdown:

• windows10-64-ccov-qr: 3
  • opt: 3

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1721011&startday=2021-08-02&endday=2021-08-08&tree=all

Comment 7

[Intermittent Failures Robot]

4 failures in 3025 pushes (0.001 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-central: 4

Platform and build breakdown:

• windows10-64-ccov-qr: 4
  • opt: 4

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1721011&startday=2021-08-09&endday=2021-08-15&tree=all

Comment 8

[Intermittent Failures Robot]

1 failures in 2899 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-beta: 1

Platform and build breakdown:

• linux1804-64-asan-qr: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1721011&startday=2021-08-16&endday=2021-08-22&tree=all

Comment 9

[BugBot [:suhaib / :marco/ :calixte]]

https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
For more information, please visit auto_nag documentation.

Comment 10

[Iulian Moraru]

The failure reappeared on mozilla-beta and is now failing on tier 1.
https://treeherder.mozilla.org/logviewer?job_id=355955218&repo=mozilla-beta&lineNumber=2598

Comment 11

[Intermittent Failures Robot]

1 failures in 2845 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-beta: 1

Platform and build breakdown:

• windows10-64-2004-shippable-qr: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1721011&startday=2021-10-25&endday=2021-10-31&tree=all

Comment 12

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

The latest failure is caused by a slow shutdown of Firefox.

Comment 13

[Intermittent Failures Robot]

1 failures in 3030 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• try: 1

Platform and build breakdown:

• windows10-64-2004-devedition-qr: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1721011&startday=2021-11-01&endday=2021-11-07&tree=all

Comment 14

[BugBot [:suhaib / :marco/ :calixte]]

https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
For more information, please visit auto_nag documentation.

Comment 15

[Marian-Vasile Laza]

Recent failure log: https://treeherder.mozilla.org/logviewer?job_id=360824285&repo=autoland&lineNumber=6704

Comment 16

[Intermittent Failures Robot]

1 failures in 3319 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 1

Platform and build breakdown:

• windows10-64-2004-qr: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1721011&startday=2021-12-06&endday=2021-12-12&tree=all

Comment 17

[BugBot [:suhaib / :marco/ :calixte]]

https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
For more information, please visit auto_nag documentation.

Comment 18

[Treeherder Bug Filer]

New failure instance: https://treeherder.mozilla.org/logviewer?job_id=365282235&repo=autoland

Comment 20

[BMO Automation]

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