Closed Bug 1772728 Opened 3 years ago Closed 3 years ago

Intermittent [Tier 2] TEST-UNEXPECTED-TIMEOUT | /webdriver/tests/perform_actions/validity.py | expected OK

Tracking

(Not tracked)

Status:

RESOLVED DUPLICATE of bug 1630162

People

(Reporter: intermittent-bug-filer, Unassigned)

Details

(Keywords: intermittent-failure)

Treeherder Bug Filer

Reporter

Description

•

3 years ago

treeherder

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

[task 2022-06-04T22:59:00.309Z] 22:59:00     INFO - STDOUT: tests/web-platform/tests/webdriver/tests/perform_actions/validity.py::test_action_without_id[pointer] 
[task 2022-06-04T22:59:00.309Z] 22:59:00     INFO - PID 21870 | 1654383540308	webdriver::server	DEBUG	-> POST /session/6b4b7246-79e9-4fe9-810f-80393693c7f4/window/rect {"width": 800, "height": 600}
[task 2022-06-04T22:59:00.310Z] 22:59:00     INFO - PID 21870 | 1654383540308	Marionette	DEBUG	0 -> [0,192,"WebDriver:SetWindowRect",{"height":600,"width":800}]
[task 2022-06-04T22:59:00.310Z] 22:59:00     INFO - PID 21870 | 1654383540309	Marionette	DEBUG	0 <- [1,192,null,{"x":100,"y":100,"width":800,"height":600}]
[task 2022-06-04T22:59:00.311Z] 22:59:00     INFO - PID 21870 | 1654383540310	webdriver::server	DEBUG	<- 200 OK {"value":{"x":100,"y":100,"width":800,"height":600}}
[task 2022-06-04T22:59:00.311Z] 22:59:00     INFO - PID 21870 | 1654383540310	webdriver::server	DEBUG	-> POST /session/6b4b7246-79e9-4fe9-810f-80393693c7f4/window/rect {"x": 100, "y": 100}
[task 2022-06-04T22:59:00.312Z] 22:59:00     INFO - PID 21870 | 1654383540311	Marionette	DEBUG	0 -> [0,193,"WebDriver:SetWindowRect",{"x":100,"y":100}]
[task 2022-06-04T22:59:00.313Z] 22:59:00     INFO - PID 21870 | 1654383540312	Marionette	DEBUG	0 <- [1,193,null,{"x":100,"y":100,"width":800,"height":600}]
[task 2022-06-04T22:59:00.313Z] 22:59:00     INFO - PID 21870 | 1654383540312	webdriver::server	DEBUG	<- 200 OK {"value":{"x":100,"y":100,"width":800,"height":600}}
[task 2022-06-04T22:59:00.314Z] 22:59:00     INFO - PID 21870 | 1654383540313	webdriver::server	DEBUG	-> POST /session/6b4b7246-79e9-4fe9-810f-80393693c7f4/actions {"actions": [{"type": "pointer", "actions": [{"type": "pause", "duration": 1}]}]}
[task 2022-06-04T22:59:00.315Z] 22:59:00     INFO - PID 21870 | 1654383540313	webdriver::server	DEBUG	<- 400 Bad Request {"value":{"error":"invalid argument","message":"missing field `id` at line 1 column 79","stacktrace":""}}
[task 2022-06-04T22:59:00.316Z] 22:59:00     INFO - STDOUT: PASSED
[task 2022-06-04T22:59:00.316Z] 22:59:00     INFO - PID 21870 | 1654383540315	webdriver::server	DEBUG	-> DELETE /session/6b4b7246-79e9-4fe9-810f-80393693c7f4/actions
[task 2022-06-04T22:59:00.317Z] 22:59:00     INFO - PID 21870 | 1654383540315	Marionette	DEBUG	0 -> [0,194,"WebDriver:ReleaseActions",{}]
[task 2022-06-04T22:59:00.317Z] 22:59:00     INFO - PID 21870 | 1654383540316	Marionette	DEBUG	0 <- [1,194,null,{"value":null}]
[task 2022-06-04T22:59:00.318Z] 22:59:00     INFO - PID 21870 | 1654383540316	webdriver::server	DEBUG	<- 200 OK {"value":null}
[task 2022-06-04T22:59:00.319Z] 22:59:00     INFO - PID 21870 | 1654383540317	webdriver::server	DEBUG	-> POST /session/6b4b7246-79e9-4fe9-810f-80393693c7f4/timeouts {"implicit": 0}
[task 2022-06-04T22:59:00.319Z] 22:59:00     INFO - PID 21870 | 1654383540317	Marionette	DEBUG	0 -> [0,195,"WebDriver:SetTimeouts",{"implicit":0}]
[task 2022-06-04T22:59:00.320Z] 22:59:00     INFO - PID 21870 | 1654383540318	Marionette	DEBUG	0 <- [1,195,null,{"value":null}]
[task 2022-06-04T22:59:00.320Z] 22:59:00     INFO - PID 21870 | 1654383540318	webdriver::server	DEBUG	<- 200 OK {"value":null}
[task 2022-06-04T22:59:00.321Z] 22:59:00     INFO - PID 21870 | 1654383540319	webdriver::server	DEBUG	-> POST /session/6b4b7246-79e9-4fe9-810f-80393693c7f4/timeouts {"pageLoad": 300000}
[task 2022-06-04T22:59:00.321Z] 22:59:00     INFO - PID 21870 | 1654383540319	Marionette	DEBUG	0 -> [0,196,"WebDriver:SetTimeouts",{"pageLoad":300000}]
[task 2022-06-04T22:59:00.322Z] 22:59:00     INFO - PID 21870 | 1654383540320	Marionette	DEBUG	0 <- [1,196,null,{"value":null}]
[task 2022-06-04T22:59:00.323Z] 22:59:00     INFO - PID 21870 | 1654383540320	webdriver::server	DEBUG	<- 200 OK {"value":null}
[task 2022-06-04T22:59:00.323Z] 22:59:00     INFO - PID 21870 | 1654383540321	webdriver::server	DEBUG	-> POST /session/6b4b7246-79e9-4fe9-810f-80393693c7f4/timeouts {"script": 30000}
[task 2022-06-04T22:59:00.324Z] 22:59:00     INFO - PID 21870 | 1654383540321	Marionette	DEBUG	0 -> [0,197,"WebDriver:SetTimeouts",{"script":30000}]
[task 2022-06-04T22:59:00.324Z] 22:59:00     INFO - PID 21870 | 1654383540321	Marionette	DEBUG	0 <- [1,197,null,{"value":null}]
[task 2022-06-04T22:59:00.325Z] 22:59:00     INFO - PID 21870 | 1654383540322	webdriver::server	DEBUG	<- 200 OK {"value":null}
[task 2022-06-04T22:59:00.325Z] 22:59:00     INFO - PID 21870 | 1654383540322	webdriver::server	DEBUG	-> GET /session/6b4b7246-79e9-4fe9-810f-80393693c7f4/window
[task 2022-06-04T22:59:00.326Z] 22:59:00     INFO - PID 21870 | 1654383540323	Marionette	DEBUG	0 -> [0,198,"WebDriver:GetWindowHandle",{}]
[task 2022-06-04T22:59:00.326Z] 22:59:00     INFO - PID 21870 | 1654383540323	Marionette	DEBUG	0 <- [1,198,null,{"value":"023519f8-25bc-4f23-8912-172d4a26b35a"}]
[task 2022-06-04T22:59:00.327Z] 22:59:00     INFO - PID 21870 | 1654383540323	webdriver::server	DEBUG	<- 200 OK {"value":"023519f8-25bc-4f23-8912-172d4a26b35a"}
[task 2022-06-04T22:59:00.327Z] 22:59:00     INFO - PID 21870 | 1654383540324	webdriver::server	DEBUG	-> GET /session/6b4b7246-79e9-4fe9-810f-80393693c7f4/window
[task 2022-06-04T22:59:00.328Z] 22:59:00     INFO - PID 21870 | 1654383540324	Marionette	DEBUG	0 -> [0,199,"WebDriver:GetWindowHandle",{}]
[task 2022-06-04T22:59:00.329Z] 22:59:00     INFO - PID 21870 | 1654383540324	Marionette	DEBUG	0 <- [1,199,null,{"value":"023519f8-25bc-4f23-8912-172d4a26b35a"}]
[task 2022-06-04T22:59:00.329Z] 22:59:00     INFO - PID 21870 | 1654383540325	webdriver::server	DEBUG	<- 200 OK {"value":"023519f8-25bc-4f23-8912-172d4a26b35a"}
[task 2022-06-04T22:59:00.330Z] 22:59:00     INFO - PID 21870 | 1654383540325	webdriver::server	DEBUG	-> GET /session/6b4b7246-79e9-4fe9-810f-80393693c7f4/window/handles
[task 2022-06-04T22:59:00.330Z] 22:59:00     INFO - PID 21870 | 1654383540326	Marionette	DEBUG	0 -> [0,200,"WebDriver:GetWindowHandles",{}]
[task 2022-06-04T22:59:00.331Z] 22:59:00     INFO - PID 21870 | 1654383540326	Marionette	DEBUG	0 <- [1,200,null,["023519f8-25bc-4f23-8912-172d4a26b35a"]]
[task 2022-06-04T22:59:00.331Z] 22:59:00     INFO - PID 21870 | 1654383540326	webdriver::server	DEBUG	<- 200 OK {"value":["023519f8-25bc-4f23-8912-172d4a26b35a"]}
[task 2022-06-04T22:59:00.332Z] 22:59:00     INFO - PID 21870 | 1654383540327	webdriver::server	DEBUG	-> POST /session/6b4b7246-79e9-4fe9-810f-80393693c7f4/window {"handle": "023519f8-25bc-4f23-8912-172d4a26b35a"}
[task 2022-06-04T22:59:00.332Z] 22:59:00     INFO - PID 21870 | 1654383540327	Marionette	DEBUG	0 -> [0,201,"WebDriver:SwitchToWindow",{"handle":"023519f8-25bc-4f23-8912-172d4a26b35a"}]
[task 2022-06-04T22:59:00.333Z] 22:59:00     INFO - PID 21870 | 1654383540328	Marionette	DEBUG	0 <- [1,201,null,{"value":null}]
[task 2022-06-04T22:59:00.334Z] 22:59:00     INFO - PID 21870 | 1654383540328	webdriver::server	DEBUG	<- 200 OK {"value":null}
[task 2022-06-04T22:59:00.334Z] 22:59:00     INFO - PID 21870 | 1654383540329	webdriver::server	DEBUG	-> POST /session/6b4b7246-79e9-4fe9-810f-80393693c7f4/alert/dismiss {}
[task 2022-06-04T22:59:00.335Z] 22:59:00     INFO - PID 21870 | 1654383540330	Marionette	DEBUG	0 -> [0,202,"WebDriver:DismissAlert",{}]
[task 2022-06-04T22:59:00.335Z] 22:59:00     INFO - PID 21870 | 1654383540331	Marionette	DEBUG	0 <- [1,202,{"error":"no such alert","message":"","stacktrace":"WebDriverError@chrome://remote/content/shared/webdriver/Errors.jsm ... ote/content/marionette/server.js:249:9\n_onJSONObjectReady/<@chrome://remote/content/marionette/transport.js:500:20\n"},null]
[task 2022-06-04T22:59:00.336Z] 22:59:00     INFO - PID 21870 | 1654383540331	webdriver::server	DEBUG	<- 404 Not Found {"value":{"error":"no such alert","message":"","stacktrace":"WebDriverError@chrome://remote/content/shared/webdriver/Errors.jsm:186:5\nNoSuchAlertError@chrome://remote/content/shared/webdriver/Errors.jsm:387:5\nGeckoDriver.prototype._checkIfAlertIsPresent@chrome://remote/content/marionette/driver.js:2523:11\nGeckoDriver.prototype.dismissDialog@chrome://remote/content/marionette/driver.js:2434:8\ndespatch@chrome://remote/content/marionette/server.js:302:40\nexecute@chrome://remote/content/marionette/server.js:275:16\nonPacket/<@chrome://remote/content/marionette/server.js:248:20\nonPacket@chrome://remote/content/marionette/server.js:249:9\n_onJSONObjectReady/<@chrome://remote/content/marionette/transport.js:500:20\n"}}
[task 2022-06-04T22:59:00.337Z] 22:59:00     INFO - PID 21870 | 1654383540332	webdriver::server	DEBUG	-> POST /session/6b4b7246-79e9-4fe9-810f-80393693c7f4/window {"handle": "023519f8-25bc-4f23-8912-172d4a26b35a"}
[task 2022-06-04T22:59:00.337Z] 22:59:00     INFO - PID 21870 | 1654383540332	Marionette	DEBUG	0 -> [0,203,"WebDriver:SwitchToWindow",{"handle":"023519f8-25bc-4f23-8912-172d4a26b35a"}]
[task 2022-06-04T22:59:00.338Z] 22:59:00     INFO - PID 21870 | 1654383540333	Marionette	DEBUG	0 <- [1,203,null,{"value":null}]
[task 2022-06-04T22:59:00.338Z] 22:59:00     INFO - PID 21870 | 1654383540333	webdriver::server	DEBUG	<- 200 OK {"value":null}
[task 2022-06-04T22:59:00.339Z] 22:59:00     INFO - PID 21870 | 1654383540334	webdriver::server	DEBUG	-> GET /session/6b4b7246-79e9-4fe9-810f-80393693c7f4/window
[task 2022-06-04T22:59:00.340Z] 22:59:00     INFO - PID 21870 | 1654383540334	Marionette	DEBUG	0 -> [0,204,"WebDriver:GetWindowHandle",{}]
[task 2022-06-04T22:59:00.340Z] 22:59:00     INFO - PID 21870 | 1654383540334	Marionette	DEBUG	0 <- [1,204,null,{"value":"023519f8-25bc-4f23-8912-172d4a26b35a"}]
[task 2022-06-04T22:59:00.341Z] 22:59:00     INFO - PID 21870 | 1654383540335	webdriver::server	DEBUG	<- 200 OK {"value":"023519f8-25bc-4f23-8912-172d4a26b35a"}
[task 2022-06-04T22:59:00.341Z] 22:59:00     INFO - PID 21870 | 1654383540335	webdriver::server	DEBUG	-> GET /session/6b4b7246-79e9-4fe9-810f-80393693c7f4/window/handles
[task 2022-06-04T22:59:00.342Z] 22:59:00     INFO - PID 21870 | 1654383540336	Marionette	DEBUG	0 -> [0,205,"WebDriver:GetWindowHandles",{}]
[task 2022-06-04T22:59:00.342Z] 22:59:00     INFO - PID 21870 | 1654383540336	Marionette	DEBUG	0 <- [1,205,null,["023519f8-25bc-4f23-8912-172d4a26b35a"]]
[task 2022-06-04T22:59:00.343Z] 22:59:00     INFO - PID 21870 | 1654383540336	webdriver::server	DEBUG	<- 200 OK {"value":["023519f8-25bc-4f23-8912-172d4a26b35a"]}
[task 2022-06-04T22:59:00.344Z] 22:59:00     INFO - PID 21870 | 1654383540337	webdriver::server	DEBUG	-> POST /session/6b4b7246-79e9-4fe9-810f-80393693c7f4/window {"handle": "023519f8-25bc-4f23-8912-172d4a26b35a"}
[task 2022-06-04T22:59:00.344Z] 22:59:00     INFO - PID 21870 | 1654383540337	Marionette	DEBUG	0 -> [0,206,"WebDriver:SwitchToWindow",{"handle":"023519f8-25bc-4f23-8912-172d4a26b35a"}]
[task 2022-06-04T22:59:00.345Z] 22:59:00     INFO - PID 21870 | 1654383540338	Marionette	DEBUG	0 <- [1,206,null,{"value":null}]
[task 2022-06-04T22:59:00.345Z] 22:59:00     INFO - PID 21870 | 1654383540338	webdriver::server	DEBUG	<- 200 OK {"value":null}
[task 2022-06-04T22:59:00.346Z] 22:59:00     INFO - PID 21870 | 1654383540339	webdriver::server	DEBUG	-> POST /session/6b4b7246-79e9-4fe9-810f-80393693c7f4/window/rect {"width": 800, "height": 600}
[task 2022-06-04T22:59:00.346Z] 22:59:00     INFO - PID 21870 | 1654383540339	Marionette	DEBUG	0 -> [0,207,"WebDriver:SetWindowRect",{"height":600,"width":800}]
[task 2022-06-04T22:59:00.347Z] 22:59:00     INFO - PID 21870 | 1654383540340	Marionette	DEBUG	0 <- [1,207,null,{"x":100,"y":100,"width":800,"height":600}]
[task 2022-06-04T22:59:00.347Z] 22:59:00     INFO - PID 21870 | 1654383540341	webdriver::server	DEBUG	<- 200 OK {"value":{"x":100,"y":100,"width":800,"height":600}}
[task 2022-06-04T22:59:00.348Z] 22:59:00     INFO - PID 21870 | 1654383540341	webdriver::server	DEBUG	-> POST /session/6b4b7246-79e9-4fe9-810f-80393693c7f4/frame {"id": null}
[task 2022-06-04T22:59:00.348Z] 22:59:00     INFO - PID 21870 | 1654383540342	Marionette	DEBUG	0 -> [0,208,"WebDriver:SwitchToFrame",{"id":null}]
[task 2022-06-04T22:59:00.349Z] 22:59:00     INFO - PID 21870 | 1654383540343	Marionette	DEBUG	0 <- [1,208,null,{"value":null}]
[task 2022-06-04T22:59:00.350Z] 22:59:00     INFO - PID 21870 | 1654383540344	webdriver::server	DEBUG	<- 200 OK {"value":null}
[task 2022-06-04T22:59:00.350Z] 22:59:00     INFO - PID 21870 | 1654383540346	webdriver::server	DEBUG	-> DELETE /session/6b4b7246-79e9-4fe9-810f-80393693c7f4
[task 2022-06-04T22:59:00.351Z] 22:59:00     INFO - PID 21870 | 1654383540347	Marionette	DEBUG	0 -> [0,209,"Marionette:Quit",{"flags":["eForceQuit"]}]
[task 2022-06-04T22:59:00.352Z] 22:59:00     INFO - PID 21870 | 1654383540348	Marionette	INFO	Stopped listening on port 46287
[task 2022-06-04T22:59:00.390Z] 22:59:00     INFO - PID 21870 | 1654383540389	Marionette	TRACE	Received observer notification quit-application
[task 2022-06-04T22:59:00.394Z] 22:59:00     INFO - PID 21870 | 1654383540393	Marionette	TRACE	Received observer notification quit-application
[task 2022-06-04T22:59:00.395Z] 22:59:00     INFO - PID 21870 | 1654383540394	Marionette	DEBUG	Marionette stopped listening
[task 2022-06-04T22:59:00.396Z] 22:59:00     INFO - PID 21870 | 1654383540395	Marionette	DEBUG	0 <- [1,209,null,{"cause":"shutdown","forced":false}]
[task 2022-06-04T22:59:00.436Z] 22:59:00     INFO - PID 21870 | 1654383540435	webdriver::server	DEBUG	Teardown session
[task 2022-06-04T22:59:00.438Z] 22:59:00     INFO - PID 21870 | 1654383540437	Marionette	DEBUG	Closed connection 0
[task 2022-06-04T22:59:15.394Z] 22:59:15     INFO - PID 21870 | console.error: (new Error("SessionFile is closed", "resource:///modules/sessionstore/SessionFile.jsm", 379))
[task 2022-06-04T22:59:18.376Z] 22:59:18     INFO - PID 21870 | WARNING: At least one completion condition is taking too long to complete. Conditions: [{"name":"ContentParent: id=7f8686084700","state":{"remoteTypePrefix":"extension"},"filename":"/builds/worker/checkouts/gecko/dom/ipc/ContentParent.cpp","lineNumber":3640,"stack":["resource://gre/modules/nsAsyncShutdown.jsm:addBlocker:162","resource://gre/modules/ExtensionParent.jsm:createBrowserElement:1295"]}] Barrier: profile-before-change
[task 2022-06-04T22:59:50.081Z] 22:59:50     INFO - TEST-UNEXPECTED-TIMEOUT | /webdriver/tests/perform_actions/validity.py | expected OK
[task 2022-06-04T22:59:50.081Z] 22:59:50     INFO - TEST-INFO took 55002ms
[task 2022-06-04T22:59:50.164Z] 22:59:50     INFO - Closing logging queue
[task 2022-06-04T22:59:50.164Z] 22:59:50  WARNING - Dropping log message: %r
[task 2022-06-04T22:59:50.164Z] 22:59:50     INFO - queue closed
[task 2022-06-04T22:59:50.173Z] 22:59:50     INFO - PID 27614 | 1654383590171	geckodriver	INFO	Listening on 127.0.0.1:48143
[task 2022-06-04T22:59:50.173Z] 22:59:50     INFO - Starting runner
[task 2022-06-04T22:59:50.410Z] 22:59:50     INFO - TEST-START | /webdriver/tests/perform_actions/wheel.py

Comment hidden (Intermittent Failures Robot)

Henrik Skupin [:whimboo][⌚️UTC+2]

Comment 2

•

3 years ago

This is a shutdown hang of Firefox:

[task 2022-06-04T22:59:00.438Z] 22:59:00     INFO - PID 21870 | 1654383540437	Marionette	DEBUG	Closed connection 0
[task 2022-06-04T22:59:15.394Z] 22:59:15     INFO - PID 21870 | console.error: (new Error("SessionFile is closed", "resource:///modules/sessionstore/SessionFile.jsm", 379))
[task 2022-06-04T22:59:18.376Z] 22:59:18     INFO - PID 21870 | WARNING: At least one completion condition is taking too long to complete. Conditions: [{"name":"ContentParent: id=7f8686084700","state":{"remoteTypePrefix":"extension"},"filename":"/builds/worker/checkouts/gecko/dom/ipc/ContentParent.cpp","lineNumber":3640,"stack":["resource://gre/modules/nsAsyncShutdown.jsm:addBlocker:162","resource://gre/modules/ExtensionParent.jsm:createBrowserElement:1295"]}] Barrier: profile-before-change
[task 2022-06-04T22:59:50.081Z] 22:59:50     INFO - TEST-UNEXPECTED-TIMEOUT | /webdriver/tests/perform_actions/validity.py | expected OK
[task 2022-06-04T22:59:50.081Z] 22:59:50     INFO - TEST-INFO took 55002ms

Status: NEW → RESOLVED

Closed: 3 years ago

Resolution: --- → DUPLICATE

BMO Automation

Comment 3

•

2 years ago

Moving bug to Remote Protocol::Marionette component per bug 1815831.

Component: geckodriver → Marionette

Product: Testing → Remote Protocol

You need to log in before you can comment on or make changes to this bug.

Bugzilla

Intermittent [Tier 2] TEST-UNEXPECTED-TIMEOUT | /webdriver/tests/perform_actions/validity.py | expected OK

Categories

(Remote Protocol :: Marionette, defect, P5)

Tracking

(Not tracked)

People

(Reporter: intermittent-bug-filer, Unassigned)

References

Details

(Keywords: intermittent-failure)

Crash Data

Security

(public)

User Story

Description

Comment 1

Comment 2

Comment 3