Closed
Bug 1846538
Opened 2 years ago
Closed 2 years ago
Intermittent [tier 2] Wd TEST-UNEXPECTED-TIMEOUT | expected OK (Forcibly terminating runner process)
Categories
(Remote Protocol :: WebDriver BiDi, defect, P5)
Remote Protocol
WebDriver BiDi
Tracking
(Not tracked)
RESOLVED
WORKSFORME
People
(Reporter: intermittent-bug-filer, Unassigned)
Details
(Keywords: intermittent-failure)
Filed by: ctuns [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer?job_id=424513776&repo=try
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/PVQeiY1hQnKewV226ANnFA/runs/0/artifacts/public/logs/live_backing.log
[task 2023-08-01T12:55:41.013Z] 12:55:41 INFO - TEST-START | /webdriver/tests/bidi/browsing_context/fragment_navigated/fragment_navigated.py
[task 2023-08-01T12:55:41.372Z] 12:55:41 INFO - STDOUT: ============================= test session starts =============================
[task 2023-08-01T12:55:41.382Z] 12:55:41 INFO - STDOUT: platform win32 -- Python 3.9.10, pytest-7.0.1, pluggy-unknown -- Z:\task_169088839798346\build\venv\Scripts\python.exe
[task 2023-08-01T12:55:41.383Z] 12:55:41 INFO - STDOUT: rootdir: Z:\task_169088839798346\build
[task 2023-08-01T12:55:41.384Z] 12:55:41 INFO - STDOUT: plugins: asyncio-0.19.0
[task 2023-08-01T12:55:41.385Z] 12:55:41 INFO - STDOUT: asyncio: mode=strict
[task 2023-08-01T12:55:41.385Z] 12:55:41 INFO - STDOUT: collecting ...
[task 2023-08-01T12:55:41.403Z] 12:55:41 INFO - STDOUT: collected 17 items
[task 2023-08-01T12:55:41.414Z] 12:55:41 INFO - STDOUT: tests/web-platform/tests/webdriver/tests/bidi/browsing_context/fragment_navigated/fragment_navigated.py::test_unsubscribe
[task 2023-08-01T12:55:41.425Z] 12:55:41 INFO - PID 7244 | 1690894541423 webdriver::server DEBUG -> POST /session {"capabilities": {"alwaysMatch": {"moz:firefoxOptions": {"args": ["--profile", "C:\\Users\\task_169088839798346\\AppData\\Local\\Temp\\tmpu36hkaeq.mozrunner"]}, "webSocketUrl": true}}}
[task 2023-08-01T12:55:41.425Z] 12:55:41 INFO - PID 7244 | 1690894541423 geckodriver::capabilities DEBUG Trying to read firefox version from ini files
[task 2023-08-01T12:55:41.426Z] 12:55:41 INFO - PID 7244 | 1690894541424 geckodriver::capabilities DEBUG Found version 118.0
[task 2023-08-01T12:55:41.434Z] 12:55:41 INFO - PID 7244 | 1690894541432 geckodriver::browser DEBUG Backing up prefs to "C:\\Users\\task_169088839798346\\AppData\\Local\\Temp\\tmpu36hkaeq.mozrunner\\user.geckodriver_backup"
[task 2023-08-01T12:55:41.449Z] 12:55:41 INFO - PID 7244 | 1690894541448 mozrunner::runner INFO Running command: "Z:\\task_169088839798346\\build\\application\\firefox\\firefox.exe" "--marionette" "--profile" "C:\\Users\\ ... AppData\\Local\\Temp\\tmpu36hkaeq.mozrunner" "--remote-debugging-port" "9222" "--remote-allow-hosts" "localhost" "-no-remote"
[task 2023-08-01T12:55:41.459Z] 12:55:41 INFO - PID 7244 | 1690894541458 geckodriver::marionette DEBUG Waiting 60s to connect to browser on 127.0.0.1
[task 2023-08-01T12:55:41.460Z] 12:55:41 INFO - PID 7244 | 1690894541458 geckodriver::browser TRACE Failed to open C:\Users\task_169088839798346\AppData\Local\Temp\tmpu36hkaeq.mozrunner\MarionetteActivePort
[task 2023-08-01T12:55:41.461Z] 12:55:41 INFO - PID 7244 | 1690894541458 geckodriver::marionette TRACE Retrying in 100ms
[task 2023-08-01T12:55:41.559Z] 12:55:41 INFO - PID 7244 | 1690894541559 geckodriver::browser TRACE Failed to open C:\Users\task_169088839798346\AppData\Local\Temp\tmpu36hkaeq.mozrunner\MarionetteActivePort
[task 2023-08-01T12:55:41.561Z] 12:55:41 INFO - PID 7244 | 1690894541559 geckodriver::marionette TRACE Retrying in 100ms
[task 2023-08-01T12:55:41.669Z] 12:55:41 INFO - PID 7244 | 1690894541669 geckodriver::browser TRACE Failed to open C:\Users\task_169088839798346\AppData\Local\Temp\tmpu36hkaeq.mozrunner\MarionetteActivePort
[task 2023-08-01T12:55:41.671Z] 12:55:41 INFO - PID 7244 | 1690894541669 geckodriver::marionette TRACE Retrying in 100ms
[task 2023-08-01T12:55:41.778Z] 12:55:41 INFO - PID 7244 | 1690894541779 geckodriver::browser TRACE Failed to open C:\Users\task_169088839798346\AppData\Local\Temp\tmpu36hkaeq.mozrunner\MarionetteActivePort
[task 2023-08-01T12:55:41.781Z] 12:55:41 INFO - PID 7244 | 1690894541779 geckodriver::marionette TRACE Retrying in 100ms
[task 2023-08-01T12:55:41.888Z] 12:55:41 INFO - PID 7244 | 1690894541888 geckodriver::browser TRACE Failed to open C:\Users\task_169088839798346\AppData\Local\Temp\tmpu36hkaeq.mozrunner\MarionetteActivePort
[task 2023-08-01T12:55:41.891Z] 12:55:41 INFO - PID 7244 | 1690894541888 geckodriver::marionette TRACE Retrying in 100ms
[task 2023-08-01T12:55:41.998Z] 12:55:41 INFO - PID 7244 | 1690894541998 geckodriver::browser TRACE Failed to open C:\Users\task_169088839798346\AppData\Local\Temp\tmpu36hkaeq.mozrunner\MarionetteActivePort
[task 2023-08-01T12:55:42.000Z] 12:55:42 INFO - PID 7244 | 1690894541998 geckodriver::marionette TRACE Retrying in 100ms
[task 2023-08-01T12:55:42.107Z] 12:55:42 INFO - PID 7244 | 1690894542108 geckodriver::browser TRACE Failed to open C:\Users\task_169088839798346\AppData\Local\Temp\tmpu36hkaeq.mozrunner\MarionetteActivePort
[task 2023-08-01T12:55:42.109Z] 12:55:42 INFO - PID 7244 | 1690894542108 geckodriver::marionette TRACE Retrying in 100ms
[task 2023-08-01T12:55:42.217Z] 12:55:42 INFO - PID 7244 | 1690894542217 geckodriver::browser TRACE Failed to open C:\Users\task_169088839798346\AppData\Local\Temp\tmpu36hkaeq.mozrunner\MarionetteActivePort
[task 2023-08-01T12:55:42.220Z] 12:55:42 INFO - PID 7244 | 1690894542217 geckodriver::marionette TRACE Retrying in 100ms
[task 2023-08-01T12:55:42.327Z] 12:55:42 INFO - PID 7244 | 1690894542327 geckodriver::browser TRACE Failed to open C:\Users\task_169088839798346\AppData\Local\Temp\tmpu36hkaeq.mozrunner\MarionetteActivePort
[task 2023-08-01T12:55:42.329Z] 12:55:42 INFO - PID 7244 | 1690894542327 geckodriver::marionette TRACE Retrying in 100ms
[task 2023-08-01T12:55:42.437Z] 12:55:42 INFO - PID 7244 | 1690894542437 geckodriver::browser TRACE Failed to open C:\Users\task_169088839798346\AppData\Local\Temp\tmpu36hkaeq.mozrunner\MarionetteActivePort
[task 2023-08-01T12:55:42.439Z] 12:55:42 INFO - PID 7244 | 1690894542437 geckodriver::marionette TRACE Retrying in 100ms
[task 2023-08-01T12:55:42.546Z] 12:55:42 INFO - PID 7244 | 1690894542547 geckodriver::browser TRACE Failed to open C:\Users\task_169088839798346\AppData\Local\Temp\tmpu36hkaeq.mozrunner\MarionetteActivePort
[task 2023-08-01T12:55:42.549Z] 12:55:42 INFO - PID 7244 | 1690894542547 geckodriver::marionette TRACE Retrying in 100ms
[task 2023-08-01T12:55:42.656Z] 12:55:42 INFO - PID 7244 | 1690894542656 geckodriver::browser TRACE Failed to open C:\Users\task_169088839798346\AppData\Local\Temp\tmpu36hkaeq.mozrunner\MarionetteActivePort
[task 2023-08-01T12:55:42.658Z] 12:55:42 INFO - PID 7244 | 1690894542656 geckodriver::marionette TRACE Retrying in 100ms
[task 2023-08-01T12:55:42.766Z] 12:55:42 INFO - PID 7244 | 1690894542766 geckodriver::browser TRACE Failed to open C:\Users\task_169088839798346\AppData\Local\Temp\tmpu36hkaeq.mozrunner\MarionetteActivePort
[task 2023-08-01T12:55:42.768Z] 12:55:42 INFO - PID 7244 | 1690894542766 geckodriver::marionette TRACE Retrying in 100ms
[task 2023-08-01T12:55:42.876Z] 12:55:42 INFO - PID 7244 | 1690894542876 geckodriver::browser TRACE Failed to open C:\Users\task_169088839798346\AppData\Local\Temp\tmpu36hkaeq.mozrunner\MarionetteActivePort
[task 2023-08-01T12:55:42.878Z] 12:55:42 INFO - PID 7244 | 1690894542876 geckodriver::marionette TRACE Retrying in 100ms
[task 2023-08-01T12:55:42.985Z] 12:55:42 INFO - PID 7244 | 1690894542985 geckodriver::browser TRACE Failed to open C:\Users\task_169088839798346\AppData\Local\Temp\tmpu36hkaeq.mozrunner\MarionetteActivePort
[task 2023-08-01T12:55:42.988Z] 12:55:42 INFO - PID 7244 | 1690894542986 geckodriver::marionette TRACE Retrying in 100ms
[task 2023-08-01T12:55:43.048Z] 12:55:43 INFO - PID 7244 | *** You are running in headless mode.
[task 2023-08-01T12:55:43.095Z] 12:55:43 INFO - PID 7244 | 1690894543096 geckodriver::browser TRACE Failed to open C:\Users\task_169088839798346\AppData\Local\Temp\tmpu36hkaeq.mozrunner\MarionetteActivePort
[task 2023-08-01T12:55:43.097Z] 12:55:43 INFO - PID 7244 | 1690894543096 geckodriver::marionette TRACE Retrying in 100ms
[task 2023-08-01T12:55:43.111Z] 12:55:43 INFO - PID 7244 | console.warn: services.settings: Ignoring preference override of remote settings server
[task 2023-08-01T12:55:43.117Z] 12:55:43 INFO - PID 7244 | console.warn: services.settings: Allow by setting MOZ_REMOTE_SETTINGS_DEVTOOLS=1 in the environment
[task 2023-08-01T12:55:43.174Z] 12:55:43 INFO - PID 7244 | 1690894543173 RemoteAgent DEBUG WebDriver BiDi enabled
[task 2023-08-01T12:55:43.175Z] 12:55:43 INFO - PID 7244 | 1690894543174 RemoteAgent DEBUG CDP enabled
[task 2023-08-01T12:55:43.176Z] 12:55:43 INFO - PID 7244 | 1690894543174 Marionette INFO Marionette enabled
[task 2023-08-01T12:55:43.176Z] 12:55:43 INFO - PID 7244 | 1690894543175 Marionette TRACE Received observer notification final-ui-startup
[task 2023-08-01T12:55:43.177Z] 12:55:43 INFO - PID 7244 | 1690894543175 RemoteAgent TRACE Received observer notification final-ui-startup
[task 2023-08-01T12:55:43.205Z] 12:55:43 INFO - PID 7244 | 1690894543204 Marionette INFO Listening on port 57131
[task 2023-08-01T12:55:43.206Z] 12:55:43 INFO - PID 7244 | 1690894543205 Marionette DEBUG Marionette is listening
[task 2023-08-01T12:55:43.207Z] 12:55:43 INFO - PID 7244 | Read port: 57131
[task 2023-08-01T12:55:43.218Z] 12:55:43 INFO - PID 7244 | 1690894543218 RemoteAgent TRACE Available local IP addresses: 127.0.0.1, [::1]
[task 2023-08-01T12:55:43.221Z] 12:55:43 INFO - PID 7244 | WebDriver BiDi listening on ws://127.0.0.1:9222
[task 2023-08-01T12:55:43.221Z] 12:55:43 INFO - PID 7244 | 1690894543220 CDP DEBUG Waiting for initial application window
[task 2023-08-01T12:55:43.224Z] 12:55:43 INFO - PID 7244 | 1690894543223 Marionette DEBUG Accepted connection 0 from 127.0.0.1:57132
[task 2023-08-01T12:55:43.226Z] 12:55:43 INFO - PID 7244 | 1690894543225 geckodriver::marionette DEBUG Connection to Marionette established on 127.0.0.1:57131.
[task 2023-08-01T12:55:43.268Z] 12:55:43 INFO - PID 7244 | 1690894543282 Marionette DEBUG 0 -> [0,1,"WebDriver:NewSession",{"webSocketUrl":true}]
[task 2023-08-01T12:55:43.284Z] 12:55:43 INFO - PID 7244 | 1690894543283 WebDriver BiDi DEBUG Waiting for initial application window
[task 2023-08-01T12:55:43.455Z] 12:55:43 INFO - PID 7244 | [GFX1-]: RenderCompositorSWGL failed mapping default framebuffer, no dt
[task 2023-08-01T12:55:43.893Z] 12:55:43 INFO - PID 7244 | console.error: ({})
[task 2023-08-01T12:55:43.924Z] 12:55:43 INFO - PID 7244 | 1690894543931 Marionette TRACE Received observer notification browser-idle-startup-tasks-finished
[task 2023-08-01T12:55:43.933Z] 12:55:43 INFO - PID 7244 | 1690894543931 RemoteAgent TRACE Received observer notification browser-idle-startup-tasks-finished
[task 2023-08-01T12:55:43.933Z] 12:55:43 INFO - PID 7244 | 1690894543932 WebDriver BiDi DEBUG Registered session handler: /session/83f79598-ffb5-46a3-90b5-d57253ad26e2
[task 2023-08-01T12:55:43.933Z] 12:55:43 INFO - PID 7244 | 1690894543932 Marionette DEBUG Waiting for initial application window
<...>
[task 2023-08-01T12:56:10.627Z] 12:56:10 INFO - STDOUT: tests/web-platform/tests/webdriver/tests/bidi/browsing_context/fragment_navigated/fragment_navigated.py::test_regular_navigation[#foo-]
[task 2023-08-01T12:56:10.628Z] 12:56:10 INFO - PID 7244 | 1690894570605 webdriver::server DEBUG -> POST /session/83f79598-ffb5-46a3-90b5-d57253ad26e2/window {"handle": "4e65b13b-3107-4f20-a97a-a39b674a4369"}
[task 2023-08-01T12:56:10.628Z] 12:56:10 INFO - PID 7244 | 1690894570606 Marionette DEBUG 0 -> [0,262,"WebDriver:SwitchToWindow",{"handle":"4e65b13b-3107-4f20-a97a-a39b674a4369"}]
[task 2023-08-01T12:56:10.629Z] 12:56:10 INFO - PID 7244 | 1690894570606 Marionette DEBUG 0 <- [1,262,null,{"value":null}]
[task 2023-08-01T12:56:10.630Z] 12:56:10 INFO - PID 7244 | 1690894570606 webdriver::server DEBUG <- 200 OK {"value":null}
[task 2023-08-01T12:56:10.631Z] 12:56:10 INFO - PID 7244 | 1690894570607 webdriver::server DEBUG -> GET /session/83f79598-ffb5-46a3-90b5-d57253ad26e2/window
[task 2023-08-01T12:56:10.631Z] 12:56:10 INFO - PID 7244 | 1690894570607 Marionette DEBUG 0 -> [0,263,"WebDriver:GetWindowHandle",{}]
[task 2023-08-01T12:56:10.632Z] 12:56:10 INFO - PID 7244 | 1690894570608 Marionette DEBUG 0 <- [1,263,null,{"value":"4e65b13b-3107-4f20-a97a-a39b674a4369"}]
[task 2023-08-01T12:56:10.633Z] 12:56:10 INFO - PID 7244 | 1690894570608 webdriver::server DEBUG <- 200 OK {"value":"4e65b13b-3107-4f20-a97a-a39b674a4369"}
[task 2023-08-01T12:56:10.634Z] 12:56:10 INFO - PID 7244 | 1690894570609 webdriver::server DEBUG -> GET /session/83f79598-ffb5-46a3-90b5-d57253ad26e2/window/handles
[task 2023-08-01T12:56:10.635Z] 12:56:10 INFO - PID 7244 | 1690894570609 Marionette DEBUG 0 -> [0,264,"WebDriver:GetWindowHandles",{}]
[task 2023-08-01T12:56:10.635Z] 12:56:10 INFO - PID 7244 | 1690894570609 Marionette DEBUG 0 <- [1,264,null,["4e65b13b-3107-4f20-a97a-a39b674a4369"]]
[task 2023-08-01T12:56:10.636Z] 12:56:10 INFO - PID 7244 | 1690894570609 webdriver::server DEBUG <- 200 OK {"value":["4e65b13b-3107-4f20-a97a-a39b674a4369"]}
[task 2023-08-01T12:56:10.637Z] 12:56:10 INFO - PID 7244 | 1690894570610 webdriver::server DEBUG -> POST /session/83f79598-ffb5-46a3-90b5-d57253ad26e2/window {"handle": "4e65b13b-3107-4f20-a97a-a39b674a4369"}
[task 2023-08-01T12:56:10.638Z] 12:56:10 INFO - PID 7244 | 1690894570610 Marionette DEBUG 0 -> [0,265,"WebDriver:SwitchToWindow",{"handle":"4e65b13b-3107-4f20-a97a-a39b674a4369"}]
[task 2023-08-01T12:56:10.639Z] 12:56:10 INFO - PID 7244 | 1690894570611 Marionette DEBUG 0 <- [1,265,null,{"value":null}]
[task 2023-08-01T12:56:10.640Z] 12:56:10 INFO - PID 7244 | 1690894570611 webdriver::server DEBUG <- 200 OK {"value":null}
[task 2023-08-01T12:56:10.641Z] 12:56:10 INFO - PID 7244 | 1690894570612 webdriver::server DEBUG -> POST /session/83f79598-ffb5-46a3-90b5-d57253ad26e2/window/rect {"width": 800, "height": 600}
[task 2023-08-01T12:56:10.641Z] 12:56:10 INFO - PID 7244 | 1690894570612 Marionette DEBUG 0 -> [0,266,"WebDriver:SetWindowRect",{"height":600,"width":800}]
[task 2023-08-01T12:56:10.642Z] 12:56:10 INFO - PID 7244 | 1690894570612 Marionette TRACE Requested window geometry matches
[task 2023-08-01T12:56:10.643Z] 12:56:10 INFO - PID 7244 | 1690894570612 Marionette DEBUG 0 <- [1,266,null,{"x":100,"y":100,"width":800,"height":600}]
[task 2023-08-01T12:56:10.644Z] 12:56:10 INFO - PID 7244 | 1690894570612 webdriver::server DEBUG <- 200 OK {"value":{"x":100,"y":100,"width":800,"height":600}}
[task 2023-08-01T12:56:10.644Z] 12:56:10 INFO - PID 7244 | 1690894570613 webdriver::server DEBUG -> POST /session/83f79598-ffb5-46a3-90b5-d57253ad26e2/frame {"id": null}
[task 2023-08-01T12:56:10.645Z] 12:56:10 INFO - PID 7244 | 1690894570613 Marionette DEBUG 0 -> [0,267,"WebDriver:SwitchToFrame",{"id":null}]
[task 2023-08-01T12:56:10.646Z] 12:56:10 INFO - PID 7244 | 1690894570614 Marionette DEBUG 0 <- [1,267,null,{"value":null}]
[task 2023-08-01T12:56:10.647Z] 12:56:10 INFO - PID 7244 | 1690894570614 webdriver::server DEBUG <- 200 OK {"value":null}
[task 2023-08-01T12:56:10.648Z] 12:56:10 INFO - PID 7244 | 1690894570619 RemoteAgent INFO Perform WebSocket upgrade for incoming connection from 127.0.0.1:57482
[task 2023-08-01T12:56:10.648Z] 12:56:10 INFO - PID 7244 | 1690894570620 RemoteAgent DEBUG WebDriverBiDiConnection 56710fc4-221e-4797-bc49-97138d243431 accepted
[task 2023-08-01T12:56:10.649Z] 12:56:10 INFO - PID 7244 | 1690894570620 WebDriver BiDi DEBUG Connection 56710fc4-221e-4797-bc49-97138d243431 attached to session 83f79598-ffb5-46a3-90b5-d57253ad26e2
[task 2023-08-01T12:56:10.650Z] 12:56:10 INFO - PID 7244 | 1690894570620 webdriver::server DEBUG -> POST /session/83f79598-ffb5-46a3-90b5-d57253ad26e2/window/rect {"width": 800, "height": 600}
[task 2023-08-01T12:56:10.651Z] 12:56:10 INFO - PID 7244 | 1690894570621 Marionette DEBUG 0 -> [0,268,"WebDriver:SetWindowRect",{"height":600,"width":800}]
[task 2023-08-01T12:56:10.652Z] 12:56:10 INFO - PID 7244 | 1690894570621 Marionette TRACE Requested window geometry matches
[task 2023-08-01T12:56:10.653Z] 12:56:10 INFO - PID 7244 | 1690894570621 Marionette DEBUG 0 <- [1,268,null,{"x":100,"y":100,"width":800,"height":600}]
[task 2023-08-01T12:56:10.653Z] 12:56:10 INFO - PID 7244 | 1690894570621 webdriver::server DEBUG <- 200 OK {"value":{"x":100,"y":100,"width":800,"height":600}}
[task 2023-08-01T12:56:10.653Z] 12:56:10 INFO - PID 7244 | 1690894570622 webdriver::server DEBUG -> POST /session/83f79598-ffb5-46a3-90b5-d57253ad26e2/window/rect {"x": 100, "y": 100}
[task 2023-08-01T12:56:10.655Z] 12:56:10 INFO - PID 7244 | 1690894570622 Marionette DEBUG 0 -> [0,269,"WebDriver:SetWindowRect",{"x":100,"y":100}]
[task 2023-08-01T12:56:10.656Z] 12:56:10 INFO - PID 7244 | 1690894570622 Marionette TRACE Requested window geometry matches
[task 2023-08-01T12:56:10.657Z] 12:56:10 INFO - PID 7244 | 1690894570622 Marionette DEBUG 0 <- [1,269,null,{"x":100,"y":100,"width":800,"height":600}]
[task 2023-08-01T12:56:10.658Z] 12:56:10 INFO - PID 7244 | 1690894570622 webdriver::server DEBUG <- 200 OK {"value":{"x":100,"y":100,"width":800,"height":600}}
[task 2023-08-01T12:56:10.659Z] 12:56:10 INFO - PID 7244 | 1690894570624 RemoteAgent DEBUG WebDriverBiDiConnection 56710fc4-221e-4797-bc49-97138d243431 -> {"id":92,"method":"browsingContext.create","params":{"type":"tab"}}
[task 2023-08-01T12:56:10.660Z] 12:56:10 INFO - PID 7244 | 1690894570624 RemoteAgent TRACE Module root/browsingContext.sys.mjs found for ROOT
[task 2023-08-01T12:56:10.660Z] 12:56:10 INFO - PID 7244 | 1690894570624 RemoteAgent TRACE Received command browsingContext.create for destination ROOT
[task 2023-08-01T12:56:10.661Z] 12:56:10 INFO - PID 7244 | 1690894570624 RemoteAgent TRACE Module root/browsingContext.sys.mjs found for ROOT
[task 2023-08-01T12:56:10.662Z] 12:56:10 INFO - PID 7244 | 1690894570632 RemoteAgent TRACE Received DOM event TabSelect for [object XULElement]
[task 2023-08-01T12:56:10.663Z] 12:56:10 INFO - PID 7244 | 1690894570637 RemoteAgent TRACE [40] ProgressListener Start: expectNavigation=false resolveWhenStarted=false unloadTimeout=5000 waitForExplicitStart=false
[task 2023-08-01T12:56:10.664Z] 12:56:10 INFO - PID 7244 | 1690894570637 RemoteAgent TRACE [40] ProgressListener Setting unload timer (5000ms)
[task 2023-08-01T12:56:10.664Z] 12:56:10 INFO - PID 7244 | 1690894570640 RemoteAgent TRACE Created MessageHandler WINDOW_GLOBAL for session 83f79598-ffb5-46a3-90b5-d57253ad26e2
[task 2023-08-01T12:56:10.664Z] 12:56:10 INFO - PID 7244 | 1690894570641 RemoteAgent TRACE [40] ProgressListener Check loading state: isStart=1 isStop=0
[task 2023-08-01T12:56:10.665Z] 12:56:10 INFO - PID 7244 | 1690894570641 RemoteAgent TRACE [40] ProgressListener state=start: about:blank
[task 2023-08-01T12:56:10.666Z] 12:56:10 INFO - PID 7244 | 1690894570641 RemoteAgent TRACE [40] ProgressListener Cleared the unload timer
[task 2023-08-01T12:56:10.667Z] 12:56:10 INFO - PID 7244 | 1690894570642 RemoteAgent TRACE [40] NavigationListener onStateChange, stateFlags: 983041, status: 0, isStart: true, isStop: false, isNetwork: true, isBindingAborted: false, targetURI: about:blank
[task 2023-08-01T12:56:10.668Z] 12:56:10 INFO - PID 7244 | 1690894570642 RemoteAgent TRACE [ad59619b-b0e2-43b1-883f-21016f619581] Navigation started for url: about:blank (d3c24e3b-1658-4c47-ba3c-575196f1f3ce)
[task 2023-08-01T12:56:10.669Z] 12:56:10 INFO - PID 7244 | 1690894570643 RemoteAgent TRACE [40] NavigationListener onStateChange, stateFlags: 131088, status: 2152398850, isStart: false, isStop: true, isNetwork: false, isBindingAborted: true, targetURI: about:blank
[task 2023-08-01T12:56:10.670Z] 12:56:10 INFO - PID 7244 | 1690894570644 RemoteAgent TRACE [40] NavigationListener onStateChange, stateFlags: 983041, status: 0, isStart: true, isStop: false, isNetwork: true, isBindingAborted: false, targetURI: about:blank
[task 2023-08-01T12:56:10.671Z] 12:56:10 INFO - PID 7244 | 1690894570644 RemoteAgent TRACE [40] ProgressListener Check loading state: isStart=0 isStop=16
[task 2023-08-01T12:56:10.672Z] 12:56:10 INFO - PID 7244 | 1690894570644 RemoteAgent TRACE [40] ProgressListener Ignore aborted navigation error to the initial document, real document will be loaded.
[task 2023-08-01T12:56:10.672Z] 12:56:10 INFO - PID 7244 | 1690894570645 RemoteAgent TRACE [40] ProgressListener Check loading state: isStart=1 isStop=0
[task 2023-08-01T12:56:10.673Z] 12:56:10 INFO - PID 7244 | 1690894570645 RemoteAgent TRACE [ad59619b-b0e2-43b1-883f-21016f619581] Skipping already tracked navigation, id: d3c24e3b-1658-4c47-ba3c-575196f1f3ce
[task 2023-08-01T12:56:10.673Z] 12:56:10 INFO - PID 7244 | 1690894570647 RemoteAgent TRACE [40] NavigationListener onStateChange, stateFlags: 196610, status: 0, isStart: false, isStop: false, isNetwork: false, isBindingAborted: false, targetURI: about:blank
[task 2023-08-01T12:56:10.673Z] 12:56:10 INFO - PID 7244 | 1690894570650 RemoteAgent TRACE Created MessageHandler WINDOW_GLOBAL for session 83f79598-ffb5-46a3-90b5-d57253ad26e2
[task 2023-08-01T12:56:10.674Z] 12:56:10 INFO - PID 7244 | 1690894570655 RemoteAgent TRACE [40] NavigationListener onStateChange, stateFlags: 196612, status: 0, isStart: false, isStop: false, isNetwork: false, isBindingAborted: false, targetURI: about:blank
[task 2023-08-01T12:56:10.675Z] 12:56:10 INFO - PID 7244 | 1690894570656 RemoteAgent TRACE [40] NavigationListener onStateChange, stateFlags: 196612, status: 0, isStart: false, isStop: false, isNetwork: false, isBindingAborted: false, targetURI: about:blank
[task 2023-08-01T12:56:10.676Z] 12:56:10 INFO - PID 7244 | 1690894570656 RemoteAgent TRACE MessageHandler WINDOW_GLOBAL for session 83f79598-ffb5-46a3-90b5-d57253ad26e2 is being destroyed
[task 2023-08-01T12:56:10.677Z] 12:56:10 INFO - PID 7244 | 1690894570656 RemoteAgent TRACE Unregistered MessageHandler WINDOW_GLOBAL for session 83f79598-ffb5-46a3-90b5-d57253ad26e2
[task 2023-08-01T12:56:10.678Z] 12:56:10 INFO - PID 7244 | 1690894570660 RemoteAgent TRACE [40] NavigationListener onStateChange, stateFlags: 131088, status: 0, isStart: false, isStop: true, isNetwork: false, isBindingAborted: false, targetURI: about:blank
[task 2023-08-01T12:56:10.679Z] 12:56:10 INFO - PID 7244 | 1690894570660 RemoteAgent TRACE [ad59619b-b0e2-43b1-883f-21016f619581] Navigation finished for url: about:blank (d3c24e3b-1658-4c47-ba3c-575196f1f3ce)
[task 2023-08-01T12:56:10.680Z] 12:56:10 INFO - PID 7244 | 1690894570662 RemoteAgent TRACE [40] ProgressListener Check loading state: isStart=0 isStop=16
[task 2023-08-01T12:56:10.681Z] 12:56:10 INFO - PID 7244 | 1690894570662 RemoteAgent TRACE [40] ProgressListener state=stop: about:blank
[task 2023-08-01T12:56:10.681Z] 12:56:10 INFO - PID 7244 | 1690894570662 RemoteAgent TRACE [40] ProgressListener Stop: has error=false
[task 2023-08-01T12:56:10.682Z] 12:56:10 INFO - PID 7244 | 1690894570663 RemoteAgent DEBUG WebDriverBiDiConnection 56710fc4-221e-4797-bc49-97138d243431 <- {"id":92,"result":{"context":"ad59619b-b0e2-43b1-883f-21016f619581"}}
[task 2023-08-01T12:56:10.682Z] 12:56:10 INFO - PID 7244 | 1690894570664 RemoteAgent DEBUG WebDriverBiDiConnection 56710fc4-221e-4797-bc49-97138d243431 -> {"id":93,"method":"browsingContext.navigate","params":{"context":"ad59619b-b0e2-43b1-883f-21016f619581","url":"http://web-platform.test:8000/webdriver/tests/bidi/support/empty.html#foo","wait":"complete"}}
[task 2023-08-01T12:56:10.683Z] 12:56:10 INFO - PID 7244 | 1690894570664 RemoteAgent TRACE Module root/browsingContext.sys.mjs found for ROOT
[task 2023-08-01T12:56:10.683Z] 12:56:10 INFO - PID 7244 | 1690894570664 RemoteAgent TRACE Received command browsingContext.navigate for destination ROOT
[task 2023-08-01T12:56:10.684Z] 12:56:10 INFO - PID 7244 | 1690894570664 RemoteAgent TRACE Module root/browsingContext.sys.mjs found for ROOT
[task 2023-08-01T12:56:10.685Z] 12:56:10 INFO - PID 7244 | 1690894570664 RemoteAgent TRACE Received command browsingContext._getBaseURL for destination WINDOW_GLOBAL
[task 2023-08-01T12:56:10.686Z] 12:56:10 INFO - PID 7244 | 1690894570664 RemoteAgent TRACE Module windowglobal-in-root/browsingContext.sys.mjs found for WINDOW_GLOBAL
[task 2023-08-01T12:56:10.686Z] 12:56:10 INFO - PID 7244 | 1690894570664 RemoteAgent TRACE Module windowglobal/browsingContext.sys.mjs found for WINDOW_GLOBAL
[task 2023-08-01T12:56:10.687Z] 12:56:10 INFO - PID 7244 | 1690894570664 RemoteAgent TRACE Received command browsingContext._getBaseURL for destination WINDOW_GLOBAL
[task 2023-08-01T12:56:10.688Z] 12:56:10 INFO - PID 7244 | 1690894570666 RemoteAgent TRACE Module windowglobal/browsingContext.sys.mjs found for WINDOW_GLOBAL
[task 2023-08-01T12:56:10.689Z] 12:56:10 INFO - PID 7244 | 1690894570666 RemoteAgent TRACE Module windowglobal/browsingContext.sys.mjs found for WINDOW_GLOBAL
[task 2023-08-01T12:56:10.690Z] 12:56:10 INFO - PID 7244 | 1690894570667 RemoteAgent TRACE [40] ProgressListener Start: expectNavigation=true resolveWhenStarted=false unloadTimeout=200 waitForExplicitStart=true
[task 2023-08-01T12:56:10.690Z] 12:56:10 INFO - PID 7244 | 1690894570667 RemoteAgent TRACE [40] ProgressListener Skip setting the unload timer
[task 2023-08-01T12:56:10.691Z] 12:56:10 INFO - PID 7244 | 1690894570667 RemoteAgent TRACE [40] NavigationListener onStateChange, stateFlags: 983041, status: 0, isStart: true, isStop: false, isNetwork: true, isBindingAborted: false, targetURI: http://web-platform.test:8000/webdriver/tests/bidi/support/empty.html#foo
[task 2023-08-01T12:56:10.692Z] 12:56:10 INFO - PID 7244 | 1690894570668 RemoteAgent TRACE [ad59619b-b0e2-43b1-883f-21016f619581] Navigation started for url: http://web-platform.test:8000/webdriver/tests/bidi/support/empty.html#foo (f74e9036-27d0-47c0-81d9-cdbc24b6bcaa)
[task 2023-08-01T12:56:10.693Z] 12:56:10 INFO - PID 7244 | 1690894570668 RemoteAgent TRACE [40] ProgressListener Check loading state: isStart=1 isStop=0
[task 2023-08-01T12:56:10.694Z] 12:56:10 INFO - PID 7244 | 1690894570668 RemoteAgent TRACE [40] ProgressListener state=start: http://web-platform.test:8000/webdriver/tests/bidi/support/empty.html#foo
[task 2023-08-01T12:56:10.695Z] 12:56:10 INFO - PID 7244 | 1690894570688 RemoteAgent TRACE [40] NavigationListener onStateChange, stateFlags: 131088, status: 2152398850, isStart: false, isStop: true, isNetwork: false, isBindingAborted: true, targetURI: http://web-platform.test:8000/webdriver/tests/bidi/support/empty.html#foo
[task 2023-08-01T12:56:10.696Z] 12:56:10 INFO - PID 7244 | 1690894570688 RemoteAgent TRACE MessageHandler WINDOW_GLOBAL for session 83f79598-ffb5-46a3-90b5-d57253ad26e2 is being destroyed
[task 2023-08-01T12:56:10.697Z] 12:56:10 INFO - PID 7244 | 1690894570688 RemoteAgent TRACE Unregistered MessageHandler WINDOW_GLOBAL for session 83f79598-ffb5-46a3-90b5-d57253ad26e2
[task 2023-08-01T12:56:11.022Z] 12:56:11 INFO - TEST-UNEXPECTED-TIMEOUT | /webdriver/tests/bidi/browsing_context/fragment_navigated/fragment_navigated.py | expected OK
[task 2023-08-01T12:56:11.022Z] 12:56:11 INFO - TEST-INFO took 30025ms
[task 2023-08-01T12:56:21.575Z] 12:56:21 WARNING - Forcibly terminating runner process
[task 2023-08-01T12:56:22.106Z] 12:56:22 INFO - PID 4580 | 1690894581618 geckodriver INFO Listening on 127.0.0.1:55398
[task 2023-08-01T12:56:22.108Z] 12:56:22 INFO - Starting runner
[task 2023-08-01T12:56:22.842Z] 12:56:22 INFO - TEST-START | /webdriver/tests/bidi/browsing_context/fragment_navigated/history_api.py
|
||
Comment 1•2 years ago
|
||
Hm, this is interesting:
https://treeherder.mozilla.org/logviewer?job_id=424513776&repo=try&lineNumber=9584-9589
[task 2023-08-01T12:55:19.063Z] 12:55:19 INFO - PID 2436 | 1690894518289 geckodriver::browser DEBUG Browser process stopped: exit code: 0
[task 2023-08-01T12:55:19.064Z] 12:55:19 INFO - PID 2436 | 1690894518290 webdriver::server DEBUG <- 200 OK {"value":null}
[task 2023-08-01T12:55:19.065Z] 12:55:19 INFO - PID 2436 | 1690894518397 webdriver::server DEBUG -> GET /status
[task 2023-08-01T12:55:19.065Z] 12:55:19 INFO - PID 2436 | 1690894518397 webdriver::server DEBUG <- 200 OK {"value":{"message":"","ready":true}}
[task 2023-08-01T12:55:29.066Z] 12:55:29 WARNING - Forcibly terminating runner process
[task 2023-08-01T12:55:29.629Z] 12:55:29 INFO - PID 4692 | 1690894529144 geckodriver INFO Listening on 127.0.0.1:55398
Why does it take 10s before the Forcibly terminating runner process warning within ensure_runner_stopped of wptrunner? I assume geckodriver didn't correctly exited?
Flags: needinfo?(james)
Summary: Intermittent [tier 2] TEST-UNEXPECTED-TIMEOUT | /webdriver/tests/bidi/browsing_context/fragment_navigated/fragment_navigated.py | expected OK → Intermittent [tier 2] Wd TEST-UNEXPECTED-TIMEOUT | expected OK (Forcibly terminating runner process)
| Comment hidden (Intermittent Failures Robot) |
|
||
Comment 3•2 years ago
|
||
The technical answer is "because the testrunner process can't directly know about the status of the browser process in the wptrunner architecture, so what we do is ask the browser to shut down, ask the testrunner to shutdown, and then wait for those things to happen". The two can be linked; in particular for non-wdpsec tests in Firefox the first thing we do when the browser is asked to shutdown is wait for it to stop knowing that the testrunner is likely doing _request_in_app_shutdown.
However for wdspec tests there shouldn't really be anything happening on the testrunner side; the browser side tries to delete the geckodriver session. So I'm not quite sure what happened here, but given that it seems to have happened twice ever and we haven't seen it for 3 months, I'm going to close this as WFM.
Status: NEW → RESOLVED
Closed: 2 years ago
Flags: needinfo?(james)
Resolution: --- → WORKSFORME
You need to log in
before you can comment on or make changes to this bug.
Description
•