Closed Bug 1654701 Opened 5 years ago Closed 5 years ago

Intermittent /webdriver/tests/close_window/user_prompts.py | test_dismiss_and_notify[capabilities0-alert-None] - assert 200 == 500

Categories

(Remote Protocol :: Marionette, defect, P5)

Product:
Remote Protocol
Component:
Marionette
Type:
defect

Tracking

(Not tracked)

Status:
RESOLVED INCOMPLETE

People

(Reporter: intermittent-bug-filer, Unassigned)

References

(Depends on 1 open bug)

Details

(Keywords: intermittent-failure)

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

[task 2020-07-22T23:31:56.812Z] 23:31:56 INFO - TEST-PASS | /webdriver/tests/close_window/user_prompts.py | test_dismiss[capabilities0-prompt]
[task 2020-07-22T23:31:56.812Z] 23:31:56 INFO - TEST-UNEXPECTED-FAIL | /webdriver/tests/close_window/user_prompts.py | test_dismiss_and_notify[capabilities0-alert-None] - assert 200 == 500
[task 2020-07-22T23:31:56.812Z] 23:31:56 INFO - check_user_prompt_closed_with_exception = <function check_user_prompt_closed_with_exception at 0x10b1d8848>
[task 2020-07-22T23:31:56.812Z] 23:31:56 INFO - dialog_type = 'alert', retval = None
[task 2020-07-22T23:31:56.812Z] 23:31:56 INFO -
[task 2020-07-22T23:31:56.812Z] 23:31:56 INFO - @pytest.mark.capabilities({"unhandledPromptBehavior": "dismiss and notify"})
[task 2020-07-22T23:31:56.813Z] 23:31:56 INFO - @pytest.mark.parametrize("dialog_type, retval", [
[task 2020-07-22T23:31:56.813Z] 23:31:56 INFO - ("alert", None),
[task 2020-07-22T23:31:56.813Z] 23:31:56 INFO - ("confirm", False),
[task 2020-07-22T23:31:56.813Z] 23:31:56 INFO - ("prompt", None),
[task 2020-07-22T23:31:56.813Z] 23:31:56 INFO - ])
[task 2020-07-22T23:31:56.813Z] 23:31:56 INFO - def test_dismiss_and_notify(check_user_prompt_closed_with_exception, dialog_type, retval):
[task 2020-07-22T23:31:56.813Z] 23:31:56 INFO - > check_user_prompt_closed_with_exception(dialog_type, retval)
[task 2020-07-22T23:31:56.813Z] 23:31:56 INFO -
[task 2020-07-22T23:31:56.813Z] 23:31:56 INFO - check_user_prompt_closed_with_exception = <function check_user_prompt_closed_with_exception at 0x10b1d8848>
[task 2020-07-22T23:31:56.813Z] 23:31:56 INFO - dialog_type = 'alert'
[task 2020-07-22T23:31:56.813Z] 23:31:56 INFO - retval = None
[task 2020-07-22T23:31:56.814Z] 23:31:56 INFO -
[task 2020-07-22T23:31:56.814Z] 23:31:56 INFO - tests/web-platform/tests/webdriver/tests/close_window/user_prompts.py:104:
[task 2020-07-22T23:31:56.814Z] 23:31:56 INFO - _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _
[task 2020-07-22T23:31:56.814Z] 23:31:56 INFO - tests/web-platform/tests/webdriver/tests/close_window/user_prompts.py:45: in check_user_prompt_closed_with_exception
[task 2020-07-22T23:31:56.814Z] 23:31:56 INFO - assert_error(response, "unexpected alert open")
[task 2020-07-22T23:31:56.814Z] 23:31:56 INFO - _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _
[task 2020-07-22T23:31:56.814Z] 23:31:56 INFO -
[task 2020-07-22T23:31:56.814Z] 23:31:56 INFO - response = <Responsetatus=200 body={"value": ["26"]}>
[task 2020-07-22T23:31:56.814Z] 23:31:56 INFO - error_code = 'unexpected alert open'
[task 2020-07-22T23:31:56.814Z] 23:31:56 INFO -
[task 2020-07-22T23:31:56.814Z] 23:31:56 INFO - def assert_error(response, error_code):
[task 2020-07-22T23:31:56.814Z] 23:31:56 INFO - """
[task 2020-07-22T23:31:56.814Z] 23:31:56 INFO - Verify that the provided webdriver.Response instance described
[task 2020-07-22T23:31:56.814Z] 23:31:56 INFO - a valid error response as defined by dfn-send-an-error and
[task 2020-07-22T23:31:56.815Z] 23:31:56 INFO - the provided error code.
[task 2020-07-22T23:31:56.815Z] 23:31:56 INFO -
[task 2020-07-22T23:31:56.815Z] 23:31:56 INFO - :param response: webdriver.Response instance.
[task 2020-07-22T23:31:56.815Z] 23:31:56 INFO - :param error_code: String value of the expected error code
[task 2020-07-22T23:31:56.815Z] 23:31:56 INFO - """
[task 2020-07-22T23:31:56.815Z] 23:31:56 INFO - > assert response.status == errors[error_code]
[task 2020-07-22T23:31:56.815Z] 23:31:56 INFO - E assert 200 == 500
[task 2020-07-22T23:31:56.815Z] 23:31:56 INFO - E + where 200 = <Responsetatus=200 body={"value": ["26"]}>.status
[task 2020-07-22T23:31:56.815Z] 23:31:56 INFO -
[task 2020-07-22T23:31:56.815Z] 23:31:56 INFO - error_code = 'unexpected alert open'
[task 2020-07-22T23:31:56.815Z] 23:31:56 INFO - response = <Responsetatus=200 body={"value": ["26"]}>
[task 2020-07-22T23:31:56.815Z] 23:31:56 INFO -
[task 2020-07-22T23:31:56.815Z] 23:31:56 INFO - tests/web-platform/tests/webdriver/tests/support/asserts.py:52: AssertionError
[task 2020-07-22T23:31:56.816Z] 23:31:56 INFO - ........
[task 2020-07-22T23:31:56.816Z] 23:31:56 INFO - TEST-OK | /webdriver/tests/close_window/user_prompts.py | took 28889ms
[task 2020-07-22T23:31:56.816Z] 23:31:56 INFO - Restarting browser for new test group
[task 2020-07-22T23:31:56.897Z] 23:31:56 INFO - Closing logging queue
[task 2020-07-22T23:31:56.898Z] 23:31:56 INFO - queue closed
[task 2020-07-22T23:31:56.898Z] 23:31:56 INFO - Starting runner
[task 2020-07-22T23:31:56.938Z] 23:31:56 INFO - PID 1778 | 1595460716915 geckodriver INFO Listening on 127.0.0.1:58573
[task 2020-07-22T23:31:57.540Z] 23:31:57 INFO - WebDriver HTTP server listening at http://127.0.0.1:58573

Here is the underlying problem:
https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=310783087&repo=autoland&lineNumber=55783-55834

[task 2020-07-22T23:31:45.798Z] 23:31:45     INFO - PID 1732 | 1595460705790	Marionette	DEBUG	0 -> [0,1,"WebDriver:NewSession",{"unhandledPromptBehavior":"dismiss and notify"}]
[..]
[task 2020-07-22T23:31:46.218Z] 23:31:46     INFO - PID 1732 | 1595460706207	Marionette	DEBUG	0 -> [0,6,"WebDriver:ExecuteAsyncScript",{"args":["alert","alert"],"script":"\n            let dialog_type = arguments[0];\n       ...                 window.dialog_return_value = window[dialog_type](text);\n              }\n            }, 0);\n            "}]
[task 2020-07-22T23:31:46.221Z] 23:31:46     INFO - PID 1732 | 1595460706211	Marionette	TRACE	[38] Child actor created for window id 19
[task 2020-07-22T23:31:46.245Z] 23:31:46     INFO - PID 1732 | 1595460706230	Marionette	TRACE	[38] Parent actor created
[task 2020-07-22T23:31:46.289Z] 23:31:46     INFO - PID 1732 | 1595460706251	Marionette	TRACE	Received observer notification tabmodal-dialog-loaded
[task 2020-07-22T23:31:46.289Z] 23:31:46     INFO - PID 1732 | 1595460706255	Marionette	DEBUG	0 <- [1,6,null,{"value":null}]
[task 2020-07-22T23:31:46.290Z] 23:31:46     INFO - PID 1732 | 1595460706263	webdriver::server	DEBUG	<- 200 OK {"value":null}
[task 2020-07-22T23:31:46.290Z] 23:31:46     INFO - PID 1732 | 1595460706265	webdriver::server	DEBUG	-> GET /session/452a6e33-5697-864a-b2e2-7de2b3c9478b/alert/text
[task 2020-07-22T23:31:46.290Z] 23:31:46     INFO - PID 1732 | 1595460706266	Marionette	DEBUG	0 -> [0,7,"WebDriver:GetAlertText",{}]
[task 2020-07-22T23:31:46.291Z] 23:31:46     INFO - PID 1732 | 1595460706267	Marionette	DEBUG	0 <- [1,7,null,{"value":"alert"}]
[task 2020-07-22T23:31:46.291Z] 23:31:46     INFO - PID 1732 | 1595460706267	webdriver::server	DEBUG	<- 200 OK {"value":"alert"}
[task 2020-07-22T23:31:46.291Z] 23:31:46     INFO - PID 1732 | 1595460706269	webdriver::server	DEBUG	-> DELETE /session/452a6e33-5697-864a-b2e2-7de2b3c9478b/window
[task 2020-07-22T23:31:46.291Z] 23:31:46     INFO - PID 1732 | JavaScript error: moz-nullprincipal:{4d34e500-8154-4a5b-9ee1-32f0f5938f73}, line 10: SecurityError: Permission denied to access property "dialog_return_value" on cross-origin object
[task 2020-07-22T23:31:46.292Z] 23:31:46     INFO - PID 1732 | 1595460706272	Marionette	TRACE	Received event DOMModalDialogClosed
[task 2020-07-22T23:31:46.292Z] 23:31:46     INFO - PID 1732 | JavaScript error: resource://gre/modules/Prompter.jsm, line 1081: AbortError: Actor 'Prompt' destroyed before query 'Prompt:Open' was resolved
[task 2020-07-22T23:31:46.293Z] 23:31:46     INFO - PID 1732 | 1595460706282	Marionette	DEBUG	0 -> [0,8,"WebDriver:CloseWindow",{}]
[task 2020-07-22T23:31:46.307Z] 23:31:46     INFO - PID 1732 | 1595460706299	Marionette	TRACE	Received DOM event TabClose for [object XULElement]
[task 2020-07-22T23:31:46.326Z] 23:31:46     INFO - PID 1732 | 1595460706316	Marionette	TRACE	[38] Child actor created for window id 6442450945
[task 2020-07-22T23:31:46.327Z] 23:31:46     INFO - PID 1732 | 1595460706322	Marionette	TRACE	[38] Parent actor created
[task 2020-07-22T23:31:46.341Z] 23:31:46     INFO - PID 1732 | 1595460706327	Marionette	TRACE	Received observer notification message-manager-disconnect
[task 2020-07-22T23:31:46.341Z] 23:31:46     INFO - PID 1732 | 1595460706327	Marionette	DEBUG	0 <- [1,8,null,["26"]]
[task 2020-07-22T23:31:46.341Z] 23:31:46     INFO - PID 1732 | 1595460706328	webdriver::server	DEBUG	<- 200 OK {"value":["26"]}

We start a new session with the capability to dismiss any open dialog and when there is one to also raise an exception. The tab modal gets created but then we receive this security error:

SecurityError: Permission denied to access property "dialog_return_value" on cross-origin object

And then a Javascript error from the prompter code appears (I filed bug 1654730 for that):

JavaScript error: resource://gre/modules/Prompter.jsm, line 1081: AbortError: Actor 'Prompt' destroyed before query 'Prompt:Open' was resolved

Not sure yet how both are related to this test failing, and that the window gets closed and no error raised. Would be good to see how often this test fails.

Depends on: 1654730

https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
For more information, please visit auto_nag documentation.

Status: NEW → RESOLVED
Closed: 5 years ago
Resolution: --- → INCOMPLETE
Moving bug to Remote Protocol::Marionette component per bug 1815831.
Component: geckodriver → Marionette
Product: Testing → Remote Protocol
You need to log in before you can comment on or make changes to this bug.