Closed Bug 1777315 Opened 3 years ago Closed 3 years ago

Intermittent [Tier 2] /webdriver/tests/bidi/browsing_context/navigate/wait.py | test_slow_image[complete-True] - AssertionError: assert 'about:blank' == 'http://web-platform.test:8000/webdriver/tests/support/inline.py?doc=%3C%21doctype+html%3E%0A%3Cmeta+

Categories

(Remote Protocol :: Marionette, defect, P5)

Product:
Remote Protocol
Component:
Marionette
Type:
defect

Tracking

(Not tracked)

Status:
RESOLVED DUPLICATE of bug 1767839

People

(Reporter: intermittent-bug-filer, Unassigned)

Details

(Keywords: assertion, intermittent-failure)

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

[task 2022-06-29T17:54:01.239Z] 17:54:01     INFO - TEST-PASS | /webdriver/tests/bidi/browsing_context/navigate/wait.py | test_expected_url[none] 
[task 2022-06-29T17:54:01.239Z] 17:54:01     INFO - TEST-PASS | /webdriver/tests/bidi/browsing_context/navigate/wait.py | test_expected_url[interactive] 
[task 2022-06-29T17:54:01.239Z] 17:54:01     INFO - TEST-PASS | /webdriver/tests/bidi/browsing_context/navigate/wait.py | test_expected_url[complete] 
[task 2022-06-29T17:54:01.240Z] 17:54:01     INFO - TEST-PASS | /webdriver/tests/bidi/browsing_context/navigate/wait.py | test_slow_image[none-False] 
[task 2022-06-29T17:54:01.240Z] 17:54:01     INFO - TEST-PASS | /webdriver/tests/bidi/browsing_context/navigate/wait.py | test_slow_image[interactive-False] 
[task 2022-06-29T17:54:01.240Z] 17:54:01     INFO - TEST-UNEXPECTED-FAIL | /webdriver/tests/bidi/browsing_context/navigate/wait.py | test_slow_image[complete-True] - AssertionError: assert 'about:blank' == 'http://web-platform.test:8000/webdriver/tests/support/inline.py?doc=%3C%21doctype+html%3E%0A%3Cmeta+charset%3DUTF-8%3E%0A%3Cimg+src%3D%27%2Fwebdriver%2Ftests%2Fbidi%2Fbrowsing_context%2Fnavigate%2Fsupport%2Fempty.svg%3Fpipe%3Dtrickle%28d10%29%27%3E&mime=text%2Fhtml&charset=UTF-8'
[task 2022-06-29T17:54:01.241Z] 17:54:01     INFO - bidi_session = <webdriver.bidi.client.BidiSession object at 0x7f5a3c34da90>
[task 2022-06-29T17:54:01.242Z] 17:54:01     INFO - inline = <function inline.<locals>.inline at 0x7f5a3c2392f0>
[task 2022-06-29T17:54:01.243Z] 17:54:01     INFO - new_tab = {'children': None, 'context': '08c09340-f3fe-4f62-b36a-11661af9f539', 'parent': None, 'url': 'about:blank'}
[task 2022-06-29T17:54:01.244Z] 17:54:01     INFO - wait = 'complete', expect_timeout = True
[task 2022-06-29T17:54:01.245Z] 17:54:01     INFO - 
[task 2022-06-29T17:54:01.245Z] 17:54:01     INFO -     @pytest.mark.parametrize(
[task 2022-06-29T17:54:01.245Z] 17:54:01     INFO -         "wait, expect_timeout",
[task 2022-06-29T17:54:01.245Z] 17:54:01     INFO -         [
[task 2022-06-29T17:54:01.245Z] 17:54:01     INFO -             ("none", False),
[task 2022-06-29T17:54:01.246Z] 17:54:01     INFO -             ("interactive", False),
[task 2022-06-29T17:54:01.246Z] 17:54:01     INFO -             ("complete", True),
[task 2022-06-29T17:54:01.246Z] 17:54:01     INFO -         ],
[task 2022-06-29T17:54:01.246Z] 17:54:01     INFO -     )
[task 2022-06-29T17:54:01.246Z] 17:54:01     INFO -     async def test_slow_image(bidi_session, inline, new_tab, wait, expect_timeout):
[task 2022-06-29T17:54:01.246Z] 17:54:01     INFO -         script_url = "/webdriver/tests/bidi/browsing_context/navigate/support/empty.svg"
[task 2022-06-29T17:54:01.246Z] 17:54:01     INFO -         url = inline(f"<img src='{script_url}?pipe=trickle(d10)'>")
[task 2022-06-29T17:54:01.246Z] 17:54:01     INFO -     
[task 2022-06-29T17:54:01.246Z] 17:54:01     INFO -         # Ultimately, "interactive" and "complete" should support a timeout argument.
[task 2022-06-29T17:54:01.247Z] 17:54:01     INFO -         # See https://github.com/w3c/webdriver-bidi/issues/188.
[task 2022-06-29T17:54:01.247Z] 17:54:01     INFO -         wait_for_navigation = asyncio.wait_for(
[task 2022-06-29T17:54:01.247Z] 17:54:01     INFO -             bidi_session.browsing_context.navigate(
[task 2022-06-29T17:54:01.247Z] 17:54:01     INFO -                 context=new_tab["context"], url=url, wait=wait
[task 2022-06-29T17:54:01.247Z] 17:54:01     INFO -             ),
[task 2022-06-29T17:54:01.247Z] 17:54:01     INFO -             timeout=1,
[task 2022-06-29T17:54:01.247Z] 17:54:01     INFO -         )
<...>
[task 2022-06-29T17:54:01.251Z] 17:54:01     INFO - url        = 'http://web-platform.test:8000/webdriver/tests/support/inline.py?doc=%3C%21doctype+html%3E%0A%3Cmeta+charset%3DUTF-8%3E%0A%3Cimg+src%3D%27%2Fwebdriver%2Ftests%2Fbidi%2Fbrowsing_context%2Fnavigate%2Fsupport%2Fempty.svg%3Fpipe%3Dtrickle%28d10%29%27%3E&mime=text%2Fhtml&charset=UTF-8'
[task 2022-06-29T17:54:01.251Z] 17:54:01     INFO - wait       = 'complete'
[task 2022-06-29T17:54:01.251Z] 17:54:01     INFO - wait_for_navigation = <generator object wait_for at 0x7f5a3c175e60>
[task 2022-06-29T17:54:01.251Z] 17:54:01     INFO - 
[task 2022-06-29T17:54:01.251Z] 17:54:01     INFO - tests/web-platform/tests/webdriver/tests/bidi/browsing_context/navigate/wait.py:52: AssertionError
[task 2022-06-29T17:54:01.251Z] 17:54:01     INFO - ......
[task 2022-06-29T17:54:01.251Z] 17:54:01     INFO - TEST-OK | /webdriver/tests/bidi/browsing_context/navigate/wait.py | took 15593ms
[task 2022-06-29T17:54:01.252Z] 17:54:01     INFO - PID 1574 | 1656525241228	webdriver::server	DEBUG	-> GET /status
[task 2022-06-29T17:54:01.252Z] 17:54:01     INFO - PID 1574 | 1656525241229	webdriver::server	DEBUG	<- 200 OK {"value":{"message":"","ready":true}}
[task 2022-06-29T17:54:01.263Z] 17:54:01 CRITICAL - Test harness output was not a valid structured log message: 
[task 2022-06-29T17:54:01.263Z] 17:54:01 CRITICAL - Task exception was never retrieved
[task 2022-06-29T17:54:01.264Z] 17:54:01 CRITICAL - future: <Task finished coro=<Transport.read_messages() done, defined at /builds/worker/workspace/build/tests/web-platform/tests/tools/webdriver/webdriver/bidi/transport.py:71> exception=InvalidStateError('invalid state',)>
[task 2022-06-29T17:54:01.264Z] 17:54:01 CRITICAL - Traceback (most recent call last):
[task 2022-06-29T17:54:01.265Z] 17:54:01 CRITICAL -   File "/builds/worker/workspace/build/tests/web-platform/tests/tools/webdriver/webdriver/bidi/transport.py", line 76, in read_messages
[task 2022-06-29T17:54:01.265Z] 17:54:01 CRITICAL -     await self.handle(msg)
[task 2022-06-29T17:54:01.266Z] 17:54:01 CRITICAL -   File "/builds/worker/workspace/build/tests/web-platform/tests/tools/webdriver/webdriver/bidi/transport.py", line 64, in handle
[task 2022-06-29T17:54:01.266Z] 17:54:01 CRITICAL -     await self.msg_handler(data)
[task 2022-06-29T17:54:01.266Z] 17:54:01 CRITICAL -   File "/builds/worker/workspace/build/tests/web-platform/tests/tools/webdriver/webdriver/bidi/client.py", line 187, in on_message
[task 2022-06-29T17:54:01.267Z] 17:54:01 CRITICAL -     future.set_exception(exception)
[task 2022-06-29T17:54:01.267Z] 17:54:01 CRITICAL - asyncio.base_futures.InvalidStateError: invalid state
[task 2022-06-29T17:54:01.268Z] 17:54:01 CRITICAL - Task exception was never retrieved
[task 2022-06-29T17:54:01.268Z] 17:54:01 CRITICAL - future: <Task finished coro=<Transport.read_messages() done, defined at /builds/worker/workspace/build/tests/web-platform/tests/tools/webdriver/webdriver/bidi/transport.py:71> exception=InvalidStateError('invalid state',)>
[task 2022-06-29T17:54:01.269Z] 17:54:01 CRITICAL - Traceback (most recent call last):
[task 2022-06-29T17:54:01.269Z] 17:54:01 CRITICAL -   File "/builds/worker/workspace/build/tests/web-platform/tests/tools/webdriver/webdriver/bidi/transport.py", line 76, in read_messages
[task 2022-06-29T17:54:01.270Z] 17:54:01 CRITICAL -     await self.handle(msg)
[task 2022-06-29T17:54:01.271Z] 17:54:01 CRITICAL -   File "/builds/worker/workspace/build/tests/web-platform/tests/tools/webdriver/webdriver/bidi/transport.py", line 64, in handle
[task 2022-06-29T17:54:01.271Z] 17:54:01 CRITICAL -     await self.msg_handler(data)
[task 2022-06-29T17:54:01.271Z] 17:54:01 CRITICAL -   File "/builds/worker/workspace/build/tests/web-platform/tests/tools/webdriver/webdriver/bidi/client.py", line 187, in on_message
[task 2022-06-29T17:54:01.272Z] 17:54:01 CRITICAL -     future.set_exception(exception)
[task 2022-06-29T17:54:01.272Z] 17:54:01 CRITICAL - asyncio.base_futures.InvalidStateError: invalid state
[task 2022-06-29T17:54:01.272Z] 17:54:01 CRITICAL - Task exception was never retrieved
[task 2022-06-29T17:54:01.272Z] 17:54:01 CRITICAL - future: <Task finished coro=<Transport.read_messages() done, defined at /builds/worker/workspace/build/tests/web-platform/tests/tools/webdriver/webdriver/bidi/transport.py:71> exception=InvalidStateError('invalid state',)>
[task 2022-06-29T17:54:01.273Z] 17:54:01 CRITICAL - Traceback (most recent call last):
[task 2022-06-29T17:54:01.273Z] 17:54:01 CRITICAL -   File "/builds/worker/workspace/build/tests/web-platform/tests/tools/webdriver/webdriver/bidi/transport.py", line 76, in read_messages
[task 2022-06-29T17:54:01.273Z] 17:54:01 CRITICAL -     await self.handle(msg)
[task 2022-06-29T17:54:01.274Z] 17:54:01 CRITICAL -   File "/builds/worker/workspace/build/tests/web-platform/tests/tools/webdriver/webdriver/bidi/transport.py", line 64, in handle
[task 2022-06-29T17:54:01.274Z] 17:54:01 CRITICAL -     await self.msg_handler(data)
[task 2022-06-29T17:54:01.275Z] 17:54:01 CRITICAL -   File "/builds/worker/workspace/build/tests/web-platform/tests/tools/webdriver/webdriver/bidi/client.py", line 187, in on_message
[task 2022-06-29T17:54:01.275Z] 17:54:01 CRITICAL -     future.set_exception(exception)
[task 2022-06-29T17:54:01.275Z] 17:54:01 CRITICAL - asyncio.base_futures.InvalidStateError: invalid state
[task 2022-06-29T17:54:01.320Z] 17:54:01     INFO - STDOUT:         url = inline(f"<img src='{script_url}?pipe=trickle(d10)'>")
<...>
[task 2022-06-29T17:54:01.337Z] 17:54:01     INFO -  'url': 'about:blank'}
[task 2022-06-29T17:54:01.338Z] 17:54:01     INFO - STDOUT: script_url = '/webdriver/tests/bidi/browsing_context/navigate/support/empty.svg'
[task 2022-06-29T17:54:01.339Z] 17:54:01     INFO - STDOUT: url        = 'http://web-platform.test:8000/webdriver/tests/support/inline.py?doc=%3C%21doctype+html%3E%0A%3Cmeta+charset%3DUTF-8%3E%0A%3Cimg+src%3D%27%2Fwebdriver%2Ftests%2Fbidi%2Fbrowsing_context%2Fnavigate%2Fsupport%2Fempty.svg%3Fpipe%3Dtrickle%28d10%29%27%3E&mime=text%2Fhtml&charset=UTF-8'
[task 2022-06-29T17:54:01.339Z] 17:54:01     INFO - STDOUT: wait       = 'complete'
[task 2022-06-29T17:54:01.340Z] 17:54:01     INFO - STDOUT: wait_for_navigation = <generator object wait_for at 0x7f5a3c175e60>
[task 2022-06-29T17:54:01.340Z] 17:54:01     INFO - STDOUT: tests/web-platform/tests/webdriver/tests/bidi/browsing_context/navigate/wait.py
[task 2022-06-29T17:54:01.341Z] 17:54:01     INFO - STDOUT: :52: AssertionError
[task 2022-06-29T17:54:01.341Z] 17:54:01     INFO - STDOUT: =========================== short test summary info ============================
[task 2022-06-29T17:54:01.342Z] 17:54:01     INFO - STDOUT: FAILED tests/web-platform/tests/webdriver/tests/bidi/browsing_context/navigate/wait.py::test_slow_image[complete-True]
[task 2022-06-29T17:54:01.342Z] 17:54:01     INFO - STDOUT: ======================== 1 failed, 11 passed in 15.50s =========================
[task 2022-06-29T17:54:01.343Z] 17:54:01     INFO - Closing logging queue
[task 2022-06-29T17:54:01.344Z] 17:54:01     INFO - queue closed
[task 2022-06-29T17:54:01.345Z] 17:54:01     INFO - Starting runner
[task 2022-06-29T17:54:01.346Z] 17:54:01     INFO - PID 7215 | 1656525241334	geckodriver	INFO	Listening on 127.0.0.1:44886
[task 2022-06-29T17:54:01.576Z] 17:54:01     INFO - TEST-START | /webdriver/tests/bidi/errors/errors.py
Status: NEW → RESOLVED
Closed: 3 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.