Closed Bug 1769430 Opened 2 years ago Closed 3 months ago

Intermittent /webdriver/tests/forward/forward.py | | single tracking bug

Categories

(Remote Protocol :: Marionette, defect, P5)

defect

Tracking

(firefox-esr102 unaffected, firefox-esr115 unaffected, firefox114 unaffected, firefox115 unaffected, firefox116 affected, firefox117 affected)

RESOLVED INCOMPLETE
Tracking Status
firefox-esr102 --- unaffected
firefox-esr115 --- unaffected
firefox114 --- unaffected
firefox115 --- unaffected
firefox116 --- affected
firefox117 --- affected

People

(Reporter: intermittent-bug-filer, Unassigned)

References

(Depends on 1 open bug, Regression)

Details

(Keywords: intermittent-failure, regression)

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


[task 2022-05-15T12:49:26.491Z] 12:49:26     INFO - TEST-START | /webdriver/tests/forward/forward.py
[task 2022-05-15T12:49:27.452Z] 12:49:27     INFO - STDOUT: ============================= test session starts =============================
[task 2022-05-15T12:49:27.466Z] 12:49:27     INFO - STDOUT: platform win32 -- Python 3.9.5, pytest-6.1.1, py-1.5.2, pluggy-unknown -- Z:\task_165261723909740\build\venv\Scripts\python.exe
[task 2022-05-15T12:49:27.470Z] 12:49:27     INFO - STDOUT: rootdir: Z:\task_165261723909740\build
[task 2022-05-15T12:49:27.471Z] 12:49:27     INFO - STDOUT: plugins: asyncio-0.14.0
[task 2022-05-15T12:49:27.472Z] 12:49:27     INFO - STDOUT: collecting ... 
[task 2022-05-15T12:49:27.578Z] 12:49:27     INFO - STDOUT: collected 10 items
[task 2022-05-15T12:49:27.584Z] 12:49:27     INFO - STDOUT: tests/web-platform/tests/webdriver/tests/forward/forward.py::test_null_response_value 
[task 2022-05-15T12:49:27.598Z] 12:49:27     INFO - PID 6556 | 1652618967595	webdriver::server	DEBUG	-> POST /session {"capabilities": {"alwaysMatch": {"moz:firefoxOptions": {"args": ["--profile", "C:\\Users\\task_165261723909740\\AppData\\Local\\Temp\\tmppswczvv0.mozrunner"], "binary": "Z:\\task_165261723909740\\build\\application\\firefox\\firefox.exe"}}}}
[task 2022-05-15T12:49:27.603Z] 12:49:27     INFO - PID 6556 | 1652618967596	geckodriver::capabilities	DEBUG	Trying to read firefox version from ini files
[task 2022-05-15T12:49:27.605Z] 12:49:27     INFO - PID 6556 | 1652618967601	geckodriver::capabilities	DEBUG	Found version 102.0
[task 2022-05-15T12:49:27.608Z] 12:49:27     INFO - PID 6556 | 1652618967605	geckodriver::browser	DEBUG	Backing up prefs to "C:\\Users\\task_165261723909740\\AppData\\Local\\Temp\\tmppswczvv0.mozrunner\\user.geckodriver_backup"
[task 2022-05-15T12:49:27.621Z] 12:49:27     INFO - PID 6556 | 1652618967624	mozrunner::runner	INFO	Running command: "Z:\\task_165261723909740\\build\\application\\firefox\\firefox.exe" "--marionette" "--profile" "C:\\Users\\task_165261723909740\\AppData\\Local\\Temp\\tmppswczvv0.mozrunner" "-no-remote"
[task 2022-05-15T12:49:27.634Z] 12:49:27     INFO - PID 6556 | 1652618967632	geckodriver::marionette	DEBUG	Waiting 60s to connect to browser on 127.0.0.1
[task 2022-05-15T12:49:27.634Z] 12:49:27     INFO - PID 6556 | 1652618967632	geckodriver::browser	TRACE	Failed to open C:\Users\task_165261723909740\AppData\Local\Temp\tmppswczvv0.mozrunner\MarionetteActivePort
[task 2022-05-15T12:49:27.635Z] 12:49:27     INFO - PID 6556 | 1652618967632	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2022-05-15T12:49:27.742Z] 12:49:27     INFO - PID 6556 | 1652618967743	geckodriver::browser	TRACE	Failed to open C:\Users\task_165261723909740\AppData\Local\Temp\tmppswczvv0.mozrunner\MarionetteActivePort
[task 2022-05-15T12:49:27.757Z] 12:49:27     INFO - PID 6556 | 1652618967744	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2022-05-15T12:49:27.850Z] 12:49:27     INFO - PID 6556 | 1652618967851	geckodriver::browser	TRACE	Failed to open C:\Users\task_165261723909740\AppData\Local\Temp\tmppswczvv0.mozrunner\MarionetteActivePort
[task 2022-05-15T12:49:27.866Z] 12:49:27     INFO - PID 6556 | 1652618967851	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2022-05-15T12:49:27.972Z] 12:49:27     INFO - PID 6556 | 1652618967957	geckodriver::browser	TRACE	Failed to open C:\Users\task_165261723909740\AppData\Local\Temp\tmppswczvv0.mozrunner\MarionetteActivePort
[task 2022-05-15T12:49:27.981Z] 12:49:27     INFO - PID 6556 | 1652618967958	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2022-05-15T12:49:28.069Z] 12:49:28     INFO - PID 6556 | 1652618968070	geckodriver::browser	TRACE	Failed to open C:\Users\task_165261723909740\AppData\Local\Temp\tmppswczvv0.mozrunner\MarionetteActivePort
[task 2022-05-15T12:49:28.084Z] 12:49:28     INFO - PID 6556 | 1652618968071	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2022-05-15T12:49:28.178Z] 12:49:28     INFO - PID 6556 | 1652618968179	geckodriver::browser	TRACE	Failed to open C:\Users\task_165261723909740\AppData\Local\Temp\tmppswczvv0.mozrunner\MarionetteActivePort
[task 2022-05-15T12:49:28.191Z] 12:49:28     INFO - PID 6556 | 1652618968179	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2022-05-15T12:49:28.283Z] 12:49:28     INFO - PID 6556 | 1652618968284	geckodriver::browser	TRACE	Failed to open C:\Users\task_165261723909740\AppData\Local\Temp\tmppswczvv0.mozrunner\MarionetteActivePort
[task 2022-05-15T12:49:28.314Z] 12:49:28     INFO - PID 6556 | 1652618968285	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2022-05-15T12:49:28.395Z] 12:49:28     INFO - PID 6556 | 1652618968396	geckodriver::browser	TRACE	Failed to open C:\Users\task_165261723909740\AppData\Local\Temp\tmppswczvv0.mozrunner\MarionetteActivePort
[task 2022-05-15T12:49:28.395Z] 12:49:28     INFO - PID 6556 | 1652618968397	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2022-05-15T12:49:28.481Z] 12:49:28     INFO - PID 6556 | 1652618968488	Marionette	INFO	Marionette enabled
[task 2022-05-15T12:49:28.495Z] 12:49:28     INFO - PID 6556 | 1652618968490	Marionette	TRACE	Received observer notification final-ui-startup
[task 2022-05-15T12:49:28.498Z] 12:49:28     INFO - PID 6556 | 1652618968494	Marionette	INFO	Listening on port 56322
[task 2022-05-15T12:49:28.499Z] 12:49:28     INFO - PID 6556 | 1652618968496	Marionette	DEBUG	Marionette is listening
[task 2022-05-15T12:49:28.513Z] 12:49:28     INFO - PID 6556 | Read port: 56322

[task 2022-05-15T12:49:52.263Z] 12:49:52     INFO - STDOUT: tests/web-platform/tests/webdriver/tests/forward/forward.py::test_cross_origin[capabilities0] 
[task 2022-05-15T12:49:52.264Z] 12:49:52     INFO - PID 6556 | 1652618992263	webdriver::server	DEBUG	-> DELETE /session/5d21768c-ce9a-4ef8-9bcb-ba79bf351b80
[task 2022-05-15T12:49:52.266Z] 12:49:52     INFO - PID 6556 | 1652618992266	Marionette	DEBUG	0 -> [0,265,"Marionette:Quit",{"flags":["eForceQuit"]}]
[task 2022-05-15T12:49:52.267Z] 12:49:52     INFO - PID 6556 | 1652618992267	Marionette	INFO	Stopped listening on port 56322
[task 2022-05-15T12:49:52.473Z] 12:49:52     INFO - PID 6556 | 1652618992476	Marionette	TRACE	Received observer notification quit-application
[task 2022-05-15T12:49:52.485Z] 12:49:52     INFO - PID 6556 | 1652618992482	Marionette	TRACE	Received observer notification quit-application
[task 2022-05-15T12:49:52.487Z] 12:49:52     INFO - PID 6556 | 1652618992483	Marionette	DEBUG	Marionette stopped listening
[task 2022-05-15T12:49:52.489Z] 12:49:52     INFO - PID 6556 | 1652618992488	Marionette	DEBUG	0 <- [1,265,null,{"cause":"shutdown","forced":false}]
[task 2022-05-15T12:49:52.605Z] 12:49:52     INFO - PID 6556 | 1652618992607	webdriver::server	DEBUG	Teardown session
[task 2022-05-15T12:49:52.618Z] 12:49:52     INFO - PID 6556 | 1652618992622	Marionette	DEBUG	Closed connection 0
[task 2022-05-15T12:49:53.685Z] 12:49:53     INFO - PID 6556 | 1652618993685	geckodriver::browser	DEBUG	Browser process stopped: exit code: 0
[task 2022-05-15T12:49:53.696Z] 12:49:53     INFO - PID 6556 | 1652618993694	webdriver::server	DEBUG	<- 200 OK {"value":null}
[task 2022-05-15T12:49:53.709Z] 12:49:53     INFO - PID 6556 | 1652618993703	webdriver::server	DEBUG	-> POST /session {"capabilities": {"alwaysMatch": {"moz:firefoxOptions": {"args": ["--profile", "C:\\Users\\task_165261723909740\\AppData\\Local\\Temp\\tmppswczvv0.mozrunner"], "binary": "Z:\\task_165261723909740\\build\\application\\firefox\\firefox.exe"}, "acceptInsecureCerts": true}}}
[task 2022-05-15T12:49:53.710Z] 12:49:53     INFO - PID 6556 | 1652618993704	geckodriver::capabilities	DEBUG	Trying to read firefox version from ini files
[task 2022-05-15T12:49:53.712Z] 12:49:53     INFO - PID 6556 | 1652618993708	geckodriver::capabilities	DEBUG	Found version 102.0
[task 2022-05-15T12:49:53.713Z] 12:49:53     INFO - PID 6556 | 1652618993711	geckodriver::browser	DEBUG	Backing up prefs to "C:\\Users\\task_165261723909740\\AppData\\Local\\Temp\\tmppswczvv0.mozrunner\\user.geckodriver_backup"
[task 2022-05-15T12:49:53.725Z] 12:49:53     INFO - PID 6556 | 1652618993729	mozrunner::runner	INFO	Running command: "Z:\\task_165261723909740\\build\\application\\firefox\\firefox.exe" "--marionette" "--profile" "C:\\Users\\task_165261723909740\\AppData\\Local\\Temp\\tmppswczvv0.mozrunner" "-no-remote"
[task 2022-05-15T12:49:53.741Z] 12:49:53     INFO - PID 6556 | 1652618993739	geckodriver::marionette	DEBUG	Waiting 60s to connect to browser on 127.0.0.1
[task 2022-05-15T12:49:53.743Z] 12:49:53     INFO - PID 6556 | 1652618993739	geckodriver::browser	TRACE	Failed to open C:\Users\task_165261723909740\AppData\Local\Temp\tmppswczvv0.mozrunner\MarionetteActivePort
[task 2022-05-15T12:49:53.744Z] 12:49:53     INFO - PID 6556 | 1652618993739	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2022-05-15T12:49:53.850Z] 12:49:53     INFO - PID 6556 | 1652618993852	geckodriver::browser	TRACE	Failed to open C:\Users\task_165261723909740\AppData\Local\Temp\tmppswczvv0.mozrunner\MarionetteActivePort
[task 2022-05-15T12:49:53.864Z] 12:49:53     INFO - PID 6556 | 1652618993853	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2022-05-15T12:49:53.971Z] 12:49:53     INFO - PID 6556 | 1652618993958	geckodriver::browser	TRACE	Failed to open C:\Users\task_165261723909740\AppData\Local\Temp\tmppswczvv0.mozrunner\MarionetteActivePort
[task 2022-05-15T12:49:53.979Z] 12:49:53     INFO - PID 6556 | 1652618993958	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2022-05-15T12:49:54.083Z] 12:49:54     INFO - PID 6556 | 1652618994070	geckodriver::browser	TRACE	Failed to open C:\Users\task_165261723909740\AppData\Local\Temp\tmppswczvv0.mozrunner\MarionetteActivePort
[task 2022-05-15T12:49:54.086Z] 12:49:54     INFO - PID 6556 | 1652618994070	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2022-05-15T12:49:54.177Z] 12:49:54     INFO - PID 6556 | 1652618994178	geckodriver::browser	TRACE	Failed to open C:\Users\task_165261723909740\AppData\Local\Temp\tmppswczvv0.mozrunner\MarionetteActivePort
[task 2022-05-15T12:49:54.190Z] 12:49:54     INFO - PID 6556 | 1652618994179	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2022-05-15T12:49:54.282Z] 12:49:54     INFO - PID 6556 | 1652618994284	geckodriver::browser	TRACE	Failed to open C:\Users\task_165261723909740\AppData\Local\Temp\tmppswczvv0.mozrunner\MarionetteActivePort
[task 2022-05-15T12:49:54.303Z] 12:49:54     INFO - PID 6556 | 1652618994285	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2022-05-15T12:49:54.394Z] 12:49:54     INFO - PID 6556 | 1652618994394	geckodriver::browser	TRACE	Failed to open C:\Users\task_165261723909740\AppData\Local\Temp\tmppswczvv0.mozrunner\MarionetteActivePort
[task 2022-05-15T12:49:54.410Z] 12:49:54     INFO - PID 6556 | 1652618994395	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2022-05-15T12:49:54.503Z] 12:49:54     INFO - PID 6556 | 1652618994504	geckodriver::browser	TRACE	Failed to open C:\Users\task_165261723909740\AppData\Local\Temp\tmppswczvv0.mozrunner\MarionetteActivePort
[task 2022-05-15T12:49:54.516Z] 12:49:54     INFO - PID 6556 | 1652618994505	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2022-05-15T12:49:54.609Z] 12:49:54     INFO - PID 6556 | 1652618994611	geckodriver::browser	TRACE	Failed to open C:\Users\task_165261723909740\AppData\Local\Temp\tmppswczvv0.mozrunner\MarionetteActivePort
[task 2022-05-15T12:49:54.626Z] 12:49:54     INFO - PID 6556 | 1652618994612	geckodriver::marionette	TRACE	Retrying in 100ms
[task 2022-05-15T12:49:54.687Z] 12:49:54     INFO - PID 6556 | 1652618994696	Marionette	INFO	Marionette enabled
[task 2022-05-15T12:49:54.701Z] 12:49:54     INFO - PID 6556 | 1652618994698	Marionette	TRACE	Received observer notification final-ui-startup
[task 2022-05-15T12:49:54.703Z] 12:49:54     INFO - PID 6556 | 1652618994701	Marionette	INFO	Listening on port 56629
[task 2022-05-15T12:49:54.704Z] 12:49:54     INFO - PID 6556 | 1652618994703	Marionette	DEBUG	Marionette is listening
[task 2022-05-15T12:49:54.733Z] 12:49:54     INFO - PID 6556 | Read port: 56629
[task 2022-05-15T12:49:54.845Z] 12:49:54     INFO - PID 6556 | 1652618994844	Marionette	DEBUG	Accepted connection 0 from 127.0.0.1:56630
[task 2022-05-15T12:49:54.869Z] 12:49:54     INFO - PID 6556 | 1652618994862	geckodriver::marionette	DEBUG	Connection to Marionette established on 127.0.0.1:56629.
[task 2022-05-15T12:49:54.976Z] 12:49:54     INFO - PID 6556 | 1652618994982	Marionette	DEBUG	0 -> [0,1,"WebDriver:NewSession",{"acceptInsecureCerts":true}]
[task 2022-05-15T12:49:54.996Z] 12:49:54     INFO - PID 6556 | 1652618994989	RemoteAgent	WARN	TLS certificate errors will be ignored for this session
[task 2022-05-15T12:49:55.011Z] 12:49:55     INFO - PID 6556 | 1652618995015	Marionette	DEBUG	Waiting for initial application window
[task 2022-05-15T12:49:56.508Z] 12:49:56     INFO - TEST-UNEXPECTED-TIMEOUT | /webdriver/tests/forward/forward.py | expected OK
[task 2022-05-15T12:49:56.508Z] 12:49:56     INFO - TEST-INFO took 30007ms
[task 2022-05-15T12:49:58.200Z] 12:49:58     INFO - Closing logging queue
[task 2022-05-15T12:49:58.200Z] 12:49:58     INFO - queue closed
[task 2022-05-15T12:49:58.738Z] 12:49:58     INFO - PID 2424 | 1652618998264	geckodriver	INFO	Listening on 127.0.0.1:49841
[task 2022-05-15T12:49:58.750Z] 12:49:58     INFO - Starting runner

Some slow startups of Firefox especially around the first application window being available and ready.

Status: NEW → RESOLVED
Closed: 2 years ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---

(In reply to Intermittent Failures Robot from comment #5)

6 failures in 3057 pushes (0.002 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

  • mozilla-central: 6

Platform and build breakdown:

  • windows10-64-2004-ccov-qr: 6
    • opt: 6

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

The last reported failures are related to a regression for CCOV builds and is covered via bug 1783217. Can we please get these classifications updated?

Status: REOPENED → RESOLVED
Closed: 2 years ago2 years ago
Flags: needinfo?(sheriffs)
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---

Failures have been reclassified.

Status: REOPENED → RESOLVED
Closed: 2 years ago2 years ago
Flags: needinfo?(sheriffs)
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---

Wrong classification which is for bug 1783217.

Status: REOPENED → RESOLVED
Closed: 2 years ago2 years ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
Status: REOPENED → RESOLVED
Closed: 2 years ago2 years ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---

I forgot to remove the former classification when I updated it. That's why this bug got reopened.

Status: REOPENED → RESOLVED
Closed: 2 years ago2 years ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
Status: REOPENED → RESOLVED
Closed: 2 years ago2 years ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
Status: REOPENED → RESOLVED
Closed: 2 years ago2 years ago
Resolution: --- → DUPLICATE
See Also: → 1801671

Not sure why this bug has been marked as duplicate to an unrelated issue. Reopening.

Status: RESOLVED → REOPENED
No longer duplicate of bug: 1783217
Resolution: DUPLICATE → ---
Duplicate of this bug: 1801671
Summary: Intermittent TEST-UNEXPECTED-TIMEOUT | /webdriver/tests/forward/forward.py | expected OK → Intermittent /webdriver/tests/forward/forward.py | | single tracking bug

All the Android failures here are wrongly classified. Sheriffs can you please correct it to bug 1804027? Thanks.

Flags: needinfo?(sheriffs)
Flags: needinfo?(sheriffs)

(In reply to Intermittent Failures Robot from comment #28)

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

All these classifications are wrong and actually related to bug 1804027. Can you please re-classify? Thanks.

Flags: needinfo?(sheriffs)

All the failures have been reclassified.

Flags: needinfo?(sheriffs)

(In reply to Intermittent Failures Robot from comment #31)

Platform and build breakdown:

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

Both of these failures are bug 1804027.

Moving bug to Remote Protocol::Marionette component per bug 1815831.
Component: geckodriver → Marionette
Product: Testing → Remote Protocol

The increased number of failures here is most likely caused by my patch on bug 1822466. There I've added two more tests to that file which now seem to be very close to the file timeout. I'll file a new bug to get the acceptInsecureCerts capabilities marker removed which doesn't seem to be needed anymore and will safe us from two restarts of Firefox.

Keywords: regression
Regressed by: 1822466

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

The removal of the acceptInsecureCerts capability requirement which causes lesser restarts of Firefox helped:

Before:

[task 2023-06-20T16:31:09.626Z] 16:31:09     INFO - TEST-START | /webdriver/tests/classic/forward/forward.py
[..]
[task 2023-06-20T16:32:29.652Z] 16:32:29     INFO - TEST-UNEXPECTED-TIMEOUT | /webdriver/tests/classic/forward/forward.py | expected OK
[task 2023-06-20T16:32:29.652Z] 16:32:29     INFO - TEST-INFO took 80005ms

After:

[task 2023-06-21T04:43:38.059Z] 04:43:38     INFO - TEST-START | /webdriver/tests/classic/forward/forward.py
[..]
[task 2023-06-21T04:44:25.891Z] 04:44:25     INFO - TEST-OK | /webdriver/tests/classic/forward/forward.py | took 47830ms

As it can be seen we no longer run into a timeout for TSAN builds after 80s but roughly take only half the time now. I expect that the intermittent failures for this bug will drop drastically.

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

No longer blocks: 1825501
Depends on: 1825501

No failures in the last 30 days, and those which were listed here are false classifications mainly for navigation timed out.

Status: REOPENED → RESOLVED
Closed: 2 years ago3 months ago
Resolution: --- → INCOMPLETE
You need to log in before you can comment on or make changes to this bug.