1757920 - Intermittent TEST-UNEXPECTED-TIMEOUT | /webdriver/tests/element_send_keys/file_upload.py | expected OK

Status: RESOLVED DUPLICATE of bug 1630162

(Remote Protocol :: Marionette, defect, P5)

Description

[Treeherder Bug Filer]

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

---

task 2022-03-03T12:35:21.805Z] 12:35:21     INFO - PID 8880 | 1646310921787	Marionette	DEBUG	0 <- [1,38,null,{"x":100,"y":100,"width":800,"height":600}]
[task 2022-03-03T12:35:21.806Z] 12:35:21     INFO - PID 8880 | 1646310921788	webdriver::server	DEBUG	<- 200 OK {"value":{"x":100,"y":100,"width":800,"height":600}}
[task 2022-03-03T12:35:21.807Z] 12:35:21     INFO - PID 8880 | 1646310921789	webdriver::server	DEBUG	-> POST /session/68130cd6-8605-4065-8685-8215ca96f2ae/frame {"id": null}
[task 2022-03-03T12:35:21.808Z] 12:35:21     INFO - PID 8880 | 1646310921794	Marionette	DEBUG	0 -> [0,39,"WebDriver:SwitchToFrame",{"id":null}]
[task 2022-03-03T12:35:21.809Z] 12:35:21     INFO - PID 8880 | 1646310921794	Marionette	DEBUG	0 <- [1,39,null,{"value":null}]
[task 2022-03-03T12:35:21.809Z] 12:35:21     INFO - PID 8880 | 1646310921795	webdriver::server	DEBUG	<- 200 OK {"value":null}
[task 2022-03-03T12:35:21.810Z] 12:35:21     INFO - PID 8880 | 1646310921798	webdriver::server	DEBUG	-> DELETE /session/68130cd6-8605-4065-8685-8215ca96f2ae
[task 2022-03-03T12:35:21.811Z] 12:35:21     INFO - PID 8880 | 1646310921798	Marionette	DEBUG	0 -> [0,40,"Marionette:Quit",{"flags":["eForceQuit"]}]
[task 2022-03-03T12:35:21.811Z] 12:35:21     INFO - PID 8880 | 1646310921798	Marionette	INFO	Stopped listening on port 52356
[task 2022-03-03T12:35:21.829Z] 12:35:21     INFO - PID 8880 | 1646310921839	Marionette	TRACE	Received observer notification quit-application
[task 2022-03-03T12:35:21.840Z] 12:35:21     INFO - PID 8880 | 1646310921839	Marionette	TRACE	Received observer notification quit-application
[task 2022-03-03T12:35:21.841Z] 12:35:21     INFO - PID 8880 | 1646310921839	Marionette	DEBUG	Marionette stopped listening
[task 2022-03-03T12:35:21.843Z] 12:35:21     INFO - PID 8880 | 1646310921842	Marionette	DEBUG	0 <- [1,40,null,{"cause":"shutdown","forced":false}]
[task 2022-03-03T12:35:21.856Z] 12:35:21     INFO - PID 8880 | 1646310921857	webdriver::server	DEBUG	Teardown session
[task 2022-03-03T12:35:21.861Z] 12:35:21     INFO - PID 8880 | 1646310921860	Marionette	DEBUG	Closed connection 0
[task 2022-03-03T12:35:23.189Z] 12:35:23     INFO - PID 8880 | JavaScript error: resource://gre/modules/TerminatorTelemetry.jsm, line 71: AbortError: IOUtils: Shutting down and refusing additional I/O tasks
[task 2022-03-03T12:35:32.176Z] 12:35:32     INFO - TEST-UNEXPECTED-TIMEOUT | /webdriver/tests/element_send_keys/file_upload.py | expected OK
[task 2022-03-03T12:35:32.176Z] 12:35:32     INFO - TEST-INFO took 30011ms
[task 2022-03-03T12:35:36.863Z] 12:35:36     INFO - PID 8880 | console.error: (new Error("SessionFile is closed", "resource:///modules/sessionstore/SessionFile.jsm", 443))
[task 2022-03-03T12:35:37.596Z] 12:35:37     INFO - PID 8880 | ###!!! [Parent][PGPUParent] Error: RunMessage(msgname=PGPU::Msg_ShutdownVR) Channel closing: too late to send/recv, messages will be lost
[task 2022-03-03T12:35:37.665Z] 12:35:37     INFO - PID 8880 | 1646310937665	geckodriver::browser	DEBUG	Browser process stopped: exit code: 0
[task 2022-03-03T12:35:37.667Z] 12:35:37     INFO - PID 8880 | 1646310937666	webdriver::server	DEBUG	<- 200 OK {"value":null}
[task 2022-03-03T12:35:37.669Z] 12:35:37     INFO - PID 8880 | 1646310937667	webdriver::server	DEBUG	-> GET /status
[task 2022-03-03T12:35:37.670Z] 12:35:37     INFO - PID 8880 | 1646310937667	webdriver::server	DEBUG	<- 200 OK {"value":{"message":"","ready":true}}
[task 2022-03-03T12:35:37.714Z] 12:35:37     INFO - Closing logging queue
[task 2022-03-03T12:35:37.729Z] 12:35:37     INFO - queue closed
[task 2022-03-03T12:35:38.242Z] 12:35:38     INFO - PID 1680 | 1646310937742	geckodriver	INFO	Listening on 127.0.0.1:49851
[task 2022-03-03T12:35:38.245Z] 12:35:38     INFO - Starting runner
[task 2022-03-03T12:35:38.782Z] 12:35:38     INFO - TEST-START | /webdriver/tests/element_send_keys/form_controls.py
[task 2022-03-03T12:35:39.071Z] 12:35:39     INFO - STDOUT: ============================= test session starts =============================
[task 2022-03-03T12:35:39.080Z] 12:35:39     INFO - STDOUT: platform win32 -- Python 3.9.5, pytest-6.1.1, py-1.5.2, pluggy-unknown -- Z:\task_164630790287673\build\venv\Scripts\python.exe
[task 2022-03-03T12:35:39.082Z] 12:35:39     INFO - STDOUT: rootdir: Z:\task_164630790287673\build
[task 2022-03-03T12:35:39.082Z] 12:35:39     INFO - STDOUT: plugins: asyncio-0.14.0
[task 2022-03-03T12:35:39.083Z] 12:35:39     INFO - STDOUT: collecting ... 
[task 2022-03-03T12:35:39.111Z] 12:35:39     INFO - STDOUT: collected 4 items
[task 2022-03-03T12:35:39.116Z] 12:35:39     INFO - STDOUT: tests/web-platform/tests/webdriver/tests/element_send_keys/form_controls.py::test_input 

Comment 1

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

Firefox hangs during shutdown.

Comment 2

[BMO Automation]

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