Closed Bug 1750441 Opened 3 years ago Closed 3 years ago

Intermittent /webdriver/tests/back/user_prompts.py | test_dismiss_and_notify[capabilities0-alert-None] - AssertionError: assert 'http://web-platform.test:8000/webdriver/tests/support/inline.py?doc=%3C%21doctype+html%3E%0A%3Cmeta+charset%3DUTF-8%

Categories

(Remote Protocol :: Marionette, defect, P5)

Product:
Remote Protocol
Component:
Marionette
Type:
defect

Tracking

(firefox-esr91 unaffected, firefox96 unaffected, firefox97 fixed, firefox98 fixed)

Status:
RESOLVED FIXED
Milestone:
98 Branch
Tracking Flags:
Tracking Status
firefox-esr91 --- unaffected
firefox96 --- unaffected
firefox97 --- fixed
firefox98 --- fixed

People

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

References

(Regression)

Details

(Keywords: assertion, intermittent-failure, regression)

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

Observed in today's central-as-early-beta simulation, it only failed on Linux 18.04 x64 WebRender Shippable.

[task 2022-01-16T14:11:41.267Z] 14:11:41     INFO - STDOUT: =================================== FAILURES ===================================
[task 2022-01-16T14:11:41.268Z] 14:11:41     INFO - STDOUT: ______________ test_dismiss_and_notify[capabilities0-alert-None] _______________
[task 2022-01-16T14:11:41.269Z] 14:11:41     INFO - STDOUT: check_user_prompt_closed_with_exception = <function check_user_prompt_closed_with_exception.<locals>.check_user_prompt_closed_with_exception at 0x7fbbf93952f0>
[task 2022-01-16T14:11:41.277Z] 14:11:41     INFO - STDOUT: dialog_type = 'alert', retval = None
[task 2022-01-16T14:11:41.278Z] 14:11:41     INFO - STDOUT:     @pytest.mark.capabilities({"unhandledPromptBehavior": "dismiss and notify"})
[task 2022-01-16T14:11:41.278Z] 14:11:41     INFO - STDOUT:     @pytest.mark.parametrize("dialog_type, retval", [
[task 2022-01-16T14:11:41.279Z] 14:11:41     INFO - STDOUT:         ("alert", None),
[task 2022-01-16T14:11:41.280Z] 14:11:41     INFO - STDOUT:         ("confirm", False),
[task 2022-01-16T14:11:41.280Z] 14:11:41     INFO - STDOUT:         ("prompt", None),
[task 2022-01-16T14:11:41.281Z] 14:11:41     INFO - STDOUT:     ])
[task 2022-01-16T14:11:41.281Z] 14:11:41     INFO - STDOUT:     def test_dismiss_and_notify(check_user_prompt_closed_with_exception, dialog_type, retval):
[task 2022-01-16T14:11:41.282Z] 14:11:41     INFO - STDOUT: >       check_user_prompt_closed_with_exception(dialog_type, retval)
[task 2022-01-16T14:11:41.282Z] 14:11:41     INFO - STDOUT: check_user_prompt_closed_with_exception = <function check_user_prompt_closed_with_exception.<locals>.check_user_prompt_closed_with_exception at 0x7fbbf93952f0>
[task 2022-01-16T14:11:41.283Z] 14:11:41     INFO - STDOUT: dialog_type = 'alert'
[task 2022-01-16T14:11:41.283Z] 14:11:41     INFO - STDOUT: retval     = None
[task 2022-01-16T14:11:41.284Z] 14:11:41     INFO - STDOUT: tests/web-platform/tests/webdriver/tests/back/user_prompts.py
[task 2022-01-16T14:11:41.284Z] 14:11:41     INFO - STDOUT: :103: 
[task 2022-01-16T14:11:41.284Z] 14:11:41     INFO - STDOUT: _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 
[task 2022-01-16T14:11:41.285Z] 14:11:41     INFO - STDOUT: dialog_type = 'alert', retval = None
[task 2022-01-16T14:11:41.285Z] 14:11:41     INFO - STDOUT:     def check_user_prompt_closed_with_exception(dialog_type, retval):
[task 2022-01-16T14:11:41.286Z] 14:11:41     INFO - STDOUT:         create_dialog(dialog_type, text=dialog_type)
[task 2022-01-16T14:11:41.286Z] 14:11:41     INFO - STDOUT:     
[task 2022-01-16T14:11:41.286Z] 14:11:41     INFO - STDOUT:         response = back(session)
[task 2022-01-16T14:11:41.287Z] 14:11:41     INFO - STDOUT:         assert_error(response, "unexpected alert open")
[task 2022-01-16T14:11:41.287Z] 14:11:41     INFO - STDOUT:     
[task 2022-01-16T14:11:41.288Z] 14:11:41     INFO - STDOUT:         assert_dialog_handled(session, expected_text=dialog_type, expected_retval=retval)
[task 2022-01-16T14:11:41.288Z] 14:11:41     INFO - STDOUT:     
[task 2022-01-16T14:11:41.288Z] 14:11:41     INFO - STDOUT: >       assert session.url == pages[1]
[task 2022-01-16T14:11:41.289Z] 14:11:41     INFO - STDOUT: E       AssertionError: assert 'http://web-platform.test:8000/webdriver/tests/support/inline.py?doc=%3C%21doctype+html%3E%0A%3Cmeta+charset%3DUTF-8%3E%0A%3Cp+id%3D1%3E&mime=text%2Fhtml&charset=UTF-8' == 'http://web-platform.test:8000/webdriver/tests/support/inline.py?doc=%3C%21doctype+html%3E%0A%3Cmeta+charset%3DUTF-8%3E%0A%3Cp+id%3D2%3E&mime=text%2Fhtml&charset=UTF-8'
[task 2022-01-16T14:11:41.290Z] 14:11:41     INFO - STDOUT: E         - http://web-platform.test:8000/webdriver/tests/support/inline.py?doc=%3C%21doctype+html%3E%0A%3Cmeta+charset%3DUTF-8%3E%0A%3Cp+id%3D2%3E&mime=text%2Fhtml&charset=UTF-8
[task 2022-01-16T14:11:41.290Z] 14:11:41     INFO - STDOUT: E         ?                                                                                                                                    ^
[task 2022-01-16T14:11:41.291Z] 14:11:41     INFO - STDOUT: E         + http://web-platform.test:8000/webdriver/tests/support/inline.py?doc=%3C%21doctype+html%3E%0A%3Cmeta+charset%3DUTF-8%3E%0A%3Cp+id%3D1%3E&mime=text%2Fhtml&charset=UTF-8
[task 2022-01-16T14:11:41.291Z] 14:11:41     INFO - STDOUT: E         ?                                                                                                                                    ^
[task 2022-01-16T14:11:41.291Z] 14:11:41     INFO - STDOUT: create_dialog = <function create_dialog.<locals>.create_dialog at 0x7fbc05642f28>
[task 2022-01-16T14:11:41.292Z] 14:11:41     INFO - STDOUT: dialog_type = 'alert'
[task 2022-01-16T14:11:41.293Z] 14:11:41     INFO - STDOUT: pages      = ['http://web-platform.test:8000/webdriver/tests/support/inline.py?doc=%3C%21doctype+html%3E%0A%3Cmeta+charset%3DUTF-8%3E%0A%3Cp+id%3D1%3E&mime=text%2Fhtml&charset=UTF-8',
[task 2022-01-16T14:11:41.293Z] 14:11:41     INFO -  'http://web-platform.test:8000/webdriver/tests/support/inline.py?doc=%3C%21doctype+html%3E%0A%3Cmeta+charset%3DUTF-8%3E%0A%3Cp+id%3D2%3E&mime=text%2Fhtml&charset=UTF-8']
[task 2022-01-16T14:11:41.293Z] 14:11:41     INFO - STDOUT: response   = <Response status=500 error=<UnexpectedAlertOpenException http_status=500>>
[task 2022-01-16T14:11:41.293Z] 14:11:41     INFO - STDOUT: retval     = None
[task 2022-01-16T14:11:41.294Z] 14:11:41     INFO - STDOUT: session    = <Session ee1e83de-b9c2-4e35-bc1c-eecee799b5ab>
[task 2022-01-16T14:11:41.294Z] 14:11:41     INFO - STDOUT: tests/web-platform/tests/webdriver/tests/back/user_prompts.py
[task 2022-01-16T14:11:41.295Z] 14:11:41     INFO - STDOUT: :51: AssertionError
[task 2022-01-16T14:11:41.295Z] 14:11:41     INFO - STDOUT: =========================== short test summary info ============================
[task 2022-01-16T14:11:41.295Z] 14:11:41     INFO - STDOUT: FAILED tests/web-platform/tests/webdriver/tests/back/user_prompts.py::test_dismiss_and_notify[capabilities0-alert-None]
[task 2022-01-16T14:11:41.296Z] 14:11:41     INFO - STDOUT: ======================== 1 failed, 17 passed in 11.14s =========================
[task 2022-01-16T14:11:41.296Z] 14:11:41     INFO - PID 1278 | 1642342301250	Marionette	DEBUG	0 <- [1,87,null,{"x":100,"y":100,"width":800,"height":600}]
[task 2022-01-16T14:11:41.297Z] 14:11:41     INFO - PID 1278 | 1642342301251	webdriver::server	DEBUG	<- 200 OK {"value":{"x":100,"y":100,"width":800,"height":600}}
[task 2022-01-16T14:11:41.297Z] 14:11:41     INFO - PID 1278 | 1642342301251	webdriver::server	DEBUG	-> POST /session/2f72de28-2b6c-4df6-9b11-e26e0a9a6ac8/frame {"id": null}
[task 2022-01-16T14:11:41.298Z] 14:11:41     INFO - PID 1278 | 1642342301252	Marionette	DEBUG	0 -> [0,88,"WebDriver:SwitchToFrame",{"id":null}]
[task 2022-01-16T14:11:41.298Z] 14:11:41     INFO - PID 1278 | 1642342301253	Marionette	DEBUG	0 <- [1,88,null,{"value":null}]
[task 2022-01-16T14:11:41.299Z] 14:11:41     INFO - PID 1278 | 1642342301253	webdriver::server	DEBUG	<- 200 OK {"value":null}
[task 2022-01-16T14:11:41.303Z] 14:11:41     INFO - 
[task 2022-01-16T14:11:41.304Z] 14:11:41     INFO - TEST-PASS | /webdriver/tests/back/user_prompts.py | test_accept[capabilities0-alert] 
[task 2022-01-16T14:11:41.304Z] 14:11:41     INFO - TEST-PASS | /webdriver/tests/back/user_prompts.py | test_accept[capabilities0-confirm] 
[task 2022-01-16T14:11:41.304Z] 14:11:41     INFO - TEST-PASS | /webdriver/tests/back/user_prompts.py | test_accept[capabilities0-prompt] 
[task 2022-01-16T14:11:41.304Z] 14:11:41     INFO - TEST-PASS | /webdriver/tests/back/user_prompts.py | test_accept_and_notify[capabilities0-alert-None] 
[task 2022-01-16T14:11:41.304Z] 14:11:41     INFO - TEST-PASS | /webdriver/tests/back/user_prompts.py | test_accept_and_notify[capabilities0-confirm-True] 
[task 2022-01-16T14:11:41.304Z] 14:11:41     INFO - TEST-PASS | /webdriver/tests/back/user_prompts.py | test_accept_and_notify[capabilities0-prompt-] 
[task 2022-01-16T14:11:41.304Z] 14:11:41     INFO - TEST-PASS | /webdriver/tests/back/user_prompts.py | test_dismiss[capabilities0-alert] 
[task 2022-01-16T14:11:41.304Z] 14:11:41     INFO - TEST-PASS | /webdriver/tests/back/user_prompts.py | test_dismiss[capabilities0-confirm] 
[task 2022-01-16T14:11:41.304Z] 14:11:41     INFO - TEST-PASS | /webdriver/tests/back/user_prompts.py | test_dismiss[capabilities0-prompt] 
[task 2022-01-16T14:11:41.304Z] 14:11:41     INFO - TEST-UNEXPECTED-FAIL | /webdriver/tests/back/user_prompts.py | test_dismiss_and_notify[capabilities0-alert-None] - AssertionError: assert 'http://web-platform.test:8000/webdriver/tests/support/inline.py?doc=%3C%21doctype+html%3E%0A%3Cmeta+charset%3DUTF-8%3E%0A%3Cp+id%3D1%3E&mime=text%2Fhtml&charset=UTF-8' == 'http://web-platform.test:8000/webdriver/tests/support/inline.py?doc=%3C%21doctype+html%3E%0A%3Cmeta+charset%3DUTF-8%3E%0A%3Cp+id%3D2%3E&mime=text%2Fhtml&charset=UTF-8'
[task 2022-01-16T14:11:41.305Z] 14:11:41     INFO - check_user_prompt_closed_with_exception = <function check_user_prompt_closed_with_exception.<locals>.check_user_prompt_closed_with_exception at 0x7fbbf93952f0>
[task 2022-01-16T14:11:41.305Z] 14:11:41     INFO - dialog_type = 'alert', retval = None
[task 2022-01-16T14:11:41.305Z] 14:11:41     INFO - 
[task 2022-01-16T14:11:41.305Z] 14:11:41     INFO -     @pytest.mark.capabilities({"unhandledPromptBehavior": "dismiss and notify"})
[task 2022-01-16T14:11:41.305Z] 14:11:41     INFO -     @pytest.mark.parametrize("dialog_type, retval", [
[task 2022-01-16T14:11:41.305Z] 14:11:41     INFO -         ("alert", None),
[task 2022-01-16T14:11:41.305Z] 14:11:41     INFO -         ("confirm", False),
[task 2022-01-16T14:11:41.305Z] 14:11:41     INFO -         ("prompt", None),
[task 2022-01-16T14:11:41.305Z] 14:11:41     INFO -     ])
[task 2022-01-16T14:11:41.306Z] 14:11:41     INFO -     def test_dismiss_and_notify(check_user_prompt_closed_with_exception, dialog_type, retval):
[task 2022-01-16T14:11:41.306Z] 14:11:41     INFO - >       check_user_prompt_closed_with_exception(dialog_type, retval)
[task 2022-01-16T14:11:41.306Z] 14:11:41     INFO - 
[task 2022-01-16T14:11:41.306Z] 14:11:41     INFO - check_user_prompt_closed_with_exception = <function check_user_prompt_closed_with_exception.<locals>.check_user_prompt_closed_with_exception at 0x7fbbf93952f0>
[task 2022-01-16T14:11:41.306Z] 14:11:41     INFO - dialog_type = 'alert'
[task 2022-01-16T14:11:41.307Z] 14:11:41     INFO - retval     = None
[task 2022-01-16T14:11:41.307Z] 14:11:41     INFO - 
[task 2022-01-16T14:11:41.307Z] 14:11:41     INFO - tests/web-platform/tests/webdriver/tests/back/user_prompts.py:103: 
[task 2022-01-16T14:11:41.307Z] 14:11:41     INFO - _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 
[task 2022-01-16T14:11:41.308Z] 14:11:41     INFO - 
[task 2022-01-16T14:11:41.308Z] 14:11:41     INFO - dialog_type = 'alert', retval = None
[task 2022-01-16T14:11:41.308Z] 14:11:41     INFO - 
[task 2022-01-16T14:11:41.308Z] 14:11:41     INFO -     def check_user_prompt_closed_with_exception(dialog_type, retval):
[task 2022-01-16T14:11:41.308Z] 14:11:41     INFO -         create_dialog(dialog_type, text=dialog_type)
[task 2022-01-16T14:11:41.308Z] 14:11:41     INFO -     
[task 2022-01-16T14:11:41.308Z] 14:11:41     INFO -         response = back(session)
[task 2022-01-16T14:11:41.308Z] 14:11:41     INFO -         assert_error(response, "unexpected alert open")
[task 2022-01-16T14:11:41.308Z] 14:11:41     INFO -     
[task 2022-01-16T14:11:41.308Z] 14:11:41     INFO -         assert_dialog_handled(session, expected_text=dialog_type, expected_retval=retval)
[task 2022-01-16T14:11:41.308Z] 14:11:41     INFO -     
[task 2022-01-16T14:11:41.308Z] 14:11:41     INFO - >       assert session.url == pages[1]
[task 2022-01-16T14:11:41.308Z] 14:11:41     INFO - E       AssertionError: assert 'http://web-platform.test:8000/webdriver/tests/support/inline.py?doc=%3C%21doctype+html%3E%0A%3Cmeta+charset%3DUTF-8%3E%0A%3Cp+id%3D1%3E&mime=text%2Fhtml&charset=UTF-8' == 'http://web-platform.test:8000/webdriver/tests/support/inline.py?doc=%3C%21doctype+html%3E%0A%3Cmeta+charset%3DUTF-8%3E%0A%3Cp+id%3D2%3E&mime=text%2Fhtml&charset=UTF-8'
[task 2022-01-16T14:11:41.308Z] 14:11:41     INFO - E         - http://web-platform.test:8000/webdriver/tests/support/inline.py?doc=%3C%21doctype+html%3E%0A%3Cmeta+charset%3DUTF-8%3E%0A%3Cp+id%3D2%3E&mime=text%2Fhtml&charset=UTF-8
[task 2022-01-16T14:11:41.308Z] 14:11:41     INFO - E         ?                                                                                                                                    ^
[task 2022-01-16T14:11:41.308Z] 14:11:41     INFO - E         + http://web-platform.test:8000/webdriver/tests/support/inline.py?doc=%3C%21doctype+html%3E%0A%3Cmeta+charset%3DUTF-8%3E%0A%3Cp+id%3D1%3E&mime=text%2Fhtml&charset=UTF-8
[task 2022-01-16T14:11:41.308Z] 14:11:41     INFO - E         ?                                                                                                                                    ^
[task 2022-01-16T14:11:41.308Z] 14:11:41     INFO - 
[task 2022-01-16T14:11:41.308Z] 14:11:41     INFO - create_dialog = <function create_dialog.<locals>.create_dialog at 0x7fbc05642f28>
[task 2022-01-16T14:11:41.308Z] 14:11:41     INFO - dialog_type = 'alert'
[task 2022-01-16T14:11:41.308Z] 14:11:41     INFO - pages      = ['http://web-platform.test:8000/webdriver/tests/support/inline.py?doc=%3C%21doctype+html%3E%0A%3Cmeta+charset%3DUTF-8%3E%0A%3Cp+id%3D1%3E&mime=text%2Fhtml&charset=UTF-8',
[task 2022-01-16T14:11:41.308Z] 14:11:41     INFO -  'http://web-platform.test:8000/webdriver/tests/support/inline.py?doc=%3C%21doctype+html%3E%0A%3Cmeta+charset%3DUTF-8%3E%0A%3Cp+id%3D2%3E&mime=text%2Fhtml&charset=UTF-8']
[task 2022-01-16T14:11:41.308Z] 14:11:41     INFO - response   = <Response status=500 error=<UnexpectedAlertOpenException http_status=500>>
[task 2022-01-16T14:11:41.308Z] 14:11:41     INFO - retval     = None
[task 2022-01-16T14:11:41.308Z] 14:11:41     INFO - session    = <Session ee1e83de-b9c2-4e35-bc1c-eecee799b5ab>
[task 2022-01-16T14:11:41.308Z] 14:11:41     INFO - 
[task 2022-01-16T14:11:41.308Z] 14:11:41     INFO - tests/web-platform/tests/webdriver/tests/back/user_prompts.py:51: AssertionError
[task 2022-01-16T14:11:41.308Z] 14:11:41     INFO - ........
[task 2022-01-16T14:11:41.308Z] 14:11:41     INFO - TEST-OK | /webdriver/tests/back/user_prompts.py | took 11196ms
[task 2022-01-16T14:11:41.308Z] 14:11:41     INFO - Restarting browser for new test group
[task 2022-01-16T14:11:41.367Z] 14:11:41     INFO - Closing logging queue
[task 2022-01-16T14:11:41.368Z] 14:11:41     INFO - queue closed
[task 2022-01-16T14:11:41.370Z] 14:11:41     INFO - Starting runner
[task 2022-01-16T14:11:41.752Z] 14:11:41     INFO - WebDriver HTTP server listening at http://127.0.0.1:33710/
[task 2022-01-16T14:11:41.752Z] 14:11:41     INFO - TEST-START | /webdriver/tests/close_window/close.py

Here the real failure:

https://treeherder.mozilla.org/logviewer?job_id=364282793&repo=try&lineNumber=5436-5439

[task 2022-01-16T14:11:36.885Z] 14:11:36     INFO - PID 1278 | 1642342296864	Marionette	DEBUG	0 -> [0,7,"WebDriver:Navigate",{"url":"http://web-platform.test:8000/webdriver/tests/support/inline.py?doc=%3C%21doctype+html%3E%0A%3Cmeta+charset%3DUTF-8%3E%0A%3Cp+id%3D1%3E&mime=text%2Fhtml&charset=UTF-8"}]
[task 2022-01-16T14:11:36.886Z] 14:11:36     INFO - PID 1278 | 1642342296866	Marionette	TRACE	[39] Received event pagehide for about:blank
[task 2022-01-16T14:11:36.887Z] 14:11:36     INFO - PID 1278 | 1642342296868	Marionette	TRACE	[39] Received event DOMContentLoaded for about:blank
[task 2022-01-16T14:11:36.888Z] 14:11:36     INFO - PID 1278 | 1642342296868	Marionette	TRACE	[39] Received event pageshow for about:blank

After opening a new tab we didn't wait long enough for the initial about:blank to be loaded. As such the request to navigate returned too early.

This will be fixed with my patch on bug 1747359.

Depends on: 1747359
Assignee: nobody → hskupin
Status: NEW → RESOLVED
Closed: 3 years ago
status-firefox97: --- → affected
status-firefox98: --- → fixed
Keywords: regression
Regressed by: 1739369
Resolution: --- → FIXED
Target Milestone: --- → 98 Branch

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

status-firefox96: --- → unaffected
status-firefox-esr91: --- → unaffected
Has Regression Range: --- → yes
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.