Open Bug 1837900 Opened 1 year ago Updated 1 year ago

Intermittent mozilla/tests/webdriver/bidi/session/<random> | <random> - setup error: json.decoder.JSONDecodeError: Expecting value: line 1 column 1 (char 0)

Categories

(Remote Protocol :: WebDriver BiDi, defect, P5)

defect

Tracking

(Not tracked)

People

(Reporter: intermittent-bug-filer, Unassigned)

References

Details

(Keywords: intermittent-failure)

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


[task 2023-06-12T01:25:22.465Z] 01:25:22     INFO - TEST-START | /_mozilla/webdriver/bidi/session/new/first_match.py
[task 2023-06-12T01:25:22.511Z] 01:25:22     INFO - STDOUT: ============================= test session starts ==============================
[task 2023-06-12T01:25:22.511Z] 01:25:22     INFO - STDOUT: platform linux -- Python 3.7.5, pytest-7.0.1, pluggy-unknown -- /builds/worker/workspace/build/venv/bin/python
[task 2023-06-12T01:25:22.512Z] 01:25:22     INFO - STDOUT: rootdir: /builds/worker/workspace/build
[task 2023-06-12T01:25:22.513Z] 01:25:22     INFO - STDOUT: plugins: asyncio-0.19.0
[task 2023-06-12T01:25:22.513Z] 01:25:22     INFO - STDOUT: asyncio: mode=strict
[task 2023-06-12T01:25:22.514Z] 01:25:22     INFO - STDOUT: collecting ... 
[task 2023-06-12T01:25:22.519Z] 01:25:22     INFO - STDOUT: collected 12 items
[task 2023-06-12T01:25:22.520Z] 01:25:22     INFO - STDOUT: tests/web-platform/mozilla/tests/webdriver/bidi/session/new/first_match.py::test_valid[acceptInsecureCerts-False] 
[task 2023-06-12T01:25:22.869Z] 01:25:22     INFO - STDOUT: ATTENTION: default value of option mesa_glthread overridden by environment.
[task 2023-06-12T01:25:22.880Z] 01:25:22     INFO - STDOUT: ATTENTION: default value of option mesa_glthread overridden by environment.
[task 2023-06-12T01:25:24.198Z] 01:25:24     INFO - STDOUT: 1686533124196	RemoteAgent	DEBUG	WebDriver BiDi enabled
[task 2023-06-12T01:25:24.199Z] 01:25:24     INFO - STDOUT: 1686533124197	RemoteAgent	DEBUG	CDP enabled
[task 2023-06-12T01:25:24.199Z] 01:25:24     INFO - STDOUT: 1686533124197	RemoteAgent	TRACE	Received observer notification final-ui-startup
[task 2023-06-12T01:25:24.311Z] 01:25:24     INFO - STDOUT: 1686533124309	RemoteAgent	TRACE	Available local IP addresses: 127.0.0.1, [::1]
[task 2023-06-12T01:25:24.315Z] 01:25:24     INFO - STDOUT: WebDriver BiDi listening on ws://127.0.0.1:35643
[task 2023-06-12T01:25:24.316Z] 01:25:24     INFO - STDOUT: 1686533124315	CDP	DEBUG	Waiting for initial application window
[task 2023-06-12T01:25:24.340Z] 01:25:24     INFO - STDOUT: console.error: (new Error("Unexpected content-type \"text/plain;charset=US-ASCII\"", "resource://services-settings/Utils.sys.mjs", 399))
[task 2023-06-12T01:25:24.340Z] 01:25:24     INFO - STDOUT: console.error: (new Error("Unexpected content-type \"text/plain;charset=US-ASCII\"", "resource://services-settings/Utils.sys.mjs", 399))
[task 2023-06-12T01:25:24.460Z] 01:25:24     INFO - STDOUT: 1686533124458	RemoteAgent	INFO	Perform WebSocket upgrade for incoming connection from 127.0.0.1:53744
[task 2023-06-12T01:25:24.555Z] 01:25:24     INFO - STDOUT: 1686533124553	RemoteAgent	DEBUG	WebDriverBiDiConnection fbac2f30-41df-4822-b01f-9b58de4162e7 accepted
[task 2023-06-12T01:25:24.556Z] 01:25:24     INFO - STDOUT: 1686533124554	RemoteAgent	DEBUG	WebDriverBiDiConnection fbac2f30-41df-4822-b01f-9b58de4162e7 -> {"id":1,"method":"session.new","params":{"capabilities":{"firstMatch":[{"moz:firefoxOptions":{"args":["--profile","/tmp/tmpet91rx8j.mozrunner"]},"acceptInsecureCerts":false}]}}}
[task 2023-06-12T01:25:24.561Z] 01:25:24     INFO - STDOUT: 1686533124560	WebDriver BiDi	DEBUG	Connection fbac2f30-41df-4822-b01f-9b58de4162e7 attached to session 4a1db6f7-da46-4f01-ac5c-f8897a438713
[task 2023-06-12T01:25:24.561Z] 01:25:24     INFO - STDOUT: 1686533124560	WebDriver BiDi	DEBUG	Waiting for initial application window
[task 2023-06-12T01:25:24.888Z] 01:25:24     INFO - STDOUT: console.error: (new Error("Unexpected content-type \"text/plain;charset=US-ASCII\"", "resource://services-settings/Utils.sys.mjs", 399))
[task 2023-06-12T01:25:26.604Z] 01:25:26     INFO - STDOUT: console.error: ({})
[task 2023-06-12T01:25:26.729Z] 01:25:26     INFO - STDOUT: console.error: (new Error("Unexpected content-type \"text/plain;charset=US-ASCII\"", "resource://services-settings/Utils.sys.mjs", 399))
[task 2023-06-12T01:25:26.762Z] 01:25:26     INFO - STDOUT: console.error: (new Error("Unexpected content-type \"text/plain;charset=US-ASCII\"", "resource://services-settings/Utils.sys.mjs", 399))
[task 2023-06-12T01:25:26.764Z] 01:25:26     INFO - STDOUT: console.error: (new Error("Unexpected content-type \"text/plain;charset=US-ASCII\"", "resource://services-settings/Utils.sys.mjs", 399))
[task 2023-06-12T01:25:26.806Z] 01:25:26     INFO - STDOUT: console.error: (new Error("Unexpected content-type \"text/plain;charset=US-ASCII\"", "resource://services-settings/Utils.sys.mjs", 399))
[task 2023-06-12T01:25:26.864Z] 01:25:26     INFO - STDOUT: console.error: (new Error("Unexpected content-type \"text/plain;charset=US-ASCII\"", "resource://services-settings/Utils.sys.mjs", 399))
[task 2023-06-12T01:25:26.979Z] 01:25:26     INFO - STDOUT: console.error: (new Error("Unexpected content-type \"text/plain;charset=US-ASCII\"", "resource://services-settings/Utils.sys.mjs", 399))
[task 2023-06-12T01:25:27.163Z] 01:25:27     INFO - STDOUT: console.error: (new Error("Unexpected content-type \"text/plain;charset=US-ASCII\"", "resource://services-settings/Utils.sys.mjs", 399))
[task 2023-06-12T01:25:27.411Z] 01:25:27     INFO - STDOUT: console.error: (new Error("Unexpected content-type \"text/plain;charset=US-ASCII\"", "resource://services-settings/Utils.sys.mjs", 399))
[task 2023-06-12T01:25:27.413Z] 01:25:27     INFO - STDOUT: console.error: (new Error("Unexpected content-type \"text/plain;charset=US-ASCII\"", "resource://services-settings/Utils.sys.mjs", 399))
[task 2023-06-12T01:25:27.415Z] 01:25:27     INFO - STDOUT: console.error: (new Error("Unexpected content-type \"text/plain;charset=US-ASCII\"", "resource://services-settings/Utils.sys.mjs", 399))
[task 2023-06-12T01:25:27.593Z] 01:25:27     INFO - STDOUT: 1686533127592	RemoteAgent	TRACE	Received observer notification browser-idle-startup-tasks-finished
[task 2023-06-12T01:25:27.608Z] 01:25:27     INFO - STDOUT: 1686533127607	WebDriver BiDi	DEBUG	Registered session handler: /session/4a1db6f7-da46-4f01-ac5c-f8897a438713
[task 2023-06-12T01:25:27.612Z] 01:25:27     INFO - STDOUT: PASSED
<...>
[task 2023-06-12T01:26:16.594Z] 01:26:16     INFO - STDOUT:         keep_browser = False
[task 2023-06-12T01:26:16.595Z] 01:26:16     INFO - STDOUT:         keep_browser_open = False
[task 2023-06-12T01:26:16.595Z] 01:26:16     INFO - STDOUT:         server_host = None
[task 2023-06-12T01:26:16.596Z] 01:26:16     INFO - STDOUT:         server_port = None
[task 2023-06-12T01:26:16.596Z] 01:26:16     INFO - STDOUT: tests/web-platform/tests/tools/webdriver/webdriver/bidi/client.py
[task 2023-06-12T01:26:16.597Z] 01:26:16     INFO - STDOUT: :145: in start
[task 2023-06-12T01:26:16.597Z] 01:26:16     INFO - STDOUT:     await self.transport.start()
[task 2023-06-12T01:26:16.598Z] 01:26:16     INFO - STDOUT:         loop       = <_UnixSelectorEventLoop running=False closed=False debug=False>
[task 2023-06-12T01:26:16.598Z] 01:26:16     INFO - STDOUT:         self       = <webdriver.bidi.client.BidiSession object at 0x7f7148421f10>
[task 2023-06-12T01:26:16.599Z] 01:26:16     INFO - STDOUT: tests/web-platform/tests/tools/webdriver/webdriver/bidi/transport.py
[task 2023-06-12T01:26:16.599Z] 01:26:16     INFO - STDOUT: :40: in start
[task 2023-06-12T01:26:16.600Z] 01:26:16     INFO - STDOUT:     self.connection = await websockets.connect(self.url)  # type: ignore
[task 2023-06-12T01:26:16.600Z] 01:26:16     INFO - STDOUT:         self       = <webdriver.bidi.transport.Transport object at 0x7f7148421310>
[task 2023-06-12T01:26:16.601Z] 01:26:16     INFO - STDOUT: tests/web-platform/tests/tools/third_party/websockets/src/websockets/client.py
[task 2023-06-12T01:26:16.602Z] 01:26:16     INFO - STDOUT: :415: in __init__
[task 2023-06-12T01:26:16.602Z] 01:26:16     INFO - STDOUT:     wsuri = parse_uri(uri)
[task 2023-06-12T01:26:16.602Z] 01:26:16     INFO - STDOUT:         close_timeout = 10
[task 2023-06-12T01:26:16.603Z] 01:26:16     INFO - STDOUT:         compression = 'deflate'
[task 2023-06-12T01:26:16.603Z] 01:26:16     INFO - STDOUT:         create_protocol = <class 'websockets.client.WebSocketClientProtocol'>
[task 2023-06-12T01:26:16.604Z] 01:26:16     INFO - STDOUT:         extensions = None
[task 2023-06-12T01:26:16.605Z] 01:26:16     INFO - STDOUT:         extra_headers = None
[task 2023-06-12T01:26:16.606Z] 01:26:16     INFO - STDOUT:         klass      = <class 'websockets.client.WebSocketClientProtocol'>
[task 2023-06-12T01:26:16.606Z] 01:26:16     INFO - STDOUT:         kwargs     = {}
[task 2023-06-12T01:26:16.606Z] 01:26:16     INFO - STDOUT:         legacy_recv = False
[task 2023-06-12T01:26:16.607Z] 01:26:16     INFO - STDOUT:         loop       = <_UnixSelectorEventLoop running=False closed=False debug=False>
[task 2023-06-12T01:26:16.607Z] 01:26:16     INFO - STDOUT:         max_queue  = 32
[task 2023-06-12T01:26:16.608Z] 01:26:16     INFO - STDOUT:         max_size   = 1048576
[task 2023-06-12T01:26:16.608Z] 01:26:16     INFO - STDOUT:         origin     = None
[task 2023-06-12T01:26:16.609Z] 01:26:16     INFO - STDOUT:         path       = None
[task 2023-06-12T01:26:16.610Z] 01:26:16     INFO - STDOUT:         ping_interval = 20
[task 2023-06-12T01:26:16.610Z] 01:26:16     INFO - STDOUT:         ping_timeout = 20
[task 2023-06-12T01:26:16.611Z] 01:26:16     INFO - STDOUT:         read_limit = 65536
[task 2023-06-12T01:26:16.611Z] 01:26:16     INFO - STDOUT:         self       = <websockets.client.Connect object at 0x7f7148421390>
[task 2023-06-12T01:26:16.612Z] 01:26:16     INFO - STDOUT:         subprotocols = None
[task 2023-06-12T01:26:16.613Z] 01:26:16     INFO - STDOUT:         timeout    = 10
[task 2023-06-12T01:26:16.613Z] 01:26:16     INFO - STDOUT:         uri        = 'ws://None:None/session'
[task 2023-06-12T01:26:16.614Z] 01:26:16     INFO - STDOUT:         write_limit = 65536
[task 2023-06-12T01:26:16.614Z] 01:26:16     INFO - STDOUT: tests/web-platform/tests/tools/third_party/websockets/src/websockets/uri.py
[task 2023-06-12T01:26:16.615Z] 01:26:16     INFO - STDOUT: :70: in parse_uri
[task 2023-06-12T01:26:16.615Z] 01:26:16     INFO - STDOUT:     port = parsed.port or (443 if secure else 80)
[task 2023-06-12T01:26:16.616Z] 01:26:16     INFO - STDOUT:         host       = 'none'
[task 2023-06-12T01:26:16.617Z] 01:26:16     INFO - STDOUT:         parsed     = ParseResult(scheme='ws', netloc='None:None', path='/session', params='', query='', fragment='')
[task 2023-06-12T01:26:16.617Z] 01:26:16     INFO - STDOUT:         secure     = False
[task 2023-06-12T01:26:16.618Z] 01:26:16     INFO - STDOUT:         uri        = 'ws://None:None/session'
[task 2023-06-12T01:26:16.618Z] 01:26:16     INFO - STDOUT: _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 
[task 2023-06-12T01:26:16.619Z] 01:26:16     INFO - STDOUT: self = ParseResult(scheme='ws', netloc='None:None', path='/session', params='', query='', fragment='')
[task 2023-06-12T01:26:16.620Z] 01:26:16     INFO - STDOUT:     @property
[task 2023-06-12T01:26:16.620Z] 01:26:16     INFO - STDOUT:     def port(self):
[task 2023-06-12T01:26:16.621Z] 01:26:16     INFO - STDOUT:         port = self._hostinfo[1]
[task 2023-06-12T01:26:16.621Z] 01:26:16     INFO - STDOUT:         if port is not None:
[task 2023-06-12T01:26:16.622Z] 01:26:16     INFO - STDOUT: >           port = int(port, 10)
[task 2023-06-12T01:26:16.622Z] 01:26:16     INFO - STDOUT: E           ValueError: invalid literal for int() with base 10: 'None'
[task 2023-06-12T01:26:16.623Z] 01:26:16     INFO - STDOUT: port       = 'None'
[task 2023-06-12T01:26:16.624Z] 01:26:16     INFO - STDOUT: self       = ParseResult(scheme='ws', netloc='None:None', path='/session', params='', query='', fragment='')
[task 2023-06-12T01:26:16.624Z] 01:26:16     INFO - STDOUT: /usr/lib/python3.7/urllib/parse.py
[task 2023-06-12T01:26:16.625Z] 01:26:16     INFO - STDOUT: :169: ValueError
[task 2023-06-12T01:26:16.625Z] 01:26:16     INFO - STDOUT: =========================== short test summary info ============================
[task 2023-06-12T01:26:16.626Z] 01:26:16     INFO - STDOUT: FAILED tests/web-platform/mozilla/tests/webdriver/bidi/session/new/first_match.py::test_valid[test:extension-None]
[task 2023-06-12T01:26:16.627Z] 01:26:16     INFO - STDOUT: ERROR tests/web-platform/mozilla/tests/webdriver/bidi/session/new/first_match.py::test_valid[proxy-None]
[task 2023-06-12T01:26:16.627Z] 01:26:16     INFO - STDOUT: ==================== 1 failed, 10 passed, 1 error in 53.99s ====================
[task 2023-06-12T01:26:16.648Z] 01:26:16     INFO - 
[task 2023-06-12T01:26:16.648Z] 01:26:16     INFO - TEST-PASS | /_mozilla/webdriver/bidi/session/new/first_match.py | test_valid[acceptInsecureCerts-False] 
[task 2023-06-12T01:26:16.648Z] 01:26:16     INFO - TEST-PASS | /_mozilla/webdriver/bidi/session/new/first_match.py | test_valid[acceptInsecureCerts-None] 
[task 2023-06-12T01:26:16.648Z] 01:26:16     INFO - TEST-PASS | /_mozilla/webdriver/bidi/session/new/first_match.py | test_valid[browserName-None] 
[task 2023-06-12T01:26:16.648Z] 01:26:16     INFO - TEST-PASS | /_mozilla/webdriver/bidi/session/new/first_match.py | test_valid[browserVersion-None] 
[task 2023-06-12T01:26:16.649Z] 01:26:16     INFO - TEST-PASS | /_mozilla/webdriver/bidi/session/new/first_match.py | test_valid[platformName-None] 
[task 2023-06-12T01:26:16.649Z] 01:26:16     INFO - TEST-UNEXPECTED-ERROR | /_mozilla/webdriver/bidi/session/new/first_match.py | test_valid[proxy-None] - setup error: json.decoder.JSONDecodeError: Expecting value: line 1 column 1 (char 0)
[task 2023-06-12T01:26:16.649Z] 01:26:16     INFO - event_loop = <_UnixSelectorEventLoop running=False closed=False debug=False>
[task 2023-06-12T01:26:16.649Z] 01:26:16     INFO - request = <SubRequest 'new_session' for <Function test_valid[proxy-None]>>
[task 2023-06-12T01:26:16.649Z] 01:26:16     INFO - kwargs = {'browser': <function browser.<locals>._browser at 0x7f71487b6dd0>}
[task 2023-06-12T01:26:16.649Z] 01:26:16     INFO - setup = <function _wrap_asyncgen.<locals>._asyncgen_fixture_wrapper.<locals>.setup at 0x7f714852bdd0>
[task 2023-06-12T01:26:16.649Z] 01:26:16     INFO - finalizer = <function _wrap_asyncgen.<locals>._asyncgen_fixture_wrapper.<locals>.finalizer at 0x7f714852b440>
[task 2023-06-12T01:26:16.649Z] 01:26:16     INFO - 
[task 2023-06-12T01:26:16.649Z] 01:26:16     INFO -     @functools.wraps(func)
[task 2023-06-12T01:26:16.649Z] 01:26:16     INFO -     def _asyncgen_fixture_wrapper(
[task 2023-06-12T01:26:16.649Z] 01:26:16     INFO -         event_loop: asyncio.AbstractEventLoop, request: SubRequest, **kwargs: Any
[task 2023-06-12T01:26:16.650Z] 01:26:16     INFO -     ) -> _R:
[task 2023-06-12T01:26:16.650Z] 01:26:16     INFO -         gen_obj = func(**_add_kwargs(func, kwargs, event_loop, request))
[task 2023-06-12T01:26:16.650Z] 01:26:16     INFO -     
[task 2023-06-12T01:26:16.650Z] 01:26:16     INFO -         async def setup() -> _R:
[task 2023-06-12T01:26:16.650Z] 01:26:16     INFO -             res = await gen_obj.__anext__()
[task 2023-06-12T01:26:16.650Z] 01:26:16     INFO -             return res
[task 2023-06-12T01:26:16.650Z] 01:26:16     INFO -     
[task 2023-06-12T01:26:16.650Z] 01:26:16     INFO -         def finalizer() -> None:
[task 2023-06-12T01:26:16.650Z] 01:26:16     INFO -             """Yield again, to finalize."""
[task 2023-06-12T01:26:16.650Z] 01:26:16     INFO -     
[task 2023-06-12T01:26:16.650Z] 01:26:16     INFO -             async def async_finalizer() -> None:
[task 2023-06-12T01:26:16.651Z] 01:26:16     INFO -                 try:
[task 2023-06-12T01:26:16.651Z] 01:26:16     INFO -                     await gen_obj.__anext__()
[task 2023-06-12T01:26:16.651Z] 01:26:16     INFO -                 except StopAsyncIteration:
[task 2023-06-12T01:26:16.651Z] 01:26:16     INFO -                     pass
[task 2023-06-12T01:26:16.651Z] 01:26:16     INFO -                 else:
[task 2023-06-12T01:26:16.651Z] 01:26:16     INFO -                     msg = "Async generator fixture didn't stop."
[task 2023-06-12T01:26:16.651Z] 01:26:16     INFO -                     msg += "Yield only once."
[task 2023-06-12T01:26:16.651Z] 01:26:16     INFO -                     raise ValueError(msg)
[task 2023-06-12T01:26:16.652Z] 01:26:16     INFO -     
[task 2023-06-12T01:26:16.652Z] 01:26:16     INFO -             event_loop.run_until_complete(async_finalizer())
[task 2023-06-12T01:26:16.652Z] 01:26:16     INFO -     
[task 2023-06-12T01:26:16.652Z] 01:26:16     INFO - >       result = event_loop.run_until_complete(setup())
[task 2023-06-12T01:26:16.652Z] 01:26:16     INFO - 
[task 2023-06-12T01:26:16.652Z] 01:26:16     INFO - event_loop = <_UnixSelectorEventLoop running=False closed=False debug=False>
[task 2023-06-12T01:26:16.652Z] 01:26:16     INFO - finalizer  = <function _wrap_asyncgen.<locals>._asyncgen_fixture_wrapper.<locals>.finalizer at 0x7f714852b440>
[task 2023-06-12T01:26:16.652Z] 01:26:16     INFO - func       = <function new_session at 0x7f714a073290>
[task 2023-06-12T01:26:16.652Z] 01:26:16     INFO - gen_obj    = <async_generator object new_session at 0x7f714852b680>
[task 2023-06-12T01:26:16.652Z] 01:26:16     INFO - kwargs     = {'browser': <function browser.<locals>._browser at 0x7f71487b6dd0>}
[task 2023-06-12T01:26:16.653Z] 01:26:16     INFO - request    = <SubRequest 'new_session' for <Function test_valid[proxy-None]>>
[task 2023-06-12T01:26:16.653Z] 01:26:16     INFO - setup      = <function _wrap_asyncgen.<locals>._asyncgen_fixture_wrapper.<locals>.setup at 0x7f714852bdd0>
[task 2023-06-12T01:26:16.653Z] 01:26:16     INFO - 
[task 2023-06-12T01:26:16.653Z] 01:26:16     INFO - tests/web-platform/tests/tools/third_party/pytest-asyncio/pytest_asyncio/plugin.py:293: 

Sadly it's not clear what's happening here. This is not much detail in the log to see what actually was failing or has been returned:
https://treeherder.mozilla.org/logviewer?job_id=418921100&repo=autoland&lineNumber=165459-165468

Note that this is a new test as introduced by the landing of the patches on bug 1731730.

Depends on: 1731730
Summary: Intermittent mozilla/tests/webdriver/bidi/session/new/first_match.py | test_valid[proxy-None] - setup error: json.decoder.JSONDecodeError: Expecting value: line 1 column 1 (char 0) → Intermittent mozilla/tests/webdriver/bidi/session/new/<random> | <random> - setup error: json.decoder.JSONDecodeError: Expecting value: line 1 column 1 (char 0)
Duplicate of this bug: 1838474
Summary: Intermittent mozilla/tests/webdriver/bidi/session/new/<random> | <random> - setup error: json.decoder.JSONDecodeError: Expecting value: line 1 column 1 (char 0) → Intermittent mozilla/tests/webdriver/bidi/session/<random> | <random> - setup error: json.decoder.JSONDecodeError: Expecting value: line 1 column 1 (char 0)
Duplicate of this bug: 1846175
You need to log in before you can comment on or make changes to this bug.