1836972 - Intermittent TEST-UNEXPECTED-TIMEOUT | /webdriver/tests/bidi/input/perform_actions/key_events.py | expected OK

Status: RESOLVED FIXED

(Remote Protocol :: WebDriver BiDi, defect, P5)

Description

[Treeherder Bug Filer]

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

---

[task 2023-06-06T12:15:32.882Z] 12:15:32     INFO - STDOUT: tests/web-platform/tests/webdriver/tests/bidi/input/perform_actions/key_events.py::test_key_special_key_sends_keydown[R_PAGEDOWN-expected59] 
[task 2023-06-06T12:15:32.885Z] 12:15:32     INFO - PID 2359 | 1686053732885	RemoteAgent	INFO	Perform WebSocket upgrade for incoming connection from 127.0.0.1:55794
[task 2023-06-06T12:15:32.888Z] 12:15:32     INFO - PID 2359 | 1686053732887	webdriver::server	DEBUG	-> POST /session/a33a789a-f4b4-4483-884d-14b703bfe264/window/rect {"width": 800, "height": 600}
[task 2023-06-06T12:15:32.890Z] 12:15:32     INFO - PID 2359 | 1686053732888	RemoteAgent	DEBUG	WebDriverBiDiConnection a8c8e575-3cea-4331-a124-ecd4ba1227e8 accepted
[task 2023-06-06T12:15:32.890Z] 12:15:32     INFO - PID 2359 | 1686053732889	WebDriver BiDi	DEBUG	Connection a8c8e575-3cea-4331-a124-ecd4ba1227e8 attached to session a33a789a-f4b4-4483-884d-14b703bfe264
[task 2023-06-06T12:15:32.891Z] 12:15:32     INFO - PID 2359 | 1686053732889	Marionette	DEBUG	0 -> [0,1282,"WebDriver:SetWindowRect",{"height":600,"width":800}]
[task 2023-06-06T12:15:32.891Z] 12:15:32     INFO - PID 2359 | 1686053732890	Marionette	TRACE	Requested window geometry matches
[task 2023-06-06T12:15:32.893Z] 12:15:32     INFO - PID 2359 | 1686053732892	Marionette	DEBUG	0 <- [1,1282,null,{"x":100,"y":100,"width":800,"height":600}]
[task 2023-06-06T12:15:32.894Z] 12:15:32     INFO - PID 2359 | 1686053732893	webdriver::server	DEBUG	<- 200 OK {"value":{"x":100,"y":100,"width":800,"height":600}}
[task 2023-06-06T12:15:32.895Z] 12:15:32     INFO - PID 2359 | 1686053732894	webdriver::server	DEBUG	-> POST /session/a33a789a-f4b4-4483-884d-14b703bfe264/window/rect {"x": 100, "y": 100}
[task 2023-06-06T12:15:32.896Z] 12:15:32     INFO - PID 2359 | 1686053732895	Marionette	DEBUG	0 -> [0,1283,"WebDriver:SetWindowRect",{"x":100,"y":100}]
[task 2023-06-06T12:15:32.897Z] 12:15:32     INFO - PID 2359 | 1686053732897	Marionette	TRACE	Requested window geometry matches
[task 2023-06-06T12:15:32.898Z] 12:15:32     INFO - PID 2359 | 1686053732898	Marionette	DEBUG	0 <- [1,1283,null,{"x":100,"y":100,"width":800,"height":600}]
[task 2023-06-06T12:15:32.900Z] 12:15:32     INFO - PID 2359 | 1686053732898	webdriver::server	DEBUG	<- 200 OK {"value":{"x":100,"y":100,"width":800,"height":600}}
[task 2023-06-06T12:15:32.903Z] 12:15:32     INFO - PID 2359 | 1686053732900	RemoteAgent	DEBUG	WebDriverBiDiConnection a8c8e575-3cea-4331-a124-ecd4ba1227e8 -> {"id":573,"method":"browsingContext.getTree","params":{}}
[task 2023-06-06T12:15:32.903Z] 12:15:32     INFO - PID 2359 | 1686053732901	RemoteAgent	TRACE	Module root/browsingContext.jsm found for ROOT
[task 2023-06-06T12:15:32.903Z] 12:15:32     INFO - PID 2359 | 1686053732901	RemoteAgent	TRACE	Received command browsingContext.getTree for destination ROOT
[task 2023-06-06T12:15:32.903Z] 12:15:32     INFO - PID 2359 | 1686053732901	RemoteAgent	TRACE	Module root/browsingContext.jsm found for ROOT
[task 2023-06-06T12:15:32.903Z] 12:15:32     INFO - PID 2359 | 1686053732902	RemoteAgent	DEBUG	WebDriverBiDiConnection a8c8e575-3cea-4331-a124-ecd4ba1227e8 <- {"id":573,"result":{"contexts":[{"context":"e5308be8-4748-458f-a095-4776665b8851","url":"http://web-platform.test:8000/webdriver/tests/support/html/test_actions.html","children":[],"parent":null}]}}
[task 2023-06-06T12:15:32.906Z] 12:15:32     INFO - PID 2359 | 1686053732904	RemoteAgent	DEBUG	WebDriverBiDiConnection a8c8e575-3cea-4331-a124-ecd4ba1227e8 -> {"id":574,"method":"browsingContext.navigate","params":{"context":"e5308be8-4748-458f-a095-4776665b8851","url":"http://web-platform.test:8000/webdriver/tests/support/html/test_actions.html","wait":"complete"}}
[task 2023-06-06T12:15:32.907Z] 12:15:32     INFO - PID 2359 | 1686053732904	RemoteAgent	TRACE	Module root/browsingContext.jsm found for ROOT
[task 2023-06-06T12:15:32.907Z] 12:15:32     INFO - PID 2359 | 1686053732904	RemoteAgent	TRACE	Received command browsingContext.navigate for destination ROOT
[task 2023-06-06T12:15:32.907Z] 12:15:32     INFO - PID 2359 | 1686053732904	RemoteAgent	TRACE	Module root/browsingContext.jsm found for ROOT
[task 2023-06-06T12:15:32.907Z] 12:15:32     INFO - PID 2359 | 1686053732905	RemoteAgent	TRACE	Received command browsingContext._getBaseURL for destination WINDOW_GLOBAL
[task 2023-06-06T12:15:32.909Z] 12:15:32     INFO - PID 2359 | 1686053732905	RemoteAgent	TRACE	Module windowglobal-in-root/browsingContext.jsm found for WINDOW_GLOBAL
[task 2023-06-06T12:15:32.910Z] 12:15:32     INFO - PID 2359 | 1686053732905	RemoteAgent	TRACE	Module windowglobal/browsingContext.jsm found for WINDOW_GLOBAL
[task 2023-06-06T12:15:32.911Z] 12:15:32     INFO - PID 2359 | 1686053732906	RemoteAgent	TRACE	Received command browsingContext._getBaseURL for destination WINDOW_GLOBAL
[task 2023-06-06T12:15:32.911Z] 12:15:32     INFO - PID 2359 | 1686053732906	RemoteAgent	TRACE	Module windowglobal/browsingContext.jsm found for WINDOW_GLOBAL
[task 2023-06-06T12:15:32.911Z] 12:15:32     INFO - PID 2359 | 1686053732906	RemoteAgent	TRACE	Module windowglobal/browsingContext.jsm found for WINDOW_GLOBAL
[task 2023-06-06T12:15:32.912Z] 12:15:32     INFO - PID 2359 | 1686053732909	RemoteAgent	TRACE	[11] ProgressListener Start: expectNavigation=true resolveWhenStarted=false unloadTimeout=1600 waitForExplicitStart=true
[task 2023-06-06T12:15:32.912Z] 12:15:32     INFO - PID 2359 | 1686053732909	RemoteAgent	TRACE	[11] ProgressListener Skip setting the unload timer
[task 2023-06-06T12:15:32.923Z] 12:15:32     INFO - PID 2359 | 1686053732922	RemoteAgent	TRACE	[11] ProgressListener Check loading state: isStart=1 isStop=0
[task 2023-06-06T12:15:32.924Z] 12:15:32     INFO - PID 2359 | 1686053732922	RemoteAgent	TRACE	[11] ProgressListener state=start: http://web-platform.test:8000/webdriver/tests/support/html/test_actions.html
[task 2023-06-06T12:15:33.081Z] 12:15:33     INFO - TEST-UNEXPECTED-TIMEOUT | /webdriver/tests/bidi/input/perform_actions/key_events.py | expected OK
[task 2023-06-06T12:15:33.081Z] 12:15:33     INFO - TEST-INFO took 80003ms
[task 2023-06-06T12:15:43.158Z] 12:15:43  WARNING - Forcibly terminating runner process
[task 2023-06-06T12:15:43.170Z] 12:15:43     INFO - PID 3415 | 1686053743168	geckodriver	INFO	Listening on 127.0.0.1:49831
[task 2023-06-06T12:15:43.171Z] 12:15:43     INFO - Starting runner

Comment 1

[Narcis Beleuzu [:NarcisB]]

Julian, could it be caused by Bug 1833090?

Comment 2

[Julian Descottes [:jdescottes]]

(In reply to Narcis Beleuzu [:NarcisB] from comment #1)

Julian, could it be caused by Bug 1833090?

It seems unlikely because this is just an individual test timing out, and this bug only changed how test suites are assigned to chunks.

This test takes a very long time to run. In the only green wd8 job from the link above, it took 78s, and otherwise it seems to timeout at 80 seconds.
I checked another run for the current beta, and it seems to take around 50 seconds: https://treeherder.mozilla.org/logviewer?job_id=418253402&repo=mozilla-beta&lineNumber=21061

I am keeping the needinfo as I will try to understand why the simulation is much slower (feel free to add other need infos if other bugs in the pushlog seem related to this issue though).

Comment 3

[Julian Descottes [:jdescottes]]

You were right, this has been regressed by Bug 1833090. I guess that must be a side effect of another test suite now running in the same chunk? Or the opposite, the fact that we are no longer running some tests prior to this one?

In any case, I also tried extending the timeout, so I think we should just do that for now, it seems to fix the issue.

Comment 4

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

Is that now the very first test that runs in a Wdspec job? Do you have a link to a try build with the extended timeout requested?

Comment 5

[Julian Descottes [:jdescottes]]

Attachment: Bug 1836972 - [wdspec] Add timeout=long to /webdriver/tests/bidi/input/perform_actions/key_events.py

Comment 6

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

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

Comment 7

[Julian Descottes [:jdescottes]]

(In reply to Henrik Skupin [:whimboo][⌚️UTC+2] from comment #4)

Is that now the very first test that runs in a Wdspec job?

No it runs in the middle of the test, both with the old and new chunks. I also compared the total runtimes of all wdspec jobs on this tsan platform:

With old chunks

wd1: 57
wd2: 23
wd3: 22
wd4: 42
wd5: 28
wd6: 29
wd7: 29
wd8: 25
Total: 255

With new chunks

wd1: 37
wd2: 28
wd3: 29
wd4: 35
wd5: 36
wd6: 27
wd7: 30
wd8: 37
Total: 259

So it's very similar, and I assume most tests have the same runtime with the old and the new chunks. It might only affect some very specific tests (and only in beta...)

Do you have a link to a try build with the extended timeout requested?

Sure, wd8 on https://treeherder.mozilla.org/jobs?repo=try&revision=5e3d1805cd652180f1b997bbc53883f88830b71a&selectedTaskRun=CgdxXkuIRp67AzErjZoJAg.0

Comment 8

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/d588d40904f7
[wdspec] Add timeout=long to /webdriver/tests/bidi/input/perform_actions/key_events.py r=webdriver-reviewers,whimboo

Comment 9

[Web Platform Test Sync Bot [:wpt-sync] (Matrix: #interop:mozilla.org)]

Created web-platform-tests PR https://github.com/web-platform-tests/wpt/pull/40440 for changes under testing/web-platform/tests

Comment 10

[Cosmin Sabou [:CosminS]]

https://hg.mozilla.org/mozilla-central/rev/d588d40904f7

Comment 11

[Web Platform Test Sync Bot [:wpt-sync] (Matrix: #interop:mozilla.org)]

Upstream PR merged by moz-wptsync-bot

Comment 12

[Intermittent Failures Robot]

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

Repository breakdown:

• try: 5
• autoland: 1

Platform and build breakdown:

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

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

Comment 13

[Intermittent Failures Robot]

1 failures in 4079 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-tsan-qr: 1
  • opt: 1

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

Comment 14

[Intermittent Failures Robot]

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

Repository breakdown:

• mozilla-beta: 2

Platform and build breakdown:

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

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

Comment 15

[Intermittent Failures Robot]

1 failures in 2956 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=1836972&startday=2023-07-03&endday=2023-07-09&tree=all

Comment 16

[Intermittent Failures Robot]

1 failures in 2218 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=1836972&startday=2023-08-21&endday=2023-08-27&tree=all

Comment 17

[Daniel Holbert [:dholbert]]

It looks like we're running into this same timeout occasionally on esr15 -- maybe worth uplifting the fix there?

(In particular, see the log linked from comment 15, and also this log that that I just found misclassified on another bug which seems to really be this bug.)

(The autoland failure in comment 16 seems to be some sort of unrelated webdriver issue that happened during this test. Not sure if that wants its own bug filed or not, I'll leave it to folks who are familiar with this test & with webdriver to handle that as-needed.)

Comment 18

[Julian Descottes [:jdescottes]]

We can try, although it's odd that it fails in 115 esr, since the regressing bug only landed on 116 and was not uplifted. But we also did not fully understand why this was timing out only on some channels, so maybe that's worth doing anyway.

Comment 19

[Julian Descottes [:jdescottes]]

Comment on attachment 9337730 [details]
Bug 1836972 - [wdspec] Add timeout=long to /webdriver/tests/bidi/input/perform_actions/key_events.py

ESR Uplift Approval Request

• If this is not a sec:{high,crit} bug, please state case for ESR consideration: Occasional timeouts for this test on CI
• User impact if declined: No user impact, only CI
• Fix Landed on Version: 116
• Risk to taking this patch: Low
• Why is the change risky/not risky? (and alternatives if risky): No risk, just adding # META: timeout=long to a wdspect test

Comment 20

[Ryan VanderMeulen [:RyanVM]]

Comment on attachment 9337730 [details]
Bug 1836972 - [wdspec] Add timeout=long to /webdriver/tests/bidi/input/perform_actions/key_events.py

test-only change, approved for ESR115

Comment 21

[Pulsebot]

https://hg.mozilla.org/releases/mozilla-esr115/rev/fe92199e8d69

Comment 22

[Intermittent Failures Robot]

1 failures in 4018 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=1836972&startday=2023-10-02&endday=2023-10-08&tree=all