Closed Bug 1665686 Opened 4 years ago Closed 2 years ago

Intermittent /webdriver/tests/switch_to_parent_frame/switch.py | test_no_parent_browsing_context - assert 200 == 404

Categories

(Remote Protocol :: Marionette, defect, P5)

defect

Tracking

(Not tracked)

RESOLVED DUPLICATE of bug 1785377

People

(Reporter: intermittent-bug-filer, Unassigned)

References

Details

(Keywords: intermittent-failure)

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


[task 2020-09-17T15:10:15.880Z] 15:10:15 INFO - STDOUT: tests/web-platform/tests/webdriver/tests/switch_to_parent_frame/switch.py::test_switch_from_top_level
[task 2020-09-17T15:10:15.880Z] 15:10:15 INFO - PID 1112 | 1600355415876 webdriver::server DEBUG -> POST /session/bac522d2-501a-194e-a8c1-3f6bc7569c24/window/rect {"width": 800, "height": 600}
[task 2020-09-17T15:10:15.888Z] 15:10:15 INFO - PID 1112 | 1600355415878 Marionette DEBUG 1 -> [0,122,"WebDriver:SetWindowRect",{"height":600,"width":800}]
[task 2020-09-17T15:10:15.888Z] 15:10:15 INFO - PID 1112 | 1600355415881 Marionette DEBUG 1 <- [1,122,null,{"x":100,"y":100,"width":800,"height":600}]
[task 2020-09-17T15:10:15.889Z] 15:10:15 INFO - PID 1112 | 1600355415881 webdriver::server DEBUG <- 200 OK {"value":{"x":100,"y":100,"width":800,"height":600}}
[task 2020-09-17T15:10:15.890Z] 15:10:15 INFO - PID 1112 | 1600355415883 webdriver::server DEBUG -> POST /session/bac522d2-501a-194e-a8c1-3f6bc7569c24/window/rect {"y": 100, "x": 100}
[task 2020-09-17T15:10:15.891Z] 15:10:15 INFO - PID 1112 | 1600355415884 Marionette DEBUG 1 -> [0,123,"WebDriver:SetWindowRect",{"x":100,"y":100}]
[task 2020-09-17T15:10:15.892Z] 15:10:15 INFO - PID 1112 | 1600355415888 Marionette DEBUG 1 <- [1,123,null,{"x":100,"y":100,"width":800,"height":600}]
[task 2020-09-17T15:10:15.892Z] 15:10:15 INFO - PID 1112 | 1600355415889 webdriver::server DEBUG <- 200 OK {"value":{"x":100,"y":100,"width":800,"height":600}}
[task 2020-09-17T15:10:15.909Z] 15:10:15 INFO - STDOUT: PASSED
[task 2020-09-17T15:10:15.910Z] 15:10:15 INFO - PID 1112 | 1600355415892 webdriver::server DEBUG -> POST /session/bac522d2-501a-194e-a8c1-3f6bc7569c24/frame/parent {}
[task 2020-09-17T15:10:15.910Z] 15:10:15 INFO - PID 1112 | 1600355415893 Marionette DEBUG 1 -> [0,124,"WebDriver:SwitchToParentFrame",{}]
[task 2020-09-17T15:10:15.911Z] 15:10:15 INFO - PID 1112 | 1600355415894 Marionette DEBUG 1 <- [1,124,null,{"value":null}]
[task 2020-09-17T15:10:15.911Z] 15:10:15 INFO - PID 1112 | 1600355415895 webdriver::server DEBUG <- 200 OK {"value":null}
[task 2020-09-17T15:10:15.911Z] 15:10:15 INFO - PID 1112 | 1600355415898 webdriver::server DEBUG -> POST /session/bac522d2-501a-194e-a8c1-3f6bc7569c24/timeouts {"implicit": 0}
[task 2020-09-17T15:10:15.912Z] 15:10:15 INFO - PID 1112 | 1600355415899 Marionette DEBUG 1 -> [0,125,"WebDriver:SetTimeouts",{"implicit":0}]
[task 2020-09-17T15:10:15.912Z] 15:10:15 INFO - PID 1112 | 1600355415900 Marionette DEBUG 1 <- [1,125,null,{"value":null}]
[task 2020-09-17T15:10:15.912Z] 15:10:15 INFO - PID 1112 | 1600355415901 webdriver::server DEBUG <- 200 OK {"value":null}
[task 2020-09-17T15:10:15.914Z] 15:10:15 INFO - PID 1112 | 1600355415904 webdriver::server DEBUG -> POST /session/bac522d2-501a-194e-a8c1-3f6bc7569c24/timeouts {"pageLoad": 300000}
[task 2020-09-17T15:10:15.915Z] 15:10:15 INFO - PID 1112 | 1600355415905 Marionette DEBUG 1 -> [0,126,"WebDriver:SetTimeouts",{"pageLoad":300000}]
[task 2020-09-17T15:10:15.919Z] 15:10:15 INFO - PID 1112 | 1600355415906 Marionette DEBUG 1 <- [1,126,null,{"value":null}]
[task 2020-09-17T15:10:15.920Z] 15:10:15 INFO - PID 1112 | 1600355415907 webdriver::server DEBUG <- 200 OK {"value":null}
[task 2020-09-17T15:10:15.920Z] 15:10:15 INFO - PID 1112 | 1600355415909 webdriver::server DEBUG -> POST /session/bac522d2-501a-194e-a8c1-3f6bc7569c24/timeouts {"script": 30000}
[task 2020-09-17T15:10:15.921Z] 15:10:15 INFO - PID 1112 | 1600355415911 Marionette DEBUG 1 -> [0,127,"WebDriver:SetTimeouts",{"script":30000}]
[task 2020-09-17T15:10:15.921Z] 15:10:15 INFO - PID 1112 | 1600355415913 Marionette DEBUG 1 <- [1,127,null,{"value":null}]
[task 2020-09-17T15:10:15.922Z] 15:10:15 INFO - PID 1112 | 1600355415914 webdriver::server DEBUG <- 200 OK {"value":null}
[task 2020-09-17T15:10:15.922Z] 15:10:15 INFO - PID 1112 | 1600355415916 webdriver::server DEBUG -> GET /session/bac522d2-501a-194e-a8c1-3f6bc7569c24/window
[task 2020-09-17T15:10:15.925Z] 15:10:15 INFO - PID 1112 | 1600355415918 Marionette DEBUG 1 -> [0,128,"WebDriver:GetWindowHandle",{}]
[task 2020-09-17T15:10:15.925Z] 15:10:15 INFO - PID 1112 | 1600355415918 Marionette DEBUG 1 <- [1,128,null,{"value":"22"}]
[task 2020-09-17T15:10:15.926Z] 15:10:15 INFO - PID 1112 | 1600355415919 webdriver::server DEBUG <- 200 OK {"value":"22"}
[task 2020-09-17T15:10:15.926Z] 15:10:15 INFO - PID 1112 | 1600355415922 webdriver::server DEBUG -> GET /session/bac522d2-501a-194e-a8c1-3f6bc7569c24/window
[task 2020-09-17T15:10:15.929Z] 15:10:15 INFO - PID 1112 | 1600355415924 Marionette DEBUG 1 -> [0,129,"WebDriver:GetWindowHandle",{}]
[task 2020-09-17T15:10:15.930Z] 15:10:15 INFO - PID 1112 | 1600355415925 Marionette DEBUG 1 <- [1,129,null,{"value":"22"}]
[task 2020-09-17T15:10:15.932Z] 15:10:15 INFO - PID 1112 | 1600355415928 webdriver::server DEBUG <- 200 OK {"value":"22"}
[task 2020-09-17T15:10:15.941Z] 15:10:15 INFO - PID 1112 | 1600355415931 webdriver::server DEBUG -> GET /session/bac522d2-501a-194e-a8c1-3f6bc7569c24/window/handles
[task 2020-09-17T15:10:15.942Z] 15:10:15 INFO - PID 1112 | 1600355415932 Marionette DEBUG 1 -> [0,130,"WebDriver:GetWindowHandles",{}]
[task 2020-09-17T15:10:15.942Z] 15:10:15 INFO - PID 1112 | 1600355415932 Marionette DEBUG 1 <- [1,130,null,["22"]]
[task 2020-09-17T15:10:15.942Z] 15:10:15 INFO - PID 1112 | 1600355415933 webdriver::server DEBUG <- 200 OK {"value":["22"]}
[task 2020-09-17T15:10:15.942Z] 15:10:15 INFO - PID 1112 | 1600355415935 webdriver::server DEBUG -> POST /session/bac522d2-501a-194e-a8c1-3f6bc7569c24/window {"handle": "22"}
[task 2020-09-17T15:10:15.942Z] 15:10:15 INFO - PID 1112 | 1600355415936 Marionette DEBUG 1 -> [0,131,"WebDriver:SwitchToWindow",{"handle":"22","name":"22"}]
[task 2020-09-17T15:10:15.951Z] 15:10:15 INFO - PID 1112 | 1600355415938 Marionette DEBUG 1 <- [1,131,null,{"value":null}]
[task 2020-09-17T15:10:15.951Z] 15:10:15 INFO - PID 1112 | 1600355415939 webdriver::server DEBUG <- 200 OK {"value":null}
[task 2020-09-17T15:10:15.952Z] 15:10:15 INFO - PID 1112 | 1600355415940 webdriver::server DEBUG -> POST /session/bac522d2-501a-194e-a8c1-3f6bc7569c24/alert/dismiss {}
[task 2020-09-17T15:10:15.953Z] 15:10:15 INFO - PID 1112 | 1600355415942 Marionette DEBUG 1 -> [0,132,"WebDriver:DismissAlert",{}]
[task 2020-09-17T15:10:15.954Z] 15:10:15 INFO - PID 1112 | 1600355415943 Marionette DEBUG 1 <- [1,132,{"error":"no such alert","message":"","stacktrace":"WebDriverError@chrome://marionette/content/error.js:181:5\nNoSuchA ... t@chrome://marionette/content/server.js:241:9\n_onJSONObjectReady/<@chrome://marionette/content/transport.js:504:20\n"},null]
[task 2020-09-17T15:10:15.957Z] 15:10:15 INFO - PID 1112 | 1600355415943 webdriver::server DEBUG <- 404 Not Found {"value":{"error":"no such alert","message":"","stacktrace":"WebDriverError@chrome://marionette/content/error.js:181:5\nNoSuchAlertError@chrome://marionette/content/error.js:382:5\nGeckoDriver.prototype._checkIfAlertIsPresent@chrome://marionette/content/driver.js:3398:11\nGeckoDriver.prototype.dismissDialog@chrome://marionette/content/driver.js:3301:8\ndespatch@chrome://marionette/content/server.js:297:40\nexecute@chrome://marionette/content/server.js:267:16\nonPacket/<@chrome://marionette/content/server.js:240:20\nonPacket@chrome://marionette/content/server.js:241:9\n_onJSONObjectReady/<@chrome://marionette/content/transport.js:504:20\n"}}
[task 2020-09-17T15:10:15.957Z] 15:10:15 INFO - PID 1112 | 1600355415946 webdriver::server DEBUG -> POST /session/bac522d2-501a-194e-a8c1-3f6bc7569c24/window {"handle": "22"}
[task 2020-09-17T15:10:15.957Z] 15:10:15 INFO - PID 1112 | 1600355415947 Marionette DEBUG 1 -> [0,133,"WebDriver:SwitchToWindow",{"handle":"22","name":"22"}]
[task 2020-09-17T15:10:15.958Z] 15:10:15 INFO - PID 1112 | 1600355415948 Marionette DEBUG 1 <- [1,133,null,{"value":null}]
[task 2020-09-17T15:10:15.958Z] 15:10:15 INFO - PID 1112 | 1600355415949 webdriver::server DEBUG <- 200 OK {"value":null}
[task 2020-09-17T15:10:15.960Z] 15:10:15 INFO - PID 1112 | 1600355415950 webdriver::server DEBUG -> GET /session/bac522d2-501a-194e-a8c1-3f6bc7569c24/window
[task 2020-09-17T15:10:15.960Z] 15:10:15 INFO - PID 1112 | 1600355415952 Marionette DEBUG 1 -> [0,134,"WebDriver:GetWindowHandle",{}]
[task 2020-09-17T15:10:15.961Z] 15:10:15 INFO - PID 1112 | 1600355415953 Marionette DEBUG 1 <- [1,134,null,{"value":"22"}]
[task 2020-09-17T15:10:15.961Z] 15:10:15 INFO - PID 1112 | 1600355415954 webdriver::server DEBUG <- 200 OK {"value":"22"}
[task 2020-09-17T15:10:15.963Z] 15:10:15 INFO - PID 1112 | 1600355415956 webdriver::server DEBUG -> GET /session/bac522d2-501a-194e-a8c1-3f6bc7569c24/window/handles
[task 2020-09-17T15:10:15.964Z] 15:10:15 INFO - PID 1112 | 1600355415958 Marionette DEBUG 1 -> [0,135,"WebDriver:GetWindowHandles",{}]
[task 2020-09-17T15:10:15.966Z] 15:10:15 INFO - PID 1112 | 1600355415959 Marionette DEBUG 1 <- [1,135,null,["22"]]
[task 2020-09-17T15:10:15.967Z] 15:10:15 INFO - PID 1112 | 1600355415960 webdriver::server DEBUG <- 200 OK {"value":["22"]}
[task 2020-09-17T15:10:15.967Z] 15:10:15 INFO - PID 1112 | 1600355415962 webdriver::server DEBUG -> POST /session/bac522d2-501a-194e-a8c1-3f6bc7569c24/window {"handle": "22"}
[task 2020-09-17T15:10:15.986Z] 15:10:15 INFO - PID 1112 | 1600355415964 Marionette DEBUG 1 -> [0,136,"WebDriver:SwitchToWindow",{"handle":"22","name":"22"}]
[task 2020-09-17T15:10:15.986Z] 15:10:15 INFO - PID 1112 | 1600355415965 Marionette DEBUG 1 <- [1,136,null,{"value":null}]
[task 2020-09-17T15:10:15.986Z] 15:10:15 INFO - PID 1112 | 1600355415965 webdriver::server DEBUG <- 200 OK {"value":null}
[task 2020-09-17T15:10:15.987Z] 15:10:15 INFO - PID 1112 | 1600355415967 webdriver::server DEBUG -> POST /session/bac522d2-501a-194e-a8c1-3f6bc7569c24/window/rect {"width": 800, "height": 600}
[task 2020-09-17T15:10:15.987Z] 15:10:15 INFO - PID 1112 | 1600355415968 Marionette DEBUG 1 -> [0,137,"WebDriver:SetWindowRect",{"height":600,"width":800}]
[task 2020-09-17T15:10:15.988Z] 15:10:15 INFO - PID 1112 | 1600355415969 Marionette DEBUG 1 <- [1,137,null,{"x":100,"y":100,"width":800,"height":600}]
[task 2020-09-17T15:10:15.988Z] 15:10:15 INFO - PID 1112 | 1600355415969 webdriver::server DEBUG <- 200 OK {"value":{"x":100,"y":100,"width":800,"height":600}}
[task 2020-09-17T15:10:15.988Z] 15:10:15 INFO - STDOUT: =================================== FAILURES ===================================
[task 2020-09-17T15:10:15.989Z] 15:10:15 INFO - STDOUT: _______________________ test_no_parent_browsing_context ________________________
[task 2020-09-17T15:10:15.989Z] 15:10:15 INFO - STDOUT: session = <Session bac522d2-501a-194e-a8c1-3f6bc7569c24>
[task 2020-09-17T15:10:15.989Z] 15:10:15 INFO - STDOUT: url = <function url at 0x106ba6b90>
[task 2020-09-17T15:10:15.989Z] 15:10:15 INFO - STDOUT: def test_no_parent_browsing_context(session, url):
[task 2020-09-17T15:10:15.990Z] 15:10:15 INFO - STDOUT: session.url = url("/webdriver/tests/support/html/frames.html")
[task 2020-09-17T15:10:15.990Z] 15:10:15 INFO - STDOUT:
[task 2020-09-17T15:10:15.990Z] 15:10:15 INFO - STDOUT: subframe = session.find.css("#sub-frame", all=False)
[task 2020-09-17T15:10:15.991Z] 15:10:15 INFO - STDOUT: session.switch_frame(subframe)
[task 2020-09-17T15:10:15.991Z] 15:10:15 INFO - STDOUT:
[task 2020-09-17T15:10:15.991Z] 15:10:15 INFO - STDOUT: deleteframe = session.find.css("#delete-frame", all=False)
[task 2020-09-17T15:10:15.991Z] 15:10:15 INFO - STDOUT: session.switch_frame(deleteframe)
[task 2020-09-17T15:10:15.992Z] 15:10:15 INFO - STDOUT:
[task 2020-09-17T15:10:15.995Z] 15:10:15 INFO - STDOUT: button = session.find.css("#remove-top", all=False)
[task 2020-09-17T15:10:15.996Z] 15:10:15 INFO - STDOUT: button.click()
[task 2020-09-17T15:10:15.996Z] 15:10:15 INFO - STDOUT:
[task 2020-09-17T15:10:15.997Z] 15:10:15 INFO - STDOUT: response = switch_to_parent_frame(session)
[task 2020-09-17T15:10:15.997Z] 15:10:15 INFO - STDOUT: > assert_error(response, "no such window")
[task 2020-09-17T15:10:15.997Z] 15:10:15 INFO - STDOUT: button = <Element e239de32-f8ef-c941-88ff-2802622fd68b>
[task 2020-09-17T15:10:15.997Z] 15:10:15 INFO - STDOUT: deleteframe = <Element fca33dcc-77ce-4143-b9a5-d26c68d5d21a>
[task 2020-09-17T15:10:15.998Z] 15:10:15 INFO - STDOUT: response = <Responsetatus=200 body={"value": null}>
[task 2020-09-17T15:10:15.998Z] 15:10:15 INFO - STDOUT: session = <Session bac522d2-501a-194e-a8c1-3f6bc7569c24>
[task 2020-09-17T15:10:15.998Z] 15:10:15 INFO - STDOUT: subframe = <Element ab810fd1-d1dd-1f4c-b58b-ef77ef5a3f14>
[task 2020-09-17T15:10:15.998Z] 15:10:15 INFO - STDOUT: url = <function url at 0x106ba6b90>
[task 2020-09-17T15:10:15.999Z] 15:10:15 INFO - STDOUT: tests/web-platform/tests/webdriver/tests/switch_to_parent_frame/switch.py
[task 2020-09-17T15:10:15.999Z] 15:10:15 INFO - STDOUT: :42:
[task 2020-09-17T15:10:15.999Z] 15:10:15 INFO - STDOUT: _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _
[task 2020-09-17T15:10:16.005Z] 15:10:16 INFO - STDOUT: response = <Responsetatus=200 body={"value": null}>
[task 2020-09-17T15:10:16.005Z] 15:10:16 INFO - STDOUT: error_code = 'no such window'
[task 2020-09-17T15:10:16.005Z] 15:10:16 INFO - PID 1112 | 1600355415972 webdriver::server DEBUG -> POST /session/bac522d2-501a-194e-a8c1-3f6bc7569c24/frame {"id": null}
[task 2020-09-17T15:10:16.006Z] 15:10:16 INFO - PID 1112 | 1600355415973 Marionette DEBUG 1 -> [0,138,"WebDriver:SwitchToFrame",{"id":null}]
[task 2020-09-17T15:10:16.006Z] 15:10:16 INFO - STDOUT: def assert_error(response, error_code):
[task 2020-09-17T15:10:16.006Z] 15:10:16 INFO - PID 1112 | 1600355415975 Marionette DEBUG 1 <- [1,138,null,{"value":null}]
[task 2020-09-17T15:10:16.006Z] 15:10:16 INFO - PID 1112 | 1600355415976 webdriver::server DEBUG <- 200 OK {"value":null}
[task 2020-09-17T15:10:16.007Z] 15:10:16 INFO - STDOUT: """
[task 2020-09-17T15:10:16.007Z] 15:10:16 INFO - STDOUT: Verify that the provided webdriver.Response instance described
[task 2020-09-17T15:10:16.007Z] 15:10:16 INFO - STDOUT: a valid error response as defined by dfn-send-an-error and
[task 2020-09-17T15:10:16.007Z] 15:10:16 INFO - STDOUT: the provided error code.
[task 2020-09-17T15:10:16.008Z] 15:10:16 INFO - STDOUT:
[task 2020-09-17T15:10:16.008Z] 15:10:16 INFO - STDOUT: :param response: webdriver.Response instance.
[task 2020-09-17T15:10:16.008Z] 15:10:16 INFO - STDOUT: :param error_code: String value of the expected error code
[task 2020-09-17T15:10:16.008Z] 15:10:16 INFO - STDOUT: """
[task 2020-09-17T15:10:16.008Z] 15:10:16 INFO - STDOUT: > assert response.status == errors[error_code]
[task 2020-09-17T15:10:16.008Z] 15:10:16 INFO - STDOUT: E assert 200 == 404
[task 2020-09-17T15:10:16.009Z] 15:10:16 INFO - STDOUT: E + where 200 = <Responsetatus=200 body={"value": null}>.status
[task 2020-09-17T15:10:16.009Z] 15:10:16 INFO - STDOUT: error_code = 'no such window'
[task 2020-09-17T15:10:16.009Z] 15:10:16 INFO - STDOUT: response = <Responsetatus=200 body={"value": null}>
[task 2020-09-17T15:10:16.009Z] 15:10:16 INFO - STDOUT: tests/web-platform/tests/webdriver/tests/support/asserts.py
[task 2020-09-17T15:10:16.009Z] 15:10:16 INFO - STDOUT: :52: AssertionError
[task 2020-09-17T15:10:16.010Z] 15:10:16 INFO - STDOUT: ===================== 1 failed, 5 passed in 10.65 seconds ======================
[task 2020-09-17T15:10:16.104Z] 15:10:16 INFO -
[task 2020-09-17T15:10:16.105Z] 15:10:16 INFO - TEST-PASS | /webdriver/tests/switch_to_parent_frame/switch.py | test_null_response_value
[task 2020-09-17T15:10:16.105Z] 15:10:16 INFO - TEST-PASS | /webdriver/tests/switch_to_parent_frame/switch.py | test_no_top_browsing_context
[task 2020-09-17T15:10:16.105Z] 15:10:16 INFO - TEST-UNEXPECTED-FAIL | /webdriver/tests/switch_to_parent_frame/switch.py | test_no_parent_browsing_context - assert 200 == 404
[task 2020-09-17T15:10:16.105Z] 15:10:16 INFO - session = <Session bac522d2-501a-194e-a8c1-3f6bc7569c24>
[task 2020-09-17T15:10:16.105Z] 15:10:16 INFO - url = <function url at 0x106ba6b90>
[task 2020-09-17T15:10:16.105Z] 15:10:16 INFO -
[task 2020-09-17T15:10:16.105Z] 15:10:16 INFO - def test_no_parent_browsing_context(session, url):
[task 2020-09-17T15:10:16.105Z] 15:10:16 INFO - session.url = url("/webdriver/tests/support/html/frames.html")
[task 2020-09-17T15:10:16.105Z] 15:10:16 INFO -
[task 2020-09-17T15:10:16.105Z] 15:10:16 INFO - subframe = session.find.css("#sub-frame", all=False)
[task 2020-09-17T15:10:16.105Z] 15:10:16 INFO - session.switch_frame(subframe)
[task 2020-09-17T15:10:16.105Z] 15:10:16 INFO -
[task 2020-09-17T15:10:16.106Z] 15:10:16 INFO - deleteframe = session.find.css("#delete-frame", all=False)
[task 2020-09-17T15:10:16.106Z] 15:10:16 INFO - session.switch_frame(deleteframe)
[task 2020-09-17T15:10:16.106Z] 15:10:16 INFO -
[task 2020-09-17T15:10:16.106Z] 15:10:16 INFO - button = session.find.css("#remove-top", all=False)
[task 2020-09-17T15:10:16.106Z] 15:10:16 INFO - button.click()
[task 2020-09-17T15:10:16.106Z] 15:10:16 INFO -
[task 2020-09-17T15:10:16.106Z] 15:10:16 INFO - response = switch_to_parent_frame(session)
[task 2020-09-17T15:10:16.106Z] 15:10:16 INFO - > assert_error(response, "no such window")
[task 2020-09-17T15:10:16.106Z] 15:10:16 INFO -
[task 2020-09-17T15:10:16.106Z] 15:10:16 INFO - button = <Element e239de32-f8ef-c941-88ff-2802622fd68b>
[task 2020-09-17T15:10:16.106Z] 15:10:16 INFO - deleteframe = <Element fca33dcc-77ce-4143-b9a5-d26c68d5d21a>
[task 2020-09-17T15:10:16.107Z] 15:10:16 INFO - response = <Responsetatus=200 body={"value": null}>
[task 2020-09-17T15:10:16.107Z] 15:10:16 INFO - session = <Session bac522d2-501a-194e-a8c1-3f6bc7569c24>
[task 2020-09-17T15:10:16.107Z] 15:10:16 INFO - subframe = <Element ab810fd1-d1dd-1f4c-b58b-ef77ef5a3f14>
[task 2020-09-17T15:10:16.107Z] 15:10:16 INFO - url = <function url at 0x106ba6b90>
[task 2020-09-17T15:10:16.107Z] 15:10:16 INFO -
[task 2020-09-17T15:10:16.107Z] 15:10:16 INFO - tests/web-platform/tests/webdriver/tests/switch_to_parent_frame/switch.py:42:
[task 2020-09-17T15:10:16.107Z] 15:10:16 INFO - _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _
[task 2020-09-17T15:10:16.107Z] 15:10:16 INFO -
[task 2020-09-17T15:10:16.107Z] 15:10:16 INFO - response = <Responsetatus=200 body={"value": null}>
[task 2020-09-17T15:10:16.107Z] 15:10:16 INFO - error_code = 'no such window'
[task 2020-09-17T15:10:16.107Z] 15:10:16 INFO -
[task 2020-09-17T15:10:16.107Z] 15:10:16 INFO - def assert_error(response, error_code):
[task 2020-09-17T15:10:16.107Z] 15:10:16 INFO - """
[task 2020-09-17T15:10:16.107Z] 15:10:16 INFO - Verify that the provided webdriver.Response instance described
[task 2020-09-17T15:10:16.108Z] 15:10:16 INFO - a valid error response as defined by dfn-send-an-error and
[task 2020-09-17T15:10:16.108Z] 15:10:16 INFO - the provided error code.
[task 2020-09-17T15:10:16.108Z] 15:10:16 INFO -
[task 2020-09-17T15:10:16.108Z] 15:10:16 INFO - :param response: webdriver.Response instance.
[task 2020-09-17T15:10:16.108Z] 15:10:16 INFO - :param error_code: String value of the expected error code
[task 2020-09-17T15:10:16.108Z] 15:10:16 INFO - """
[task 2020-09-17T15:10:16.108Z] 15:10:16 INFO - > assert response.status == errors[error_code]
[task 2020-09-17T15:10:16.108Z] 15:10:16 INFO - E assert 200 == 404
[task 2020-09-17T15:10:16.108Z] 15:10:16 INFO - E + where 200 = <Responsetatus=200 body={"value": null}>.status
[task 2020-09-17T15:10:16.108Z] 15:10:16 INFO -
[task 2020-09-17T15:10:16.108Z] 15:10:16 INFO - error_code = 'no such window'
[task 2020-09-17T15:10:16.108Z] 15:10:16 INFO - response = <Responsetatus=200 body={"value": null}>
[task 2020-09-17T15:10:16.109Z] 15:10:16 INFO -
[task 2020-09-17T15:10:16.109Z] 15:10:16 INFO - tests/web-platform/tests/webdriver/tests/support/asserts.py:52: AssertionError
[task 2020-09-17T15:10:16.109Z] 15:10:16 INFO - ...
[task 2020-09-17T15:10:16.109Z] 15:10:16 INFO - TEST-OK | /webdriver/tests/switch_to_parent_frame/switch.py | took 11156ms
[task 2020-09-17T15:10:16.109Z] 15:10:16 INFO - Restarting browser for new test group

Here the real failure:

https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=315963703&repo=autoland&lineNumber=1379-1394

[task 2020-09-17T15:10:14.420Z] 15:10:14     INFO - PID 1112 | 1600355414407	Marionette	DEBUG	1 -> [0,53,"WebDriver:ElementClick",{"id":"e239de32-f8ef-c941-88ff-2802622fd68b"}]
[task 2020-09-17T15:10:14.490Z] 15:10:14     INFO - PID 1112 | 1600355414484	Marionette	TRACE	Received message pagehide for http://web-platform.test:8000/webdriver/tests/support/html/deleteframe.html
[task 2020-09-17T15:10:14.498Z] 15:10:14     INFO - PID 1112 | 1600355414486	Marionette	TRACE	[22] Frame with id 4294967299 got removed
[task 2020-09-17T15:10:14.499Z] 15:10:14     INFO - PID 1112 | 1600355414487	Marionette	TRACE	Canceled page load listener because current frame has been removed
[task 2020-09-17T15:10:14.502Z] 15:10:14     INFO - PID 1112 | 1600355414488	Marionette	DEBUG	1 <- [1,53,null,{"value":null}]
[task 2020-09-17T15:10:14.504Z] 15:10:14     INFO - PID 1112 | 1600355414489	webdriver::server	DEBUG	<- 200 OK {"value":null}
[task 2020-09-17T15:10:14.504Z] 15:10:14     INFO - PID 1112 | 1600355414491	webdriver::server	DEBUG	-> POST /session/bac522d2-501a-194e-a8c1-3f6bc7569c24/frame/parent {}
[task 2020-09-17T15:10:14.505Z] 15:10:14     INFO - PID 1112 | 1600355414493	Marionette	DEBUG	1 -> [0,54,"WebDriver:SwitchToParentFrame",{}]
[task 2020-09-17T15:10:14.516Z] 15:10:14     INFO - PID 1112 | [Child 1116, Main Thread] WARNING: '!inner', file /builds/worker/checkouts/gecko/dom/ipc/jsactor/JSWindowActorProtocol.cpp, line 172
[task 2020-09-17T15:10:14.516Z] 15:10:14     INFO - PID 1112 | [Child 1116, Main Thread] WARNING: '!inner', file /builds/worker/checkouts/gecko/dom/ipc/jsactor/JSWindowActorProtocol.cpp, line 172
[task 2020-09-17T15:10:14.516Z] 15:10:14     INFO - PID 1112 | [Child 1116, Main Thread] WARNING: '!inner', file /builds/worker/checkouts/gecko/dom/ipc/jsactor/JSWindowActorProtocol.cpp, line 172
[task 2020-09-17T15:10:14.517Z] 15:10:14     INFO - PID 1112 | [Child 1116, Main Thread] WARNING: '!inner', file /builds/worker/checkouts/gecko/dom/ipc/jsactor/JSWindowActorProtocol.cpp, line 172
[task 2020-09-17T15:10:14.535Z] 15:10:14     INFO - PID 1112 | [Child 1116, Main Thread] WARNING: NS_ENSURE_TRUE(info) failed: file /builds/worker/checkouts/gecko/extensions/permissions/PermissionDelegateHandler.cpp, line 348
[task 2020-09-17T15:10:14.536Z] 15:10:14     INFO - PID 1112 | [Child 1116, Main Thread] WARNING: NS_ENSURE_TRUE(wc) failed: file /builds/worker/checkouts/gecko/extensions/permissions/PermissionDelegateHandler.cpp, line 344
[task 2020-09-17T15:10:14.536Z] 15:10:14     INFO - PID 1112 | [Child 1116, Main Thread] WARNING: NS_ENSURE_TRUE(wc) failed: file /builds/worker/checkouts/gecko/extensions/permissions/PermissionDelegateHandler.cpp, line 344
[task 2020-09-17T15:10:14.536Z] 15:10:14     INFO - PID 1112 | 1600355414518	Marionette	DEBUG	1 <- [1,54,null,{"value":null}]

Looks like this needs bug 1666204.

Depends on: 1666204

Checking the log again this is most likely a problem with a delayed click due to the synchronous capabilities update with the parent process. This has been removed with the patch on bug 1394354, and as such this failure should no longer happen.

Depends on: 1394354

No more failures since the patch on bug 1666204 has been landed. Marking as fixed.

Assignee: nobody → hskupin
Status: NEW → RESOLVED
Closed: 4 years ago
Resolution: --- → FIXED
Target Milestone: --- → 83 Branch

whimbo, this has happened again:
https://treeherder.mozilla.org/logviewer?job_id=325553494&repo=autoland&lineNumber=122066
Should we reopen this bug or make a new one?

Flags: needinfo?(hskupin)
Status: RESOLVED → REOPENED
Flags: needinfo?(hskupin)
Resolution: FIXED → ---
Assignee: hskupin → nobody
Status: REOPENED → NEW
Target Milestone: 83 Branch → ---
Status: NEW → RESOLVED
Closed: 4 years ago3 years ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---

There is a problem with the WebDriver:ElementClick call before:
https://treeherder.mozilla.org/logviewer?job_id=331293710&repo=mozilla-central&lineNumber=132898-132912

1614315411689   Marionette  DEBUG   0 -> [0,55,"WebDriver:ElementClick",{"id":"d36d07df-6ecd-42d0-95e1-b57463bd725e"}]
1614315411733   Marionette  TRACE   Received event pagehide for http://web-platform.test:8000/webdriver/tests/support/html/deleteframe.html
1614315411736   Marionette  TRACE   Canceled page load listener because browsing context with id 6442450949 has been removed
1614315411737   Marionette  DEBUG   0 <- [1,55,null,{"value":null}]
1614315411741   Marionette  DEBUG   0 -> [0,56,"WebDriver:SwitchToParentFrame",{}]
1614315411746   Marionette  TRACE   Received DOM event click for [object HTMLInputElement]
1614315411746   Marionette  DEBUG   0 <- [1,56,null,{"value":null}]

Why is the click event for the button that we clicked and which removed the frame reported after the frame has already been removed? Shouldn't it be always be the other way around? Or is the code that runs as part of the the click event handler blocking the event to be sent?

Olli, do you have an idea?

Oh wait. Shouldn't we use capturing in this case?
https://searchfox.org/mozilla-release/rev/e5ba265af55ca7b40241d4aa6d6235d5797eca9d/testing/marionette/interaction.js#424-425

By doing that we might not even have to handle the unload event.

Olli, when I was asking for your feedback in comment 14 I totally forgot to actually needinfo you. Maybe you could help us here to understand why the click event is delayed? Thanks.

Flags: needinfo?(bugs)

I'm not quite sure if I answer to the right question.
If some user input event is dispatched from the parent process to the child process, it uses "input priority", which is different than some other priority (especially it is different than 'normal priorit'y), and the ordering isn't guaranteed. Input event handling especially is special, since
the priority vs. normal priority changes depending on whether we're about to handle a refreshdriver tick or not.

Flags: needinfo?(bugs)

(In reply to Olli Pettay [:smaug] from comment #27)

If some user input event is dispatched from the parent process to the child process, it uses "input priority", which is different than some other priority (especially it is different than 'normal priorit'y), and the ordering isn't guaranteed. Input event handling especially is special, since
the priority vs. normal priority changes depending on whether we're about to handle a refreshdriver tick or not.

So even with a delay due to lower priority the actual click onto the DOM element in the child process should trigger the click event immediately, which means before any kind of page load event will be received in the child process, or not? The element the click is performed on is:

https://searchfox.org/mozilla-central/source/testing/web-platform/tests/webdriver/tests/support/html/deleteframe.html#3

So it has an onclick handler that calls parent.remove(). I assume that the method is called first (before the click event is emitted). By using capture: true for the click event registration the pagehide event still comes first, but maybe there is no way around it and using capture should be done anyway?

Flags: needinfo?(bugs)

oh, you're destroying the current document effectively. And synchronously inside a click event listener. Then yes, various notifications and events about the document may get fired while the click is still being handled.

Flags: needinfo?(bugs)
Status: REOPENED → RESOLVED
Closed: 3 years ago3 years ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
Status: REOPENED → RESOLVED
Closed: 3 years ago2 years ago
Resolution: --- → DUPLICATE
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.