Closed Bug 1508700 Opened 6 years ago Closed 5 years ago

Intermittent TEST-UNEXPECTED-OK | /webdriver/tests/execute_script/promise.py | expected TIMEOUT

Categories

(Remote Protocol :: Marionette, defect, P5)

Product:
Remote Protocol
Component:
Marionette
Version:
Version 3
Type:
defect

Tracking

(firefox65 fixed)

Status:
RESOLVED FIXED
Milestone:
mozilla65
Tracking Flags:
Tracking Status
firefox65 --- fixed

People

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

References

Details

(Keywords: intermittent-failure, Whiteboard: [stockwell needswork:owner]) 

Filed by: nerli [at] mozilla.com

https://treeherder.mozilla.org/logviewer.html#?job_id=212904814&repo=mozilla-inbound

https://queue.taskcluster.net/v1/task/O43S9X9_QiqzWZ6u9qMsEA/runs/0/artifacts/public/logs/live_backing.log

[task 2018-11-20T15:16:53.407Z] 15:16:53     INFO - TEST-UNEXPECTED-OK | /webdriver/tests/execute_script/promise.py | expected TIMEOUT
[task 2018-11-20T15:16:53.408Z] 15:16:53     INFO - TEST-INFO expected TIMEOUT | took 3536ms
[task 2018-11-20T15:16:53.409Z] 15:16:53     INFO - Closing logging queue
[task 2018-11-20T15:16:53.410Z] 15:16:53     INFO - queue closed
[task 2018-11-20T15:16:53.412Z] 15:16:53     INFO - Starting runner
[task 2018-11-20T15:16:53.415Z] 15:16:53     INFO - WebDriver HTTP server listening at http://127.0.0.1:4444/
[task 2018-11-20T15:16:53.416Z] 15:16:53     INFO - TEST-START | /webdriver/tests/execute_script/user_prompts.py
[task 2018-11-20T15:16:53.418Z] 15:16:53     INFO - PID 6910 | 1542727013370	webdriver::httpapi	DEBUG	Creating routes
[task 2018-11-20T15:16:53.419Z] 15:16:53     INFO - PID 6910 | 1542727013377	geckodriver	DEBUG	Listening on 127.0.0.1:4444
[task 2018-11-20T15:16:53.961Z] 15:16:53     INFO - STDOUT: ============================= test session starts ==============================
[task 2018-11-20T15:16:53.961Z] 15:16:53     INFO - STDOUT: platform linux2 -- Python 2.7.12, pytest-unknown, py-1.5.2, pluggy-0.5.3.dev -- /builds/worker/workspace/build/venv/bin/python
[task 2018-11-20T15:16:53.963Z] 15:16:53     INFO - STDOUT: rootdir: /builds/worker/workspace/build, inifile:
[task 2018-11-20T15:16:53.964Z] 15:16:53     INFO - STDOUT: collecting ... 
[task 2018-11-20T15:16:53.992Z] 15:16:53     INFO - STDOUT: collected 18 items
[task 2018-11-20T15:16:53.993Z] 15:16:53     INFO - STDOUT: tests/web-platform/tests/webdriver/tests/execute_script/user_prompts.py::test_accept[capabilities0-alert-None]
This occurred when bug Bug 1504756 landed. Henrik, can you take a look?

There are 45 total failures in the last 7 days, recent failure log: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=215507864&repo=autoland&lineNumber=31428

[task 2018-12-05T02:49:46.627Z] 02:49:46     INFO - TEST-START | /webdriver/tests/execute_script/promise.py

[task 2018-12-05T02:49:50.397Z] 02:49:50     INFO - STDOUT: tests/web-platform/tests/webdriver/tests/support/asserts.py
[task 2018-12-05T02:49:50.398Z] 02:49:50     INFO - STDOUT: :50: KeyError
[task 2018-12-05T02:49:50.398Z] 02:49:50     INFO - STDOUT: =============================== warnings summary ===============================
[task 2018-12-05T02:49:50.400Z] 02:49:50     INFO - STDOUT: <undetermined location>
[task 2018-12-05T02:49:50.401Z] 02:49:50     INFO - STDOUT:   Module already imported so cannot be rewritten: mozlog
[task 2018-12-05T02:49:50.402Z] 02:49:50     INFO - STDOUT:   Module already imported so cannot be rewritten: tests.support.fixtures
[task 2018-12-05T02:49:50.403Z] 02:49:50     INFO - STDOUT: -- Docs: http://doc.pytest.org/en/latest/warnings.html
[task 2018-12-05T02:49:50.404Z] 02:49:50     INFO - STDOUT: ================ 6 failed, 4 passed, 2 warnings in 3.69 seconds ================
[task 2018-12-05T02:49:50.415Z] 02:49:50     INFO - TEST-UNEXPECTED-OK | /webdriver/tests/execute_script/promise.py | expected TIMEOUT
[task 2018-12-05T02:49:50.416Z] 02:49:50     INFO - TEST-INFO expected TIMEOUT | took 3784ms
[task 2018-12-05T02:49:50.417Z] 02:49:50     INFO - Closing logging queue
[task 2018-12-05T02:49:50.423Z] 02:49:50     INFO - queue closed
[task 2018-12-05T02:49:50.423Z] 02:49:50     INFO - Starting runner
[task 2018-12-05T02:49:50.423Z] 02:49:50     INFO - PID 7185 | 1543978190411	webdriver::httpapi	DEBUG	Creating routes
[task 2018-12-05T02:49:50.423Z] 02:49:50     INFO - PID 7185 | 1543978190417	geckodriver	DEBUG	Listening on 127.0.0.1:4444
Flags: needinfo?(hskupin)
Whiteboard: [stockwell needswork:owner]
Blocks: 1504756
The hang here is coming from the seconds dialog which gets opened in the execute script call in the test `test_abort_by_user_prompt_twice`:

https://searchfox.org/mozilla-central/rev/3fdc51e66c9487b39220ad58dcee275fca070ccd/testing/web-platform/tests/webdriver/tests/execute_script/execute.py#47

My patch on bug 1504756 makes this test not to timeout anymore, means the second dialog gets correctly closed now, and doesn't hang around and blocks further calls to execute_script with promises involved. The following lines with the improved handling of the `DOMModalDialogClosed` event make it work: https://phabricator.services.mozilla.com//D13660#change-XmYvVg2wKtAJ

I will have to update the expectation data of this test file, which I will have to do directly in my patch on bug 1504756.
No longer blocks: 1504756
Depends on: 1504756
Flags: needinfo?(hskupin)
Update: there are 77 total failures in the last 7 days, all of them on autoland.

Recent failure log: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=215506871&repo=autoland&lineNumber=21115

18:09:01     INFO - STDOUT: response = <Response status=500 error=<UnknownErrorException http_status=500>>
18:09:01     INFO - STDOUT: error_code = 'timeout error'
18:09:01     INFO - STDOUT:     def assert_error(response, error_code):
18:09:01     INFO - STDOUT:         """
18:09:01     INFO - STDOUT:         Verify that the provided webdriver.Response instance described
18:09:01     INFO - STDOUT:         a valid error response as defined by `dfn-send-an-error` and
18:09:01     INFO - STDOUT:         the provided error code.
18:09:01     INFO - STDOUT:     
18:09:01     INFO - STDOUT:         :param response: ``webdriver.Response`` instance.
18:09:01     INFO - STDOUT:         :param error_code: String value of the expected error code
18:09:01     INFO - STDOUT:         """
18:09:01     INFO - STDOUT: >       assert response.status == errors[error_code]
18:09:01     INFO - STDOUT: E       KeyError: 'timeout error'
18:09:01     INFO - STDOUT: error_code = 'timeout error'
18:09:01     INFO - STDOUT: response   = <Response status=500 error=<UnknownErrorException http_status=500>>
18:09:01     INFO - STDOUT: tests/web-platform/tests/webdriver/tests/support/asserts.py
18:09:01     INFO - STDOUT: :50: KeyError
18:09:01     INFO - STDOUT: =============================== warnings summary ===============================
18:09:01     INFO - STDOUT: <undetermined location>
18:09:01     INFO - STDOUT:   Module already imported so cannot be rewritten: mozlog
18:09:01     INFO - STDOUT:   Module already imported so cannot be rewritten: tests.support.fixtures
18:09:01     INFO - STDOUT: -- Docs: http://doc.pytest.org/en/latest/warnings.html
18:09:01     INFO - STDOUT: ================ 6 failed, 4 passed, 2 warnings in 2.91 seconds ================
18:09:01     INFO - TEST-UNEXPECTED-OK | /webdriver/tests/execute_script/promise.py | expected TIMEOUT
18:09:01     INFO - TEST-INFO expected TIMEOUT | took 2989ms
18:09:01     INFO - Closing logging queue
18:09:01     INFO - queue closed
18:09:01     INFO - Starting runner
18:09:01     INFO - PID 2082 | 1543975741361	webdriver::httpapi	DEBUG	Creating routes
18:09:01     INFO - PID 2082 | 1543975741368	geckodriver	DEBUG	Listening on 127.0.0.1:4444
18:09:01     INFO - WebDriver HTTP server listening at http://127.0.0.1:4444/
Fixed by my patch on bug 1504756.
Assignee: nobody → hskupin
Status: NEW → RESOLVED
Closed: 5 years ago
status-firefox65: --- → fixed
Resolution: --- → FIXED
Target Milestone: --- → mozilla65
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.