Closed Bug 1830564 Opened 2 years ago Closed 2 years ago

Intermittent TEST-UNEXPECTED-TIMEOUT | /webdriver/tests/bidi/input/perform_actions/key.py | expected OK

Categories

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

defect

Tracking

(Not tracked)

RESOLVED DUPLICATE of bug 1791951

People

(Reporter: intermittent-bug-filer, Unassigned)

Details

(Keywords: intermittent-failure)

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


[task 2023-04-28T16:38:57.015Z] 16:38:57     INFO - STDOUT: PASSED
[task 2023-04-28T16:38:57.017Z] 16:38:57     INFO - PID 1020 | 1682699937016	RemoteAgent	DEBUG	WebDriverBiDiConnection 5e54950a-f34a-4310-b402-793be1269d47 -> {"id":695,"method":"input.releaseActions","params":{"context":"a29653f5-91f4-48f8-ab3d-060e1af754cd"}}
[task 2023-04-28T16:38:57.019Z] 16:38:57     INFO - PID 1020 | 1682699937016	RemoteAgent	TRACE	Received command input.releaseActions for destination ROOT
[task 2023-04-28T16:38:57.026Z] 16:38:57     INFO - PID 1020 | 1682699937025	RemoteAgent	TRACE	Received command input.releaseActions for destination WINDOW_GLOBAL
[task 2023-04-28T16:38:57.030Z] 16:38:57     INFO - PID 1020 | 1682699937025	Marionette	TRACE	Dispatch KeyUpAction with key-0 a
[task 2023-04-28T16:38:57.031Z] 16:38:57     INFO - PID 1020 | 1682699937028	RemoteAgent	DEBUG	WebDriverBiDiConnection 5e54950a-f34a-4310-b402-793be1269d47 <- {"id":695,"result":{}}
[task 2023-04-28T16:38:57.039Z] 16:38:57     INFO - PID 1020 | 1682699937034	webdriver::server	DEBUG	-> POST /session/17beb64e-5efd-4cd9-906a-ff5728378748/timeouts {"implicit": 0}
[task 2023-04-28T16:38:57.040Z] 16:38:57     INFO - PID 1020 | 1682699937035	RemoteAgent	DEBUG	WebDriverBiDiConnection 5e54950a-f34a-4310-b402-793be1269d47 closed
[task 2023-04-28T16:38:57.041Z] 16:38:57     INFO - PID 1020 | 1682699937036	Marionette	DEBUG	0 -> [0,1572,"WebDriver:SetTimeouts",{"implicit":0}]
[task 2023-04-28T16:38:57.041Z] 16:38:57     INFO - PID 1020 | 1682699937037	Marionette	DEBUG	0 <- [1,1572,null,{"value":null}]
[task 2023-04-28T16:38:57.042Z] 16:38:57     INFO - PID 1020 | 1682699937038	webdriver::server	DEBUG	<- 200 OK {"value":null}
[task 2023-04-28T16:38:57.043Z] 16:38:57     INFO - PID 1020 | 1682699937040	webdriver::server	DEBUG	-> POST /session/17beb64e-5efd-4cd9-906a-ff5728378748/timeouts {"pageLoad": 300000}
[task 2023-04-28T16:38:57.043Z] 16:38:57     INFO - PID 1020 | 1682699937042	Marionette	DEBUG	0 -> [0,1573,"WebDriver:SetTimeouts",{"pageLoad":300000}]
[task 2023-04-28T16:38:57.044Z] 16:38:57     INFO - PID 1020 | 1682699937043	Marionette	DEBUG	0 <- [1,1573,null,{"value":null}]
[task 2023-04-28T16:38:57.053Z] 16:38:57     INFO - PID 1020 | 1682699937051	webdriver::server	DEBUG	<- 200 OK {"value":null}
[task 2023-04-28T16:38:57.054Z] 16:38:57     INFO - PID 1020 | 1682699937052	webdriver::server	DEBUG	-> POST /session/17beb64e-5efd-4cd9-906a-ff5728378748/timeouts {"script": 30000}
[task 2023-04-28T16:38:57.057Z] 16:38:57     INFO - PID 1020 | 1682699937055	Marionette	DEBUG	0 -> [0,1574,"WebDriver:SetTimeouts",{"script":30000}]
[task 2023-04-28T16:38:57.058Z] 16:38:57     INFO - PID 1020 | 1682699937056	Marionette	DEBUG	0 <- [1,1574,null,{"value":null}]
[task 2023-04-28T16:38:57.062Z] 16:38:57     INFO - PID 1020 | 1682699937061	webdriver::server	DEBUG	<- 200 OK {"value":null}
[task 2023-04-28T16:38:57.063Z] 16:38:57     INFO - PID 1020 | 1682699937062	webdriver::server	DEBUG	-> GET /session/17beb64e-5efd-4cd9-906a-ff5728378748/window
[task 2023-04-28T16:38:57.066Z] 16:38:57     INFO - PID 1020 | 1682699937065	Marionette	DEBUG	0 -> [0,1575,"WebDriver:GetWindowHandle",{}]
[task 2023-04-28T16:38:57.067Z] 16:38:57     INFO - PID 1020 | 1682699937065	Marionette	DEBUG	0 <- [1,1575,null,{"value":"a29653f5-91f4-48f8-ab3d-060e1af754cd"}]
[task 2023-04-28T16:38:57.068Z] 16:38:57     INFO - PID 1020 | 1682699937067	webdriver::server	DEBUG	<- 200 OK {"value":"a29653f5-91f4-48f8-ab3d-060e1af754cd"}
[task 2023-04-28T16:38:57.069Z] 16:38:57     INFO - PID 1020 | 1682699937068	webdriver::server	DEBUG	-> GET /session/17beb64e-5efd-4cd9-906a-ff5728378748/window
[task 2023-04-28T16:38:57.070Z] 16:38:57     INFO - PID 1020 | 1682699937070	Marionette	DEBUG	0 -> [0,1576,"WebDriver:GetWindowHandle",{}]
[task 2023-04-28T16:38:57.071Z] 16:38:57     INFO - PID 1020 | 1682699937070	Marionette	DEBUG	0 <- [1,1576,null,{"value":"a29653f5-91f4-48f8-ab3d-060e1af754cd"}]
[task 2023-04-28T16:38:57.074Z] 16:38:57     INFO - PID 1020 | 1682699937071	webdriver::server	DEBUG	<- 200 OK {"value":"a29653f5-91f4-48f8-ab3d-060e1af754cd"}
[task 2023-04-28T16:38:57.074Z] 16:38:57     INFO - PID 1020 | 1682699937072	webdriver::server	DEBUG	-> GET /session/17beb64e-5efd-4cd9-906a-ff5728378748/window/handles
[task 2023-04-28T16:38:57.075Z] 16:38:57     INFO - PID 1020 | 1682699937074	Marionette	DEBUG	0 -> [0,1577,"WebDriver:GetWindowHandles",{}]
[task 2023-04-28T16:38:57.076Z] 16:38:57     INFO - PID 1020 | 1682699937075	Marionette	DEBUG	0 <- [1,1577,null,["a29653f5-91f4-48f8-ab3d-060e1af754cd"]]
[task 2023-04-28T16:38:57.078Z] 16:38:57     INFO - PID 1020 | 1682699937076	webdriver::server	DEBUG	<- 200 OK {"value":["a29653f5-91f4-48f8-ab3d-060e1af754cd"]}
[task 2023-04-28T16:38:57.079Z] 16:38:57     INFO - PID 1020 | 1682699937077	webdriver::server	DEBUG	-> POST /session/17beb64e-5efd-4cd9-906a-ff5728378748/window {"handle": "a29653f5-91f4-48f8-ab3d-060e1af754cd"}
[task 2023-04-28T16:38:57.090Z] 16:38:57     INFO - PID 1020 | 1682699937084	Marionette	DEBUG	0 -> [0,1578,"WebDriver:SwitchToWindow",{"handle":"a29653f5-91f4-48f8-ab3d-060e1af754cd"}]
[task 2023-04-28T16:38:57.090Z] 16:38:57     INFO - PID 1020 | 1682699937086	Marionette	DEBUG	0 <- [1,1578,null,{"value":null}]
[task 2023-04-28T16:38:57.091Z] 16:38:57     INFO - PID 1020 | 1682699937088	webdriver::server	DEBUG	<- 200 OK {"value":null}
[task 2023-04-28T16:38:57.093Z] 16:38:57     INFO - PID 1020 | 1682699937089	webdriver::server	DEBUG	-> POST /session/17beb64e-5efd-4cd9-906a-ff5728378748/alert/dismiss {}
[task 2023-04-28T16:38:57.096Z] 16:38:57     INFO - PID 1020 | 1682699937095	Marionette	DEBUG	0 -> [0,1579,"WebDriver:DismissAlert",{}]
[task 2023-04-28T16:38:57.099Z] 16:38:57     INFO - PID 1020 | 1682699937097	Marionette	DEBUG	0 <- [1,1579,{"error":"no such alert","message":"","stacktrace":"RemoteError@chrome://remote/content/shared/RemoteError.sys.mjs:8:8\nWebDriverError@chrome://remote/content/shared/webdriver/Er ... ote/content/marionette/server.sys.mjs:249:9\n_onJSONObjectReady/<@chrome://remote/content/marionette/transport.sys.mjs:496:20\n"},null]
[task 2023-04-28T16:38:57.101Z] 16:38:57     INFO - PID 1020 | 1682699937098	webdriver::server	DEBUG	<- 404 Not Found {"value":{"error":"no such alert","message":"","stacktrace":"RemoteError@chrome://remote/content/shared/Remo ... ontent/marionette/server.sys.mjs:249:9\n_onJSONObjectReady/<@chrome://remote/content/marionette/transport.sys.mjs:496:20\n"}}
[task 2023-04-28T16:38:57.102Z] 16:38:57     INFO - PID 1020 | 1682699937100	webdriver::server	DEBUG	-> POST /session/17beb64e-5efd-4cd9-906a-ff5728378748/window {"handle": "a29653f5-91f4-48f8-ab3d-060e1af754cd"}
[task 2023-04-28T16:38:57.120Z] 16:38:57     INFO - PID 1020 | 1682699937118	Marionette	DEBUG	0 -> [0,1580,"WebDriver:SwitchToWindow",{"handle":"a29653f5-91f4-48f8-ab3d-060e1af754cd"}]
[task 2023-04-28T16:38:57.122Z] 16:38:57     INFO - PID 1020 | 1682699937121	Marionette	DEBUG	0 <- [1,1580,null,{"value":null}]
[task 2023-04-28T16:38:57.123Z] 16:38:57     INFO - PID 1020 | 1682699937122	webdriver::server	DEBUG	<- 200 OK {"value":null}
[task 2023-04-28T16:38:57.125Z] 16:38:57     INFO - PID 1020 | 1682699937124	webdriver::server	DEBUG	-> GET /session/17beb64e-5efd-4cd9-906a-ff5728378748/window
[task 2023-04-28T16:38:57.127Z] 16:38:57     INFO - PID 1020 | 1682699937126	Marionette	DEBUG	0 -> [0,1581,"WebDriver:GetWindowHandle",{}]
[task 2023-04-28T16:38:57.128Z] 16:38:57     INFO - PID 1020 | 1682699937127	Marionette	DEBUG	0 <- [1,1581,null,{"value":"a29653f5-91f4-48f8-ab3d-060e1af754cd"}]
[task 2023-04-28T16:38:57.131Z] 16:38:57     INFO - PID 1020 | 1682699937129	webdriver::server	DEBUG	<- 200 OK {"value":"a29653f5-91f4-48f8-ab3d-060e1af754cd"}
[task 2023-04-28T16:38:57.131Z] 16:38:57     INFO - PID 1020 | 1682699937130	webdriver::server	DEBUG	-> GET /session/17beb64e-5efd-4cd9-906a-ff5728378748/window/handles
[task 2023-04-28T16:38:57.133Z] 16:38:57     INFO - PID 1020 | 1682699937132	Marionette	DEBUG	0 -> [0,1582,"WebDriver:GetWindowHandles",{}]
[task 2023-04-28T16:38:57.136Z] 16:38:57     INFO - PID 1020 | 1682699937134	Marionette	DEBUG	0 <- [1,1582,null,["a29653f5-91f4-48f8-ab3d-060e1af754cd"]]
[task 2023-04-28T16:38:57.136Z] 16:38:57     INFO - PID 1020 | 1682699937134	webdriver::server	DEBUG	<- 200 OK {"value":["a29653f5-91f4-48f8-ab3d-060e1af754cd"]}
[task 2023-04-28T16:38:57.137Z] 16:38:57     INFO - PID 1020 | 1682699937136	webdriver::server	DEBUG	-> POST /session/17beb64e-5efd-4cd9-906a-ff5728378748/window {"handle": "a29653f5-91f4-48f8-ab3d-060e1af754cd"}
[task 2023-04-28T16:38:57.141Z] 16:38:57     INFO - PID 1020 | 1682699937140	Marionette	DEBUG	0 -> [0,1583,"WebDriver:SwitchToWindow",{"handle":"a29653f5-91f4-48f8-ab3d-060e1af754cd"}]
[task 2023-04-28T16:38:57.144Z] 16:38:57     INFO - PID 1020 | 1682699937143	Marionette	DEBUG	0 <- [1,1583,null,{"value":null}]
[task 2023-04-28T16:38:57.145Z] 16:38:57     INFO - PID 1020 | 1682699937144	webdriver::server	DEBUG	<- 200 OK {"value":null}
[task 2023-04-28T16:38:57.146Z] 16:38:57     INFO - PID 1020 | 1682699937145	webdriver::server	DEBUG	-> POST /session/17beb64e-5efd-4cd9-906a-ff5728378748/window/rect {"width": 800, "height": 600}
[task 2023-04-28T16:38:57.147Z] 16:38:57     INFO - PID 1020 | 1682699937147	Marionette	DEBUG	0 -> [0,1584,"WebDriver:SetWindowRect",{"height":600,"width":800}]
[task 2023-04-28T16:38:57.148Z] 16:38:57     INFO - PID 1020 | 1682699937148	Marionette	TRACE	Requested window geometry matches
[task 2023-04-28T16:38:57.150Z] 16:38:57     INFO - PID 1020 | 1682699937149	Marionette	DEBUG	0 <- [1,1584,null,{"x":100,"y":100,"width":800,"height":600}]
[task 2023-04-28T16:38:57.150Z] 16:38:57     INFO - PID 1020 | 1682699937150	webdriver::server	DEBUG	<- 200 OK {"value":{"x":100,"y":100,"width":800,"height":600}}
[task 2023-04-28T16:38:57.152Z] 16:38:57     INFO - PID 1020 | 1682699937151	webdriver::server	DEBUG	-> POST /session/17beb64e-5efd-4cd9-906a-ff5728378748/frame {"id": null}
[task 2023-04-28T16:38:57.153Z] 16:38:57     INFO - PID 1020 | 1682699937152	Marionette	DEBUG	0 -> [0,1585,"WebDriver:SwitchToFrame",{"id":null}]
[task 2023-04-28T16:38:57.158Z] 16:38:57     INFO - PID 1020 | 1682699937157	Marionette	DEBUG	0 <- [1,1585,null,{"value":null}]
[task 2023-04-28T16:38:57.160Z] 16:38:57     INFO - PID 1020 | 1682699937158	webdriver::server	DEBUG	<- 200 OK {"value":null}
[task 2023-04-28T16:38:57.171Z] 16:38:57     INFO - PID 1020 | 1682699937170	webdriver::server	DEBUG	-> DELETE /session/17beb64e-5efd-4cd9-906a-ff5728378748
[task 2023-04-28T16:38:57.173Z] 16:38:57     INFO - PID 1020 | 1682699937172	Marionette	DEBUG	0 -> [0,1586,"Marionette:Quit",{"flags":["eForceQuit"]}]
[task 2023-04-28T16:38:57.174Z] 16:38:57     INFO - PID 1020 | 1682699937173	Marionette	INFO	Stopped listening on port 45618
[task 2023-04-28T16:38:57.177Z] 16:38:57     INFO - PID 1020 | 1682699937176	Marionette	TRACE	[11] MarionetteCommands actor destroyed for window id 6442451042
[task 2023-04-28T16:38:57.185Z] 16:38:57     INFO - PID 1020 | 1682699937183	WebDriver BiDi	DEBUG	Unregistered session handler: /session/17beb64e-5efd-4cd9-906a-ff5728378748
[task 2023-04-28T16:38:57.195Z] 16:38:57     INFO - PID 1020 | 1682699937194	RemoteAgent	TRACE	MessageHandler ROOT for session 17beb64e-5efd-4cd9-906a-ff5728378748 is being destroyed
[task 2023-04-28T16:38:57.197Z] 16:38:57     INFO - PID 1020 | 1682699937195	RemoteAgent	TRACE	Unregistered MessageHandler ROOT for session 17beb64e-5efd-4cd9-906a-ff5728378748
[task 2023-04-28T16:38:57.334Z] 16:38:57     INFO - PID 1020 | [Child 17914, Main Thread] WARNING: JSWindowActorChild::SendRawMessage (Conduits, ConduitClosed) not sent: !CanSend() || !mManager || !mManager->CanSend(): file /builds/worker/checkouts/gecko/dom/ipc/jsactor/JSWindowActorChild.cpp:57
[task 2023-04-28T16:38:57.336Z] 16:38:57     INFO - PID 1020 | [Child 17914, Main Thread] WARNING: JSWindowActorChild::SendRawMessage (Conduits, ConduitClosed) not sent: !CanSend() || !mManager || !mManager->CanSend(): file /builds/worker/checkouts/gecko/dom/ipc/jsactor/JSWindowActorChild.cpp:57
[task 2023-04-28T16:38:57.357Z] 16:38:57     INFO - PID 1020 | [Child 17914, Main Thread] WARNING: JSWindowActorChild::SendRawMessage (Conduits, ConduitClosed) not sent: !CanSend() || !mManager || !mManager->CanSend(): file /builds/worker/checkouts/gecko/dom/ipc/jsactor/JSWindowActorChild.cpp:57
[task 2023-04-28T16:38:57.366Z] 16:38:57     INFO - PID 1020 | [Child 17914, Main Thread] WARNING: JSWindowActorChild::SendRawMessage (Conduits, ConduitClosed) not sent: !CanSend() || !mManager || !mManager->CanSend(): file /builds/worker/checkouts/gecko/dom/ipc/jsactor/JSWindowActorChild.cpp:57
[task 2023-04-28T16:38:57.368Z] 16:38:57     INFO - PID 1020 | [Child 17914, Main Thread] WARNING: JSWindowActorChild::SendRawMessage (Conduits, ConduitClosed) not sent: !CanSend() || !mManager || !mManager->CanSend(): file /builds/worker/checkouts/gecko/dom/ipc/jsactor/JSWindowActorChild.cpp:57
[task 2023-04-28T16:38:57.369Z] 16:38:57     INFO - PID 1020 | [Child 17914, Main Thread] WARNING: JSWindowActorChild::SendRawMessage (Conduits, ConduitClosed) not sent: !CanSend() || !mManager || !mManager->CanSend(): file /builds/worker/checkouts/gecko/dom/ipc/jsactor/JSWindowActorChild.cpp:57
[task 2023-04-28T16:38:57.371Z] 16:38:57     INFO - PID 1020 | [Child 17914, Main Thread] WARNING: JSWindowActorChild::SendRawMessage (Conduits, ConduitClosed) not sent: !CanSend() || !mManager || !mManager->CanSend(): file /builds/worker/checkouts/gecko/dom/ipc/jsactor/JSWindowActorChild.cpp:57
[task 2023-04-28T16:38:57.509Z] 16:38:57     INFO - PID 1020 | 1682699937508	Marionette	TRACE	Received observer notification quit-application
[task 2023-04-28T16:38:57.519Z] 16:38:57     INFO - PID 1020 | 1682699937518	Marionette	TRACE	Received observer notification quit-application
[task 2023-04-28T16:38:57.520Z] 16:38:57     INFO - PID 1020 | 1682699937519	Marionette	DEBUG	Marionette stopped listening
[task 2023-04-28T16:38:57.521Z] 16:38:57     INFO - PID 1020 | 1682699937520	RemoteAgent	TRACE	Received observer notification quit-application
[task 2023-04-28T16:38:57.526Z] 16:38:57     INFO - PID 1020 | 1682699937525	Marionette	DEBUG	0 <- [1,1586,null,{"cause":"shutdown","forced":false,"in_app":true}]
[task 2023-04-28T16:38:57.662Z] 16:38:57     INFO - PID 1020 | 1682699937659	RemoteAgent	TRACE	MessageHandler WINDOW_GLOBAL for session 17beb64e-5efd-4cd9-906a-ff5728378748 is being destroyed
[task 2023-04-28T16:38:57.662Z] 16:38:57     INFO - PID 1020 | 1682699937661	RemoteAgent	TRACE	Unregistered MessageHandler WINDOW_GLOBAL for session 17beb64e-5efd-4cd9-906a-ff5728378748
[task 2023-04-28T16:38:57.679Z] 16:38:57     INFO - PID 1020 | 1682699937678	RemoteAgent	DEBUG	Resetting recommended pref browser.contentblocking.features.standard
[task 2023-04-28T16:38:57.680Z] 16:38:57     INFO - PID 1020 | 1682699937678	RemoteAgent	DEBUG	Resetting recommended pref network.cookie.cookieBehavior
[task 2023-04-28T16:38:57.683Z] 16:38:57     INFO - PID 1020 | 1682699937680	webdriver::server	DEBUG	Teardown session
[task 2023-04-28T16:38:57.705Z] 16:38:57     INFO - PID 1020 | 1682699937703	Marionette	DEBUG	Closed connection 0
[task 2023-04-28T16:38:57.935Z] 16:38:57     INFO - PID 1020 | *** You are running in background task mode. ***
[task 2023-04-28T16:38:57.935Z] 16:38:57     INFO - PID 1020 | *** You are running in headless mode.
[task 2023-04-28T16:38:58.449Z] 16:38:58     INFO - PID 1020 | console.error: "/tmp/tmph7b05mzk.mozrunner/storage" "to-be-removed" 0 "" ""
[task 2023-04-28T16:38:58.455Z] 16:38:58     INFO - PID 1020 | console.error: "started removing /tmp/tmph7b05mzk.mozrunner/storage/to-be-removed"
[task 2023-04-28T16:38:58.456Z] 16:38:58     INFO - PID 1020 | console.error: "done removing /tmp/tmph7b05mzk.mozrunner/storage/to-be-removed. removed 1 entries."
[task 2023-04-28T16:38:58.458Z] 16:38:58     INFO - PID 1020 | console.warn: "Skipping Glean as no metrics id is passed"
[task 2023-04-28T16:38:58.477Z] 16:38:58     INFO - TEST-UNEXPECTED-TIMEOUT | /webdriver/tests/bidi/input/perform_actions/key.py | expected OK
[task 2023-04-28T16:38:58.477Z] 16:38:58     INFO - TEST-INFO took 80002ms
[task 2023-04-28T16:38:58.712Z] 16:38:58     INFO - Closing logging queue
[task 2023-04-28T16:38:58.713Z] 16:38:58     INFO - queue closed
[task 2023-04-28T16:38:58.726Z] 16:38:58     INFO - PID 18143 | 1682699938724	geckodriver	INFO	Listening on 127.0.0.1:41512
[task 2023-04-28T16:38:58.727Z] 16:38:58     INFO - Starting runner
[task 2023-04-28T16:38:58.983Z] 16:38:58     INFO - TEST-START | /webdriver/tests/bidi/input/perform_actions/key_modifier.py

The initial launch of Firefox took quite some time for these particular TSAN builds. So it's basically a dupe of bug 1791951.

Status: NEW → RESOLVED
Closed: 2 years ago
Duplicate of bug: 1791951
Resolution: --- → DUPLICATE
You need to log in before you can comment on or make changes to this bug.