1715647 - Intermittent /webdriver/tests/back/user_prompts.py | test_accept[capabilities0-confirm] - AssertionError: timeout (500): TimedPromise timed out after 300000 ms

Status: RESOLVED DUPLICATE of bug 1715884

(Remote Protocol :: Marionette, defect, P5)

Description

[Treeherder Bug Filer]

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

---

[task 2021-06-09T19:48:01.305Z] 19:48:01     INFO - STDOUT: =========================== short test summary info ============================
[task 2021-06-09T19:48:01.305Z] 19:48:01     INFO - STDOUT: FAILED tests/web-platform/tests/webdriver/tests/back/user_prompts.py::test_accept[capabilities0-confirm]
[task 2021-06-09T19:48:01.306Z] 19:48:01     INFO - STDOUT: =================== 1 failed, 17 passed in 371.65s (0:06:11) ===================
[task 2021-06-09T19:48:01.309Z] 19:48:01     INFO - 
[task 2021-06-09T19:48:01.309Z] 19:48:01     INFO - TEST-PASS | /webdriver/tests/back/user_prompts.py | test_accept[capabilities0-alert] 
[task 2021-06-09T19:48:01.309Z] 19:48:01     INFO - TEST-UNEXPECTED-FAIL | /webdriver/tests/back/user_prompts.py | test_accept[capabilities0-confirm] - AssertionError: timeout (500): TimedPromise timed out after 300000 ms
[task 2021-06-09T19:48:01.309Z] 19:48:01     INFO - check_user_prompt_closed_without_exception = <function check_user_prompt_closed_without_exception.<locals>.check_user_prompt_closed_without_exception at 0x7f4eddf7da60>
[task 2021-06-09T19:48:01.310Z] 19:48:01     INFO - dialog_type = 'confirm'
[task 2021-06-09T19:48:01.310Z] 19:48:01     INFO - 
[task 2021-06-09T19:48:01.310Z] 19:48:01     INFO -     @pytest.mark.capabilities({"unhandledPromptBehavior": "accept"})
[task 2021-06-09T19:48:01.310Z] 19:48:01     INFO -     @pytest.mark.parametrize("dialog_type", ["alert", "confirm", "prompt"])
[task 2021-06-09T19:48:01.310Z] 19:48:01     INFO -     def test_accept(check_user_prompt_closed_without_exception, dialog_type):
[task 2021-06-09T19:48:01.310Z] 19:48:01     INFO -         # retval not testable for confirm and prompt because window is gone
[task 2021-06-09T19:48:01.310Z] 19:48:01     INFO - >       check_user_prompt_closed_without_exception(dialog_type, None)
[task 2021-06-09T19:48:01.310Z] 19:48:01     INFO - 
[task 2021-06-09T19:48:01.310Z] 19:48:01     INFO - check_user_prompt_closed_without_exception = <function check_user_prompt_closed_without_exception.<locals>.check_user_prompt_closed_without_exception at 0x7f4eddf7da60>
[task 2021-06-09T19:48:01.310Z] 19:48:01     INFO - dialog_type = 'confirm'
[task 2021-06-09T19:48:01.311Z] 19:48:01     INFO - 
[task 2021-06-09T19:48:01.311Z] 19:48:01     INFO - tests/web-platform/tests/webdriver/tests/back/user_prompts.py:76: 
[task 2021-06-09T19:48:01.311Z] 19:48:01     INFO - _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 
[task 2021-06-09T19:48:01.311Z] 19:48:01     INFO - tests/web-platform/tests/webdriver/tests/back/user_prompts.py:32: in check_user_prompt_closed_without_exception
[task 2021-06-09T19:48:01.311Z] 19:48:01     INFO -     assert_success(response)
[task 2021-06-09T19:48:01.311Z] 19:48:01     INFO -         create_dialog = <function create_dialog.<locals>.create_dialog at 0x7f4eddfcb840>
[task 2021-06-09T19:48:01.311Z] 19:48:01     INFO -         dialog_type = 'confirm'
[task 2021-06-09T19:48:01.311Z] 19:48:01     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 2021-06-09T19:48:01.312Z] 19:48:01     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 2021-06-09T19:48:01.312Z] 19:48:01     INFO -         response   = <Response status=500 error=<TimeoutException http_status=500>>
[task 2021-06-09T19:48:01.312Z] 19:48:01     INFO -         retval     = None
[task 2021-06-09T19:48:01.312Z] 19:48:01     INFO -         session    = <Session 0cc27200-da03-42a6-9d07-25243a32849d>
[task 2021-06-09T19:48:01.312Z] 19:48:01     INFO - _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 
[task 2021-06-09T19:48:01.312Z] 19:48:01     INFO - 
[task 2021-06-09T19:48:01.312Z] 19:48:01     INFO - response = <Response status=500 error=<TimeoutException http_status=500>>
[task 2021-06-09T19:48:01.312Z] 19:48:01     INFO - value = None
[task 2021-06-09T19:48:01.312Z] 19:48:01     INFO - 
[task 2021-06-09T19:48:01.312Z] 19:48:01     INFO -     def assert_success(response, value=None):
[task 2021-06-09T19:48:01.312Z] 19:48:01     INFO -         """
[task 2021-06-09T19:48:01.312Z] 19:48:01     INFO -         Verify that the provided webdriver.Response instance described
[task 2021-06-09T19:48:01.312Z] 19:48:01     INFO -         a valid success response as defined by `dfn-send-a-response` and
[task 2021-06-09T19:48:01.312Z] 19:48:01     INFO -         the provided response value.
[task 2021-06-09T19:48:01.312Z] 19:48:01     INFO -     
[task 2021-06-09T19:48:01.312Z] 19:48:01     INFO -         :param response: ``webdriver.Response`` instance.
[task 2021-06-09T19:48:01.312Z] 19:48:01     INFO -         :param value: Expected value of the response body, if any.
[task 2021-06-09T19:48:01.312Z] 19:48:01     INFO -         """
[task 2021-06-09T19:48:01.312Z] 19:48:01     INFO - >       assert response.status == 200, str(response.error)
[task 2021-06-09T19:48:01.312Z] 19:48:01     INFO - E       AssertionError: timeout (500): TimedPromise timed out after 300000 ms
[task 2021-06-09T19:48:01.313Z] 19:48:01     INFO - E         
[task 2021-06-09T19:48:01.313Z] 19:48:01     INFO - E         Remote-end stacktrace:
[task 2021-06-09T19:48:01.313Z] 19:48:01     INFO - E         
[task 2021-06-09T19:48:01.313Z] 19:48:01     INFO - E         WebDriverError@chrome://remote/content/marionette/error.js:181:5
[task 2021-06-09T19:48:01.313Z] 19:48:01     INFO - E         TimeoutError@chrome://remote/content/marionette/error.js:450:5
[task 2021-06-09T19:48:01.313Z] 19:48:01     INFO - E         bail@chrome://remote/content/marionette/sync.js:229:19
[task 2021-06-09T19:48:01.313Z] 19:48:01     INFO - E         
[task 2021-06-09T19:48:01.313Z] 19:48:01     INFO - E       assert 500 == 200
[task 2021-06-09T19:48:01.313Z] 19:48:01     INFO - E         +500
[task 2021-06-09T19:48:01.313Z] 19:48:01     INFO - E         -200
[task 2021-06-09T19:48:01.314Z] 19:48:01     INFO - 

Comment 1

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

There is an assertion happening and then navigation times out:

[task 2021-06-09T19:41:59.819Z] 19:41:59     INFO - PID 1536 | 1623267719817	Marionette	DEBUG	0 -> [0,40,"WebDriver:Back",{}]
[task 2021-06-09T19:41:59.834Z] 19:41:59     INFO - PID 1536 | 1623267719832	Marionette	TRACE	Received event DOMModalDialogClosed
[task 2021-06-09T19:41:59.852Z] 19:41:59     INFO - PID 1536 | [Child 2394, Main Thread] ###!!! ASSERTION: Overwriting an existing document channel!: '(loadFlags & nsIChannel::LOAD_REPLACE) || !(mDocumentRequest.get())', file /builds/worker/checkouts/gecko/uriloader/base/nsDocLoader.cpp:463
[task 2021-06-09T19:41:59.854Z] 19:41:59     INFO - PID 1536 | 1623267719851	Marionette	TRACE	Remoteness change detected. Set new top-level browsing context to 49
..
[task 2021-06-09T19:46:59.848Z] 19:46:59     INFO - PID 1536 | 1623268019846	Marionette	DEBUG	0 <- [1,40,{"error":"timeout","message":"TimedPromise timed out after 300000 ms","stacktrace":"WebDriverError@chrome://remote/cont ... eoutError@chrome://remote/content/marionette/error.js:450:5\nbail@chrome://remote/content/marionette/sync.js:229:19\n"},null]
[task 2021-06-09T19:46:59.884Z] 19:46:59     INFO - PID 1536 | 1623268019847	webdriver::server	DEBUG	<- 500 Internal Server Error {"value":{"error":"timeout","message":"TimedPromise timed out after 300000 ms","stacktrace":"WebDriverError@chrome://remote/content/marionette/error.js:181:5\nTimeoutError@chrome://remote/content/marionette/error.js:450:5\nbail@chrome://remote/content/marionette/sync.js:229:19\n"}}

Olli, did something land recently for bfcache that could have caused that? Maybe the fix on bug 1697905 that caused it? There are a lot of other failures of the same kind in Wdspec and Mn jobs.

Comment 2

[Olli Pettay [:smaug][[e-mail]]]

bfcache was enabled yesterday. bug 1715300.
Could that have caused this?

Comment 3

[Intermittent Failures Robot]

2 failures in 3502 pushes (0.001 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 2

Platform and build breakdown:

• linux1804-64-qr: 1
  • debug: 1
• linux1804-64-asan-qr: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1715647&startday=2021-06-07&endday=2021-06-13&tree=all

Comment 5

[BMO Automation]

Moving bug to Remote Protocol::Marionette component per bug 1815831.