Closed
Bug 1838337
Opened 1 year ago
Closed 1 year ago
Intermittent [tier 2] /webdriver/tests/bidi/browsing_context/navigate/data_url.py | test_navigate_from_single_page[document to data:text] - setup error: webdriver.error.SessionNotCreatedException: session not created (500): Session is already started
Categories
(Remote Protocol :: WebDriver BiDi, defect, P5)
Remote Protocol
WebDriver BiDi
Tracking
(Not tracked)
RESOLVED
WORKSFORME
People
(Reporter: intermittent-bug-filer, Unassigned)
References
Details
(Keywords: intermittent-failure)
Filed by: sstanca [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer?job_id=419179298&repo=mozilla-beta
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/ZTqINvnuSoiGIPpED3hFkg/runs/0/artifacts/public/logs/live_backing.log
[task 2023-06-13T20:38:41.000Z] 20:38:41 INFO - TEST-PASS | /webdriver/tests/bidi/browsing_context/navigate/data_url.py | test_navigate_from_single_page[data:html to document]
[task 2023-06-13T20:38:41.000Z] 20:38:41 INFO - TEST-UNEXPECTED-ERROR | /webdriver/tests/bidi/browsing_context/navigate/data_url.py | test_navigate_from_single_page[document to data:text] - setup error: webdriver.error.SessionNotCreatedException: session not created (500): Session is already started
[task 2023-06-13T20:38:41.000Z] 20:38:41 INFO - event_loop = <ProactorEventLoop running=False closed=False debug=False>
[task 2023-06-13T20:38:41.000Z] 20:38:41 INFO - request = <SubRequest 'bidi_session' for <Function test_navigate_from_single_page[document to data:text]>>
[task 2023-06-13T20:38:41.001Z] 20:38:41 INFO - kwargs = {'capabilities': {}, 'configuration': {'browser': {'args': ['--profile', 'C:\\Users\\task_168668633882569\\AppData\\Lo...Users\\task_168668633882569\\AppData\\Local\\Temp\\tmp47cr0p7w.mozrunner']}}, 'host': '127.0.0.1', 'port': 55516, ...}}
[task 2023-06-13T20:38:41.001Z] 20:38:41 INFO - setup = <function _wrap_asyncgen.<locals>._asyncgen_fixture_wrapper.<locals>.setup at 0x0000026CEA7CA5E0>
[task 2023-06-13T20:38:41.001Z] 20:38:41 INFO - finalizer = <function _wrap_asyncgen.<locals>._asyncgen_fixture_wrapper.<locals>.finalizer at 0x0000026CEA7CA940>
[task 2023-06-13T20:38:41.001Z] 20:38:41 INFO -
[task 2023-06-13T20:38:41.001Z] 20:38:41 INFO - @functools.wraps(func)
[task 2023-06-13T20:38:41.001Z] 20:38:41 INFO - def _asyncgen_fixture_wrapper(
[task 2023-06-13T20:38:41.001Z] 20:38:41 INFO - event_loop: asyncio.AbstractEventLoop, request: SubRequest, **kwargs: Any
[task 2023-06-13T20:38:41.001Z] 20:38:41 INFO - ) -> _R:
[task 2023-06-13T20:38:41.001Z] 20:38:41 INFO - gen_obj = func(**_add_kwargs(func, kwargs, event_loop, request))
[task 2023-06-13T20:38:41.001Z] 20:38:41 INFO -
[task 2023-06-13T20:38:41.001Z] 20:38:41 INFO - async def setup() -> _R:
[task 2023-06-13T20:38:41.001Z] 20:38:41 INFO - res = await gen_obj.__anext__()
[task 2023-06-13T20:38:41.001Z] 20:38:41 INFO - return res
[task 2023-06-13T20:38:41.001Z] 20:38:41 INFO -
[task 2023-06-13T20:38:41.001Z] 20:38:41 INFO - def finalizer() -> None:
[task 2023-06-13T20:38:41.002Z] 20:38:41 INFO - """Yield again, to finalize."""
[task 2023-06-13T20:38:41.002Z] 20:38:41 INFO -
[task 2023-06-13T20:38:41.002Z] 20:38:41 INFO - async def async_finalizer() -> None:
[task 2023-06-13T20:38:41.002Z] 20:38:41 INFO - try:
[task 2023-06-13T20:38:41.002Z] 20:38:41 INFO - await gen_obj.__anext__()
[task 2023-06-13T20:38:41.002Z] 20:38:41 INFO - except StopAsyncIteration:
[task 2023-06-13T20:38:41.002Z] 20:38:41 INFO - pass
[task 2023-06-13T20:38:41.002Z] 20:38:41 INFO - else:
[task 2023-06-13T20:38:41.003Z] 20:38:41 INFO - msg = "Async generator fixture didn't stop."
[task 2023-06-13T20:38:41.003Z] 20:38:41 INFO - msg += "Yield only once."
[task 2023-06-13T20:38:41.003Z] 20:38:41 INFO - raise ValueError(msg)
[task 2023-06-13T20:38:41.003Z] 20:38:41 INFO -
[task 2023-06-13T20:38:41.003Z] 20:38:41 INFO - event_loop.run_until_complete(async_finalizer())
[task 2023-06-13T20:38:41.003Z] 20:38:41 INFO -
[task 2023-06-13T20:38:41.003Z] 20:38:41 INFO - > result = event_loop.run_until_complete(setup())
[task 2023-06-13T20:38:41.003Z] 20:38:41 INFO -
[task 2023-06-13T20:38:41.003Z] 20:38:41 INFO - event_loop = <ProactorEventLoop running=False closed=False debug=False>
[task 2023-06-13T20:38:41.003Z] 20:38:41 INFO - finalizer = <function _wrap_asyncgen.<locals>._asyncgen_fixture_wrapper.<locals>.finalizer at 0x0000026CEA7CA940>
[task 2023-06-13T20:38:41.003Z] 20:38:41 INFO - func = <function bidi_session at 0x0000026CEA008CA0>
[task 2023-06-13T20:38:41.003Z] 20:38:41 INFO - gen_obj = <async_generator object bidi_session at 0x0000026CEA7CAB80>
[task 2023-06-13T20:38:41.003Z] 20:38:41 INFO - kwargs = {'capabilities': {},
[task 2023-06-13T20:38:41.003Z] 20:38:41 INFO - 'configuration': {'browser': {'args': ['--profile',
[task 2023-06-13T20:38:41.004Z] 20:38:41 INFO - 'C:\\Users\\task_168668633882569\\AppData\\Local\\Temp\\tmp47cr0p7w.mozrunner'],
[task 2023-06-13T20:38:41.004Z] 20:38:41 INFO - 'binary': 'Z:\\task_168668633882569\\build\\application\\firefox\\firefox.exe'},
[task 2023-06-13T20:38:41.004Z] 20:38:41 INFO - 'capabilities': {'moz:firefoxOptions': {'args': ['--profile',
[task 2023-06-13T20:38:41.004Z] 20:38:41 INFO - 'C:\\Users\\task_168668633882569\\AppData\\Local\\Temp\\tmp47cr0p7w.mozrunner']}},
[task 2023-06-13T20:38:41.004Z] 20:38:41 INFO - 'host': '127.0.0.1',
[task 2023-06-13T20:38:41.004Z] 20:38:41 INFO - 'port': 55516,
[task 2023-06-13T20:38:41.004Z] 20:38:41 INFO - 'timeout_multiplier': 3,
[task 2023-06-13T20:38:41.004Z] 20:38:41 INFO - 'webdriver': {'args': ['-vv',
[task 2023-06-13T20:38:41.004Z] 20:38:41 INFO - '--binary',
[task 2023-06-13T20:38:41.004Z] 20:38:41 INFO - 'Z:\\task_168668633882569\\build\\application\\firefox\\firefox.exe'],
[task 2023-06-13T20:38:41.004Z] 20:38:41 INFO - 'binary': 'Z:\\task_168668633882569\\fetches\\geckodriver.exe'}}}
[task 2023-06-13T20:38:41.004Z] 20:38:41 INFO - request = <SubRequest 'bidi_session' for <Function test_navigate_from_single_page[document to data:text]>>
[task 2023-06-13T20:38:41.004Z] 20:38:41 INFO - setup = <function _wrap_asyncgen.<locals>._asyncgen_fixture_wrapper.<locals>.setup at 0x0000026CEA7CA5E0>
[task 2023-06-13T20:38:41.004Z] 20:38:41 INFO -
[task 2023-06-13T20:38:41.004Z] 20:38:41 INFO - tests\web-platform\tests\tools\third_party\pytest-asyncio\pytest_asyncio\plugin.py:293:
[task 2023-06-13T20:38:41.004Z] 20:38:41 INFO - _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _
[task 2023-06-13T20:38:41.004Z] 20:38:41 INFO - c:\mozilla-build\python3\lib\asyncio\base_events.py:642: in run_until_complete
[task 2023-06-13T20:38:41.004Z] 20:38:41 INFO - return future.result()
[task 2023-06-13T20:38:41.004Z] 20:38:41 INFO - future = <Task finished name='Task-887' coro=<_wrap_asyncgen.<locals>._asyncgen_fixture_wrapper.<locals>.setup() done, defined at Z:\task_168668633882569\build\tests\web-platform\tests\tools\third_party\pytest-asyncio\pytest_asyncio\plugin.py:274> exception=<SessionNotCreatedException http_status=500>>
[task 2023-06-13T20:38:41.004Z] 20:38:41 INFO - new_task = True
[task 2023-06-13T20:38:41.004Z] 20:38:41 INFO - self = <ProactorEventLoop running=False closed=False debug=False>
[task 2023-06-13T20:38:41.004Z] 20:38:41 INFO - tests\web-platform\tests\tools\third_party\pytest-asyncio\pytest_asyncio\plugin.py:275: in setup
[task 2023-06-13T20:38:41.005Z] 20:38:41 INFO - res = await gen_obj.__anext__()
[task 2023-06-13T20:38:41.005Z] 20:38:41 INFO - gen_obj = <async_generator object bidi_session at 0x0000026CEA7CAB80>
[task 2023-06-13T20:38:41.005Z] 20:38:41 INFO - tests\web-platform\tests\webdriver\tests\support\fixtures.py:183: in bidi_session
[task 2023-06-13T20:38:41.005Z] 20:38:41 INFO - _current_session.start()
[task 2023-06-13T20:38:41.005Z] 20:38:41 INFO - capabilities = {}
[task 2023-06-13T20:38:41.005Z] 20:38:41 INFO - caps = {'alwaysMatch': {'moz:firefoxOptions': {'args': ['--profile',
[task 2023-06-13T20:38:41.005Z] 20:38:41 INFO - 'C:\\Users\\task_168668633882569\\AppData\\Local\\Temp\\tmp47cr0p7w.mozrunner']},
[task 2023-06-13T20:38:41.005Z] 20:38:41 INFO - 'webSocketUrl': True}}
[task 2023-06-13T20:38:41.005Z] 20:38:41 INFO - configuration = {'browser': {'args': ['--profile',
[task 2023-06-13T20:38:41.006Z] 20:38:41 INFO - 'C:\\Users\\task_168668633882569\\AppData\\Local\\Temp\\tmp47cr0p7w.mozrunner'],
[task 2023-06-13T20:38:41.006Z] 20:38:41 INFO - 'binary': 'Z:\\task_168668633882569\\build\\application\\firefox\\firefox.exe'},
[task 2023-06-13T20:38:41.006Z] 20:38:41 INFO - 'capabilities': {'moz:firefoxOptions': {'args': ['--profile',
[task 2023-06-13T20:38:41.006Z] 20:38:41 INFO - 'C:\\Users\\task_168668633882569\\AppData\\Local\\Temp\\tmp47cr0p7w.mozrunner']}},
[task 2023-06-13T20:38:41.006Z] 20:38:41 INFO - 'host': '127.0.0.1',
[task 2023-06-13T20:38:41.006Z] 20:38:41 INFO - 'port': 55516,
[task 2023-06-13T20:38:41.006Z] 20:38:41 INFO - 'timeout_multiplier': 3,
[task 2023-06-13T20:38:41.006Z] 20:38:41 INFO - 'webdriver': {'args': ['-vv',
[task 2023-06-13T20:38:41.006Z] 20:38:41 INFO - '--binary',
[task 2023-06-13T20:38:41.006Z] 20:38:41 INFO - 'Z:\\task_168668633882569\\build\\application\\firefox\\firefox.exe'],
[task 2023-06-13T20:38:41.006Z] 20:38:41 INFO - 'binary': 'Z:\\task_168668633882569\\fetches\\geckodriver.exe'}}
[task 2023-06-13T20:38:41.006Z] 20:38:41 INFO - tests\web-platform\tests\tools\webdriver\webdriver\client.py:558: in start
[task 2023-06-13T20:38:41.006Z] 20:38:41 INFO - value = self.send_command("POST", "session", body=body)
[task 2023-06-13T20:38:41.006Z] 20:38:41 INFO - body = {'capabilities': {'alwaysMatch': {'moz:firefoxOptions': {'args': ['--profile',
[task 2023-06-13T20:38:41.007Z] 20:38:41 INFO - 'C:\\Users\\task_168668633882569\\AppData\\Local\\Temp\\tmp47cr0p7w.mozrunner']},
[task 2023-06-13T20:38:41.007Z] 20:38:41 INFO - 'webSocketUrl': True}}}
[task 2023-06-13T20:38:41.007Z] 20:38:41 INFO - self = <Session (disconnected)>
[task 2023-06-13T20:38:41.007Z] 20:38:41 INFO - _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _
[task 2023-06-13T20:38:41.007Z] 20:38:41 INFO -
[task 2023-06-13T20:38:41.007Z] 20:38:41 INFO - self = <Session (disconnected)>, method = 'POST', url = 'session'
[task 2023-06-13T20:38:41.007Z] 20:38:41 INFO - body = {'capabilities': {'alwaysMatch': {'moz:firefoxOptions': {'args': ['--profile', 'C:\\Users\\task_168668633882569\\AppData\\Local\\Temp\\tmp47cr0p7w.mozrunner']}, 'webSocketUrl': True}}}
[task 2023-06-13T20:38:41.007Z] 20:38:41 INFO - timeout = None
[task 2023-06-13T20:38:41.007Z] 20:38:41 INFO -
[task 2023-06-13T20:38:41.008Z] 20:38:41 INFO - def send_command(self, method, url, body=None, timeout=None):
[task 2023-06-13T20:38:41.008Z] 20:38:41 INFO - """
[task 2023-06-13T20:38:41.008Z] 20:38:41 INFO - Send a command to the remote end and validate its success.
[task 2023-06-13T20:38:41.008Z] 20:38:41 INFO -
[task 2023-06-13T20:38:41.008Z] 20:38:41 INFO - :param method: HTTP method to use in request.
[task 2023-06-13T20:38:41.008Z] 20:38:41 INFO - :param uri: "Command part" of the HTTP request URL,
[task 2023-06-13T20:38:41.008Z] 20:38:41 INFO - e.g. `window/rect`.
[task 2023-06-13T20:38:41.008Z] 20:38:41 INFO - :param body: Optional body of the HTTP request.
[task 2023-06-13T20:38:41.008Z] 20:38:41 INFO -
[task 2023-06-13T20:38:41.008Z] 20:38:41 INFO - :return: `None` if the HTTP response body was empty, otherwise
[task 2023-06-13T20:38:41.008Z] 20:38:41 INFO - the `value` field returned after parsing the response
[task 2023-06-13T20:38:41.008Z] 20:38:41 INFO - body as JSON.
[task 2023-06-13T20:38:41.008Z] 20:38:41 INFO -
[task 2023-06-13T20:38:41.008Z] 20:38:41 INFO - :raises error.WebDriverException: If the remote end returns
[task 2023-06-13T20:38:41.008Z] 20:38:41 INFO - an error.
[task 2023-06-13T20:38:41.008Z] 20:38:41 INFO - :raises ValueError: If the response body does not contain a
[task 2023-06-13T20:38:41.009Z] 20:38:41 INFO - `value` key.
[task 2023-06-13T20:38:41.009Z] 20:38:41 INFO - """
[task 2023-06-13T20:38:41.009Z] 20:38:41 INFO -
[task 2023-06-13T20:38:41.009Z] 20:38:41 INFO - response = self.transport.send(
[task 2023-06-13T20:38:41.009Z] 20:38:41 INFO - method, url, body,
[task 2023-06-13T20:38:41.009Z] 20:38:41 INFO - encoder=protocol.Encoder, decoder=protocol.Decoder,
[task 2023-06-13T20:38:41.009Z] 20:38:41 INFO - session=self, timeout=timeout)
[task 2023-06-13T20:38:41.009Z] 20:38:41 INFO -
[task 2023-06-13T20:38:41.009Z] 20:38:41 INFO - if response.status != 200:
[task 2023-06-13T20:38:41.009Z] 20:38:41 INFO - err = error.from_response(response)
[task 2023-06-13T20:38:41.009Z] 20:38:41 INFO -
[task 2023-06-13T20:38:41.009Z] 20:38:41 INFO - if isinstance(err, error.InvalidSessionIdException):
[task 2023-06-13T20:38:41.009Z] 20:38:41 INFO - # The driver could have already been deleted the session.
[task 2023-06-13T20:38:41.009Z] 20:38:41 INFO - self.session_id = None
[task 2023-06-13T20:38:41.009Z] 20:38:41 INFO -
[task 2023-06-13T20:38:41.009Z] 20:38:41 INFO - > raise err
[task 2023-06-13T20:38:41.009Z] 20:38:41 INFO - E webdriver.error.SessionNotCreatedException: session not created (500): Session is already started
[task 2023-06-13T20:38:41.009Z] 20:38:41 INFO -
[task 2023-06-13T20:38:41.010Z] 20:38:41 INFO - body = {'capabilities': {'alwaysMatch': {'moz:firefoxOptions': {'args': ['--profile',
[task 2023-06-13T20:38:41.010Z] 20:38:41 INFO - 'C:\\Users\\task_168668633882569\\AppData\\Local\\Temp\\tmp47cr0p7w.mozrunner']},
[task 2023-06-13T20:38:41.010Z] 20:38:41 INFO - 'webSocketUrl': True}}}
[task 2023-06-13T20:38:41.010Z] 20:38:41 INFO - err = <SessionNotCreatedException http_status=500>
[task 2023-06-13T20:38:41.010Z] 20:38:41 INFO - method = 'POST'
[task 2023-06-13T20:38:41.010Z] 20:38:41 INFO - response = <Response status=500 error=<SessionNotCreatedException http_status=500>>
[task 2023-06-13T20:38:41.010Z] 20:38:41 INFO - self = <Session (disconnected)>
[task 2023-06-13T20:38:41.010Z] 20:38:41 INFO - timeout = None
[task 2023-06-13T20:38:41.010Z] 20:38:41 INFO - url = 'session'
[task 2023-06-13T20:38:41.010Z] 20:38:41 INFO -
[task 2023-06-13T20:38:41.010Z] 20:38:41 INFO - tests\web-platform\tests\tools\webdriver\webdriver\client.py:622: SessionNotCreatedException
[task 2023-06-13T20:38:41.015Z] 20:38:41 INFO -
[task 2023-06-13T20:38:41.015Z] 20:38:41 INFO - TEST-UNEXPECTED-ERROR | /webdriver/tests/bidi/browsing_context/navigate/data_url.py | test_navigate_from_single_page[data:text to data:text] - setup error:
<...>
[task 2023-06-13T20:38:41.091Z] 20:38:41 INFO -
[task 2023-06-13T20:38:41.091Z] 20:38:41 INFO - tests\web-platform\tests\tools\webdriver\webdriver\client.py:622: SessionNotCreatedException
[task 2023-06-13T20:38:41.091Z] 20:38:41 INFO - PID 5260 | [Parent 8740, IPDL Background] WARNING: cache: '0.047000s: completed', file /builds/worker/checkouts/gecko/dom/quota/ActorsParent.cpp:3383
[task 2023-06-13T20:38:41.092Z] 20:38:41 INFO - PID 5260 | [Parent 8740, IPDL Background] WARNING: sdb: '0.047000s: completed', file /builds/worker/checkouts/gecko/dom/quota/ActorsParent.cpp:3383
[task 2023-06-13T20:38:41.092Z] 20:38:41 INFO - TEST-OK | /webdriver/tests/bidi/browsing_context/navigate/data_url.py | took 18214ms
|
||
Comment 1•1 year ago
|
||
There are problems visible for the IPC channel as used to communicate with the child process, and finally the content process crashed:
https://treeherder.mozilla.org/logviewer?job_id=419179298&repo=mozilla-beta&lineNumber=17734-17739
[task 2023-06-13T20:38:40.186Z] 20:38:40 INFO - PID 5260 | [1608, IPC I/O Child] WARNING: failed to create pipe: 2: file /builds/worker/checkouts/gecko/ipc/chromium/src/chrome/common/ipc_channel_win.cc:237
[task 2023-06-13T20:38:40.187Z] 20:38:40 INFO - PID 5260 | [1608, IPC I/O Child] WARNING: Unable to create pipe named "8740.18.1022662857\367089241" in client mode.: file /builds/worker/checkouts/gecko/ipc/chromium/src/chrome/common/ipc_channel_win.cc:55
[task 2023-06-13T20:38:40.188Z] 20:38:40 INFO - PID 5260 | [1608, IPC I/O Child] WARNING: Dropping message as channel has been closed: file /builds/worker/checkouts/gecko/ipc/glue/NodeChannel.cpp:209
[task 2023-06-13T20:38:40.194Z] 20:38:40 INFO - PID 5260 | Exiting due to channel error.
[task 2023-06-13T20:38:40.201Z] 20:38:40 INFO - PID 5260 | [Parent 8740, Main Thread] WARNING: content process pid = 1608 crashed without leaving a minidump behind: file /builds/worker/checkouts/gecko/dom/ipc/ContentParent.cpp:4486
[task 2023-06-13T20:38:40.205Z] 20:38:40 INFO - PID 5260 | A content process crashed and MOZ_CRASHREPORTER_SHUTDOWN is set, shutting down
Sadly no minidump file has been created. Gabriele, does that ring a bell? I cannot find any bug report for that.
Flags: needinfo?(gsvelto)
| Comment hidden (Intermittent Failures Robot) |
|
||
Comment 3•1 year ago
|
||
Looking at the logs here and in bug 1839187 this looks like it could be a very early crash where we fail to create a pipe for IPC during startup. Bug 1838906 has removed the affected code so chances are that this issue will go away.
Flags: needinfo?(gsvelto)
|
|
||
Comment 4•1 year ago
|
||
Thanks Gabriele! I'll check back on this bug in about 2 or 3 weeks to check if any other failure has been recorded. If not I'll close it as WFM.
Depends on: 1838906
|
|
||
Comment 5•1 year ago
|
||
This failure seems to be gone.
Status: NEW → RESOLVED
Closed: 1 year ago
Resolution: --- → WORKSFORME
You need to log in
before you can comment on or make changes to this bug.
Description
•