Closed
Bug 1827777
Opened 2 years ago
Closed 2 years ago
Intermittent /webdriver/tests/find_elements_from_shadow_root/find.py | test_find_elements[closed-partial link text-link text] - AssertionError: Expected value is not a dictionary or web element (!realm_->hasActiveAutoSetNewObjectMetadata_)
Categories
(Remote Protocol :: Marionette, defect, P5)
Remote Protocol
Marionette
Tracking
(Not tracked)
RESOLVED
DUPLICATE
of bug 1827830
People
(Reporter: intermittent-bug-filer, Unassigned)
References
(Depends on 1 open bug)
Details
(Keywords: assertion, intermittent-failure)
Filed by: abutkovits [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer?job_id=412249182&repo=autoland
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/fqjsUOrxQ1GJTKVtQ_1LJA/runs/0/artifacts/public/logs/live_backing.log
[task 2023-04-13T02:47:18.513Z] 02:47:18 INFO - TEST-PASS | /webdriver/tests/find_elements_from_shadow_root/find.py | test_find_elements[closed-link text-full link text]
[task 2023-04-13T02:47:18.513Z] 02:47:18 INFO - TEST-UNEXPECTED-FAIL | /webdriver/tests/find_elements_from_shadow_root/find.py | test_find_elements[closed-partial link text-link text] - AssertionError: Expected value is not a dictionary or web element
[task 2023-04-13T02:47:18.513Z] 02:47:18 INFO - session = <Session b4823706-99dd-4d5c-84ee-b445a2aeeffc>
[task 2023-04-13T02:47:18.513Z] 02:47:18 INFO - get_test_page = <function get_test_page.<locals>.get_test_page at 0x7f9864cc9c20>
[task 2023-04-13T02:47:18.513Z] 02:47:18 INFO - using = 'partial link text', value = 'link text', mode = 'closed'
[task 2023-04-13T02:47:18.513Z] 02:47:18 INFO -
[task 2023-04-13T02:47:18.513Z] 02:47:18 INFO - @pytest.mark.parametrize("using,value",
[task 2023-04-13T02:47:18.513Z] 02:47:18 INFO - [("css selector", "#linkText"),
[task 2023-04-13T02:47:18.513Z] 02:47:18 INFO - ("link text", "full link text"),
[task 2023-04-13T02:47:18.513Z] 02:47:18 INFO - ("partial link text", "link text"),
[task 2023-04-13T02:47:18.513Z] 02:47:18 INFO - ("tag name", "a"),
[task 2023-04-13T02:47:18.513Z] 02:47:18 INFO - ("xpath", "//a")])
[task 2023-04-13T02:47:18.513Z] 02:47:18 INFO - @pytest.mark.parametrize("mode", ["open", "closed"])
[task 2023-04-13T02:47:18.513Z] 02:47:18 INFO - def test_find_elements(session, get_test_page, using, value, mode):
[task 2023-04-13T02:47:18.513Z] 02:47:18 INFO - session.url = get_test_page(
[task 2023-04-13T02:47:18.513Z] 02:47:18 INFO - shadow_doc="<div><a href=# id=linkText>full link text</a></div>",
[task 2023-04-13T02:47:18.513Z] 02:47:18 INFO - shadow_root_mode=mode,
[task 2023-04-13T02:47:18.513Z] 02:47:18 INFO - )
[task 2023-04-13T02:47:18.513Z] 02:47:18 INFO - shadow_root = session.find.css("custom-element", all=False).shadow_root
[task 2023-04-13T02:47:18.513Z] 02:47:18 INFO -
[task 2023-04-13T02:47:18.513Z] 02:47:18 INFO - response = find_elements(session, shadow_root.id, using, value)
[task 2023-04-13T02:47:18.513Z] 02:47:18 INFO - response_value = assert_success(response)
[task 2023-04-13T02:47:18.513Z] 02:47:18 INFO -
[task 2023-04-13T02:47:18.513Z] 02:47:18 INFO - assert len(response_value) == 1
[task 2023-04-13T02:47:18.513Z] 02:47:18 INFO -
[task 2023-04-13T02:47:18.513Z] 02:47:18 INFO - # Script evaluation cannot use the DOM within a closed shadow root,
[task 2023-04-13T02:47:18.513Z] 02:47:18 INFO - # that's why we assert on the copy of the shadow root on window.
[task 2023-04-13T02:47:18.514Z] 02:47:18 INFO - expected = session.execute_script("""
[task 2023-04-13T02:47:18.514Z] 02:47:18 INFO - return window._shadowRoot.querySelector('#linkText')
[task 2023-04-13T02:47:18.514Z] 02:47:18 INFO - """)
[task 2023-04-13T02:47:18.514Z] 02:47:18 INFO - > assert_same_element(session, response_value[0], expected)
[task 2023-04-13T02:47:18.514Z] 02:47:18 INFO -
[task 2023-04-13T02:47:18.514Z] 02:47:18 INFO - expected = None
[task 2023-04-13T02:47:18.514Z] 02:47:18 INFO - get_test_page = <function get_test_page.<locals>.get_test_page at 0x7f9864cc9c20>
[task 2023-04-13T02:47:18.514Z] 02:47:18 INFO - mode = 'closed'
[task 2023-04-13T02:47:18.514Z] 02:47:18 INFO - response = <[ValueError('Sign not allowed in string format specifier') raised in repr()] Response object at 0x7f9864d34d50>
[task 2023-04-13T02:47:18.514Z] 02:47:18 INFO - response_value = [{'element-6066-11e4-a52e-4f735466cecf': 'a521d393-bdb3-4a5b-887b-47ca576cfcd2'}]
[task 2023-04-13T02:47:18.514Z] 02:47:18 INFO - session = <Session b4823706-99dd-4d5c-84ee-b445a2aeeffc>
[task 2023-04-13T02:47:18.514Z] 02:47:18 INFO - shadow_root = <webdriver.client.ShadowRoot object at 0x7f9864d34a90>
[task 2023-04-13T02:47:18.514Z] 02:47:18 INFO - using = 'partial link text'
[task 2023-04-13T02:47:18.514Z] 02:47:18 INFO - value = 'link text'
[task 2023-04-13T02:47:18.514Z] 02:47:18 INFO -
[task 2023-04-13T02:47:18.514Z] 02:47:18 INFO - tests/web-platform/tests/webdriver/tests/find_elements_from_shadow_root/find.py:184:
[task 2023-04-13T02:47:18.514Z] 02:47:18 INFO - _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _
[task 2023-04-13T02:47:18.514Z] 02:47:18 INFO -
[task 2023-04-13T02:47:18.514Z] 02:47:18 INFO - session = <Session b4823706-99dd-4d5c-84ee-b445a2aeeffc>
[task 2023-04-13T02:47:18.514Z] 02:47:18 INFO - a = {'element-6066-11e4-a52e-4f735466cecf': 'a521d393-bdb3-4a5b-887b-47ca576cfcd2'}
[task 2023-04-13T02:47:18.514Z] 02:47:18 INFO - b = None
[task 2023-04-13T02:47:18.514Z] 02:47:18 INFO -
[task 2023-04-13T02:47:18.514Z] 02:47:18 INFO - def assert_same_element(session, a, b):
[task 2023-04-13T02:47:18.514Z] 02:47:18 INFO - """Verify that two element references describe the same element."""
[task 2023-04-13T02:47:18.514Z] 02:47:18 INFO - if isinstance(a, dict):
[task 2023-04-13T02:47:18.514Z] 02:47:18 INFO - assert Element.identifier in a, "Actual value does not describe an element"
[task 2023-04-13T02:47:18.514Z] 02:47:18 INFO - a_id = a[Element.identifier]
[task 2023-04-13T02:47:18.514Z] 02:47:18 INFO - elif isinstance(a, Element):
[task 2023-04-13T02:47:18.514Z] 02:47:18 INFO - a_id = a.id
[task 2023-04-13T02:47:18.514Z] 02:47:18 INFO - else:
[task 2023-04-13T02:47:18.515Z] 02:47:18 INFO - raise AssertionError("Actual value is not a dictionary or web element")
[task 2023-04-13T02:47:18.515Z] 02:47:18 INFO -
[task 2023-04-13T02:47:18.515Z] 02:47:18 INFO - if isinstance(b, dict):
[task 2023-04-13T02:47:18.515Z] 02:47:18 INFO - assert Element.identifier in b, "Expected value does not describe an element"
[task 2023-04-13T02:47:18.515Z] 02:47:18 INFO - b_id = b[Element.identifier]
[task 2023-04-13T02:47:18.515Z] 02:47:18 INFO - elif isinstance(b, Element):
[task 2023-04-13T02:47:18.515Z] 02:47:18 INFO - b_id = b.id
[task 2023-04-13T02:47:18.515Z] 02:47:18 INFO - else:
[task 2023-04-13T02:47:18.515Z] 02:47:18 INFO - > raise AssertionError("Expected value is not a dictionary or web element")
[task 2023-04-13T02:47:18.515Z] 02:47:18 INFO - E AssertionError: Expected value is not a dictionary or web element
[task 2023-04-13T02:47:18.515Z] 02:47:18 INFO -
[task 2023-04-13T02:47:18.515Z] 02:47:18 INFO - a = {'element-6066-11e4-a52e-4f735466cecf': 'a521d393-bdb3-4a5b-887b-47ca576cfcd2'}
[task 2023-04-13T02:47:18.515Z] 02:47:18 INFO - a_id = 'a521d393-bdb3-4a5b-887b-47ca576cfcd2'
[task 2023-04-13T02:47:18.515Z] 02:47:18 INFO - b = None
[task 2023-04-13T02:47:18.515Z] 02:47:18 INFO - session = <Session b4823706-99dd-4d5c-84ee-b445a2aeeffc>
[task 2023-04-13T02:47:18.515Z] 02:47:18 INFO -
[task 2023-04-13T02:47:18.515Z] 02:47:18 INFO - tests/web-platform/tests/webdriver/tests/support/asserts.py:163: AssertionError
[task 2023-04-13T02:47:18.534Z] 02:47:18 INFO - ...............
[task 2023-04-13T02:47:18.534Z] 02:47:18 INFO - TEST-OK | /webdriver/tests/find_elements_from_shadow_root/find.py | took 32100ms
[task 2023-04-13T02:47:18.535Z] 02:47:18 INFO - PID 3142 | 1681354038500 webdriver::server DEBUG -> GET /status
[task 2023-04-13T02:47:18.536Z] 02:47:18 INFO - PID 3142 | 1681354038500 webdriver::server DEBUG <- 200 OK {"value":{"message":"","ready":true}}
[task 2023-04-13T02:47:28.539Z] 02:47:28 WARNING - Forcibly terminating runner process
[task 2023-04-13T02:47:28.618Z] 02:47:28 INFO - Starting runner
[task 2023-04-13T02:47:28.618Z] 02:47:28 INFO - PID 3207 | 1681354048617 geckodriver INFO Listening on 127.0.0.1:60471
[task 2023-04-13T02:47:28.817Z] 02:47:28 INFO - TEST-START | /webdriver/tests/find_elements_from_shadow_root/user_prompts.py
|
||
Comment 1•2 years ago
|
||
The problem here is that WebDriver:ExecuteScript returns null after 6s of execution time. But note that right after we also do not have the window reference anymore:
https://treeherder.mozilla.org/logviewer?job_id=412249182&repo=autoland&lineNumber=29700-29717
[task 2023-04-13T02:47:02.360Z] 02:47:02 INFO - PID 3142 | 1681354022360 webdriver::server DEBUG -> POST /session/b4823706-99dd-4d5c-84ee-b445a2aeeffc/execute/sync {"script": "\n return window._shadowRoot.querySelector('#linkText')\n ", "args": []}
[task 2023-04-13T02:47:08.844Z] 02:47:08 INFO - PID 3142 | 1681354028844 webdriver::server DEBUG <- 200 OK {"value":null}
[task 2023-04-13T02:47:08.852Z] 02:47:08 INFO - STDOUT: FAILED
[task 2023-04-13T02:47:08.852Z] 02:47:08 INFO - PID 3142 | 1681354028851 webdriver::server DEBUG -> POST /session/b4823706-99dd-4d5c-84ee-b445a2aeeffc/timeouts {"implicit": 0}
[task 2023-04-13T02:47:08.869Z] 02:47:08 INFO - PID 3142 | 1681354028868 webdriver::server DEBUG <- 200 OK {"value":null}
[task 2023-04-13T02:47:08.870Z] 02:47:08 INFO - PID 3142 | 1681354028869 webdriver::server DEBUG -> POST /session/b4823706-99dd-4d5c-84ee-b445a2aeeffc/timeouts {"pageLoad": 300000}
[task 2023-04-13T02:47:08.891Z] 02:47:08 INFO - PID 3142 | 1681354028891 webdriver::server DEBUG <- 200 OK {"value":null}
[task 2023-04-13T02:47:08.892Z] 02:47:08 INFO - PID 3142 | 1681354028892 webdriver::server DEBUG -> POST /session/b4823706-99dd-4d5c-84ee-b445a2aeeffc/timeouts {"script": 30000}
[task 2023-04-13T02:47:08.941Z] 02:47:08 INFO - PID 3142 | 1681354028941 webdriver::server DEBUG <- 200 OK {"value":null}
[task 2023-04-13T02:47:08.942Z] 02:47:08 INFO - PID 3142 | 1681354028941 webdriver::server DEBUG -> GET /session/b4823706-99dd-4d5c-84ee-b445a2aeeffc/window
[task 2023-04-13T02:47:08.955Z] 02:47:08 INFO - PID 3142 | 1681354028954 webdriver::server DEBUG <- 404 Not Found {"value":{"error":"no such window","message":"Browsing context has been discarded","stacktrace":"RemoteError ... ontent/marionette/server.sys.mjs:249:9\n_onJSONObjectReady/<@chrome://remote/content/marionette/transport.sys.mjs:496:20\n"}}
[task 2023-04-13T02:47:08.955Z] 02:47:08 INFO - PID 3142 | 1681354028954 webdriver::server DEBUG -> GET /session/b4823706-99dd-4d5c-84ee-b445a2aeeffc/window/handles
[task 2023-04-13T02:47:08.964Z] 02:47:08 INFO - PID 3142 | 1681354028963 webdriver::server DEBUG <- 200 OK {"value":["86031dc2-c26d-47c0-87b2-0c4894736293"]}
[task 2023-04-13T02:47:08.965Z] 02:47:08 INFO - PID 3142 | 1681354028964 webdriver::server DEBUG -> POST /session/b4823706-99dd-4d5c-84ee-b445a2aeeffc/window {"handle": "86031dc2-c26d-47c0-87b2-0c4894736293"}
[task 2023-04-13T02:47:08.975Z] 02:47:08 INFO - PID 3142 | 1681354028974 webdriver::server DEBUG <- 404 Not Found {"value":{"error":"no such window","message":"Unable to locate window: 86031dc2-c26d-47c0-87b2-0c4894736293" ... ver/Errors.sys.mjs:468:5\nGeckoDriver.prototype.switchToWindow@chrome://remote/content/marionette/driver.sys.mjs:1230:11\n"}}
[task 2023-04-13T02:47:08.976Z] 02:47:08 INFO - STDERR: Ignored exception no such window (404): Unable to locate window: 86031dc2-c26d-47c0-87b2-0c4894736293
Checking the android log cat shows:
https://firefoxci.taskcluster-artifacts.net/fqjsUOrxQ1GJTKVtQ_1LJA/0/public/test_info/logcat-emulator-5554.log
04-13 02:47:01.480 21175 21190 I Gecko : 1681354021480 Marionette DEBUG 0 -> [0,699,"WebDriver:ExecuteScript",{"args":[],"script":"\n return window._shadowRoot.querySelector('#linkText')\n "}]
04-13 02:47:01.500 21384 21399 F MOZ_Assert: Assertion failure: !realm_->hasActiveAutoSetNewObjectMetadata_ (Shouldn't nest AutoSetNewObjectMetadata), at /builds/worker/checkouts/gecko/js/src/vm/Realm.h:904
04-13 02:47:01.500 21384 21399 F MOZ_Assert: #01: ???[/data/app/org.mozilla.geckoview.test_runner-1/lib/x86_64/libxul.so +0x58505e1]
04-13 02:47:01.500 21384 21399 F MOZ_Assert:
04-13 02:47:01.501 21384 21399 F MOZ_Assert: #02: ???[/data/app/org.mozilla.geckoview.test_runner-1/lib/x86_64/libxul.so +0x5897482]
04-13 02:47:01.501 21384 21399 F MOZ_Assert:
04-13 02:47:01.501 21384 21399 F MOZ_Assert: #03: ???[/data/app/org.mozilla.geckoview.test_runner-1/lib/x86_64/libxul.so +0x584f7ec]
04-13 02:47:01.501 21384 21399 F MOZ_Assert:
04-13 02:47:01.501 21384 21399 F MOZ_Assert: #04: ???[/data/app/org.mozilla.geckoview.test_runner-1/lib/x86_64/libxul.so +0x59ef694]
04-13 02:47:01.501 21384 21399 F MOZ_Assert:
04-13 02:47:01.501 21384 21399 F MOZ_Assert: #05: ???[/data/app/org.mozilla.geckoview.test_runner-1/lib/x86_64/libxul.so +0x59f060d]
[..]
04-13 02:47:01.511 21384 21399 F MOZ_Assert: #76: Java_org_mozilla_gecko_mozglue_GeckoLoader_nativeRun[/data/app/org.mozilla.geckoview.test_runner-1/lib/x86_64/libmozglue.so +0x74efe]
04-13 02:47:01.511 21384 21399 F MOZ_Assert:
04-13 02:47:07.921 21175 21194 I Gecko : [Parent 21175, Unnamed thread 7bd18f9229a0] WARNING: [1.1]: Ignoring message 'EVENT_MESSAGE' to unknown peer 344177FE30E3D2F9.9E43247CB8363DE3: file /builds/worker/checkouts/gecko/ipc/glue/NodeController.cpp:344
04-13 02:47:07.921 21175 21194 I Gecko : [Parent 21175, Unnamed thread 7bd18f9229a0] WARNING: [1.1]: Ignoring message 'EVENT_MESSAGE' to unknown peer 344177FE30E3D2F9.9E43247CB8363DE3: file /builds/worker/checkouts/gecko/ipc/glue/NodeController.cpp:344
04-13 02:47:07.921 21175 21194 I Gecko : [Parent 21175, Unnamed thread 7bd18f9229a0] WARNING: [1.1]: Ignoring message 'EVENT_MESSAGE' to unknown peer 344177FE30E3D2F9.9E43247CB8363DE3: file /builds/worker/checkouts/gecko/ipc/glue/NodeController.cpp:344
04-13 02:47:07.921 21175 21194 I Gecko : [Parent 21175, Unnamed thread 7bd18f9229a0] WARNING: [1.1]: Ignoring message 'EVENT_MESSAGE' to unknown peer 344177FE30E3D2F9.9E43247CB8363DE3: file /builds/worker/checkouts/gecko/ipc/glue/NodeController.cpp:344
04-13 02:47:07.921 21175 21194 I Gecko : [Parent 21175, Unnamed thread 7bd18f9229a0] WARNING: [1.1]: Ignoring message 'EVENT_MESSAGE' to unknown peer 344177FE30E3D2F9.9E43247CB8363DE3: file /builds/worker/checkouts/gecko/ipc/glue/NodeController.cpp:344
04-13 02:47:07.921 21175 21194 I Gecko : [Parent 21175, Unnamed thread 7bd18f9229a0] WARNING: [1.1]: Ignoring message 'EVENT_MESSAGE' to unknown peer 344177FE30E3D2F9.9E43247CB8363DE3: file /builds/worker/checkouts/gecko/ipc/glue/NodeController.cpp:344
04-13 02:47:07.922 21175 21194 I Gecko : [Parent 21175, Unnamed thread 7bd18f9229a0] WARNING: [1.1]: Ignoring message 'EVENT_MESSAGE' to unknown peer 344177FE30E3D2F9.9E43247CB8363DE3: file /builds/worker/checkouts/gecko/ipc/glue/NodeController.cpp:344
04-13 02:47:07.922 21175 21194 I Gecko : [Parent 21175, Unnamed thread 7bd18f9229a0] WARNING: [1.1]: Ignoring message 'EVENT_MESSAGE' to unknown peer 344177FE30E3D2F9.9E43247CB8363DE3: file /builds/worker/checkouts/gecko/ipc/glue/NodeController.cpp:344
04-13 02:47:07.922 21175 21194 I Gecko : [Parent 21175, Unnamed thread 7bd18f9229a0] WARNING: [1.1]: Rejecting introduction request from '2F79E1219DAB83EF.86C28ADC01D9B027' for unknown peer '344177FE30E3D2F9.9E43247CB8363DE3': file /builds/worker/checkouts/gecko/ipc/glue/NodeController.cpp:675
04-13 02:47:07.922 1658 2079 I ActivityManager: Process org.mozilla.geckoview.test_runner:tab15 (pid 21384) has died
04-13 02:47:07.923 1658 2079 D ActivityManager: cleanUpApplicationRecord -- 21384
04-13 02:47:07.923 1658 2079 W ActivityManager: Scheduling restart of crashed service org.mozilla.geckoview.test_runner/org.mozilla.gecko.process.GeckoChildProcessServices$tab15 in 1000ms
04-13 02:47:07.923 21175 21190 I Gecko : [Parent 21175, Main Thread] WARNING: IPC Connection Error: [Parent][PContentParent] Send(msgname=PContent::Reply_DiscardBrowsingContext) Channel error: cannot send/recv: file /builds/worker/checkouts/gecko/ipc/glue/MessageChannel.cpp:1927
04-13 02:47:07.924 21239 21260 I Gecko : [GPU 21239, Unnamed thread 7bd1a201f890] WARNING: [2F79E1219DAB83EF.86C28ADC01D9B027]: Could not be introduced to peer 344177FE30E3D2F9.9E43247CB8363DE3: file /builds/worker/checkouts/gecko/ipc/glue/NodeController.cpp:605
04-13 02:47:07.933 21175 21190 I Gecko : [Parent 21175, Main Thread] WARNING: IPC message 'PBrowser::Msg_StopIMEStateManagement' discarded: actor cannot send: file /builds/worker/checkouts/gecko/ipc/glue/ProtocolUtils.cpp:504
04-13 02:47:07.934 21175 21190 I Gecko : [Parent 21175, Main Thread] WARNING: IPC message 'PBrowser::Msg_Destroy' discarded: actor cannot send: file /builds/worker/checkouts/gecko/ipc/glue/ProtocolUtils.cpp:504
04-13 02:47:07.937 21175 21190 D GeckoViewContent: observe: oop-frameloader-crashed
04-13 02:47:07.938 21175 21190 I Gecko : [Parent 21175, Main Thread] WARNING: No build ID mismatch: file /builds/worker/checkouts/gecko/dom/base/nsFrameLoader.cpp:3812
04-13 02:47:07.942 21175 21190 I Gecko : 1681354027942 Marionette TRACE [8] Querying "executeScript" failed with AbortError, returning "null" as fallback
04-13 02:47:07.943 21175 21190 I Gecko : 1681354027943 Marionette DEBUG 0 <- [1,699,null,{"value":null}]
Means that the tab crashed due to the assertion. Otherwise we should not return null and this is tracked on bug 1761634.
So it looks like it is the same as bug 1827830.
Status: NEW → RESOLVED
Closed: 2 years ago
Depends on: 1761634
Duplicate of bug: 1827830
Resolution: --- → DUPLICATE
Summary: Intermittent /webdriver/tests/find_elements_from_shadow_root/find.py | test_find_elements[closed-partial link text-link text] - AssertionError: Expected value is not a dictionary or web element → Intermittent /webdriver/tests/find_elements_from_shadow_root/find.py | test_find_elements[closed-partial link text-link text] - AssertionError: Expected value is not a dictionary or web element (!realm_->hasActiveAutoSetNewObjectMetadata_)
You need to log in
before you can comment on or make changes to this bug.
Description
•