Closed
Bug 1838479
Opened 3 years ago
Closed 3 years ago
Intermittent [tier 2] /webdriver/tests/bidi/script/add_preload_script/arguments.py | test_channel[default] - AssertionError
Categories
(Remote Protocol :: WebDriver BiDi, defect, P5)
Remote Protocol
WebDriver BiDi
Tracking
(Not tracked)
RESOLVED
INCOMPLETE
People
(Reporter: intermittent-bug-filer, Unassigned)
Details
(Keywords: assertion, intermittent-failure)
Filed by: nfay [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer?job_id=419286355&repo=try
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/ZEiOihqPSw-5IjMk8CNEpQ/runs/0/artifacts/public/logs/live_backing.log
[task 2023-06-14T15:17:51.052Z] 15:17:51 INFO - PID 5264 | 1686755871022 webdriver::server DEBUG -> DELETE /session/1481b53f-273e-4c5f-9ff3-320caf502891
[task 2023-06-14T15:17:51.052Z] 15:17:51 INFO - PID 5264 | 1686755871022 Marionette DEBUG 0 -> [0,123,"Marionette:Quit",{"flags":["eForceQuit"]}]
[task 2023-06-14T15:17:51.053Z] 15:17:51 INFO - PID 5264 | 1686755871022 Marionette INFO Stopped listening on port 51453
[task 2023-06-14T15:17:51.054Z] 15:17:51 INFO - PID 5264 | 1686755871023 Marionette TRACE [3] MarionetteCommands actor destroyed for window id 6442450945
[task 2023-06-14T15:17:51.055Z] 15:17:51 INFO - PID 5264 | 1686755871024 WebDriver BiDi DEBUG Unregistered session handler: /session/1481b53f-273e-4c5f-9ff3-320caf502891
[task 2023-06-14T15:17:51.056Z] 15:17:51 INFO - PID 5264 | 1686755871026 RemoteAgent TRACE MessageHandler ROOT for session 1481b53f-273e-4c5f-9ff3-320caf502891 is being destroyed
[task 2023-06-14T15:17:51.056Z] 15:17:51 INFO - PID 5264 | 1686755871026 RemoteAgent TRACE Unregistered MessageHandler ROOT for session 1481b53f-273e-4c5f-9ff3-320caf502891
[task 2023-06-14T15:17:51.060Z] 15:17:51 INFO - PID 5264 | 1686755871059 Marionette TRACE Received observer notification quit-application
[task 2023-06-14T15:17:51.060Z] 15:17:51 INFO - PID 5264 | 1686755871060 Marionette TRACE Received observer notification quit-application
[task 2023-06-14T15:17:51.062Z] 15:17:51 INFO - PID 5264 | 1686755871060 RemoteAgent TRACE Received observer notification quit-application
[task 2023-06-14T15:17:51.063Z] 15:17:51 INFO - PID 5264 | 1686755871061 Marionette DEBUG Marionette stopped listening
[task 2023-06-14T15:17:51.063Z] 15:17:51 INFO - PID 5264 | 1686755871062 Marionette DEBUG 0 <- [1,123,null,{"cause":"shutdown","forced":false,"in_app":true}]
[task 2023-06-14T15:17:51.071Z] 15:17:51 INFO - PID 5264 | 1686755871074 RemoteAgent TRACE MessageHandler WINDOW_GLOBAL for session 1481b53f-273e-4c5f-9ff3-320caf502891 is being destroyed
[task 2023-06-14T15:17:51.078Z] 15:17:51 INFO - PID 5264 | 1686755871076 RemoteAgent TRACE Unregistered MessageHandler WINDOW_GLOBAL for session 1481b53f-273e-4c5f-9ff3-320caf5028911686755871077 RemoteAgent DEBUG Resetting recommended pref browser.contentblocking.features.standard
[task 2023-06-14T15:17:51.079Z] 15:17:51 INFO - PID 5264 | 1686755871077 RemoteAgent DEBUG Resetting recommended pref network.cookie.cookieBehavior
[task 2023-06-14T15:17:51.080Z] 15:17:51 INFO - PID 5264 | 1686755871077 webdriver::server DEBUG Teardown session
[task 2023-06-14T15:17:51.083Z] 15:17:51 INFO - PID 5264 | 1686755871082 Marionette DEBUG Closed connection 0
[task 2023-06-14T15:17:51.959Z] 15:17:51 INFO - PID 5264 | 1686755871959 geckodriver::browser DEBUG Browser process stopped: exit code: 0
[task 2023-06-14T15:17:51.961Z] 15:17:51 INFO - PID 5264 | 1686755871960 webdriver::server DEBUG <- 200 OK {"value":null}
[task 2023-06-14T15:17:51.964Z] 15:17:51 INFO - STDOUT: ================================== FAILURES ===================================
[task 2023-06-14T15:17:51.965Z] 15:17:51 INFO - STDOUT: ____________________________ test_channel[default] ____________________________
[task 2023-06-14T15:17:51.966Z] 15:17:51 INFO - STDOUT: bidi_session = <webdriver.bidi.client.BidiSession object at 0x0000027E5B11E0D0>
[task 2023-06-14T15:17:51.967Z] 15:17:51 INFO - STDOUT: subscribe_events = <function subscribe_events.<locals>.subscribe_events at 0x0000027E5B0CD670>
[task 2023-06-14T15:17:51.967Z] 15:17:51 INFO - STDOUT: wait_for_event = <function wait_for_event.<locals>.wait_for_event at 0x0000027E5B0CDDC0>
[task 2023-06-14T15:17:51.968Z] 15:17:51 INFO - STDOUT: add_preload_script = <function add_preload_script.<locals>.add_preload_script at 0x0000027E5B0CDD30>
[task 2023-06-14T15:17:51.978Z] 15:17:51 INFO -
[task 2023-06-14T15:17:51.978Z] 15:17:51 INFO - TEST-UNEXPECTED-FAIL | /webdriver/tests/bidi/script/add_preload_script/arguments.py | test_channel[default] - AssertionError
[task 2023-06-14T15:17:51.978Z] 15:17:51 INFO - bidi_session = <webdriver.bidi.client.BidiSession object at 0x0000027E5B11E0D0>
[task 2023-06-14T15:17:51.978Z] 15:17:51 INFO - subscribe_events = <function subscribe_events.<locals>.subscribe_events at 0x0000027E5B0CD670>
[task 2023-06-14T15:17:51.978Z] 15:17:51 INFO - wait_for_event = <function wait_for_event.<locals>.wait_for_event at 0x0000027E5B0CDDC0>
[task 2023-06-14T15:17:51.978Z] 15:17:51 INFO - add_preload_script = <function add_preload_script.<locals>.add_preload_script at 0x0000027E5B0CDD30>
[task 2023-06-14T15:17:51.978Z] 15:17:51 INFO - channel = {'type': 'channel', 'value': {'channel': 'channel_name'}}
[task 2023-06-14T15:17:51.978Z] 15:17:51 INFO - expected_data = {'type': 'object', 'value': [['foo', {'type': 'string', 'value': 'bar'}], ['baz', {'type': 'object', 'value': [['1', {...}]]}]]}
[task 2023-06-14T15:17:51.978Z] 15:17:51 INFO -
[task 2023-06-14T15:17:51.978Z] 15:17:51 INFO - @pytest.mark.parametrize(
[task 2023-06-14T15:17:51.978Z] 15:17:51 INFO - "channel, expected_data",
[task 2023-06-14T15:17:51.979Z] 15:17:51 INFO - [
[task 2023-06-14T15:17:51.979Z] 15:17:51 INFO - (
[task 2023-06-14T15:17:51.979Z] 15:17:51 INFO - {"type": "channel", "value": {"channel": "channel_name"}},
[task 2023-06-14T15:17:51.979Z] 15:17:51 INFO - {
[task 2023-06-14T15:17:51.979Z] 15:17:51 INFO - "type": "object",
[task 2023-06-14T15:17:51.979Z] 15:17:51 INFO - "value": [
[task 2023-06-14T15:17:51.979Z] 15:17:51 INFO - ["foo", {"type": "string", "value": "bar"}],
[task 2023-06-14T15:17:51.979Z] 15:17:51 INFO - [
[task 2023-06-14T15:17:51.979Z] 15:17:51 INFO - "baz",
[task 2023-06-14T15:17:51.979Z] 15:17:51 INFO - {
[task 2023-06-14T15:17:51.979Z] 15:17:51 INFO - "type": "object",
[task 2023-06-14T15:17:51.979Z] 15:17:51 INFO - "value": [["1", {"type": "number", "value": 2}]],
[task 2023-06-14T15:17:51.979Z] 15:17:51 INFO - },
[task 2023-06-14T15:17:51.979Z] 15:17:51 INFO - ],
[task 2023-06-14T15:17:51.979Z] 15:17:51 INFO - ],
[task 2023-06-14T15:17:51.979Z] 15:17:51 INFO - },
[task 2023-06-14T15:17:51.979Z] 15:17:51 INFO - ),
[task 2023-06-14T15:17:51.979Z] 15:17:51 INFO - (
[task 2023-06-14T15:17:51.979Z] 15:17:51 INFO - {
[task 2023-06-14T15:17:51.979Z] 15:17:51 INFO - "type": "channel",
[task 2023-06-14T15:17:51.979Z] 15:17:51 INFO - "value": {
[task 2023-06-14T15:17:51.979Z] 15:17:51 INFO - "channel": "channel_name",
[task 2023-06-14T15:17:51.979Z] 15:17:51 INFO - "serializationOptions": {"maxObjectDepth": 0},
[task 2023-06-14T15:17:51.980Z] 15:17:51 INFO - },
[task 2023-06-14T15:17:51.980Z] 15:17:51 INFO - },
[task 2023-06-14T15:17:51.980Z] 15:17:51 INFO - {"type": "object"},
[task 2023-06-14T15:17:51.980Z] 15:17:51 INFO - ),
[task 2023-06-14T15:17:51.980Z] 15:17:51 INFO - (
[task 2023-06-14T15:17:51.980Z] 15:17:51 INFO - {
[task 2023-06-14T15:17:51.980Z] 15:17:51 INFO - "type": "channel",
[task 2023-06-14T15:17:51.980Z] 15:17:51 INFO - "value": {"channel": "channel_name", "ownership": "root"},
[task 2023-06-14T15:17:51.980Z] 15:17:51 INFO - },
[task 2023-06-14T15:17:51.980Z] 15:17:51 INFO - {
[task 2023-06-14T15:17:51.980Z] 15:17:51 INFO - "handle": any_string,
[task 2023-06-14T15:17:51.980Z] 15:17:51 INFO - "type": "object",
[task 2023-06-14T15:17:51.980Z] 15:17:51 INFO - "value": [
[task 2023-06-14T15:17:51.980Z] 15:17:51 INFO - ["foo", {"type": "string", "value": "bar"}],
[task 2023-06-14T15:17:51.980Z] 15:17:51 INFO - [
[task 2023-06-14T15:17:51.980Z] 15:17:51 INFO - "baz",
[task 2023-06-14T15:17:51.980Z] 15:17:51 INFO - {
[task 2023-06-14T15:17:51.980Z] 15:17:51 INFO - "type": "object",
[task 2023-06-14T15:17:51.980Z] 15:17:51 INFO - "value": [["1", {"type": "number", "value": 2}]],
[task 2023-06-14T15:17:51.980Z] 15:17:51 INFO - },
[task 2023-06-14T15:17:51.980Z] 15:17:51 INFO - ],
[task 2023-06-14T15:17:51.980Z] 15:17:51 INFO - ],
[task 2023-06-14T15:17:51.980Z] 15:17:51 INFO - },
[task 2023-06-14T15:17:51.981Z] 15:17:51 INFO - ),
[task 2023-06-14T15:17:51.981Z] 15:17:51 INFO - ],
[task 2023-06-14T15:17:51.981Z] 15:17:51 INFO - ids=["default", "with serializationOptions", "with ownership"],
[task 2023-06-14T15:17:51.981Z] 15:17:51 INFO - )
[task 2023-06-14T15:17:51.981Z] 15:17:51 INFO - async def test_channel(
[task 2023-06-14T15:17:51.981Z] 15:17:51 INFO - bidi_session,
[task 2023-06-14T15:17:51.981Z] 15:17:51 INFO - subscribe_events,
[task 2023-06-14T15:17:51.981Z] 15:17:51 INFO - wait_for_event,
[task 2023-06-14T15:17:51.981Z] 15:17:51 INFO - add_preload_script,
[task 2023-06-14T15:17:51.981Z] 15:17:51 INFO - channel,
[task 2023-06-14T15:17:51.981Z] 15:17:51 INFO - expected_data,
[task 2023-06-14T15:17:51.981Z] 15:17:51 INFO - ):
[task 2023-06-14T15:17:51.981Z] 15:17:51 INFO - await subscribe_events(["script.message"])
[task 2023-06-14T15:17:51.981Z] 15:17:51 INFO -
[task 2023-06-14T15:17:51.981Z] 15:17:51 INFO - on_script_message = wait_for_event("script.message")
[task 2023-06-14T15:17:51.981Z] 15:17:51 INFO - await add_preload_script(
[task 2023-06-14T15:17:51.981Z] 15:17:51 INFO - function_declaration="""(channel) => channel({'foo': 'bar', 'baz': {'1': 2}})""",
[task 2023-06-14T15:17:51.981Z] 15:17:51 INFO - arguments=[channel],
[task 2023-06-14T15:17:51.981Z] 15:17:51 INFO - )
[task 2023-06-14T15:17:51.981Z] 15:17:51 INFO -
[task 2023-06-14T15:17:51.981Z] 15:17:51 INFO - new_tab = await bidi_session.browsing_context.create(type_hint="tab")
[task 2023-06-14T15:17:51.981Z] 15:17:51 INFO - event_data = await on_script_message
[task 2023-06-14T15:17:51.981Z] 15:17:51 INFO -
[task 2023-06-14T15:17:51.982Z] 15:17:51 INFO - > recursive_compare(
[task 2023-06-14T15:17:51.982Z] 15:17:51 INFO - {
[task 2023-06-14T15:17:51.982Z] 15:17:51 INFO - "channel": "channel_name",
[task 2023-06-14T15:17:51.982Z] 15:17:51 INFO - "data": expected_data,
[task 2023-06-14T15:17:51.982Z] 15:17:51 INFO - "source": {
[task 2023-06-14T15:17:51.982Z] 15:17:51 INFO - "realm": any_string,
[task 2023-06-14T15:17:51.982Z] 15:17:51 INFO - "context": new_tab["context"],
[task 2023-06-14T15:17:51.982Z] 15:17:51 INFO - },
[task 2023-06-14T15:17:51.982Z] 15:17:51 INFO - },
[task 2023-06-14T15:17:51.982Z] 15:17:51 INFO - event_data,
[task 2023-06-14T15:17:51.982Z] 15:17:51 INFO - )
[task 2023-06-14T15:17:51.982Z] 15:17:51 INFO -
[task 2023-06-14T15:17:51.982Z] 15:17:51 INFO - add_preload_script = <function add_preload_script.<locals>.add_preload_script at 0x0000027E5B0CDD30>
[task 2023-06-14T15:17:51.982Z] 15:17:51 INFO - bidi_session = <webdriver.bidi.client.BidiSession object at 0x0000027E5B11E0D0>
[task 2023-06-14T15:17:51.982Z] 15:17:51 INFO - channel = {'type': 'channel', 'value': {'channel': 'channel_name'}}
[task 2023-06-14T15:17:51.982Z] 15:17:51 INFO - event_data = {'channel': 'channel_name',
[task 2023-06-14T15:17:51.982Z] 15:17:51 INFO - 'data': {'type': 'object',
[task 2023-06-14T15:17:51.982Z] 15:17:51 INFO - 'value': [['foo', {'type': 'string', 'value': 'bar'}],
[task 2023-06-14T15:17:51.982Z] 15:17:51 INFO - ['baz',
[task 2023-06-14T15:17:51.982Z] 15:17:51 INFO - {'type': 'object',
[task 2023-06-14T15:17:51.982Z] 15:17:51 INFO - 'value': [['1', {'type': 'number', 'value': 2}]]}]]},
[task 2023-06-14T15:17:51.982Z] 15:17:51 INFO - 'source': {'context': 'd56556b1-e085-493e-808d-4550d9873acc',
[task 2023-06-14T15:17:51.982Z] 15:17:51 INFO - 'realm': '8e334d1b-7307-41dc-bc5e-c7f7092b4dcf'}}
[task 2023-06-14T15:17:51.982Z] 15:17:51 INFO - expected_data = {'type': 'object',
[task 2023-06-14T15:17:51.983Z] 15:17:51 INFO - 'value': [['foo', {'type': 'string', 'value': 'bar'}],
[task 2023-06-14T15:17:51.983Z] 15:17:51 INFO - ['baz',
[task 2023-06-14T15:17:51.983Z] 15:17:51 INFO - {'type': 'object',
[task 2023-06-14T15:17:51.983Z] 15:17:51 INFO - 'value': [['1', {'type': 'number', 'value': 2}]]}]]}
[task 2023-06-14T15:17:51.983Z] 15:17:51 INFO - new_tab = {'context': 'ddd9cce1-eba5-41da-995c-c873294b3ced'}
[task 2023-06-14T15:17:51.983Z] 15:17:51 INFO - on_script_message = <Future finished result={'channel': 'channel_name', 'data': {'type': 'object', 'value': [['foo', {'type': 'string', 'value': 'bar'}], ['baz', {'type': 'object', 'value': [[...]]}]]}, 'source': {'context': 'd56556b1-e08...-4550d9873acc', 'realm': '8e334d1b-730...-c7f7092b4dcf'}}>
[task 2023-06-14T15:17:51.983Z] 15:17:51 INFO - subscribe_events = <function subscribe_events.<locals>.subscribe_events at 0x0000027E5B0CD670>
[task 2023-06-14T15:17:51.983Z] 15:17:51 INFO - wait_for_event = <function wait_for_event.<locals>.wait_for_event at 0x0000027E5B0CDDC0>
[task 2023-06-14T15:17:51.983Z] 15:17:51 INFO -
[task 2023-06-14T15:17:51.983Z] 15:17:51 INFO - tests\web-platform\tests\webdriver\tests\bidi\script\add_preload_script\arguments.py:82:
[task 2023-06-14T15:17:51.983Z] 15:17:51 INFO - _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _
[task 2023-06-14T15:17:51.983Z] 15:17:51 INFO - tests\web-platform\tests\webdriver\tests\bidi\__init__.py:26: in recursive_compare
[task 2023-06-14T15:17:51.983Z] 15:17:51 INFO - recursive_compare(expected[key], actual[key])
[task 2023-06-14T15:17:51.983Z] 15:17:51 INFO - actual = {'channel': 'channel_name',
[task 2023-06-14T15:17:51.983Z] 15:17:51 INFO - 'data': {'type': 'object',
[task 2023-06-14T15:17:51.983Z] 15:17:51 INFO - 'value': [['foo', {'type': 'string', 'value': 'bar'}],
[task 2023-06-14T15:17:51.983Z] 15:17:51 INFO - ['baz',
[task 2023-06-14T15:17:51.983Z] 15:17:51 INFO - {'type': 'object',
[task 2023-06-14T15:17:51.983Z] 15:17:51 INFO - 'value': [['1', {'type': 'number', 'value': 2}]]}]]},
[task 2023-06-14T15:17:51.983Z] 15:17:51 INFO - 'source': {'context': 'd56556b1-e085-493e-808d-4550d9873acc',
[task 2023-06-14T15:17:51.983Z] 15:17:51 INFO - 'realm': '8e334d1b-7307-41dc-bc5e-c7f7092b4dcf'}}
[task 2023-06-14T15:17:51.984Z] 15:17:51 INFO - expected = {'channel': 'channel_name',
[task 2023-06-14T15:17:51.984Z] 15:17:51 INFO - 'data': {'type': 'object',
[task 2023-06-14T15:17:51.984Z] 15:17:51 INFO - 'value': [['foo', {'type': 'string', 'value': 'bar'}],
[task 2023-06-14T15:17:51.984Z] 15:17:51 INFO - ['baz',
[task 2023-06-14T15:17:51.984Z] 15:17:51 INFO - {'type': 'object',
[task 2023-06-14T15:17:51.984Z] 15:17:51 INFO - 'value': [['1', {'type': 'number', 'value': 2}]]}]]},
[task 2023-06-14T15:17:51.984Z] 15:17:51 INFO - 'source': {'context': 'ddd9cce1-eba5-41da-995c-c873294b3ced',
[task 2023-06-14T15:17:51.984Z] 15:17:51 INFO - 'realm': <function any_string at 0x0000027E5AF5F430>}}
[task 2023-06-14T15:17:51.984Z] 15:17:51 INFO - key = 'source'
[task 2023-06-14T15:17:51.984Z] 15:17:51 INFO - tests\web-platform\tests\webdriver\tests\bidi\__init__.py:26: in recursive_compare
[task 2023-06-14T15:17:51.984Z] 15:17:51 INFO - recursive_compare(expected[key], actual[key])
[task 2023-06-14T15:17:51.984Z] 15:17:51 INFO - actual = {'context': 'd56556b1-e085-493e-808d-4550d9873acc',
[task 2023-06-14T15:17:51.984Z] 15:17:51 INFO - 'realm': '8e334d1b-7307-41dc-bc5e-c7f7092b4dcf'}
[task 2023-06-14T15:17:51.984Z] 15:17:51 INFO - expected = {'context': 'ddd9cce1-eba5-41da-995c-c873294b3ced',
[task 2023-06-14T15:17:51.984Z] 15:17:51 INFO - 'realm': <function any_string at 0x0000027E5AF5F430>}
[task 2023-06-14T15:17:51.984Z] 15:17:51 INFO - key = 'context'
[task 2023-06-14T15:17:51.984Z] 15:17:51 INFO - _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _
[task 2023-06-14T15:17:51.984Z] 15:17:51 INFO -
[task 2023-06-14T15:17:51.984Z] 15:17:51 INFO - expected = 'ddd9cce1-eba5-41da-995c-c873294b3ced'
[task 2023-06-14T15:17:51.984Z] 15:17:51 INFO - actual = 'd56556b1-e085-493e-808d-4550d9873acc'
[task 2023-06-14T15:17:51.984Z] 15:17:51 INFO -
[task 2023-06-14T15:17:51.984Z] 15:17:51 INFO - def recursive_compare(expected: Any, actual: Any) -> None:
[task 2023-06-14T15:17:51.984Z] 15:17:51 INFO - if callable(expected):
[task 2023-06-14T15:17:51.984Z] 15:17:51 INFO - expected(actual)
[task 2023-06-14T15:17:51.984Z] 15:17:51 INFO - return
[task 2023-06-14T15:17:51.985Z] 15:17:51 INFO -
[task 2023-06-14T15:17:51.985Z] 15:17:51 INFO - assert type(expected) == type(actual)
[task 2023-06-14T15:17:51.985Z] 15:17:51 INFO - if type(expected) is list:
[task 2023-06-14T15:17:51.985Z] 15:17:51 INFO - assert len(expected) == len(actual)
[task 2023-06-14T15:17:51.985Z] 15:17:51 INFO - for index, _ in enumerate(expected):
[task 2023-06-14T15:17:51.985Z] 15:17:51 INFO - recursive_compare(expected[index], actual[index])
[task 2023-06-14T15:17:51.985Z] 15:17:51 INFO - return
[task 2023-06-14T15:17:51.985Z] 15:17:51 INFO -
[task 2023-06-14T15:17:51.985Z] 15:17:51 INFO - if type(expected) is dict:
[task 2023-06-14T15:17:51.985Z] 15:17:51 INFO - # Actual dict can have more keys as part of the forwards-compat design.
[task 2023-06-14T15:17:51.985Z] 15:17:51 INFO - assert expected.keys() <= actual.keys(), \
[task 2023-06-14T15:17:51.985Z] 15:17:51 INFO - f"Key set should be present: {set(expected.keys()) - set(actual.keys())}"
[task 2023-06-14T15:17:51.985Z] 15:17:51 INFO - for key in expected.keys():
[task 2023-06-14T15:17:51.985Z] 15:17:51 INFO - recursive_compare(expected[key], actual[key])
[task 2023-06-14T15:17:51.985Z] 15:17:51 INFO - return
[task 2023-06-14T15:17:51.985Z] 15:17:51 INFO -
[task 2023-06-14T15:17:51.985Z] 15:17:51 INFO - > assert expected == actual
[task 2023-06-14T15:17:51.985Z] 15:17:51 INFO - E AssertionError
[task 2023-06-14T15:17:51.985Z] 15:17:51 INFO -
[task 2023-06-14T15:17:51.985Z] 15:17:51 INFO - actual = 'd56556b1-e085-493e-808d-4550d9873acc'
[task 2023-06-14T15:17:51.985Z] 15:17:51 INFO - expected = 'ddd9cce1-eba5-41da-995c-c873294b3ced'
[task 2023-06-14T15:17:51.986Z] 15:17:51 INFO -
[task 2023-06-14T15:17:51.986Z] 15:17:51 INFO - tests\web-platform\tests\webdriver\tests\bidi\__init__.py:29: AssertionError
[task 2023-06-14T15:17:51.988Z] 15:17:51 INFO - .....
[task 2023-06-14T15:17:51.989Z] 15:17:51 INFO - TEST-OK | /webdriver/tests/bidi/script/add_preload_script/arguments.py | took 8427ms
[task 2023-06-14T15:17:51.990Z] 15:17:51 INFO - PID 5264 | 1686755871977 webdriver::server DEBUG -> GET /status
[task 2023-06-14T15:17:51.991Z] 15:17:51 INFO - PID 5264 | 1686755871977 webdriver::server DEBUG <- 200 OK {"value":{"message":"","ready":true}}
[task 2023-06-14T15:18:02.028Z] 15:18:02 WARNING - Forcibly terminating runner process
[task 2023-06-14T15:18:02.575Z] 15:18:02 INFO - PID 8756 | 1686755882073 geckodriver INFO Listening on 127.0.0.1:49975
[task 2023-06-14T15:18:02.577Z] 15:18:02 INFO - Starting runner
[task 2023-06-14T15:18:03.387Z] 15:18:03 INFO - TEST-START | /webdriver/tests/bidi/script/add_preload_script/invalid.py
|
||
Comment 1•3 years ago
•
|
||
The problem here is the failing assertion for the context between the script.message payload and the context of the tab as returned by browsingContext.create which is d56556b1-e085-493e-808d-4550d9873acc vs. ddd9cce1-eba5-41da-995c-c873294b3ced.
Having a closer look at the test II actually wonder why we do not expect two script.message events. When we are subscribed for this event and a pre-load script gets added, it should automatically be installed and run, which would trigger the first event. And then when adding a new tab, the script is installed as well, and another script.message event needs to be emitted.
So why don't we only expect a single event and that for the new tab only? Do I overlook something? Sasha, could you have a look please? Thank you.
Flags: needinfo?(aborovova)
|
||
Comment 2•3 years ago
|
||
From what I can see, per spec preload scripts run (at the moment) only on creation of a new Window, so they are not supposed to run when they are installed. This is how it's also implemented.
But in this case weirdly we receive two events. Looks like the created tab is getting reloaded during creation and that's why the preload script is executed twice with different browsing context ids.
[task 2023-06-14T15:17:46.568Z] 15:17:46 INFO - PID 5264 | 1686755866566 RemoteAgent DEBUG WebDriverBiDiConnection 4fac5030-25f5-4168-aeaa-9f253de3fa12 -> {"id":2,"method":"script.addPreloadScript","params":{"functionDeclaration":"(channel) => channel({'foo': 'bar', 'baz': {'1': 2}})","arguments":[{"type":"channel","value":{"channel":"channel_name"}}]}}
[task 2023-06-14T15:17:46.571Z] 15:17:46 INFO - PID 5264 | 1686755866566 RemoteAgent TRACE Module root/script.jsm found for ROOT
[task 2023-06-14T15:17:46.572Z] 15:17:46 INFO - PID 5264 | 1686755866566 RemoteAgent TRACE Received command script.addPreloadScript for destination ROOT
[task 2023-06-14T15:17:46.573Z] 15:17:46 INFO - PID 5264 | 1686755866566 RemoteAgent TRACE Module root/script.jsm found for ROOT
[task 2023-06-14T15:17:46.574Z] 15:17:46 INFO - PID 5264 | 1686755866566 RemoteAgent TRACE Module root/script.jsm found for ROOT
[task 2023-06-14T15:17:46.575Z] 15:17:46 INFO - PID 5264 | 1686755866569 RemoteAgent TRACE Module windowglobal-in-root/script.jsm found for WINDOW_GLOBAL
[task 2023-06-14T15:17:46.575Z] 15:17:46 INFO - PID 5264 | 1686755866569 RemoteAgent TRACE Module windowglobal/script.jsm found for WINDOW_GLOBAL
[task 2023-06-14T15:17:46.576Z] 15:17:46 INFO - PID 5264 | 1686755866569 RemoteAgent TRACE Received command script._applySessionData for destination WINDOW_GLOBAL
[task 2023-06-14T15:17:46.577Z] 15:17:46 INFO - PID 5264 | 1686755866569 RemoteAgent TRACE Module windowglobal-in-root/script.jsm found for WINDOW_GLOBAL
[task 2023-06-14T15:17:46.578Z] 15:17:46 INFO - PID 5264 | 1686755866569 RemoteAgent TRACE Module windowglobal/script.jsm found for WINDOW_GLOBAL
[task 2023-06-14T15:17:46.579Z] 15:17:46 INFO - PID 5264 | 1686755866569 RemoteAgent TRACE Module root/script.jsm found for ROOT
[task 2023-06-14T15:17:46.580Z] 15:17:46 INFO - PID 5264 | 1686755866569 RemoteAgent TRACE Received command script._applySessionData for destination WINDOW_GLOBAL
[task 2023-06-14T15:17:46.581Z] 15:17:46 INFO - PID 5264 | 1686755866569 RemoteAgent TRACE Module windowglobal/script.jsm found for WINDOW_GLOBAL
[task 2023-06-14T15:17:46.582Z] 15:17:46 INFO - PID 5264 | 1686755866571 RemoteAgent DEBUG WebDriverBiDiConnection 4fac5030-25f5-4168-aeaa-9f253de3fa12 <- {"id":2,"result":{"script":"9aae34ed-f9ac-43dc-a952-ee80084051f0"}}
[task 2023-06-14T15:17:46.583Z] 15:17:46 INFO - PID 5264 | 1686755866572 RemoteAgent DEBUG WebDriverBiDiConnection 4fac5030-25f5-4168-aeaa-9f253de3fa12 -> {"id":3,"method":"browsingContext.create","params":{"type":"tab"}}
[task 2023-06-14T15:17:46.584Z] 15:17:46 INFO - PID 5264 | 1686755866572 RemoteAgent TRACE Module root/browsingContext.jsm found for ROOT
[task 2023-06-14T15:17:46.585Z] 15:17:46 INFO - PID 5264 | 1686755866572 RemoteAgent TRACE Received command browsingContext.create for destination ROOT
[task 2023-06-14T15:17:46.586Z] 15:17:46 INFO - PID 5264 | 1686755866572 RemoteAgent TRACE Module root/browsingContext.jsm found for ROOT
[task 2023-06-14T15:17:46.586Z] 15:17:46 INFO - PID 5264 | 1686755866572 RemoteAgent TRACE Module root/browsingContext.jsm found for ROOT
[task 2023-06-14T15:17:46.588Z] 15:17:46 INFO - PID 5264 | 1686755866586 RemoteAgent TRACE [11] ProgressListener Start: expectNavigation=false resolveWhenStarted=false unloadTimeout=5000 waitForExplicitStart=false
[task 2023-06-14T15:17:46.588Z] 15:17:46 INFO - PID 5264 | 1686755866586 RemoteAgent TRACE [11] ProgressListener Setting unload timer (5000ms)
[task 2023-06-14T15:17:46.592Z] 15:17:46 INFO - PID 5264 | 1686755866591 Marionette TRACE Remoteness change detected. Set new top-level browsing context to 3
[task 2023-06-14T15:17:46.596Z] 15:17:46 INFO - PID 5264 | 1686755866594 RemoteAgent TRACE MessageHandler WINDOW_GLOBAL for session 1481b53f-273e-4c5f-9ff3-320caf502891 is being destroyed
[task 2023-06-14T15:17:46.598Z] 15:17:46 INFO - PID 5264 | 1686755866596 RemoteAgent TRACE Unregistered MessageHandler WINDOW_GLOBAL for session 1481b53f-273e-4c5f-9ff3-320caf502891
[task 2023-06-14T15:17:47.484Z] 15:17:47 INFO - PID 5264 | 1686755867497 RemoteAgent TRACE Module windowglobal/script.jsm found for WINDOW_GLOBAL
[task 2023-06-14T15:17:47.499Z] 15:17:47 INFO - PID 5264 | 1686755867497 RemoteAgent TRACE Received command script._applySessionData for destination WINDOW_GLOBAL
[task 2023-06-14T15:17:47.501Z] 15:17:47 INFO - PID 5264 | 1686755867497 RemoteAgent TRACE Module windowglobal/script.jsm found for WINDOW_GLOBAL
[task 2023-06-14T15:17:47.501Z] 15:17:47 INFO - PID 5264 | 1686755867497 RemoteAgent TRACE Module windowglobal/script.jsm found for WINDOW_GLOBAL
[task 2023-06-14T15:17:47.502Z] 15:17:47 INFO - PID 5264 | 1686755867497 RemoteAgent TRACE Received command script._applySessionData for destination WINDOW_GLOBAL
[task 2023-06-14T15:17:47.503Z] 15:17:47 INFO - PID 5264 | 1686755867498 RemoteAgent TRACE Module windowglobal/script.jsm found for WINDOW_GLOBAL
[task 2023-06-14T15:17:47.504Z] 15:17:47 INFO - PID 5264 | 1686755867498 RemoteAgent TRACE Created MessageHandler WINDOW_GLOBAL for session 1481b53f-273e-4c5f-9ff3-320caf502891
[task 2023-06-14T15:17:47.505Z] 15:17:47 INFO - PID 5264 | 1686755867498 RemoteAgent TRACE Module windowglobal-in-root/window-global-handler-created.jsm not found for WINDOW_GLOBAL
[task 2023-06-14T15:17:47.506Z] 15:17:47 INFO - PID 5264 | 1686755867500 RemoteAgent TRACE [11] ProgressListener Check loading state: isStart=1 isStop=0
[task 2023-06-14T15:17:47.507Z] 15:17:47 INFO - PID 5264 | 1686755867500 RemoteAgent TRACE [11] ProgressListener state=start: about:blank
[task 2023-06-14T15:17:47.508Z] 15:17:47 INFO - PID 5264 | 1686755867500 RemoteAgent TRACE [11] ProgressListener Cleared the unload timer
[task 2023-06-14T15:17:47.509Z] 15:17:47 INFO - PID 5264 | 1686755867502 RemoteAgent TRACE [11] ProgressListener Check loading state: isStart=0 isStop=16
[task 2023-06-14T15:17:47.510Z] 15:17:47 INFO - PID 5264 | 1686755867502 RemoteAgent TRACE [11] ProgressListener Ignore aborted navigation error to the initial document, real document will be loaded.
[task 2023-06-14T15:17:47.511Z] 15:17:47 INFO - PID 5264 | 1686755867503 RemoteAgent TRACE [11] ProgressListener Check loading state: isStart=1 isStop=0
[task 2023-06-14T15:17:47.512Z] 15:17:47 INFO - PID 5264 | 1686755867503 RemoteAgent TRACE Module windowglobal/script.jsm found for WINDOW_GLOBAL
[task 2023-06-14T15:17:47.512Z] 15:17:47 INFO - PID 5264 | 1686755867504 RemoteAgent TRACE Received command script._applySessionData for destination WINDOW_GLOBAL
[task 2023-06-14T15:17:47.514Z] 15:17:47 INFO - PID 5264 | 1686755867504 RemoteAgent TRACE Module windowglobal/script.jsm found for WINDOW_GLOBAL
[task 2023-06-14T15:17:47.515Z] 15:17:47 INFO - PID 5264 | 1686755867504 RemoteAgent TRACE Module windowglobal/script.jsm found for WINDOW_GLOBAL
[task 2023-06-14T15:17:47.515Z] 15:17:47 INFO - PID 5264 | 1686755867504 RemoteAgent TRACE Received command script._applySessionData for destination WINDOW_GLOBAL
[task 2023-06-14T15:17:47.516Z] 15:17:47 INFO - PID 5264 | 1686755867504 RemoteAgent TRACE Module windowglobal/script.jsm found for WINDOW_GLOBAL
[task 2023-06-14T15:17:47.517Z] 15:17:47 INFO - PID 5264 | 1686755867504 RemoteAgent TRACE Created MessageHandler WINDOW_GLOBAL for session 1481b53f-273e-4c5f-9ff3-320caf502891
[task 2023-06-14T15:17:47.518Z] 15:17:47 INFO - PID 5264 | 1686755867511 RemoteAgent TRACE Module windowglobal/script.jsm found for WINDOW_GLOBAL
[task 2023-06-14T15:17:47.519Z] 15:17:47 INFO - PID 5264 | 1686755867511 RemoteAgent TRACE Received command script._applySessionData for destination WINDOW_GLOBAL
[task 2023-06-14T15:17:47.520Z] 15:17:47 INFO - PID 5264 | 1686755867511 RemoteAgent TRACE Module windowglobal/script.jsm found for WINDOW_GLOBAL
[task 2023-06-14T15:17:47.521Z] 15:17:47 INFO - PID 5264 | 1686755867511 RemoteAgent TRACE Module windowglobal/script.jsm found for WINDOW_GLOBAL
[task 2023-06-14T15:17:47.522Z] 15:17:47 INFO - PID 5264 | 1686755867511 RemoteAgent TRACE Received command script._applySessionData for destination WINDOW_GLOBAL
[task 2023-06-14T15:17:47.522Z] 15:17:47 INFO - PID 5264 | 1686755867511 RemoteAgent TRACE Module windowglobal/script.jsm found for WINDOW_GLOBAL
[task 2023-06-14T15:17:47.524Z] 15:17:47 INFO - PID 5264 | 1686755867511 RemoteAgent TRACE Created MessageHandler WINDOW_GLOBAL for session 1481b53f-273e-4c5f-9ff3-320caf502891
[task 2023-06-14T15:17:47.525Z] 15:17:47 INFO - PID 5264 | 1686755867513 RemoteAgent TRACE WebDriverProcessData actor created for PID 8968
[task 2023-06-14T15:17:47.526Z] 15:17:47 INFO - PID 5264 | 1686755867523 RemoteAgent DEBUG WebDriverBiDiConnection 4fac5030-25f5-4168-aeaa-9f253de3fa12 <- {"method":"script.message","params":{"channel":"channel_name","data":{"type":"object","value":[["foo",{"type":"string","value":"bar"}],["baz",{"type":"object","value":[["1",{"type":"number","value":2}]]}]]},"source":{"realm":"8e334d1b-7307-41dc-bc5e-c7f7092b4dcf","context":"d56556b1-e085-493e-808d-4550d9873acc"}}}
[task 2023-06-14T15:17:47.527Z] 15:17:47 INFO - PID 5264 | 1686755867524 RemoteAgent TRACE MessageHandler WINDOW_GLOBAL for session 1481b53f-273e-4c5f-9ff3-320caf502891 is being destroyed
[task 2023-06-14T15:17:47.528Z] 15:17:47 INFO - PID 5264 | 1686755867524 RemoteAgent TRACE Unregistered MessageHandler WINDOW_GLOBAL for session 1481b53f-273e-4c5f-9ff3-320caf502891
[task 2023-06-14T15:17:47.532Z] 15:17:47 INFO - PID 5264 | 1686755867531 RemoteAgent TRACE Module windowglobal/script.jsm found for WINDOW_GLOBAL
[task 2023-06-14T15:17:47.533Z] 15:17:47 INFO - PID 5264 | 1686755867532 RemoteAgent TRACE Received command script._applySessionData for destination WINDOW_GLOBAL
[task 2023-06-14T15:17:47.534Z] 15:17:47 INFO - PID 5264 | 1686755867532 RemoteAgent TRACE Module windowglobal/script.jsm found for WINDOW_GLOBAL
[task 2023-06-14T15:17:47.535Z] 15:17:47 INFO - PID 5264 | 1686755867532 RemoteAgent TRACE Module windowglobal/script.jsm found for WINDOW_GLOBAL
[task 2023-06-14T15:17:47.536Z] 15:17:47 INFO - PID 5264 | 1686755867532 RemoteAgent TRACE Received command script._applySessionData for destination WINDOW_GLOBAL
[task 2023-06-14T15:17:47.537Z] 15:17:47 INFO - PID 5264 | 1686755867532 RemoteAgent TRACE Module windowglobal/script.jsm found for WINDOW_GLOBAL
[task 2023-06-14T15:17:47.537Z] 15:17:47 INFO - PID 5264 | 1686755867532 RemoteAgent TRACE Created MessageHandler WINDOW_GLOBAL for session 1481b53f-273e-4c5f-9ff3-320caf502891
[task 2023-06-14T15:17:47.538Z] 15:17:47 INFO - PID 5264 | 1686755867534 RemoteAgent DEBUG WebDriverBiDiConnection 4fac5030-25f5-4168-aeaa-9f253de3fa12 <- {"method":"script.message","params":{"channel":"channel_name","data":{"type":"object","value":[["foo",{"type":"string","value":"bar"}],["baz",{"type":"object","value":[["1",{"type":"number","value":2}]]}]]},"source":{"realm":"4879427f-7845-440f-a8d2-8222a267e4ff","context":"ddd9cce1-eba5-41da-995c-c873294b3ced"}}}
[task 2023-06-14T15:17:47.540Z] 15:17:47 INFO - PID 5264 | 1686755867534 RemoteAgent TRACE MessageHandler WINDOW_GLOBAL for session 1481b53f-273e-4c5f-9ff3-320caf502891 is being destroyed
[task 2023-06-14T15:17:47.540Z] 15:17:47 INFO - PID 5264 | 1686755867534 RemoteAgent TRACE Unregistered MessageHandler WINDOW_GLOBAL for session 1481b53f-273e-4c5f-9ff3-320caf502891
[task 2023-06-14T15:17:47.541Z] 15:17:47 INFO - PID 5264 | 1686755867536 RemoteAgent TRACE [11] ProgressListener Check loading state: isStart=0 isStop=16
[task 2023-06-14T15:17:47.542Z] 15:17:47 INFO - PID 5264 | 1686755867536 RemoteAgent TRACE [11] ProgressListener state=stop: about:blank
[task 2023-06-14T15:17:47.543Z] 15:17:47 INFO - PID 5264 | 1686755867536 RemoteAgent TRACE [11] ProgressListener Stop: has error=false
[task 2023-06-14T15:17:47.544Z] 15:17:47 INFO - PID 5264 | 1686755867537 RemoteAgent DEBUG WebDriverBiDiConnection 4fac5030-25f5-4168-aeaa-9f253de3fa12 <- {"id":3,"result":{"context":"ddd9cce1-eba5-41da-995c-c873294b3ced"}}
[task 2023-06-14T15:17:47.551Z] 15:17:47 INFO - STDOUT: FAILED
Flags: needinfo?(aborovova)
|
|
||
Comment 3•3 years ago
|
||
(In reply to Alexandra Borovova [:Sasha] from comment #2)
From what I can see, per spec preload scripts run (at the moment) only on creation of a new Window, so they are not supposed to run when they are installed. This is how it's also implemented.
Hm, I thought we also run them when adding the script. But that's a different topic then, right.
But in this case weirdly we receive two events. Looks like the created tab is getting reloaded during creation and that's why the preload script is executed twice with different browsing context ids.
I saw that as well but that's not the underlying reason. When you search for WebDriver:GetWindowHandles you will see the following:
[task 2023-06-14T15:17:47.600Z] 15:17:47 INFO - PID 5264 | 1686755867578 Marionette DEBUG 0 -> [0,9,"WebDriver:GetWindowHandles",{}]
[task 2023-06-14T15:17:47.601Z] 15:17:47 INFO - PID 5264 | 1686755867578 Marionette DEBUG 0 <- [1,9,null,["d56556b1-e085-493e-808d-4550d9873acc","ddd9cce1-eba5-41da-995c-c873294b3ced"]]
Note that this reports exactly two open tabs. The ids here match up perfectly with the ids that were returned by the events. As such I still think that the event is reported twice including for the original tab. As such my question above.
| Comment hidden (Intermittent Failures Robot) |
|
||
Comment 5•3 years ago
|
||
https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
For more information, please visit BugBot documentation.
Status: NEW → RESOLVED
Closed: 3 years ago
Resolution: --- → INCOMPLETE
You need to log in
before you can comment on or make changes to this bug.
Description
•