1936804 - Frequent Android debug /webdriver/tests/bidi/input/perform_actions/pointer_mouse.py | expected OK

Status: RESOLVED FIXED

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

Description

[Treeherder Bug Filer]

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

---

[task 2024-12-12T09:57:24.214Z] 09:57:24     INFO - STDOUT: PASSED
[task 2024-12-12T09:57:24.240Z] 09:57:24     INFO - PID 1984 | 1733997444239	webdriver::server	DEBUG	-> POST /session/34a9d6ec-0a24-4357-9c98-00d0520d3308/timeouts {"implicit": 0}
[task 2024-12-12T09:57:24.255Z] 09:57:24     INFO - PID 1984 | 1733997444254	webdriver::server	DEBUG	<- 200 OK {"value":null}
[task 2024-12-12T09:57:24.257Z] 09:57:24     INFO - PID 1984 | 1733997444256	webdriver::server	DEBUG	-> POST /session/34a9d6ec-0a24-4357-9c98-00d0520d3308/timeouts {"pageLoad": 300000}
[task 2024-12-12T09:57:24.280Z] 09:57:24     INFO - PID 1984 | 1733997444279	webdriver::server	DEBUG	<- 200 OK {"value":null}
[task 2024-12-12T09:57:24.281Z] 09:57:24     INFO - PID 1984 | 1733997444280	webdriver::server	DEBUG	-> POST /session/34a9d6ec-0a24-4357-9c98-00d0520d3308/timeouts {"script": 30000}
[task 2024-12-12T09:57:24.288Z] 09:57:24     INFO - PID 1984 | 1733997444287	webdriver::server	DEBUG	<- 200 OK {"value":null}
[task 2024-12-12T09:57:24.288Z] 09:57:24     INFO - PID 1984 | 1733997444288	webdriver::server	DEBUG	-> GET /session/34a9d6ec-0a24-4357-9c98-00d0520d3308/window
[task 2024-12-12T09:57:24.294Z] 09:57:24     INFO - PID 1984 | 1733997444293	webdriver::server	DEBUG	<- 200 OK {"value":"b9f84ae6-7501-4e42-b9f6-ddecd69f82d2"}
[task 2024-12-12T09:57:24.295Z] 09:57:24     INFO - PID 1984 | 1733997444294	webdriver::server	DEBUG	-> GET /session/34a9d6ec-0a24-4357-9c98-00d0520d3308/window
[task 2024-12-12T09:57:24.301Z] 09:57:24     INFO - PID 1984 | 1733997444300	webdriver::server	DEBUG	<- 200 OK {"value":"b9f84ae6-7501-4e42-b9f6-ddecd69f82d2"}
[task 2024-12-12T09:57:24.302Z] 09:57:24     INFO - PID 1984 | 1733997444301	webdriver::server	DEBUG	-> GET /session/34a9d6ec-0a24-4357-9c98-00d0520d3308/window/handles
[task 2024-12-12T09:57:24.309Z] 09:57:24     INFO - PID 1984 | 1733997444308	webdriver::server	DEBUG	<- 200 OK {"value":["b9f84ae6-7501-4e42-b9f6-ddecd69f82d2"]}
[task 2024-12-12T09:57:24.310Z] 09:57:24     INFO - PID 1984 | 1733997444309	webdriver::server	DEBUG	-> POST /session/34a9d6ec-0a24-4357-9c98-00d0520d3308/window {"handle": "b9f84ae6-7501-4e42-b9f6-ddecd69f82d2"}
[task 2024-12-12T09:57:24.319Z] 09:57:24     INFO - PID 1984 | 1733997444318	webdriver::server	DEBUG	<- 200 OK {"value":null}
[task 2024-12-12T09:57:24.320Z] 09:57:24     INFO - PID 1984 | 1733997444319	webdriver::server	DEBUG	-> POST /session/34a9d6ec-0a24-4357-9c98-00d0520d3308/alert/dismiss {}
[task 2024-12-12T09:57:24.328Z] 09:57:24     INFO - PID 1984 | 1733997444326	webdriver::server	DEBUG	<- 404 Not Found {"value":{"error":"no such alert","message":"","stacktrace":"RemoteError@chrome://remote/content/shared/Remo ... ontent/marionette/server.sys.mjs:263:9\n_onJSONObjectReady/<@chrome://remote/content/marionette/transport.sys.mjs:494:20\n"}}
[task 2024-12-12T09:57:24.328Z] 09:57:24     INFO - PID 1984 | 1733997444327	webdriver::server	DEBUG	-> POST /session/34a9d6ec-0a24-4357-9c98-00d0520d3308/window {"handle": "b9f84ae6-7501-4e42-b9f6-ddecd69f82d2"}
[task 2024-12-12T09:57:24.336Z] 09:57:24     INFO - PID 1984 | 1733997444335	webdriver::server	DEBUG	<- 200 OK {"value":null}
[task 2024-12-12T09:57:24.337Z] 09:57:24     INFO - PID 1984 | 1733997444336	webdriver::server	DEBUG	-> GET /session/34a9d6ec-0a24-4357-9c98-00d0520d3308/window
[task 2024-12-12T09:57:24.344Z] 09:57:24     INFO - PID 1984 | 1733997444343	webdriver::server	DEBUG	<- 200 OK {"value":"b9f84ae6-7501-4e42-b9f6-ddecd69f82d2"}
[task 2024-12-12T09:57:24.344Z] 09:57:24     INFO - PID 1984 | 1733997444343	webdriver::server	DEBUG	-> GET /session/34a9d6ec-0a24-4357-9c98-00d0520d3308/window/handles
[task 2024-12-12T09:57:24.355Z] 09:57:24     INFO - PID 1984 | 1733997444354	webdriver::server	DEBUG	<- 200 OK {"value":["b9f84ae6-7501-4e42-b9f6-ddecd69f82d2"]}
[task 2024-12-12T09:57:24.356Z] 09:57:24     INFO - PID 1984 | 1733997444355	webdriver::server	DEBUG	-> POST /session/34a9d6ec-0a24-4357-9c98-00d0520d3308/window {"handle": "b9f84ae6-7501-4e42-b9f6-ddecd69f82d2"}
[task 2024-12-12T09:57:24.364Z] 09:57:24     INFO - PID 1984 | 1733997444363	webdriver::server	DEBUG	<- 200 OK {"value":null}
[task 2024-12-12T09:57:24.365Z] 09:57:24     INFO - PID 1984 | 1733997444364	webdriver::server	DEBUG	-> POST /session/34a9d6ec-0a24-4357-9c98-00d0520d3308/frame {"id": null}
[task 2024-12-12T09:57:24.382Z] 09:57:24     INFO - PID 1984 | 1733997444381	webdriver::server	DEBUG	<- 200 OK {"value":null}
[task 2024-12-12T09:57:24.384Z] 09:57:24     INFO - STDOUT: tests/web-platform/tests/webdriver/tests/bidi/input/perform_actions/pointer_mouse.py::test_click_navigation 
[task 2024-12-12T09:58:57.613Z] 09:58:57     INFO - TEST-UNEXPECTED-TIMEOUT | /webdriver/tests/bidi/input/perform_actions/pointer_mouse.py | expected OK
[task 2024-12-12T09:58:57.613Z] 09:58:57     INFO - TEST-INFO took 105003ms
[task 2024-12-12T09:59:07.616Z] 09:59:07  WARNING - Forcibly terminating runner process
[task 2024-12-12T09:59:07.753Z] 09:59:07     INFO - Starting WebDriver: /builds/worker/fetches/geckodriver --host 127.0.0.1 --port 0 -vv
[task 2024-12-12T09:59:07.861Z] 09:59:07     INFO - PID 2238 | 1733997547759	geckodriver	INFO	Listening on 127.0.0.1:36430
[task 2024-12-12T09:59:07.861Z] 09:59:07     INFO - Webdriver started successfully.
[task 2024-12-12T09:59:07.861Z] 09:59:07     INFO - Starting runner
[task 2024-12-12T09:59:08.152Z] 09:59:08     INFO - TEST-START | /webdriver/tests/bidi/input/perform_actions/pointer_mouse_drag.py

Comment 1

[Serban Stanca [:SerbanS]]

Hi Henrik! Could you please take a look? It seems to have an increase failure rate and seems to have started once Bug 1922077 landed on autoland, as it can be seen here.

Thank you!

Comment 2

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

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

Comment 3

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

Yes, I'll take a look. As of a quick look at the android logcat it's not clear why it's hanging. I hope that I can reproduce the issue locally as well.

Comment 4

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

There seems to be actually a hang in tests/web-platform/tests/webdriver/tests/bidi/input/perform_actions/pointer_mouse.py::test_click_navigation which is finally causing this timeout. Here an excerpt from the Android logcat:

12-12 11:55:30.393 11915 11931 I Gecko   : 1734004530393	RemoteAgent	TRACE	Received command input._dispatchEvent for destination WINDOW_GLOBAL
12-12 11:55:30.394 11883 11898 D GeckoViewContentDelegateParent: receiveMessage: DispatcherMessage
12-12 11:55:30.395 11915 11931 D GeckoViewPrompt[C]: handleEvent: click
12-12 11:55:30.400 11915 11931 I Gecko   : 1734004530400	RemoteAgent	TRACE	[2] NavigationListenerChild Loading state: flags: 983041, status: 0,  isStart: true, isStop: false, isNetwork: true, isBindingAborted: false, targetURI: https://web-platform.test:8443/webdriver/tests/support/html/test_actions.html
[..]
2-12 11:55:30.411 11915 11931 I Gecko   : 1734004530411	RemoteAgent	TRACE	Received command input._finalizeAction for destination WINDOW_GLOBAL
12-12 11:55:30.424 11953 11980 E eglCodecCommon: glUtilsParamSize: unknow param 0x00008caa
[..]
12-12 11:55:30.516 11883 11898 I Gecko   : 1734004530516	RemoteAgent	TRACE	[bccbfcd4-fac9-4c1c-aa64-cd5e3c40a9af] Navigation finished for url: https://web-platform.test:8443/webdriver/tests/support/html/test_actions.html (37594553-b441-40d3-88f7-835f9715d49d)
12-12 11:55:30.516 11915 11931 I Gecko   : 1734004530516	RemoteAgent	TRACE	[2] NavigationListenerChild Loading state: flags: 131088, status: 0,  isStart: false, isStop: true, isNetwork: false, isBindingAborted: false, targetURI: https://web-platform.test:8443/webdriver/tests/support/html/test_actions.html
12-12 11:55:30.517 11883 11898 I Gecko   : 1734004530517	RemoteAgent	TRACE	[bccbfcd4-fac9-4c1c-aa64-cd5e3c40a9af] Navigation already marked as finished, navigationId: 37594553-b441-40d3-88f7-835f9715d49d
12-12 11:55:30.518 11883 11898 I Gecko   : 1734004530518	RemoteAgent	TRACE	[bccbfcd4-fac9-4c1c-aa64-cd5e3c40a9af] Navigation already marked as finished, navigationId: 37594553-b441-40d3-88f7-835f9715d49d
12-12 11:55:30.519 11883 11898 I Gecko   : 1734004530519	RemoteAgent	TRACE	[bccbfcd4-fac9-4c1c-aa64-cd5e3c40a9af] Navigation already marked as finished, navigationId: 37594553-b441-40d3-88f7-835f9715d49d
12-12 11:55:30.520 11915 11931 D GeckoViewContent[C]: handleEvent: pageshow
12-12 11:55:30.521 11915 11931 D GeckoViewAutoFill[C]: handleEvent: pageshow
12-12 11:55:30.521 11883 11898 I Gecko   : 1734004530521	RemoteAgent	TRACE	[bccbfcd4-fac9-4c1c-aa64-cd5e3c40a9af] Navigation already marked as finished, navigationId: 37594553-b441-40d3-88f7-835f9715d49d
12-12 11:55:30.521 11883 11898 I Gecko   : 1734004530521	RemoteAgent	TRACE	[bccbfcd4-fac9-4c1c-aa64-cd5e3c40a9af] Navigation already marked as finished, navigationId: 37594553-b441-40d3-88f7-835f9715d49d
12-12 11:55:30.523 11883 11898 I Gecko   : 1734004530523	RemoteAgent	DEBUG	WebDriverBiDiConnection 286c6dcf-8aa4-4b99-813d-2d58595771f8 <- {"type":"event","method":"browsingContext.load","params":{"context":"bccbfcd4-fac9-4c1c-aa64-cd5e3c40a9af","timestamp":1734004530518,"url":"https://web-platform.test:8443/webdriver/tests/support/html/test_actions.html","navigation":"37594553-b441-40d3-88f7-835f9715d49d"}}
12-12 11:55:30.530 11883 11898 I Gecko   : 1734004530530	RemoteAgent	TRACE	[4294967298] Navigation already marked as finished, navigationId: 96c6e24c-1c48-4995-b759-1ce0e5c3a297
12-12 11:55:30.532 11953 11980 E eglCodecCommon: glUtilsParamSize: unknow param 0x00008caa
12-12 11:55:30.544 11915 11931 D GeckoViewContentDelegateChild[C]: handleEvent: MozFirstContentfulPaint
12-12 11:55:30.546 11883 11898 D GeckoViewContentDelegateParent: receiveMessage: DispatcherMessage
12-12 11:55:30.547 11915 11931 I Gecko   : 1734004530547	Marionette	TRACE	[2] MarionetteCommands actor destroyed for window id 4294967306
12-12 11:55:30.736 11883 11898 I Gecko   : nsWindow 0x75af39b9f100 destructor
12-12 11:55:35.548 11915 11931 I Gecko   : 1734004535547	Marionette	TRACE	[2] MarionetteCommands actor destroyed for window id 4294967297
12-12 11:55:38.845 11883 11898 W GeckoEventDispatcher: No listener for GeckoView:StateUpdated
12-12 11:57:14.317 11883 11898 I Gecko   : 1734004634317	RemoteAgent	DEBUG	WebDriverBiDiConnection 286c6dcf-8aa4-4b99-813d-2d58595771f8 closed
12-12 11:57:14.322 11883 11898 I Gecko   : 1734004634322	WebDriver BiDi	DEBUG	Unregistered session handler: /session/c3f31680-f8b8-4892-bcc7-9a75209ff0c3
12-12 11:57:14.327 11915 11931 I Gecko   : 1734004634326	Marionette	TRACE	[2] MarionetteCommands actor destroyed for window id 4294967312
12-12 11:57:14.328 11915 11931 I Gecko   : 1734004634328	Marionette	TRACE	[2] MarionetteCommands actor destroyed for window id 4294967309
12-12 11:57:14.332 11915 11931 E Web Content: [JavaScript Error: "InvalidStateError: JSWindowActorChild.contentWindow getter: Cannot access property 'contentWindow' after actor 'PictureInPictureToggle' has been destroyed" {file: "resource://gre/actors/PictureInPictureChild.sys.mjs" line: 510}]
12-12 11:57:14.332 11915 11931 E Web Content: handleEvent@resource://gre/actors/PictureInPictureChild.sys.mjs:510:29
12-12 11:57:14.334 11883 11898 I Gecko   : 1734004634333	RemoteAgent	TRACE	MessageHandler ROOT for session c3f31680-f8b8-4892-bcc7-9a75209ff0c3 is being destroyed
12-12 11:57:14.335 11883 11898 I Gecko   : 1734004634335	RemoteAgent	TRACE	Unregistered MessageHandler ROOT for session c3f31680-f8b8-4892-bcc7-9a75209ff0c3
12-12 11:57:14.336 11883 11898 I Gecko   : 1734004634336	Marionette	DEBUG	Closed connection 0

From the above logs it's not clear if we return from the IPC call to input._finalizeAction. Also with the actor destroyed we should get an AbortError but that's I'm not seeing as well.

Beside that I just noticed something interesting. The [BiDi test is running the steps twice](https://searchfox.org/mozilla-central/rev/39e6d5b609b74a19c0824d98ae654b60d6310152/testing/web-platform/tests/webdriver/tests/bidi/input/perform_actions/pointer_mouse.py#268-306 while the original test in classic does it only a single time. Julian, do you remember why you added that extra loop when porting the tests? Maybe it's an artifact from local testing?

Comment 5

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

Err, please drop the last question regarding the loop. I missed that the original code duplicated the lines and just didn't use a for loop.

Comment 6

[Julian Descottes [:jdescottes]]

Yep, and since the BiDi test was slightly more verbose, we suggested switching to a loop instead of duplicating during the review.

Comment 7

[Intermittent Failures Robot]

Summary

19 failures in 940 pushes (0.02 failures/push) were associated with this bug yesterday.

Repository breakdown:

• autoland: 13
• mozilla-central: 4
• try: 2

Platform and build breakdown:

• android-em-7-0-x86_64-qr: 19
  • debug-isolated-process: 9
  • debug: 10

Table

	nofis	nofis-ship
android-em-7-0-x86_64-qr/debug-isolated-process	9
android-em-7-0-x86_64-qr/debug	3	7

For more details, see:

https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1936804&startday=2024-12-12&endday=2024-12-12&tree=all

Comment 8

[Intermittent Failures Robot]

Summary

22 failures in 809 pushes (0.027 failures/push) were associated with this bug yesterday.

Repository breakdown:

• autoland: 21
• try: 1

Platform and build breakdown:

• android-em-7-0-x86_64-lite-qr: 6
  • opt: 6
• android-em-7-0-x86_64-qr: 16
  • debug: 9
  • debug-isolated-process: 4
  • opt: 3

Table

	nofis	nofis-ship
android-em-7-0-x86_64-lite-qr/opt	4	2
android-em-7-0-x86_64-qr/debug	5	4
android-em-7-0-x86_64-qr/debug-isolated-process	4
android-em-7-0-x86_64-qr/opt		3

For more details, see:

https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1936804&startday=2024-12-13&endday=2024-12-13&tree=all

Comment 9

[Intermittent Failures Robot]

Summary

19 failures in 179 pushes (0.106 failures/push) were associated with this bug yesterday.

Repository breakdown:

• autoland: 13
• mozilla-central: 4
• try: 2

Platform and build breakdown:

• android-em-7-0-x86_64-lite-qr: 3
  • opt: 3
• android-em-7-0-x86_64-qr: 14
  • debug: 6
  • debug-isolated-process: 6
  • opt: 2
• android-em-7-0-x86_64-shippable-lite-qr: 2
  • opt: 2

Table

	nofis	nofis-s	nofis-ship
android-em-7-0-x86_64-lite-qr/opt			3
android-em-7-0-x86_64-qr/debug	3		3
android-em-7-0-x86_64-qr/debug-isolated-process	6
android-em-7-0-x86_64-qr/opt	2
android-em-7-0-x86_64-shippable-lite-qr/opt		2

For more details, see:

https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1936804&startday=2024-12-14&endday=2024-12-14&tree=all

Comment 10

[Intermittent Failures Robot]

Summary

92 failures in 4615 pushes (0.02 failures/push) were associated with this bug in the last 7 days.

This is the #18 most frequent failure this week.

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

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

Repository breakdown:

• autoland: 69
• try: 9
• mozilla-central: 14

Platform and build breakdown:

• android-em-7-0-x86_64-lite-qr: 12
  • opt: 12
• android-em-7-0-x86_64-qr: 73
  • debug: 38
  • debug-isolated-process: 27
  • opt: 8
• android-em-7-0-x86_64-shippable-lite-qr: 5
  • opt: 5
• android-em-7-0-x86_64-shippable-qr: 2
  • opt: 2

Table

	1proc	a11y-checks-swr	condprof	fis	fis-hv	fis-hv-s	fis-s	headless-s	http2	http3	no_variant	nofis	nofis-aab	nofis-s	nofis-ship	nofis-ship-s	nofis-spi	nofis-swr	nofis-swr-s	nogpu	nogpu-s	s	spi	spi-nw	spi-nw-1proc	spi-nw-s	swr	wr-dc1-p	xorig	xorig-s
android-em-7-0-x86_64-lite-qr/opt												6			6
android-em-7-0-x86_64-qr/debug												17			21
android-em-7-0-x86_64-qr/debug-isolated-process												27
android-em-7-0-x86_64-qr/opt												3			5
android-em-7-0-x86_64-shippable-lite-qr/opt														3		2
android-em-7-0-x86_64-shippable-qr/opt														1		1

For more details, see:

https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1936804&startday=2024-12-09&endday=2024-12-15&tree=all

Comment 11

[Intermittent Failures Robot]

Summary

22 failures in 727 pushes (0.03 failures/push) were associated with this bug yesterday.

Repository breakdown:

• autoland: 15
• mozilla-central: 4
• try: 3

Platform and build breakdown:

• android-em-7-0-x86_64-lite-qr: 5
  • opt: 5
• android-em-7-0-x86_64-qr: 13
  • debug: 7
  • debug-isolated-process: 5
  • opt: 1
• android-em-7-0-x86_64-shippable-lite-qr: 4
  • opt: 4

Table

	nofis	nofis-s	nofis-ship	nofis-ship-s
android-em-7-0-x86_64-lite-qr/opt	3		2
android-em-7-0-x86_64-qr/debug	4		3
android-em-7-0-x86_64-qr/debug-isolated-process	5
android-em-7-0-x86_64-qr/opt	1
android-em-7-0-x86_64-shippable-lite-qr/opt		2		2

For more details, see:

https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1936804&startday=2024-12-16&endday=2024-12-16&tree=all

Comment 12

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

This kind of failure is now fixed with the landing of the patch on bug 1937118.

Comment 13

[Intermittent Failures Robot]

Summary

36 failures in 3774 pushes (0.01 failures/push) were associated with this bug in the last 7 days.

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:

• autoland: 20
• try: 9
• mozilla-central: 7

Platform and build breakdown:

• android-em-7-0-x86_64-lite-qr: 9
  • opt: 9
• android-em-7-0-x86_64-qr: 21
  • debug: 11
  • debug-isolated-process: 9
  • opt: 1
• android-em-7-0-x86_64-shippable-lite-qr: 4
  • opt: 4
• android-em-7-0-x86_64-shippable-qr: 2
  • opt: 2

Table

	1proc	fis	fis-hv	fis-hv-s	fis-s	headless	http2	http3	mda-gpu-s	no_variant	nofis	nofis-aab	nofis-s	nofis-ship	nofis-ship-s	nofis-spi	nofis-swr	nofis-swr-s	nogpu	nogpu-s	s	spi	spi-nw	spi-nw-s	swr	xorig	xorig-s
android-em-7-0-x86_64-lite-qr/opt											5			4
android-em-7-0-x86_64-qr/debug											7			4
android-em-7-0-x86_64-qr/debug-isolated-process											9
android-em-7-0-x86_64-qr/opt											1
android-em-7-0-x86_64-shippable-lite-qr/opt													2		2
android-em-7-0-x86_64-shippable-qr/opt													2

For more details, see:

https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1936804&startday=2024-12-16&endday=2024-12-22&tree=all