Open
Bug 1848593
Opened 1 year ago
Updated 1 month ago
Intermittent Wd TEST-UNEXPECTED-TIMEOUT | expected OK (hang in "browsingContext.create")
Categories
(Remote Protocol :: WebDriver BiDi, defect, P5)
Remote Protocol
WebDriver BiDi
Tracking
(Not tracked)
REOPENED
People
(Reporter: intermittent-bug-filer, Unassigned)
References
(Blocks 1 open bug)
Details
(Keywords: intermittent-failure)
Filed by: imoraru [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer?job_id=425878318&repo=autoland
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/cigfHaLUQpqgsU3fT13qwQ/runs/0/artifacts/public/logs/live_backing.log
[task 2023-08-14T07:23:22.451Z] 07:23:22 INFO - STDOUT: PASSED
[task 2023-08-14T07:23:22.517Z] 07:23:22 INFO - PID 3005 | 1691997802517 webdriver::server DEBUG -> POST /session/0330ba01-70f4-49a7-b02a-2c487d797e5e/timeouts {"implicit": 0}
[task 2023-08-14T07:23:22.525Z] 07:23:22 INFO - PID 3005 | 1691997802524 webdriver::server DEBUG <- 200 OK {"value":null}
[task 2023-08-14T07:23:22.526Z] 07:23:22 INFO - PID 3005 | 1691997802525 webdriver::server DEBUG -> POST /session/0330ba01-70f4-49a7-b02a-2c487d797e5e/timeouts {"pageLoad": 300000}
[task 2023-08-14T07:23:22.530Z] 07:23:22 INFO - PID 3005 | 1691997802530 webdriver::server DEBUG <- 200 OK {"value":null}
[task 2023-08-14T07:23:22.531Z] 07:23:22 INFO - PID 3005 | 1691997802530 webdriver::server DEBUG -> POST /session/0330ba01-70f4-49a7-b02a-2c487d797e5e/timeouts {"script": 30000}
[task 2023-08-14T07:23:22.536Z] 07:23:22 INFO - PID 3005 | 1691997802535 webdriver::server DEBUG <- 200 OK {"value":null}
[task 2023-08-14T07:23:22.536Z] 07:23:22 INFO - PID 3005 | 1691997802536 webdriver::server DEBUG -> GET /session/0330ba01-70f4-49a7-b02a-2c487d797e5e/window
[task 2023-08-14T07:23:22.540Z] 07:23:22 INFO - PID 3005 | 1691997802540 webdriver::server DEBUG <- 200 OK {"value":"57020b04-bfb4-4ac7-bc54-e1058cab70fa"}
[task 2023-08-14T07:23:22.541Z] 07:23:22 INFO - PID 3005 | 1691997802540 webdriver::server DEBUG -> GET /session/0330ba01-70f4-49a7-b02a-2c487d797e5e/window
[task 2023-08-14T07:23:22.546Z] 07:23:22 INFO - PID 3005 | 1691997802545 webdriver::server DEBUG <- 200 OK {"value":"57020b04-bfb4-4ac7-bc54-e1058cab70fa"}
[task 2023-08-14T07:23:22.546Z] 07:23:22 INFO - PID 3005 | 1691997802545 webdriver::server DEBUG -> GET /session/0330ba01-70f4-49a7-b02a-2c487d797e5e/window/handles
[task 2023-08-14T07:23:22.551Z] 07:23:22 INFO - PID 3005 | 1691997802550 webdriver::server DEBUG <- 200 OK {"value":["57020b04-bfb4-4ac7-bc54-e1058cab70fa"]}
[task 2023-08-14T07:23:22.552Z] 07:23:22 INFO - PID 3005 | 1691997802551 webdriver::server DEBUG -> POST /session/0330ba01-70f4-49a7-b02a-2c487d797e5e/window {"handle": "57020b04-bfb4-4ac7-bc54-e1058cab70fa"}
[task 2023-08-14T07:23:22.556Z] 07:23:22 INFO - PID 3005 | 1691997802556 webdriver::server DEBUG <- 200 OK {"value":null}
[task 2023-08-14T07:23:22.557Z] 07:23:22 INFO - PID 3005 | 1691997802556 webdriver::server DEBUG -> POST /session/0330ba01-70f4-49a7-b02a-2c487d797e5e/alert/dismiss {}
[task 2023-08-14T07:23:22.563Z] 07:23:22 INFO - PID 3005 | 1691997802562 webdriver::server DEBUG <- 404 Not Found {"value":{"error":"no such alert","message":"","stacktrace":"RemoteError@chrome://remote/content/shared/Remo ... ontent/marionette/server.sys.mjs:263:9\n_onJSONObjectReady/<@chrome://remote/content/marionette/transport.sys.mjs:494:20\n"}}
[task 2023-08-14T07:23:22.563Z] 07:23:22 INFO - PID 3005 | 1691997802563 webdriver::server DEBUG -> POST /session/0330ba01-70f4-49a7-b02a-2c487d797e5e/window {"handle": "57020b04-bfb4-4ac7-bc54-e1058cab70fa"}
[task 2023-08-14T07:23:22.572Z] 07:23:22 INFO - PID 3005 | 1691997802572 webdriver::server DEBUG <- 200 OK {"value":null}
[task 2023-08-14T07:23:22.573Z] 07:23:22 INFO - PID 3005 | 1691997802572 webdriver::server DEBUG -> GET /session/0330ba01-70f4-49a7-b02a-2c487d797e5e/window
[task 2023-08-14T07:23:22.577Z] 07:23:22 INFO - PID 3005 | 1691997802577 webdriver::server DEBUG <- 200 OK {"value":"57020b04-bfb4-4ac7-bc54-e1058cab70fa"}
[task 2023-08-14T07:23:22.578Z] 07:23:22 INFO - PID 3005 | 1691997802577 webdriver::server DEBUG -> GET /session/0330ba01-70f4-49a7-b02a-2c487d797e5e/window/handles
[task 2023-08-14T07:23:22.583Z] 07:23:22 INFO - PID 3005 | 1691997802583 webdriver::server DEBUG <- 200 OK {"value":["57020b04-bfb4-4ac7-bc54-e1058cab70fa"]}
[task 2023-08-14T07:23:22.584Z] 07:23:22 INFO - PID 3005 | 1691997802583 webdriver::server DEBUG -> POST /session/0330ba01-70f4-49a7-b02a-2c487d797e5e/window {"handle": "57020b04-bfb4-4ac7-bc54-e1058cab70fa"}
[task 2023-08-14T07:23:22.589Z] 07:23:22 INFO - PID 3005 | 1691997802588 webdriver::server DEBUG <- 200 OK {"value":null}
[task 2023-08-14T07:23:22.589Z] 07:23:22 INFO - PID 3005 | 1691997802589 webdriver::server DEBUG -> POST /session/0330ba01-70f4-49a7-b02a-2c487d797e5e/frame {"id": null}
[task 2023-08-14T07:23:22.598Z] 07:23:22 INFO - PID 3005 | 1691997802598 webdriver::server DEBUG <- 200 OK {"value":null}
[task 2023-08-14T07:23:22.600Z] 07:23:22 INFO - STDOUT: tests/web-platform/tests/webdriver/tests/bidi/script/evaluate/sandbox.py::test_exception_details[True]
[task 2023-08-14T07:25:01.864Z] 07:25:01 INFO - TEST-UNEXPECTED-TIMEOUT | /webdriver/tests/bidi/script/evaluate/sandbox.py | expected OK
[task 2023-08-14T07:25:01.864Z] 07:25:01 INFO - TEST-INFO took 105028ms
[task 2023-08-14T07:25:11.910Z] 07:25:11 WARNING - Forcibly terminating runner process
[task 2023-08-14T07:25:11.992Z] 07:25:11 INFO - PID 3154 | 1691997911990 geckodriver INFO Listening on 127.0.0.1:47108
[task 2023-08-14T07:25:11.992Z] 07:25:11 INFO - Starting runner
[task 2023-08-14T07:25:12.185Z] 07:25:12 INFO - TEST-START | /webdriver/tests/bidi/script/evaluate/serialization_options.py
|
||
Comment 1•1 year ago
|
||
The hang here happens when browsingContext.create is called for type tab. Here the except from the Android log cat output:
08-14 07:23:22.180 25214 25229 I Gecko : 1691997802180 RemoteAgent DEBUG WebDriverBiDiConnection c8ddf1f8-6be2-49c3-843a-5e4e732c262d -> {"id":28,"method":"browsingContext.create","params":{"type":"tab"}}
08-14 07:23:22.180 25214 25229 I Gecko : 1691997802180 RemoteAgent TRACE Module root/browsingContext.sys.mjs found for ROOT
08-14 07:23:22.180 25214 25229 I Gecko : 1691997802180 RemoteAgent TRACE Received command browsingContext.create for destination ROOT
08-14 07:23:22.180 25214 25229 I Gecko : 1691997802180 RemoteAgent TRACE Module root/browsingContext.sys.mjs found for ROOT
08-14 07:23:22.181 25214 25229 D GeckoViewModule: dispatch GeckoView:WebExtension:SetTabActive, data={"active":false}
08-14 07:23:22.181 25214 25229 D GeckoViewTab: onEvent: event=GeckoView:WebExtension:SetTabActive, data={"active":false}
08-14 07:23:22.185 25214 25229 I Gecko : 1691997802185 Marionette TRACE Received observer notification domwindowopened
08-14 07:23:22.206 25214 25229 D GeckoViewNavigation: sessionContextId=null
08-14 07:23:22.216 25587 25587 I art : Late-enabling -Xcheck:jni
08-14 07:23:22.216 25587 25587 W art : Unexpected CPU variant for X86 using defaults: x86_64
08-14 07:23:22.221 1657 2061 I ActivityManager: Start proc 25587:org.mozilla.geckoview.test_runner:tab32/u0a62 for service org.mozilla.geckoview.test_runner/org.mozilla.gecko.process.GeckoChildProcessServices$tab32
08-14 07:23:22.223 25214 25242 D ServiceAllocator: org.mozilla.gecko.process.GeckoChildProcessServices$tab32 updateBindings: FOREGROUND priority, 0 importance, 3 successful binds, 0 failed binds, 0 successful unbinds
08-14 07:23:22.248 25587 25587 I MultiDex: VM with version 2.1.0 has multidex support
08-14 07:23:22.248 25587 25587 I MultiDex: Installing application
08-14 07:23:22.248 25587 25587 I MultiDex: VM has multidex support, MultiDex support library is disabled.
08-14 07:23:22.256 25587 25587 I ServiceChildProcess: onCreate
08-14 07:23:22.262 25587 25587 D GeckoThread: State changed to LAUNCHED
08-14 07:23:22.267 25587 25602 I GeckoThread: preparing to run Gecko
08-14 07:23:22.271 25214 25242 D ServiceAllocator: org.mozilla.gecko.process.GeckoChildProcessServices$tab32 updateBindings: FOREGROUND priority, 2 importance, 0 successful binds, 0 failed binds, 0 successful unbinds
08-14 07:23:22.274 25279 25315 D EGL_emulation: eglMakeCurrent: 0x73bf8207e560: ver 3 0 (tinfo 0x73bf778b9120)
08-14 07:23:22.274 25587 25602 D GeckoThread: State changed to MOZGLUE_READY
08-14 07:23:22.275 25587 25602 I GeckoLoader: Library base=/data/app/org.mozilla.geckoview.test_runner-1/lib/x86_64
08-14 07:23:22.275 25587 25602 I GeckoLoader: Library base=/data/app/org.mozilla.geckoview.test_runner-1/lib/x86_64
08-14 07:23:22.276 25587 25602 E GeckoLibLoad: Load sqlite start
08-14 07:23:22.276 25279 25315 E eglCodecCommon: glUtilsParamSize: unknow param 0x00008caa
08-14 07:23:22.276 25587 25602 E GeckoLibLoad: Load sqlite done
08-14 07:23:22.276 25587 25602 I GeckoLoader: Library base=/data/app/org.mozilla.geckoview.test_runner-1/lib/x86_64
08-14 07:23:22.276 25587 25602 E GeckoLibLoad: Load nss start
08-14 07:23:22.276 25587 25602 E GeckoLibLoad: Load nss done
08-14 07:23:22.276 25587 25602 I GeckoLoader: Library base=/data/app/org.mozilla.geckoview.test_runner-1/lib/x86_64
08-14 07:23:22.281 25587 25602 E GeckoLibLoad: Loaded libs in 4.909850ms total, 0ms(0ms) user, 0ms(0ms) system, 0(0) faults
08-14 07:23:22.282 25587 25602 D GeckoThread: State changed to LIBS_READY
08-14 07:23:22.282 25587 25602 W GeckoThread: zerdatime 535509 - runGecko
08-14 07:23:22.285 25279 25315 E eglCodecCommon: glUtilsParamSize: unknow param 0x00008741
08-14 07:23:22.293 25214 25229 D GeckoViewModule: registerListener ["GeckoViewContent:ExitFullScreen","GeckoView:ClearMatches","GeckoView:DisplayMatches","GeckoView:FindInPage","GeckoView:HasCookieBannerRuleForBrowsingContextTree","GeckoView:RestoreState","GeckoView:ContainsFormData","GeckoView:RequestAnalysis","GeckoView:RequestRecommendations","GeckoView:ScrollBy","GeckoView:ScrollTo","GeckoView:SetActive","GeckoView:SetFocused","GeckoView:SetPriorityHint","GeckoView:UpdateInitData","GeckoView:ZoomToInput","GeckoView:IsPdfJs"]
08-14 07:23:22.293 25214 25229 D GeckoViewNavigation: onInit
08-14 07:23:22.293 25214 25229 D GeckoViewModule: registerListener ["GeckoView:GoBack","GeckoView:GoForward","GeckoView:GotoHistoryIndex","GeckoView:LoadUri","GeckoView:Reload","GeckoView:Stop","GeckoView:PurgeHistory","GeckoView:DotPrintFinish"]
08-14 07:23:22.294 25214 25229 D GeckoViewNavigation: onEnable
08-14 07:23:22.294 25214 25229 D GeckoViewProcessHangMonitor: onInit
08-14 07:23:22.294 25214 25229 D GeckoViewProcessHangMonitor: onEnable
08-14 07:23:22.295 25214 25229 D GeckoViewModule: registerListener ["GeckoView:HangReportStop","GeckoView:HangReportWait"]
08-14 07:23:22.295 25214 25229 D GeckoViewSettings: onInit
08-14 07:23:22.295 25279 25315 D EGL_emulation: eglMakeCurrent: 0x73bf8207e560: ver 3 0 (tinfo 0x73bf778b9120)
08-14 07:23:22.296 25214 25229 D GeckoViewModule: registerListener ["GeckoView:GetUserAgent"]
08-14 07:23:22.296 25214 25229 D GeckoViewSettings: onSettingsUpdate: {"chromeUri":null,"screenId":0,"userAgentOverride":null,"allowJavascript":true,"userAgentMode":0,"viewportMode":0,"useTrackingProtection":false,"suspendMediaWhenInactive":false,"usePrivateMode":false,"unsafeSessionContextId":null,"displayMode":0,"sessionContextId":null,"fullAccessibilityTree":false,"isPopup":false}
08-14 07:23:22.297 25214 25229 D GeckoViewModule: registerListener ["GeckoView:WebExtension:SetTabActive"]
08-14 07:23:22.299 25214 25229 I GeckoSession: zerdatime 535527 - chrome startup finished
08-14 07:23:22.300 25214 25229 I Gecko : 1691997802299 RemoteAgent TRACE Received DOM event load for [object HTMLDocument]
08-14 07:23:22.301 25244 25261 D GeckoViewClipboardPermissionChild[C]: handleEvent: deactivate
08-14 07:23:22.302 25244 25261 D GeckoViewSelectionActionDelegate[C]: handleEvent: visibilitychange
08-14 07:23:22.310 25587 25602 D GeckoThread: State changed to RUNNING
08-14 07:23:22.310 25279 25315 D EGL_emulation: eglMakeCurrent: 0x73bf8207e560: ver 3 0 (tinfo 0x73bf778b9120)
08-14 07:23:22.311 25279 25315 E eglCodecCommon: glUtilsParamSize: unknow param 0x00008caa
08-14 07:23:22.318 25214 25229 D GeckoViewModule: dispatch GeckoView:WebExtension:SetTabActive, data={"active":true}
08-14 07:23:22.320 25214 25229 D GeckoViewTab: onEvent: event=GeckoView:WebExtension:SetTabActive, data={"active":true}
08-14 07:23:22.321 25214 25229 D GeckoViewXUL: onEvent GeckoView:UpdateModuleState {"enabled":true,"module":"GeckoViewExperiment"}
08-14 07:23:22.326 25214 25229 D GeckoViewClipboardPermissionParent: receiveMessage: DispatcherMessage
08-14 07:23:22.326 25214 25214 D GeckoSession: handleMessage: GeckoView:DismissClipboardPermissionRequest
08-14 07:23:22.335 25587 25602 D GeckoViewStartup: observe: content-process-ready-for-script
08-14 07:23:22.336 25587 25602 D GeckoViewConsole: enabled = true
08-14 07:23:22.343 25279 25315 D EGL_emulation: eglMakeCurrent: 0x73bf8207e560: ver 3 0 (tinfo 0x73bf778b9120)
08-14 07:23:22.343 25279 25315 E eglCodecCommon: glUtilsParamSize: unknow param 0x00008caa
08-14 07:23:22.358 25214 25229 I Gecko : 1691997802358 Marionette TRACE Received observer notification browser-delayed-startup-finished
08-14 07:23:22.370 25587 25602 D GeckoViewSelectionActionDelegate[C]: handleEvent: visibilitychange
08-14 07:23:22.372 25587 25602 D GeckoViewClipboardPermissionChild[C]: handleEvent: deactivate
08-14 07:23:22.374 25214 25229 D GeckoViewClipboardPermissionParent: receiveMessage: DispatcherMessage
08-14 07:23:22.375 25214 25229 W GeckoEventDispatcher: No listener for GeckoView:DismissClipboardPermissionRequest
08-14 07:23:22.376 25587 25602 D GeckoViewSettings[C]: receiveMessage: SettingsUpdate
08-14 07:23:22.380 25214 25229 D GeckoViewXUL: receiveMessage GeckoView:ContentModuleLoaded {"module":"SessionStateAggregator"}
08-14 07:23:22.393 25279 25315 E eglCodecCommon: glUtilsParamSize: unknow param 0x00008caa
08-14 07:23:23.397 25214 25229 W GeckoEventDispatcher: No listener for GeckoView:StateUpdated
08-14 07:23:23.737 25214 25623 D ProfileInstaller: Installing profile for org.mozilla.geckoview.test_runner
08-14 07:23:24.925 25214 25229 D GeckoIdleService: Get idle time: time since reset 5395 msec
08-14 07:23:24.925 25214 25229 D GeckoIdleService: Idle timer callback: current idle time 5395 msec
08-14 07:23:24.925 25214 25229 D GeckoIdleService: next timeout 4294967289605 msec from now
08-14 07:23:24.925 25214 25229 D GeckoIdleService: SetTimerExpiryIfBefore: next timeout 4294967289605 msec from now
08-14 07:23:24.925 25214 25229 D GeckoIdleService: reset timer expiry to 4294967289615 msec from now
08-14 07:23:24.925 25214 25229 D GeckoIdleService: Idle timer callback: tell observer 0x73bf55438b28 user is idle
08-14 07:23:48.983 25214 25229 I Gecko : console.error: (new Error("Polling for changes failed: Unexpected content-type \"text/plain;charset=US-ASCII\".", "resource://services-settings/remote-settings.sys.mjs", 321))
08-14 07:23:48.983 25214 25229 E GeckoConsole: [JavaScript Error: "Error: Polling for changes failed: Unexpected content-type "text/plain;charset=US-ASCII"."]
08-14 07:24:17.085 25214 25229 D GeckoIdleService: Get idle time: time since reset 57555 msec
08-14 07:25:01.448 25214 25229 I Gecko : 1691997901448 WebDriver BiDi DEBUG Unregistered session handler: /session/0330ba01-70f4-49a7-b02a-2c487d797e5e
08-14 07:25:01.449 25244 25261 I Gecko : 1691997901449 Marionette TRACE [2] MarionetteCommands actor destroyed for window id 2147483649
08-14 07:25:01.453 25214 25229 I Gecko : 1691997901453 RemoteAgent DEBUG WebDriverBiDiConnection c8ddf1f8-6be2-49c3-843a-5e4e732c262d closed
08-14 07:25:01.458 25214 25229 I Gecko : 1691997901458 RemoteAgent TRACE MessageHandler ROOT for session 0330ba01-70f4-49a7-b02a-2c487d797e5e is being destroyed
08-14 07:25:01.459 25214 25229 I Gecko : 1691997901459 RemoteAgent TRACE Unregistered MessageHandler ROOT for session 0330ba01-70f4-49a7-b02a-2c487d797e5e
08-14 07:25:01.460 25214 25229 I Gecko : 1691997901460 Marionette DEBUG Closed connection 0
For now lets observe how often this happens.
OS: Unspecified → Android
Hardware: Unspecified → All
Summary: Intermittent TEST-UNEXPECTED-TIMEOUT | /webdriver/tests/bidi/script/evaluate/sandbox.py | expected OK (hang after POST /session/<id>/frame {"id": null} ) → Intermittent Wd Android TEST-UNEXPECTED-TIMEOUT | expected OK (hang in "browsingContext.create")
| Comment hidden (Intermittent Failures Robot) |
|
|
||
Comment 3•1 year ago
|
||
Latest failure is on desktop for a CCOV build: https://treeherder.mozilla.org/logviewer?job_id=436413781&repo=mozilla-central
OS: Android → All
Summary: Intermittent Wd Android TEST-UNEXPECTED-TIMEOUT | expected OK (hang in "browsingContext.create") → Intermittent Wd TEST-UNEXPECTED-TIMEOUT | expected OK (hang in "browsingContext.create")
| Comment hidden (Intermittent Failures Robot) |
|
||
Comment 5•1 year ago
|
||
https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
For more information, please visit BugBot documentation.
Status: NEW → RESOLVED
Closed: 1 year ago
Resolution: --- → INCOMPLETE
|
Reporter | |
Comment 6•8 months ago
|
||
| treeherder | ||
New failure instance: https://treeherder.mozilla.org/logviewer?job_id=452658307&repo=mozilla-central
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
|
|
||
Comment 7•7 months ago
|
||
https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
For more information, please visit BugBot documentation.
Status: REOPENED → RESOLVED
Closed: 1 year ago → 7 months ago
Resolution: --- → INCOMPLETE
|
|
Reporter | |
Comment 8•3 months ago
|
||
| treeherder | ||
New failure instance: https://treeherder.mozilla.org/logviewer?job_id=474141725&repo=mozilla-central
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
| Comment hidden (Intermittent Failures Robot) |
|
|
||
Comment 10•2 months ago
|
||
https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
For more information, please visit BugBot documentation.
Status: REOPENED → RESOLVED
Closed: 7 months ago → 2 months ago
Resolution: --- → INCOMPLETE
|
|
Reporter | |
Comment 11•2 months ago
|
||
| treeherder | ||
New failure instance: https://treeherder.mozilla.org/logviewer?job_id=478027634&repo=mozilla-central
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
| Comment hidden (Intermittent Failures Robot) |
You need to log in
before you can comment on or make changes to this bug.
Description
•