1784870 - Intermittent Windows Shippable TEST-UNEXPECTED-TIMEOUT | /webdriver/tests/<test-name> | expected OK (Waiting for initial application window)

Status: RESOLVED FIXED

(Remote Protocol :: Marionette, defect, P5)

Description

[Treeherder Bug Filer]

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

---

[task 2022-08-15T11:40:53.617Z] 11:40:53     INFO - TEST-START | /webdriver/tests/bidi/browsing_context/navigate/invalid.py
[task 2022-08-15T11:40:53.691Z] 11:40:53     INFO - STDOUT: ============================= test session starts =============================
[task 2022-08-15T11:40:53.706Z] 11:40:53     INFO - STDOUT: platform win32 -- Python 3.9.5, pytest-7.0.1, pluggy-unknown -- Z:\task_166055952866513\build\venv\Scripts\python.exe
[task 2022-08-15T11:40:53.708Z] 11:40:53     INFO - STDOUT: rootdir: Z:\task_166055952866513\build
[task 2022-08-15T11:40:53.709Z] 11:40:53     INFO - STDOUT: plugins: asyncio-0.14.0
[task 2022-08-15T11:40:53.710Z] 11:40:53     INFO - STDOUT: collecting ... 
[task 2022-08-15T11:40:53.737Z] 11:40:53     INFO - STDOUT: collected 20 items
[task 2022-08-15T11:40:53.743Z] 11:40:53     INFO - STDOUT: tests/web-platform/tests/webdriver/tests/bidi/browsing_context/navigate/invalid.py::test_params_context_invalid_type[None] 
[task 2022-08-15T11:40:53.754Z] 11:40:53     INFO - PID 2256 | 1660563653752	webdriver::server	DEBUG	-> POST /session {"capabilities": {"alwaysMatch": {"moz:firefoxOptions": {"args": ["--profile", "C:\\Users\\task_166055952866513\\AppData\\Local\\Temp\\tmpcp2p5hij.mozrunner"], "binary": "Z:\\task_166055952866513\\build\\application\\firefox\\firefox.exe"}, "webSocketUrl": true}}}
[task 2022-08-15T11:40:53.754Z] 11:40:53     INFO - PID 2256 | 1660563653752	geckodriver::capabilities	DEBUG	Trying to read firefox version from ini files
[task 2022-08-15T11:40:53.755Z] 11:40:53     INFO - PID 2256 | 1660563653753	geckodriver::capabilities	DEBUG	Found version 105.0a1
[task 2022-08-15T11:40:53.761Z] 11:40:53     INFO - PID 2256 | 1660563653760	geckodriver::browser	DEBUG	Backing up prefs to "C:\\Users\\task_166055952866513\\AppData\\Local\\Temp\\tmpcp2p5hij.mozrunner\\user.geckodriver_backup"
[task 2022-08-15T11:40:53.772Z] 11:40:53     INFO - PID 2256 | 1660563653774	mozrunner::runner	INFO	Running command: "Z:\\task_166055952866513\\build\\application\\firefox\\firefox.exe" "--marionette" "--profile" "C:\\Users\\task_166055952866513\\AppData\\Local\\Temp\\tmpcp2p5hij.mozrunner" "--remote-debugging-port" "9222" "--remote-allow-hosts" "localhost" "-no-remote"
[task 2022-08-15T11:40:53.778Z] 11:40:53     INFO - PID 2256 | 1660563653777	geckodriver::marionette	DEBUG	Waiting 60s to connect to browser on 127.0.0.1
[task 2022-08-15T11:40:53.779Z] 11:40:53     INFO - PID 2256 | 1660563653777	geckodriver::browser	TRACE	Failed to open C:\Users\task_166055952866513\AppData\Local\Temp\tmpcp2p5hij.mozrunner\MarionetteActivePort
[task 2022-08-15T11:40:53.780Z] 11:40:53     INFO - PID 2256 | 1660563653777	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2022-08-15T11:40:53.885Z] 11:40:53     INFO - PID 2256 | 1660563653885	geckodriver::browser	TRACE	Failed to open C:\Users\task_166055952866513\AppData\Local\Temp\tmpcp2p5hij.mozrunner\MarionetteActivePort
[task 2022-08-15T11:40:53.887Z] 11:40:53     INFO - PID 2256 | 1660563653885	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2022-08-15T11:40:53.992Z] 11:40:53     INFO - PID 2256 | 1660563653993	geckodriver::browser	TRACE	Failed to open C:\Users\task_166055952866513\AppData\Local\Temp\tmpcp2p5hij.mozrunner\MarionetteActivePort
[task 2022-08-15T11:40:53.994Z] 11:40:53     INFO - PID 2256 | 1660563653993	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2022-08-15T11:40:54.005Z] 11:40:54     INFO - PID 2256 | 1660563654007	RemoteAgent	DEBUG	WebDriver BiDi enabled
[task 2022-08-15T11:40:54.008Z] 11:40:54     INFO - PID 2256 | 1660563654007	RemoteAgent	DEBUG	CDP enabled
[task 2022-08-15T11:40:54.009Z] 11:40:54     INFO - PID 2256 | 1660563654007	Marionette	INFO	Marionette enabled
[task 2022-08-15T11:40:54.010Z] 11:40:54     INFO - PID 2256 | 1660563654008	Marionette	TRACE	Received observer notification final-ui-startup
[task 2022-08-15T11:40:54.010Z] 11:40:54     INFO - PID 2256 | 1660563654009	Marionette	INFO	Listening on port 51778
[task 2022-08-15T11:40:54.011Z] 11:40:54     INFO - PID 2256 | 1660563654009	Marionette	DEBUG	Marionette is listening
[task 2022-08-15T11:40:54.012Z] 11:40:54     INFO - PID 2256 | 1660563654009	RemoteAgent	TRACE	Received observer notification final-ui-startup
[task 2022-08-15T11:40:54.012Z] 11:40:54     INFO - PID 2256 | WebDriver BiDi listening on ws://localhost:9222
[task 2022-08-15T11:40:54.013Z] 11:40:54     INFO - PID 2256 | 1660563654011	CDP	DEBUG	Waiting for initial application window
[task 2022-08-15T11:40:54.102Z] 11:40:54     INFO - PID 2256 | Read port: 51778
[task 2022-08-15T11:40:54.114Z] 11:40:54     INFO - PID 2256 | 1660563654113	Marionette	DEBUG	Accepted connection 0 from 127.0.0.1:51779
[task 2022-08-15T11:40:54.125Z] 11:40:54     INFO - PID 2256 | 1660563654128	geckodriver::marionette	DEBUG	Connection to Marionette established on 127.0.0.1:51778.
[task 2022-08-15T11:40:54.140Z] 11:40:54     INFO - PID 2256 | 1660563654154	Marionette	DEBUG	0 -> [0,1,"WebDriver:NewSession",{"webSocketUrl":true}]
[task 2022-08-15T11:40:54.157Z] 11:40:54     INFO - PID 2256 | 1660563654156	WebDriver BiDi	DEBUG	Waiting for initial application window
[task 2022-08-15T11:41:23.637Z] 11:41:23     INFO - TEST-UNEXPECTED-TIMEOUT | /webdriver/tests/bidi/browsing_context/navigate/invalid.py | expected OK
[task 2022-08-15T11:41:23.637Z] 11:41:23     INFO - TEST-INFO took 30024ms
[task 2022-08-15T11:41:23.983Z] 11:41:23     INFO - Closing logging queue
[task 2022-08-15T11:41:23.994Z] 11:41:23     INFO - queue closed
[task 2022-08-15T11:41:24.505Z] 11:41:24     INFO - PID 5612 | 1660563684011	geckodriver	INFO	Listening on 127.0.0.1:49892
[task 2022-08-15T11:41:24.508Z] 11:41:24     INFO - Starting runner
[task 2022-08-15T11:41:25.114Z] 11:41:25     INFO - TEST-START | /webdriver/tests/bidi/browsing_context/navigate/navigate.py

Comment 1

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

The initial application window cannot be found by Marionette. It needs bug 1784625 to be fixed.

Comment 3

[Natalia Csoregi [:nataliaCs]]

Update:

There have been 32 failures within the last 7 days:

• 13 failures on Windows 10 x86 2004 WebRender Shippable opt
• 3 failures on Windows 10 x64 2004 CCov WebRender opt
• 16 failures on Windows 10 x64 2004 WebRender Shippable opt

Recent failure log: https://treeherder.mozilla.org/logviewer?job_id=387928223&repo=mozilla-central&lineNumber=90491

Comment 4

[Intermittent Failures Robot]

34 failures in 2916 pushes (0.012 failures/push) were associated with this bug in the last 7 days.

This is the #32 most frequent failure this week.

** This failure happened more than 30 times this week! Resolving this bug is a high priority. **

** Try to resolve this bug as soon as possible. If unresolved for 2 weeks, the affected test(s) may be disabled. **

Repository breakdown:

• mozilla-central: 34

Platform and build breakdown:

• windows10-64-2004-shippable-qr: 17
  • opt: 17
• windows10-32-2004-shippable-qr: 14
  • opt: 14
• windows10-64-2004-ccov-qr: 3
  • opt: 3

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

Comment 5

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

(In reply to Natalia Csoregi [:nataliaCs] from comment #3)

• 3 failures on Windows 10 x64 2004 CCov WebRender opt

The CCOV failures are wrongly classified and are related to 1783217. Updating the bug's summary to clarify for which test failures this bug is actually relevant.

Comment 8

[Intermittent Failures Robot]

23 failures in 3293 pushes (0.007 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-central: 22
• mozilla-beta: 1

Platform and build breakdown:

• windows10-64-2004-shippable-qr: 16
  • opt: 16
• windows10-32-2004-shippable-qr: 7
  • opt: 7

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

Comment 10

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

Caused by bug 965392 which now has been backed out. We can mark this one as fixed.

Comment 11

[Intermittent Failures Robot]

15 failures in 3537 pushes (0.004 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-central: 15

Platform and build breakdown:

• windows10-64-2004-shippable-qr: 4
  • opt: 4
• windows10-32-2004-shippable-qr: 6
  • opt: 6
• windows10-64-2004-ccov-qr: 5
  • opt: 5

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1784870&startday=2022-08-29&endday=2022-09-04&tree=all

Comment 12

[BMO Automation]

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

Comment 13

[Intermittent Failures Robot]

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

Repository breakdown:

• autoland: 1

Platform and build breakdown:

• windows11-32-2009-qr: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1784870&startday=2023-04-03&endday=2023-04-09&tree=all

Comment 14

[Intermittent Failures Robot]

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

Repository breakdown:

• autoland: 1

Platform and build breakdown:

• android-em-7-0-x86_64-qr: 1
  • debug: 1

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

Comment 15

[Intermittent Failures Robot]

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

Repository breakdown:

• mozilla-central: 1

Platform and build breakdown:

• windows11-64-2009-ccov-qr: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1784870&startday=2023-08-07&endday=2023-08-13&tree=all

Comment 16

[Intermittent Failures Robot]

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

Repository breakdown:

• autoland: 1

Platform and build breakdown:

• windows11-32-2009-qr: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1784870&startday=2023-09-18&endday=2023-09-24&tree=all

Comment 17

[Intermittent Failures Robot]

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

Repository breakdown:

• mozilla-beta: 1

Platform and build breakdown:

• windows11-64-2009-qr: 1
  • debug: 1

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

Comment 18

[Intermittent Failures Robot]

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

Repository breakdown:

• mozilla-esr115: 1

Platform and build breakdown:

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

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1784870&startday=2024-02-05&endday=2024-02-11&tree=all

Comment 19

[Intermittent Failures Robot]

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

Repository breakdown:

• autoland: 1

Platform and build breakdown:

• android-em-7-0-x86_64-qr: 1
  • debug-isolated-process: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1784870&startday=2024-03-04&endday=2024-03-10&tree=all