Closed Bug 1931822 Opened 18 days ago Closed 14 days ago

Do not always wrap errors into WebDriverError for IPC messages returned by the MarionetteCommandsChild actor

Categories

(Remote Protocol :: Marionette, defect, P2)

Product:
Remote Protocol
Component:
Marionette
Type:
defect
Points:
2

Tracking

(firefox134 fixed)

Status:
RESOLVED FIXED
Milestone:
134 Branch
Tracking Flags:
Tracking Status
firefox134 --- fixed

People

(Reporter: intermittent-bug-filer, Assigned: whimboo)

References

(Blocks 2 open bugs)

Details

(Keywords: intermittent-failure, Whiteboard: [webdriver:m14])

Attachments

(1 file, 2 obsolete files)

Bug 1931822 - [marionette] Do not always wrap errors into a WebDriver error for IPC messages.
48 bytes, text/x-phabricator-request
Details | Review

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

11-15 22:15:31.011 17209 17224 I Gecko   : 1731708931011	Marionette	DEBUG	0 -> [0,29,"WebDriver:PerformActions",{"actions":[{"actions":[{"origin":{"element-6066-11e4-a52e-4f735466cecf":"71752edb-dc53-4b84-87ce-b08b4ad87c06"},"type":"pointerMove","x":0,"y":0},{"button":0,"type":"pointerDown"},{"button":0,"type":"pointerUp"},{"duration":1000,"type":"pause"},{"origin":"viewport","type":"pointerMove","x":200,"y":200}],"id":"pointer_id","parameters":{"pointerType":"mouse"},"type":"pointer"}]}]
11-15 22:15:31.016 17209 17224 I Gecko   : 1731708931016	Marionette	TRACE	Dispatching tick 1/5
11-15 22:15:31.017 17209 17224 I Gecko   : 1731708931017	Marionette	TRACE	Dispatch PointerMoveAction mouse with id: pointer_id x: 0 y: 0
11-15 22:15:31.043 17209 17224 I Gecko   : 1731708931043	Marionette	TRACE	moveOverTime start: 0,0 target: 98,20 duration: 0
11-15 22:15:31.043 17209 17224 I Gecko   : 1731708931043	Marionette	TRACE	PointerMoveAction.performPointerMoveStep [98,20]
11-15 22:15:31.064 17209 17224 I Gecko   : 1731708931064	Marionette	TRACE	Dispatching tick 2/5
11-15 22:15:31.067 17209 17224 I Gecko   : 1731708931067	Marionette	TRACE	Dispatch PointerDownAction mouse with id: pointer_id button: 0
11-15 22:15:31.073 17278 17304 E eglCodecCommon: glUtilsParamSize: unknow param 0x00008caa
11-15 22:15:31.076 17352 17367 I Gecko   : [Child 17352, Main Thread] WARNING: EditorBase::GetInlineSpellChecker() failed, but ignored: 'NS_SUCCEEDED(rvIgnored)', file /builds/worker/checkouts/gecko/editor/libeditor/EditorBase.cpp:2274
11-15 22:15:31.080 17209 17224 D GeckoViewAutocomplete: fetchAddresses
11-15 22:15:31.081 17209 17224 W GeckoEventDispatcher: No listener for GeckoView:Autocomplete:Fetch:Address
11-15 22:15:31.081 17209 17224 D GeckoViewAutocomplete: fetchCreditCards
11-15 22:15:31.082 17209 17224 W GeckoEventDispatcher: No listener for GeckoView:Autocomplete:Fetch:CreditCard
11-15 22:15:31.085 17352 17367 D GeckoViewAutoFill[C]: handleEvent: focusin
11-15 22:15:31.093 17352 17367 D GeckoViewContentDelegateChild[C]: handleEvent: MozFirstContentfulPaint
11-15 22:15:31.095 17209 17224 D GeckoViewXUL: WillChangeBrowserRemoteness
11-15 22:15:31.096  1732  1732 W InputMethodService: Window size has been changed. This may cause jankiness of resizing window: -1 -> -2
11-15 22:15:31.098 17352 17367 D GeckoViewSelectionActionDelegate[C]: handleEvent: visibilitychange
11-15 22:15:31.099 17352 17367 D GeckoViewAutoFill[C]: handleEvent: pagehide
11-15 22:15:31.099  1732  1732 I LatinIME: Starting input. Cursor position = 1,1
11-15 22:15:31.100 17209 17224 D GeckoViewSessionStore: observe browsing-context-did-set-embedder
11-15 22:15:31.100 17209 17209 W IInputConnectionWrapper: getSelectedText on inactive InputConnection
11-15 22:15:31.100 17352 17367 D GeckoViewAutoFill[C]: handleEvent: focusout
11-15 22:15:31.101 17352 17367 D GeckoViewAutoFill[C]: Auto-fill focus on null
11-15 22:15:31.101 17209 17209 W IInputConnectionWrapper: requestCursorAnchorInfo on inactive InputConnection
11-15 22:15:31.101 17209 17209 W IInputConnectionWrapper: getTextBeforeCursor on inactive InputConnection
11-15 22:15:31.101  1732  1732 E RichInputConnection: Unable to connect to the editor to retrieve text.
11-15 22:15:31.101  1732  1732 D RichInputConnection: Will try to retrieve text later.
11-15 22:15:31.102 17209 17209 W IInputConnectionWrapper: getTextBeforeCursor on inactive InputConnection
11-15 22:15:31.102  1732  1732 E RichInputConnection: Unable to connect to the editor to retrieve text.
11-15 22:15:31.103  1732  1732 W RichInputConnection: Unable to connect to the editor. Setting caps mode without knowing text.
11-15 22:15:31.104 17209 17224 D GeckoViewSessionStore: observe browsing-context-did-set-embedder
11-15 22:15:31.108  1732  1732 I LatinIME: Starting input. Cursor position = 0,0
11-15 22:15:31.110 17209 17224 I Gecko   : 1731708931110	Marionette	TRACE	Remoteness change detected. Set new top-level browsing context to 6
11-15 22:15:31.110 17209 17209 W IInputConnectionWrapper: requestCursorAnchorInfo on inactive InputConnection
11-15 22:15:31.111 17209 17224 D GeckoViewXUL: DidChangeBrowserRemoteness
11-15 22:15:31.111 17209 17224 D GeckoViewNavigation: sessionContextId=null
11-15 22:15:31.116 17209 17209 W IInputConnectionWrapper: getTextBeforeCursor on inactive InputConnection
11-15 22:15:31.116  1732  1732 E RichInputConnection: Unable to connect to the editor to retrieve text.
11-15 22:15:31.117  1732  1732 D RichInputConnection: Will try to retrieve text later.
11-15 22:15:31.117 17209 17209 W IInputConnectionWrapper: getTextBeforeCursor on inactive InputConnection
11-15 22:15:31.117  1732  1732 E RichInputConnection: Unable to connect to the editor to retrieve text.
11-15 22:15:31.118  1732  1732 W RichInputConnection: Unable to connect to the editor. Setting caps mode without knowing text.
11-15 22:15:31.118 17209 17224 I Gecko   : 1731708931118	Marionette	TRACE	Dispatching tick 3/5
11-15 22:15:31.118 17209 17209 W IInputConnectionWrapper: getTextBeforeCursor on inactive InputConnection
11-15 22:15:31.118 17209 17224 I Gecko   : 1731708931118	Marionette	TRACE	Dispatch PointerUpAction mouse with id: pointer_id button: 0
11-15 22:15:31.119  1732  1732 E RichInputConnection: Unable to connect to the editor to retrieve text.
11-15 22:15:31.119  1732  1732 W RichInputConnection: Unable to connect to the editor. Setting caps mode without knowing text.
11-15 22:15:31.128  1732  1732 I LatinIME: Starting input. Cursor position = 0,0
11-15 22:15:31.129 17209 17224 D GeckoViewContentDelegateParent: receiveMessage: DispatcherMessage
11-15 22:15:31.131 17209 17224 D GeckoViewModule: dispatch GeckoView:ZoomToInput, data={"force":true}
11-15 22:15:31.131 17209 17224 D GeckoViewContent: onEvent: event=GeckoView:ZoomToInput, data={"force":true}
11-15 22:15:31.139  1732  1732 W InputMethodService: Window size has been changed. This may cause jankiness of resizing window: -1 -> -2
11-15 22:15:31.142 17352 17367 I Gecko   : 1731708931142	Marionette	TRACE	[6] MarionetteCommands actor created for window id 11
11-15 22:15:31.148 17209 17224 D GeckoViewAutocomplete: delegateDismiss
11-15 22:15:31.151 17209 17224 D GeckoViewAutoFill: receiveMessage Clear
11-15 22:15:31.152 17209 17224 D GeckoViewModule: dispatch GeckoView:ZoomToInput, data={"force":true}
11-15 22:15:31.152 17209 17224 D GeckoViewContent: onEvent: event=GeckoView:ZoomToInput, data={"force":true}
11-15 22:15:31.154 17209 17224 D GeckoViewAutoFill: receiveMessage Focus
11-15 22:15:31.155 17209 17224 W GeckoViewAutofill: Disregarding old session 766ac714-c1fc-44b6-a153-736afd018ce2
11-15 22:15:31.168 17352 17367 I Gecko   : [Child 17352, Main Thread] WARNING: NS_ENSURE_TRUE(winInner) failed: file /builds/worker/checkouts/gecko/widget/nsBaseDragService.cpp:1266
11-15 22:15:31.168 17352 17367 I Gecko   : [Child 17352, Main Thread] WARNING: NS_ENSURE_TRUE(widget) failed: file /builds/worker/checkouts/gecko/widget/nsDragServiceProxy.cpp:148
11-15 22:15:31.182 17209 17224 D GeckoViewModule: dispatch GeckoView:ZoomToInput, data={"force":true}
11-15 22:15:31.182 17209 17224 D GeckoViewContent: onEvent: event=GeckoView:ZoomToInput, data={"force":true}
11-15 22:15:31.187 17209 17224 D GeckoViewXUL: receiveMessage GeckoView:ContentModuleLoaded {}
11-15 22:15:31.190 17278 17304 E eglCodecCommon: glUtilsParamSize: unknow param 0x00008caa
11-15 22:15:31.198 17209 17224 I Gecko   : 1731708931198	Marionette	DEBUG	0 <- [1,29,{"error":"unknown error","message":"AbortError: Failed to dispatch event \"synthesizeMouseAtPoint\": Component returned failure code: 0x80004005 (NS_ERROR_FAILURE) [nsIDOMWindowUtils.sendMouseEvent]","stacktrace":"#dispatchEvent@chrome://remote/content/marionette/actors/MarionetteCommandsChild.sys.mjs:158:15\nreceiveMessage@chrome://remote/content/marionette/actors/MarionetteCommandsChild.sys.mjs:206:30\n"},null]
11-15 22:15:31.200 17352 17367 D GeckoViewSelectionActionDelegate[C]: handleEvent: visibilitychange
11-15 22:15:31.202 17352 17367 D GeckoViewAutoFill[C]: handleEvent: pagehide
11-15 22:15:31.208 17209 17224 D GeckoViewAutoFill: receiveMessage Clear
11-15 22:15:31.220 17209 17224 D GeckoViewNavigation: onLocationChange
11-15 22:15:31.222 17209 17209 D GeckoSession: handleMessage GeckoView:LocationChange uri=https://web-platform.test:8443/webdriver/tests/support/inline.py?doc=%3C%21doctype+html%3E%0A%3Cmeta+charset%3DUTF-8%3E%0A%0A++++%3Cinput%3E%3C%2Finput%3E%0A++++%3Cscript%3E%0A++++++++%22use+strict%3B%22%0A%0A++++++++var+allEvents+%3D+%7B+events%3A+%5B%5D+%7D%3B%0A%0A++++++++const+input+%3D+document.querySelector%28%22input%22%29%3B%0A++++++++input.focus%28%29%3B%0A%0A++++++++window.addEventListener%28%22keydown%22%2C+e+%3D%3E+allEvents.events.push%28%5Be.key%5D%29%29%3B%0A++++++++window.addEventListener%28%22mousemove%22%2C+e+%3D%3E+%7B%0A++++++++++++allEvents.events.push%28%5B%0A++++++++++++++++e.clientX%2C%0A++++++++++++++++e.clientY%2C%0A++++++++++++%5D%29%3B%0A++++++++%7D%29%3B%0A++++%3C%2Fscript%3E%0A&mime=text%2Fhtml&charset=UTF-8
11-15 22:15:31.223 17352 17367 I Gecko   : [Child 17352, Main Thread] WARNING: EditorBase::GetInlineSpellChecker() failed, but ignored: 'NS_SUCCEEDED(rvIgnored)', file /builds/worker/checkouts/gecko/editor/libeditor/EditorBase.cpp:2274
11-15 22:15:31.228 17352 17367 D GeckoViewAutoFill[C]: handleEvent: focusin
11-15 22:15:31.237 17352 17367 I Gecko   : 1731708931237	Marionette	TRACE	[6] MarionetteCommands actor destroyed for window id 11
11-15 22:15:31.246 17209 17224 D GeckoViewContent: handleEvent: pagetitlechanged
11-15 22:15:31.251 17209 17224 D GeckoViewAutocomplete: fetchAddresses
11-15 22:15:31.251 17209 17224 W GeckoEventDispatcher: No listener for GeckoView:Autocomplete:Fetch:Address
11-15 22:15:31.252 17209 17224 D GeckoViewAutocomplete: fetchCreditCards
11-15 22:15:31.252 17209 17224 W GeckoEventDispatcher: No listener for GeckoView:Autocomplete:Fetch:CreditCard
11-15 22:15:31.267 17352 17367 D GeckoViewContentDelegateChild[C]: handleEvent: DOMContentLoaded
11-15 22:15:31.270 17209 17209 W IInputConnectionWrapper: getTextAfterCursor on inactive InputConnection
11-15 22:15:31.272 17278 17304 E eglCodecCommon: glUtilsParamSize: unknow param 0x00008caa
11-15 22:15:31.274 17352 17367 D GeckoViewContent[C]: handleEvent: pageshow
11-15 22:15:31.275 17352 17367 D GeckoViewAutoFill[C]: handleEvent: pageshow
11-15 22:15:31.285 17352 17367 D GeckoViewContentDelegateChild[C]: handleEvent: MozFirstContentfulPaint
11-15 22:15:31.286 17209 17224 D GeckoViewContentDelegateParent: receiveMessage: DispatcherMessage
11-15 22:15:31.291 17209 17221 W GeckoEditable: Mismatched reply
11-15 22:15:31.293 17209 17224 D GeckoViewContentDelegateParent: receiveMessage: DispatcherMessage
11-15 22:15:31.304 17209 17224 I Gecko   : 1731708931304	Marionette	DEBUG	0 -> [0,30,"WebDriver:ReleaseActions",{}]
11-15 22:15:31.307 17209 17224 I Gecko   : 1731708931307	Marionette	DEBUG	0 <- [1,30,null,{"value":null}]

Even with bug 1930530 fixed this seems to be an issue with parent process action processing. The failure above is from Android. As it looks like we retried once but then aborted.

Blocks: parent-actions, 1922077
Component: WebDriver BiDi → Marionette
Depends on: 1930530

The problem here is actually that even through we throw a custom error in dispatchEvent the final lines in receiveMessage that catch any kind of error convert it to a WebDriver error. I'm surprised about that given that it only seems to happen on Android. On desktop I still see a AbortError. Given that this is a perma failure on Android we need to get this fixed.

The problem here is actually the pause(1000) action that we have in the action sequence for the pointer test. Because Android debug builds are much slower as on desktop the triggered navigation is not complete at this point. Changing that to use duration=1000 for the following pointerMove action I can reproduce it on desktop debug builds as well.

I got this fixed locally by not always wrapping errors into a WebDriver error. That way we can correctly return standard errors as well, which means errors like an AbortError can be handled correctly in the parent process.

Severity: S4 → S3
Points: --- → 2
Priority: P5 → P2
Summary: AbortError: Failed to dispatch event "synthesizeMouseAtPoint": Component returned failure code: 0x80004005 (NS_ERROR_FAILURE) [nsIDOMWindowUtils.sendMouseEvent] → Do not always wrap errors into WebDriverError for IPC messages returned by the MarionetteCommandsChild actor
Whiteboard: [webdriver:m14]
Assignee: nobody → hskupin
Status: NEW → ASSIGNED
Pushed by hskupin@mozilla.com: https://hg.mozilla.org/integration/autoland/rev/a3d24dc25bfd [marionette] Do not always wrap errors into a WebDriver error for IPC messages. r=webdriver-reviewers,jdescottes

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

Status: ASSIGNED → RESOLVED
Closed: 14 days ago
status-firefox134: --- → fixed
Resolution: --- → FIXED
Target Milestone: --- → 134 Branch

Comment on attachment 9441323 [details]
Bug 1931822 - [remote] Enable processing and dispatching actions via the parent process by default.

Revision D230930 was moved to bug 1922077. Setting attachment 9441323 [details] to obsolete.

Attachment #9441323 - Attachment is obsolete: true

Comment on attachment 9441421 [details]
Bug 1931822 - [wdspec] Fix navigation tests for the perform action commands.

Revision D230965 was moved to bug 1922077. Setting attachment 9441421 [details] to obsolete.

Attachment #9441421 - Attachment is obsolete: true
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: