Closed
Bug 1872146
Opened 2 years ago
Closed 2 years ago
Intermittent [tier 2] TEST-UNEXPECTED-ERROR | /webdriver/tests/bidi/browsing_context/navigate/about_blank.py | test_navigate_from_frameset - 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
INCOMPLETE
People
(Reporter: intermittent-bug-filer, Unassigned)
References
Details
(Keywords: intermittent-failure, intermittent-testcase)
Filed by: imoraru [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer?job_id=441462365&repo=mozilla-central
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/EcfBzGyoROu3TOcOyD78yQ/runs/0/artifacts/public/logs/live_backing.log
[task 2023-12-27T10:45:00.974Z] 10:45:00 INFO - STDOUT: PASSED
[task 2023-12-27T10:45:00.991Z] 10:45:00 INFO - PID 5148 | 1703673901002 RemoteAgent TRACE MessageHandler WINDOW_GLOBAL for session 5da7fd5c-ba14-40d3-bd24-fb6f6eb6a23b is being destroyed
[task 2023-12-27T10:45:01.004Z] 10:45:01 INFO - PID 5148 | 1703673901003 RemoteAgent TRACE Unregistered MessageHandler WINDOW_GLOBAL for session 5da7fd5c-ba14-40d3-bd24-fb6f6eb6a23b
[task 2023-12-27T10:45:01.010Z] 10:45:01 INFO - PID 5148 | 1703673901009 RemoteAgent DEBUG Resetting recommended pref browser.contentblocking.features.standard
[task 2023-12-27T10:45:01.010Z] 10:45:01 INFO - PID 5148 | 1703673901009 RemoteAgent DEBUG Resetting recommended pref network.cookie.cookieBehavior
[task 2023-12-27T10:45:01.011Z] 10:45:01 INFO - PID 5148 | 1703673901010 RemoteAgent DEBUG WebDriverBiDiConnection f80183ff-2237-46f6-a00d-aa9ea6f8cbb3 -> {"id":6,"method":"browsingContext.close","params":{"context":"290fe7eb-175a-4d83-940e-79152f622fcc"}}
[task 2023-12-27T10:45:01.012Z] 10:45:01 INFO - PID 5148 | 1703673901010 RemoteAgent TRACE Module root/browsingContext.sys.mjs found for ROOT
[task 2023-12-27T10:45:01.014Z] 10:45:01 INFO - PID 5148 | 1703673901010 RemoteAgent TRACE Received command browsingContext.close for destination ROOT
[task 2023-12-27T10:45:01.014Z] 10:45:01 INFO - PID 5148 | 1703673901010 RemoteAgent TRACE Module root/browsingContext.sys.mjs found for ROOT
[task 2023-12-27T10:45:01.016Z] 10:45:01 INFO - PID 5148 | 1703673901011 RemoteAgent DEBUG WebDriverBiDiConnection f80183ff-2237-46f6-a00d-aa9ea6f8cbb3 <- {"type":"error","id":6,"error":"no such frame","message":"Browsing Context with id 290fe7eb-175a-4d83-940e-79152f622fcc not found","stacktrace":"RemoteError@chrome://remote/content/shared/RemoteError.sys.mjs:8:8\nWebDriverError@chrome://remote/content/shared/webdriver/Er ... ontent/server/WebSocketTransport.sys.mjs:127:18\nhandleEvent@chrome://remote/content/server/WebSocketTransport.sys.mjs:109:14\n"}
[task 2023-12-27T10:45:01.017Z] 10:45:01 INFO - STDOUT: Tab with id 290fe7eb-175a-4d83-940e-79152f622fcc has already been closed
[task 2023-12-27T10:45:01.022Z] 10:45:01 INFO - PID 5148 | 1703673901021 WebDriver BiDi DEBUG Unregistered session handler: /session/5da7fd5c-ba14-40d3-bd24-fb6f6eb6a23b
[task 2023-12-27T10:45:01.023Z] 10:45:01 INFO - PID 5148 | 1703673901022 RemoteAgent DEBUG WebDriverBiDiConnection f80183ff-2237-46f6-a00d-aa9ea6f8cbb3 closed
[task 2023-12-27T10:45:01.025Z] 10:45:01 INFO - PID 5148 | 1703673901024 RemoteAgent TRACE MessageHandler ROOT for session 5da7fd5c-ba14-40d3-bd24-fb6f6eb6a23b is being destroyed
[task 2023-12-27T10:45:01.026Z] 10:45:01 INFO - PID 5148 | 1703673901024 RemoteAgent TRACE Unregistered MessageHandler ROOT for session 5da7fd5c-ba14-40d3-bd24-fb6f6eb6a23b
[task 2023-12-27T10:45:01.034Z] 10:45:01 INFO - PID 5148 | 1703673901032 webdriver::server DEBUG -> POST /session/5da7fd5c-ba14-40d3-bd24-fb6f6eb6a23b/timeouts {"implicit": 0}
[task 2023-12-27T10:45:01.037Z] 10:45:01 INFO - PID 5148 | 1703673901036 Marionette DEBUG 0 -> [0,4,"WebDriver:SetTimeouts",{"implicit":0}]
[task 2023-12-27T10:45:01.038Z] 10:45:01 INFO - PID 5148 | 1703673901037 Marionette DEBUG 0 <- [1,4,{"error":"invalid session id","message":"WebDriver session does not exist, or is not active","stacktrace":"RemoteError@chrome://remote/content/shared/RemoteError.sys.mjs:8:8\nWebDriverError@chrome://remote/content/shared/webdriver/Er ... ote/content/marionette/server.sys.mjs:263:9\n_onJSONObjectReady/<@chrome://remote/content/marionette/transport.sys.mjs:494:20\n"},null]
[task 2023-12-27T10:45:01.040Z] 10:45:01 INFO - PID 5148 | 1703673901038 webdriver::server DEBUG <- 404 Not Found {"value":{"error":"invalid session id","message":"WebDriver session does not exist, or is not active","stack ... ontent/marionette/server.sys.mjs:263:9\n_onJSONObjectReady/<@chrome://remote/content/marionette/transport.sys.mjs:494:20\n"}}
[task 2023-12-27T10:45:01.041Z] 10:45:01 INFO - STDERR: Ignored exception invalid session id (404): WebDriver session does not exist, or is not active
[task 2023-12-27T10:45:01.041Z] 10:45:01 INFO -
[task 2023-12-27T10:45:01.041Z] 10:45:01 INFO - Remote-end stacktrace:
[task 2023-12-27T10:45:01.041Z] 10:45:01 INFO -
[task 2023-12-27T10:45:01.043Z] 10:45:01 INFO - RemoteError@chrome://remote/content/shared/RemoteError.sys.mjs:8:8
[task 2023-12-27T10:45:01.043Z] 10:45:01 INFO - WebDriverError@chrome://remote/content/shared/webdriver/Errors.sys.mjs:191:5
[task 2023-12-27T10:45:01.043Z] 10:45:01 INFO - InvalidSessionIDError@chrome://remote/content/shared/webdriver/Errors.sys.mjs:446:5
[task 2023-12-27T10:45:01.043Z] 10:45:01 INFO - assert.that/<@chrome://remote/content/shared/webdriver/Assert.sys.mjs:485:13
[task 2023-12-27T10:45:01.043Z] 10:45:01 INFO - assert.session@chrome://remote/content/shared/webdriver/Assert.sys.mjs:37:4
[task 2023-12-27T10:45:01.043Z] 10:45:01 INFO - despatch@chrome://remote/content/marionette/server.sys.mjs:315:19
[task 2023-12-27T10:45:01.043Z] 10:45:01 INFO - execute@chrome://remote/content/marionette/server.sys.mjs:289:16
[task 2023-12-27T10:45:01.044Z] 10:45:01 INFO - onPacket/<@chrome://remote/content/marionette/server.sys.mjs:262:20
[task 2023-12-27T10:45:01.044Z] 10:45:01 INFO - onPacket@chrome://remote/content/marionette/server.sys.mjs:263:9
[task 2023-12-27T10:45:01.044Z] 10:45:01 INFO - _onJSONObjectReady/<@chrome://remote/content/marionette/transport.sys.mjs:494:20
[task 2023-12-27T10:45:01.044Z] 10:45:01 INFO - PID 5148 | 1703673901040 webdriver::server DEBUG -> POST /session {"capabilities": {"alwaysMatch": {"moz:firefoxOptions": {"args": ["--profile", "C:\\Users\\task_170367334341 ... stderr", "R_LOG_VERBOSE": "1", "NSS_MAX_MP_PBE_ITERATION_COUNT": "10", "MOZ_WINDOW_OCCLUSION": "0"}}, "webSocketUrl": true}}}
[task 2023-12-27T10:45:01.046Z] 10:45:01 INFO - PID 5148 | 1703673901041 webdriver::server DEBUG <- 500 Internal Server Error {"value":{"error":"session not created","message":"Session is already started","stacktrace":""}}
[task 2023-12-27T10:45:01.046Z] 10:45:01 INFO - STDERR: Ignored exception session not created (500): Session is already started
[task 2023-12-27T10:45:01.046Z] 10:45:01 INFO - PID 5148 | 1703673901042 webdriver::server DEBUG -> POST /session {"capabilities": {"alwaysMatch": {"moz:firefoxOptions": {"args": ["--profile", "C:\\Users\\task_170367334341 ... stderr", "R_LOG_VERBOSE": "1", "NSS_MAX_MP_PBE_ITERATION_COUNT": "10", "MOZ_WINDOW_OCCLUSION": "0"}}, "webSocketUrl": true}}}
[task 2023-12-27T10:45:01.046Z] 10:45:01 INFO - PID 5148 | 1703673901043 webdriver::server DEBUG <- 500 Internal Server Error {"value":{"error":"session not created","message":"Session is already started","stacktrace":""}}
[task 2023-12-27T10:45:01.050Z] 10:45:01 INFO - STDERR: Ignored exception session not created (500): Session is already started
[task 2023-12-27T10:45:01.051Z] 10:45:01 INFO - PID 5148 | 1703673901045 webdriver::server DEBUG -> POST /session {"capabilities": {"alwaysMatch": {"moz:firefoxOptions": {"args": ["--profile", "C:\\Users\\task_170367334341 ... stderr", "R_LOG_VERBOSE": "1", "NSS_MAX_MP_PBE_ITERATION_COUNT": "10", "MOZ_WINDOW_OCCLUSION": "0"}}, "webSocketUrl": true}}}
[task 2023-12-27T10:45:01.052Z] 10:45:01 INFO - PID 5148 | 1703673901045 webdriver::server DEBUG <- 500 Internal Server Error {"value":{"error":"session not created","message":"Session is already started","stacktrace":""}}
[task 2023-12-27T10:45:01.053Z] 10:45:01 INFO - STDERR: Ignored exception session not created (500): Session is already started
[task 2023-12-27T10:45:01.054Z] 10:45:01 INFO - PID 5148 | 1703673901046 webdriver::server DEBUG -> POST /session {"capabilities": {"alwaysMatch": {"moz:firefoxOptions": {"args": ["--profile", "C:\\Users\\task_170367334341 ... stderr", "R_LOG_VERBOSE": "1", "NSS_MAX_MP_PBE_ITERATION_COUNT": "10", "MOZ_WINDOW_OCCLUSION": "0"}}, "webSocketUrl": true}}}
[task 2023-12-27T10:45:01.055Z] 10:45:01 INFO - PID 5148 | 1703673901047 webdriver::server DEBUG <- 500 Internal Server Error {"value":{"error":"session not created","message":"Session is already started","stacktrace":""}}
[task 2023-12-27T10:45:01.056Z] 10:45:01 INFO - STDERR: Ignored exception session not created (500): Session is already started
[task 2023-12-27T10:45:01.057Z] 10:45:01 INFO - PID 5148 | 1703673901048 webdriver::server DEBUG -> POST /session/None/frame {"id": null}
[task 2023-12-27T10:45:01.057Z] 10:45:01 INFO - PID 5148 | 1703673901048 webdriver::server DEBUG <- 404 Not Found {"value":{"error":"invalid session id","message":"Got unexpected session id None","stacktrace":""}}
[task 2023-12-27T10:45:01.059Z] 10:45:01 INFO - PID 5148 | 1703673901049 Marionette DEBUG Closed connection 0
[task 2023-12-27T10:45:01.059Z] 10:45:01 INFO - STDERR: Ignored exception invalid session id (404): Got unexpected session id None
[task 2023-12-27T10:45:01.060Z] 10:45:01 INFO - STDOUT: tests/web-platform/tests/webdriver/tests/bidi/browsing_context/navigate/about_blank.py::test_navigate_from_frameset
[task 2023-12-27T10:45:01.062Z] 10:45:01 INFO - PID 5148 | 1703673901053 webdriver::server DEBUG -> POST /session {"capabilities": {"alwaysMatch": {"moz:firefoxOptions": {"args": ["--profile", "C:\\Users\\task_170367334341 ... stderr", "R_LOG_VERBOSE": "1", "NSS_MAX_MP_PBE_ITERATION_COUNT": "10", "MOZ_WINDOW_OCCLUSION": "0"}}, "webSocketUrl": true}}}
[task 2023-12-27T10:45:01.062Z] 10:45:01 INFO - PID 5148 | 1703673901054 webdriver::server DEBUG <- 500 Internal Server Error {"value":{"error":"session not created","message":"Session is already started","stacktrace":""}}
[task 2023-12-27T10:45:01.074Z] 10:45:01 INFO - PID 5148 | console.error: ({})
[task 2023-12-27T10:45:01.414Z] 10:45:01 INFO - STDOUT: ERROR
[task 2023-12-27T10:45:01.429Z] 10:45:01 INFO - STDOUT: tests/web-platform/tests/webdriver/tests/bidi/browsing_context/navigate/about_blank.py::test_navigate_in_iframe
[task 2023-12-27T10:45:01.433Z] 10:45:01 INFO - PID 5148 | 1703673901432 webdriver::server DEBUG -> POST /session {"capabilities": {"alwaysMatch": {"moz:firefoxOptions": {"args": ["--profile", "C:\\Users\\task_170367334341 ... stderr", "R_LOG_VERBOSE": "1", "NSS_MAX_MP_PBE_ITERATION_COUNT": "10", "MOZ_WINDOW_OCCLUSION": "0"}}, "webSocketUrl": true}}}
[task 2023-12-27T10:45:01.433Z] 10:45:01 INFO - PID 5148 | 1703673901432 webdriver::server DEBUG <- 500 Internal Server Error {"value":{"error":"session not created","message":"Session is already started","stacktrace":""}}
[task 2023-12-27T10:45:01.555Z] 10:45:01 INFO - STDOUT: ERROR
[task 2023-12-27T10:45:01.573Z] 10:45:01 INFO - STDOUT: =================================== ERRORS ====================================
[task 2023-12-27T10:45:01.578Z] 10:45:01 INFO - STDOUT: ________________ ERROR at setup of test_navigate_from_frameset ________________
[task 2023-12-27T10:45:01.578Z] 10:45:01 INFO - STDOUT: event_loop = <ProactorEventLoop running=False closed=False debug=False>
[task 2023-12-27T10:45:01.578Z] 10:45:01 INFO - STDOUT: request = <SubRequest 'bidi_session' for <Function test_navigate_from_frameset>>
[task 2023-12-27T10:45:01.578Z] 10:45:01 INFO - STDOUT: kwargs = {'capabilities': {}, 'configuration': {'browser': {'args': ['--profile', 'C:\\Users\\task_170367334341851\\AppData\\Lo..., 'COMMONPROGRAMFILES(X86)': 'C:\\Program Files (x86)\\Common Files', ...}}}, 'host': '127.0.0.1', 'port': 52395, ...}}
[task 2023-12-27T10:45:01.578Z] 10:45:01 INFO - STDOUT: setup = <function _wrap_asyncgen.<locals>._asyncgen_fixture_wrapper.<locals>.setup at 0x0000022DBE620820>
[task 2023-12-27T10:45:01.578Z] 10:45:01 INFO - STDOUT: finalizer = <function _wrap_asyncgen.<locals>._asyncgen_fixture_wrapper.<locals>.finalizer at 0x0000022DBE620040>
[task 2023-12-27T10:45:01.791Z] 10:45:01 INFO -
[task 2023-12-27T10:45:01.791Z] 10:45:01 INFO - TEST-PASS | /webdriver/tests/bidi/browsing_context/navigate/about_blank.py | test_navigate_from_single_page
[task 2023-12-27T10:45:01.791Z] 10:45:01 INFO - TEST-UNEXPECTED-ERROR | /webdriver/tests/bidi/browsing_context/navigate/about_blank.py | test_navigate_from_frameset - setup error: webdriver.error.SessionNotCreatedException: session not created (500): Session is already started
[task 2023-12-27T10:45:01.791Z] 10:45:01 INFO - event_loop = <ProactorEventLoop running=False closed=False debug=False>
[task 2023-12-27T10:45:01.791Z] 10:45:01 INFO - request = <SubRequest 'bidi_session' for <Function test_navigate_from_frameset>>
|
||
Comment 1•2 years ago
|
||
Somehow the WebDriver session got closed but it's not clear why that happens based on the command browsingContext.close. Lets observe for now.
| Comment hidden (Intermittent Failures Robot) |
|
||
Comment 3•2 years ago
|
||
https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
For more information, please visit BugBot documentation.
Status: NEW → RESOLVED
Closed: 2 years ago
Resolution: --- → INCOMPLETE
You need to log in
before you can comment on or make changes to this bug.
Description
•