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

[task 2022-11-23T18:24:03.502Z] 18:24:03     INFO - TEST-PASS | /webdriver/tests/send_alert_text/send.py | test_send_alert_text[ Fed erer ] 
[task 2022-11-23T18:24:03.502Z] 18:24:03     INFO - TEST-UNEXPECTED-FAIL | /webdriver/tests/send_alert_text/send.py | test_send_alert_text[Fed\terer] - AssertionError: no such alert (404):
[task 2022-11-23T18:24:03.502Z] 18:24:03     INFO - session = <Session bd0da01a-56e1-4712-a468-560c7977ea69>, page = None
[task 2022-11-23T18:24:03.502Z] 18:24:03     INFO - text = 'Fed\terer'
[task 2022-11-23T18:24:03.502Z] 18:24:03     INFO - 
[task 2022-11-23T18:24:03.502Z] 18:24:03     INFO -     @pytest.mark.parametrize("text", ["", "Federer", " Fed erer ", "Fed\terer"])
[task 2022-11-23T18:24:03.502Z] 18:24:03     INFO -     def test_send_alert_text(session, page, text):
[task 2022-11-23T18:24:03.502Z] 18:24:03     INFO -         send_response = send_alert_text(session, text)
[task 2022-11-23T18:24:03.502Z] 18:24:03     INFO - >       assert_success(send_response)
[task 2022-11-23T18:24:03.502Z] 18:24:03     INFO - 
[task 2022-11-23T18:24:03.502Z] 18:24:03     INFO - page       = None
[task 2022-11-23T18:24:03.502Z] 18:24:03     INFO - send_response = <Response status=404 error=<NoSuchAlertException http_status=404>>
[task 2022-11-23T18:24:03.502Z] 18:24:03     INFO - session    = <Session bd0da01a-56e1-4712-a468-560c7977ea69>
[task 2022-11-23T18:24:03.502Z] 18:24:03     INFO - text       = 'Fed\terer'
[task 2022-11-23T18:24:03.502Z] 18:24:03     INFO - 
[task 2022-11-23T18:24:03.502Z] 18:24:03     INFO - tests/web-platform/tests/webdriver/tests/send_alert_text/send.py:77: 
[task 2022-11-23T18:24:03.502Z] 18:24:03     INFO - _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 
[task 2022-11-23T18:24:03.502Z] 18:24:03     INFO - 
[task 2022-11-23T18:24:03.502Z] 18:24:03     INFO - response = <Response status=404 error=<NoSuchAlertException http_status=404>>
[task 2022-11-23T18:24:03.502Z] 18:24:03     INFO - value = None
[task 2022-11-23T18:24:03.502Z] 18:24:03     INFO - 
[task 2022-11-23T18:24:03.502Z] 18:24:03     INFO -     def assert_success(response, value=None):
[task 2022-11-23T18:24:03.502Z] 18:24:03     INFO -         """
[task 2022-11-23T18:24:03.502Z] 18:24:03     INFO -         Verify that the provided webdriver.Response instance described
[task 2022-11-23T18:24:03.502Z] 18:24:03     INFO -         a valid success response as defined by `dfn-send-a-response` and
[task 2022-11-23T18:24:03.502Z] 18:24:03     INFO -         the provided response value.
[task 2022-11-23T18:24:03.502Z] 18:24:03     INFO -     
[task 2022-11-23T18:24:03.502Z] 18:24:03     INFO -         :param response: ``webdriver.Response`` instance.
[task 2022-11-23T18:24:03.502Z] 18:24:03     INFO -         :param value: Expected value of the response body, if any.
[task 2022-11-23T18:24:03.502Z] 18:24:03     INFO -         """
[task 2022-11-23T18:24:03.503Z] 18:24:03     INFO - >       assert response.status == 200, str(response.error)
[task 2022-11-23T18:24:03.503Z] 18:24:03     INFO - E       AssertionError: no such alert (404): 
[task 2022-11-23T18:24:03.503Z] 18:24:03     INFO - E         
[task 2022-11-23T18:24:03.503Z] 18:24:03     INFO - E         Remote-end stacktrace:
[task 2022-11-23T18:24:03.503Z] 18:24:03     INFO - E         
[task 2022-11-23T18:24:03.503Z] 18:24:03     INFO - E         RemoteError@chrome://remote/content/shared/RemoteError.sys.mjs:8:8
[task 2022-11-23T18:24:03.503Z] 18:24:03     INFO - E         WebDriverError@chrome://remote/content/shared/webdriver/Errors.sys.mjs:182:5
[task 2022-11-23T18:24:03.503Z] 18:24:03     INFO - E         NoSuchAlertError@chrome://remote/content/shared/webdriver/Errors.sys.mjs:383:5
[task 2022-11-23T18:24:03.503Z] 18:24:03     INFO - E         GeckoDriver.prototype._checkIfAlertIsPresent@chrome://remote/content/marionette/driver.sys.mjs:2666:11
[task 2022-11-23T18:24:03.503Z] 18:24:03     INFO - E         GeckoDriver.prototype.sendKeysToDialog@chrome://remote/content/marionette/driver.sys.mjs:2642:8
[task 2022-11-23T18:24:03.503Z] 18:24:03     INFO - E         despatch@chrome://remote/content/marionette/server.sys.mjs:303:40
[task 2022-11-23T18:24:03.503Z] 18:24:03     INFO - E         execute@chrome://remote/content/marionette/server.sys.mjs:276:16
[task 2022-11-23T18:24:03.503Z] 18:24:03     INFO - E         onPacket/<@chrome://remote/content/marionette/server.sys.mjs:249:20
[task 2022-11-23T18:24:03.503Z] 18:24:03     INFO - E         onPacket@chrome://remote/content/marionette/server.sys.mjs:250:9
[task 2022-11-23T18:24:03.503Z] 18:24:03     INFO - E         _onJSONObjectReady/<@chrome://remote/content/marionette/transport.sys.mjs:496:20
[task 2022-11-23T18:24:03.503Z] 18:24:03     INFO - E         
[task 2022-11-23T18:24:03.503Z] 18:24:03     INFO - E       assert 404 == 200
[task 2022-11-23T18:24:03.503Z] 18:24:03     INFO - E         +404
[task 2022-11-23T18:24:03.503Z] 18:24:03     INFO - E         -200
[task 2022-11-23T18:24:03.504Z] 18:24:03     INFO - 
[task 2022-11-23T18:24:03.504Z] 18:24:03     INFO - response   = <Response status=404 error=<NoSuchAlertException http_status=404>>
[task 2022-11-23T18:24:03.504Z] 18:24:03     INFO - value      = None
[task 2022-11-23T18:24:03.504Z] 18:24:03     INFO - 
[task 2022-11-23T18:24:03.504Z] 18:24:03     INFO - tests/web-platform/tests/webdriver/tests/support/asserts.py:69: AssertionError
[task 2022-11-23T18:24:03.504Z] 18:24:03     INFO - .
[task 2022-11-23T18:24:03.504Z] 18:24:03     INFO - TEST-OK | /webdriver/tests/send_alert_text/send.py | took 20304ms

This is for an Android test of a isolated-process job. It appears to only happen on the same build as bug 1802197:

https://treeherder.mozilla.org/jobs?repo=autoland&revision=eee37f3bfaba651c3625e9e6288fa0130e2eec1f&searchStr=wd%2Candroid

Lets see how often it happens.

I triggered some backfill jobs based on the commit when the failure started to appear.

The backfill jobs all seem to point to bug 1800263. Jon, do you think that your patches could have anything to do here with our code that we cannot find alerts on Android only.

From the adb logcat:

11-23 18:24:01.078 21630 21645 I Gecko   : 1669227841078	Marionette	TRACE	Received observer notification geckoview-prompt-show
11-23 18:24:01.079 21630 21645 I Gecko   : 1669227841079	Marionette	TRACE	Canceled page load listener because a dialog opened
11-23 18:24:01.081 21630 21645 I Gecko   : 1669227841081	Marionette	DEBUG	0 <- [1,383,null,{"value":null}]
11-23 18:24:01.154 21630 21645 I Gecko   : 1669227841091	Marionette	DEBUG	0 -> [0,384,"WebDriver:SendAlertText",{"text":"Fed\terer","value":["F","e","d","\t","e","r","e","r"]}]
11-23 18:24:01.155 21630 21645 I Gecko   : 1669227841155	Marionette	DEBUG	0 <- [1,384,{"error":"no such alert","message":"","stacktrace":"RemoteError@chrome://remote/content/shared/RemoteError.sys.mjs:8:8\nWebDriverError@chrome://remote/content/shared/webdriver/Er ... ote/content/marionette/server.sys.mjs:250:9\n_onJSONObjectReady/<@chrome://remote/content/marionette/transport.sys.mjs:496:20\n"},null]

As it can be seen a dialog has been opened but then with the next command we cannot find the dialog. this.dialog has been set before here. Interesting is also bug 1802197 where the window of the related dialog is unexpectedly null.

I cannot reproduce that locally with running the tests in an emulator. Before I dig deeper into the failures lets wait for a response from Jon.

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

The backfill jobs all seem to point to bug 1800263. Jon, do you think that your patches could have anything to do here with our code that we cannot find alerts on Android only.

No, this is unlikely to be related (problems with that change would cause repeated GCs, or perhaps a crash).

Thanks Jon! Let me push a try build later today with extra log lines included. That might reveal what's wrong.

Potentially fixed by bug 1848167. Lets reopen if the problem is still persistent.

This happened again here.

failure log

Checking the Android adb log this is very suspicious:

08-17 00:29:24.374 19653 19668 I Gecko   : 1692232164374	Marionette	DEBUG	0 -> [0,382,"WebDriver:SwitchToWindow",{"handle":"a35cca80-1736-4724-ac80-3552d904b9a5"}]
08-17 00:29:24.377 19653 19668 I Gecko   : 1692232164377	Marionette	DEBUG	0 <- [1,382,null,{"value":null}]
08-17 00:29:24.378 19717 19742 W webrender::device::gl: Cropping texture upload Box2D((0, 0), (0, 1)) to None
08-17 00:29:24.378 19717 19742 W webrender::device::gl: Cropping texture upload Box2D((0, 0), (0, 1)) to None
08-17 00:29:24.380 19653 19668 D GeckoViewContentDelegateParent: receiveMessage: DispatcherMessage
08-17 00:29:24.385 19653 19668 I Gecko   : 1692232164385	Marionette	DEBUG	0 -> [0,383,"WebDriver:Navigate",{"url":"https://web-platform.test:8443/webdriver/tests/support/inline.py?doc=%3C%21doctype+html%3E%0A%3Cmeta+charset%3DUTF-8%3E%0A%0A ... result+%3D+window.prompt%28%27Enter+Your+Name%3A+%27%2C+%27Name%27%29%3B%3C%2Fscript%3E%0A++++&mime=text%2Fhtml&charset=UTF-8"}]
08-17 00:29:24.398 19653 19668 I Gecko   : 1692232164398	Marionette	TRACE	[38] Received event beforeunload for about:blank
08-17 00:29:24.420 20396 20411 D GeckoViewSelectionActionDelegate[C]: handleEvent: visibilitychange
08-17 00:29:24.422 20396 20411 D GeckoViewClipboardPermissionChild[C]: handleEvent: pagehide
08-17 00:29:24.423 20396 20411 D GeckoViewAutoFill[C]: handleEvent: pagehide
08-17 00:29:24.424 19653 19668 D GeckoViewClipboardPermissionParent: receiveMessage: DispatcherMessage
08-17 00:29:24.424 19653 19668 W GeckoEventDispatcher: No listener for GeckoView:DismissClipboardPermissionRequest
08-17 00:29:24.425 19653 19668 D GeckoViewAutoFill: receiveMessage Clear
08-17 00:29:24.426 19653 19668 I Gecko   : 1692232164426	Marionette	TRACE	[38] Received event pagehide for about:blank
08-17 00:29:24.433 19653 19668 D GeckoViewNavigation: onLocationChange
08-17 00:29:24.434 20396 20411 W Web Content: [JavaScript Warning: "Layout was forced before the page was fully loaded. If stylesheets are not yet loaded this may cause a flash of unstyled content." {file: "https://web-platform.test:8443/webdriver/tests/support/inline.py?doc=%3C%21doctype+html%3E%0A%3Cmeta+charset%3DUTF-8%3E%0A%0A++++++++%3Cscript%3Ewindow.result+%3D+window.prompt%28%27Enter+Your+Name%3A+%27%2C+%27Name%27%29%3B%3C%2Fscript%3E%0A++++&mime=text%2Fhtml&charset=UTF-8" line: 4}]
08-17 00:29:24.435 19653 19653 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++++++++%3Cscript%3Ewindow.result+%3D+window.prompt%28%27Enter+Your+Name%3A+%27%2C+%27Name%27%29%3B%3C%2Fscript%3E%0A++++&mime=text%2Fhtml&charset=UTF-8
08-17 00:29:24.452 19653 19653 D GeckoSession: handleMessage GeckoView:Prompt
08-17 00:29:24.452 19653 19653 D Prompts : handleEvent text
08-17 00:29:24.453 19653 19668 I Gecko   : 1692232164453	RemoteAgent	TRACE	Received observer notification geckoview-prompt-show
08-17 00:29:24.454 19653 19668 I Gecko   : 1692232164454	Marionette	TRACE	Canceled page load listener because a dialog opened
08-17 00:29:24.456 19653 19668 I Gecko   : 1692232164456	Marionette	DEBUG	0 <- [1,383,null,{"value":null}]
08-17 00:29:24.465 19653 19668 I Gecko   : 1692232164465	Marionette	DEBUG	0 -> [0,384,"WebDriver:SendAlertText",{"text":"Federer","value":["F","e","d","e","r","e","r"]}]
08-17 00:29:24.467 19653 19668 I Gecko   : 1692232164467	Marionette	DEBUG	0 <- [1,384,null,{"value":null}]
08-17 00:29:24.473 19653 19668 I Gecko   : 1692232164473	Marionette	DEBUG	0 -> [0,385,"WebDriver:AcceptAlert",{}]
08-17 00:29:24.474 19653 19668 I Gecko   : 1692232164474	RemoteAgent	TRACE	Received event DOMModalDialogClosed
08-17 00:29:24.477 19653 19653 D GeckoSession: handleMessage GeckoView:Prompt:Dismiss
08-17 00:29:24.479 20396 20411 D GeckoViewContentDelegateChild[C]: handleEvent: DOMContentLoaded
08-17 00:29:24.479 19653 19668 I Gecko   : 1692232164479	Marionette	DEBUG	0 <- [1,385,null,{"value":null}]
08-17 00:29:24.481 19653 19668 D GeckoViewContent: handleEvent: pagetitlechanged
08-17 00:29:24.487 19653 19668 I Gecko   : 1692232164487	Marionette	DEBUG	0 -> [0,386,"WebDriver:ExecuteScript",{"args":[],"script":"return window.result"}]
08-17 00:29:24.493 20396 20411 D GeckoViewContent[C]: handleEvent: pageshow
08-17 00:29:24.494 20396 20411 D GeckoViewAutoFill[C]: handleEvent: pageshow
08-17 00:29:24.504 20396 20411 I Gecko   : 1692232164504	RemoteAgent	TRACE	WebDriverProcessData actor created for PID 20396
08-17 00:29:24.507 20396 20411 I Gecko   : 1692232164507	Marionette	TRACE	[38] MarionetteCommands actor created for window id 36507222018
08-17 00:29:24.528 19653 19668 I Gecko   : 1692232164528	Marionette	DEBUG	0 <- [1,386,null,{"value":"Federer"}]
08-17 00:29:24.531 19653 19668 D GeckoViewContentDelegateParent: receiveMessage: DispatcherMessage
08-17 00:29:24.534 19653 19668 I Gecko   : 1692232164534	Marionette	DEBUG	0 -> [0,387,"WebDriver:DismissAlert",{}]
08-17 00:29:24.536 19653 19668 I Gecko   : 1692232164535	Marionette	DEBUG	0 <- [1,387,{"error":"no such alert","message":"","stacktrace":"RemoteError@chrome://remote/content/shared/RemoteError.sys.mjs:8:8\nWebDriverError@chrome://remote/content/shared/webdriver/Er ... ote/content/marionette/server.sys.mjs:263:9\n_onJSONObjectReady/<@chrome://remote/content/marionette/transport.sys.mjs:494:20\n"},null]

It looks like that parts of test_chained_alert_element_not_interactable sneak in here? It might be good to use different alert text that we send so it would be easier to differentiate. Lets see how often it continues to fail now after bug 1848167.