1655294 - Intermittent testing/firefox-ui/tests/functional/sessionstore/test_restore_windows_after_windows_shutdown.py <test> | IOError: Process killed because the connection to Marionette server is lost

Status: RESOLVED INCOMPLETE

(Testing :: Firefox UI Tests, defect, P5)

Description

[Treeherder Bug Filer]

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

---

[task 2020-07-25T22:22:19.020Z] 22:22:19     INFO - TEST-START | testing/firefox-ui/tests/functional/sessionstore/test_restore_windows_after_windows_shutdown.py TestWindowsShutdownRegisterRestart.test_manual_restart
[task 2020-07-25T22:22:19.020Z] 22:22:19     INFO -  1595715739018	Marionette	DEBUG	Closed connection 3
[task 2020-07-25T22:22:19.027Z] 22:22:19     INFO -  1595715739020	Marionette	DEBUG	Accepted connection 4 from 127.0.0.1:50384
[task 2020-07-25T22:22:19.027Z] 22:22:19     INFO -  1595715739022	Marionette	DEBUG	4 -> [0,1,"WebDriver:NewSession",{"strictFileInteractability":true}]
[task 2020-07-25T22:22:19.034Z] 22:22:19     INFO -  1595715739027	Marionette	TRACE	[20] Frame script loaded
[task 2020-07-25T22:22:19.034Z] 22:22:19     INFO -  1595715739029	Marionette	TRACE	[20] Frame script registered
[task 2020-07-25T22:22:19.034Z] 22:22:19     INFO -  1595715739031	Marionette	DEBUG	4 <- [1,1,null,{"sessionId":"71aa405e-7f2d-4eec-8d39-39a5d6104b3d","capabilities":{"browserName":"firefox","browserVersion":"80.0a ... d\\tmp5yijjs.mozrunner","moz:shutdownTimeout":60000,"moz:useNonSpecCompliantPointerOrigin":false,"moz:webdriverClick":true}}]
[task 2020-07-25T22:22:19.037Z] 22:22:19     INFO -  1595715739033	Marionette	DEBUG	4 -> [0,2,"WebDriver:SetTimeouts",{"script":30000}]
[task 2020-07-25T22:22:19.040Z] 22:22:19     INFO -  1595715739034	Marionette	DEBUG	4 <- [1,2,null,{"value":null}]
[task 2020-07-25T22:22:19.040Z] 22:22:19     INFO -  1595715739036	Marionette	DEBUG	4 -> [0,3,"WebDriver:SetTimeouts",{"pageLoad":300000}]
[task 2020-07-25T22:22:19.043Z] 22:22:19     INFO -  1595715739037	Marionette	DEBUG	4 <- [1,3,null,{"value":null}]
[task 2020-07-25T22:22:19.043Z] 22:22:19     INFO -  1595715739039	Marionette	DEBUG	4 -> [0,4,"WebDriver:SetTimeouts",{"implicit":0}]
[task 2020-07-25T22:22:19.046Z] 22:22:19     INFO -  1595715739040	Marionette	DEBUG	4 <- [1,4,null,{"value":null}]
[task 2020-07-25T22:22:19.046Z] 22:22:19     INFO -  1595715739042	Marionette	DEBUG	4 -> [0,5,"WebDriver:GetChromeWindowHandle",{}]
[task 2020-07-25T22:22:19.046Z] 22:22:19     INFO -  1595715739043	Marionette	DEBUG	4 <- [1,5,null,{"value":"8"}]
[task 2020-07-25T22:22:19.049Z] 22:22:19     INFO -  1595715739046	Marionette	DEBUG	4 -> [0,6,"WebDriver:GetChromeWindowHandles",{}]
[task 2020-07-25T22:22:19.049Z] 22:22:19     INFO -  1595715739047	Marionette	DEBUG	4 <- [1,6,null,["8"]]
[task 2020-07-25T22:22:19.069Z] 22:22:19     INFO -  1595715739058	Marionette	DEBUG	4 -> [0,7,"WebDriver:GetWindowHandle",{}]
[task 2020-07-25T22:22:19.069Z] 22:22:19     INFO -  1595715739059	Marionette	DEBUG	4 <- [1,7,null,{"value":"20"}]
[task 2020-07-25T22:22:19.069Z] 22:22:19     INFO -  1595715739060	Marionette	DEBUG	4 -> [0,8,"WebDriver:GetWindowHandles",{}]
[task 2020-07-25T22:22:19.069Z] 22:22:19     INFO -  1595715739061	Marionette	DEBUG	4 <- [1,8,null,["20"]]
[task 2020-07-25T22:22:19.069Z] 22:22:19     INFO -  1595715739062	Marionette	DEBUG	4 -> [0,9,"Marionette:SetContext",{"value":"chrome"}]
[task 2020-07-25T22:22:19.069Z] 22:22:19     INFO -  1595715739063	Marionette	DEBUG	4 <- [1,9,null,{"value":null}]
[task 2020-07-25T22:22:19.070Z] 22:22:19     INFO -  1595715739064	Marionette	DEBUG	4 -> [0,10,"Marionette:GetContext",{}]
[task 2020-07-25T22:22:19.070Z] 22:22:19     INFO -  1595715739065	Marionette	DEBUG	4 <- [1,10,null,{"value":"chrome"}]
[task 2020-07-25T22:22:19.070Z] 22:22:19     INFO -  1595715739066	Marionette	DEBUG	4 -> [0,11,"Marionette:SetContext",{"value":"chrome"}]
[task 2020-07-25T22:22:19.070Z] 22:22:19     INFO -  1595715739067	Marionette	DEBUG	4 <- [1,11,null,{"value":null}]
[task 2020-07-25T22:22:19.073Z] 22:22:19     INFO -  1595715739070	Marionette	DEBUG	4 -> [0,12,"WebDriver:ExecuteScript",{"script":"let prefInterface = Components.classes[\"@mozilla.org/preferences-service;1\"]\n   ... me":"Z:\\task_1595715065\\build\\venv\\lib\\site-packages\\marionette_driver\\marionette.py","sandbox":"default","line":847}]
[task 2020-07-25T22:22:19.080Z] 22:22:19     INFO -  1595715739075	Marionette	DEBUG	4 <- [1,12,null,{"value":false}]
[task 2020-07-25T22:22:19.080Z] 22:22:19     INFO -  1595715739078	Marionette	DEBUG	4 -> [0,13,"Marionette:SetContext",{"value":"chrome"}]
[task 2020-07-25T22:22:19.080Z] 22:22:19     INFO -  1595715739078	Marionette	DEBUG	4 <- [1,13,null,{"value":null}]
[task 2020-07-25T22:22:19.087Z] 22:22:19     INFO -  1595715739079	Marionette	DEBUG	4 -> [0,14,"Marionette:GetContext",{}]
[task 2020-07-25T22:22:19.087Z] 22:22:19     INFO -  1595715739080	Marionette	DEBUG	4 <- [1,14,null,{"value":"chrome"}]
[task 2020-07-25T22:22:19.087Z] 22:22:19     INFO -  1595715739081	Marionette	DEBUG	4 -> [0,15,"WebDriver:DeleteSession",{}]
[task 2020-07-25T22:22:19.087Z] 22:22:19     INFO -  1595715739083	Marionette	DEBUG	4 <- [1,15,null,{"value":null}]
[task 2020-07-25T22:22:19.128Z] 22:22:19     INFO -  Exiting due to channel error.
[task 2020-07-25T22:22:19.335Z] 22:22:19     INFO - Application command: Z:\task_1595715065\build\application\firefox\firefox.exe -no-remote -marionette --wait-for-browser -profile Z:\task_1595715065\build\tmpfswru5.mozrunner
[task 2020-07-25T22:22:20.858Z] 22:22:20     INFO -  [4292, Main Thread] WARNING: Failed to acquire a DXGI adapter for enumerating outputs.: file /builds/worker/checkouts/gecko/gfx/thebes/DeviceManagerDx.cpp, line 146
[task 2020-07-25T22:22:20.858Z] 22:22:20     INFO -  [4292, Main Thread] WARNING: Failed to acquire a DXGI adapter for checking hardware stretching support.: file /builds/worker/checkouts/gecko/gfx/thebes/DeviceManagerDx.cpp, line 207
[task 2020-07-25T22:22:20.858Z] 22:22:20     INFO -  [4292, Main Thread] WARNING: DWM not enabled, falling back to software vsync: file /builds/worker/checkouts/gecko/gfx/thebes/gfxWindowsPlatform.cpp, line 1948
[task 2020-07-25T22:22:20.865Z] 22:22:20     INFO -  [4292, Main Thread] WARNING: 'NS_FAILED(rv)', file /builds/worker/checkouts/gecko/widget/windows/nsLookAndFeel.cpp, line 859
[task 2020-07-25T22:22:20.964Z] 22:22:20     INFO -  1595715740961	Marionette	TRACE	Marionette enabled
[task 2020-07-25T22:22:21.119Z] 22:22:21     INFO -  1595715741111	Marionette	TRACE	Received observer notification toplevel-window-ready
[task 2020-07-25T22:22:21.154Z] 22:22:21     INFO -  [4292, Main Thread] WARNING: 'NS_FAILED(GetAccentColor(unused))', file /builds/worker/checkouts/gecko/widget/windows/nsLookAndFeel.cpp, line 485
[task 2020-07-25T22:22:21.157Z] 22:22:21     INFO -  [4292, Main Thread] WARNING: NS_ENSURE_TRUE(rootFrame) failed: file /builds/worker/checkouts/gecko/dom/base/nsGlobalWindowOuter.cpp, line 4245
[task 2020-07-25T22:22:21.157Z] 22:22:21     INFO -  [4292, Main Thread] WARNING: NS_ENSURE_TRUE(rootFrame) failed: file /builds/worker/checkouts/gecko/dom/base/nsGlobalWindowOuter.cpp, line 4245
[task 2020-07-25T22:22:21.312Z] 22:22:21     INFO -  [4292, Main Thread] WARNING: Failed to retarget HTML data delivery to the parser thread.: file /builds/worker/checkouts/gecko/parser/html/nsHtml5StreamParser.cpp, line 1131
[task 2020-07-25T22:22:21.827Z] 22:22:21     INFO -  [4292, Main Thread] WARNING: NS_ENSURE_TRUE(presShell) failed: file /builds/worker/checkouts/gecko/dom/base/nsGlobalWindowOuter.cpp, line 4243
[task 2020-07-25T22:22:21.862Z] 22:22:21     INFO -  [Parent 4292, GMPThread] WARNING: Failed to delete GMP storage directory: file /builds/worker/checkouts/gecko/dom/media/gmp/GMPServiceParent.cpp, line 1562
[task 2020-07-25T22:25:30.459Z] 22:25:30     INFO - TEST-UNEXPECTED-ERROR | testing/firefox-ui/tests/functional/sessionstore/test_restore_windows_after_windows_shutdown.py TestWindowsShutdownRegisterRestart.test_manual_restart | IOError: Process killed because the connection to Marionette server is lost. Check gecko.log for errors (Reason: Timed out waiting for connection on 127.0.0.1:2828!)
[task 2020-07-25T22:25:30.459Z] 22:25:30     INFO - Traceback (most recent call last):
[task 2020-07-25T22:25:30.459Z] 22:25:30     INFO -   File "Z:\task_1595715065\build\venv\lib\site-packages\marionette_harness\marionette_test\testcases.py", line 177, in run
[task 2020-07-25T22:25:30.459Z] 22:25:30     INFO -     self.setUp()
[task 2020-07-25T22:25:30.459Z] 22:25:30     INFO -   File "Z:\task_1595715065\build\tests\firefox-ui\tests\testing\firefox-ui\tests\functional\sessionstore\test_restore_windows_after_windows_shutdown.py", line 41, in setUp
[task 2020-07-25T22:25:30.459Z] 22:25:30     INFO -     win_register_restart=True)
[task 2020-07-25T22:25:30.459Z] 22:25:30     INFO -   File "Z:\task_1595715065\build\tests\firefox-ui\tests\testing\firefox-ui\tests\functional\sessionstore\session_store_test_case.py", line 57, in setUp
[task 2020-07-25T22:25:30.459Z] 22:25:30     INFO -     'toolkit.winRegisterApplicationRestart': win_register_restart,
[task 2020-07-25T22:25:30.459Z] 22:25:30     INFO -   File "Z:\task_1595715065\build\venv\lib\site-packages\marionette_driver\decorators.py", line 36, in _
[task 2020-07-25T22:25:30.460Z] 22:25:30     INFO -     m._handle_socket_failure()
[task 2020-07-25T22:25:30.460Z] 22:25:30     INFO -   File "Z:\task_1595715065\build\venv\lib\site-packages\marionette_driver\marionette.py", line 682, in _handle_socket_failure
[task 2020-07-25T22:25:30.460Z] 22:25:30     INFO -     reraise(IOError, IOError(message.format(returncode=returncode, reason=exc)), tb)
[task 2020-07-25T22:25:30.460Z] 22:25:30     INFO -   File "Z:\task_1595715065\build\venv\lib\site-packages\marionette_driver\decorators.py", line 26, in _
[task 2020-07-25T22:25:30.460Z] 22:25:30     INFO -     return func(*args, **kwargs)
[task 2020-07-25T22:25:30.460Z] 22:25:30     INFO -   File "Z:\task_1595715065\build\venv\lib\site-packages\marionette_driver\marionette.py", line 856, in enforce_gecko_prefs
[task 2020-07-25T22:25:30.460Z] 22:25:30     INFO -     self.raise_for_port()
[task 2020-07-25T22:25:30.460Z] 22:25:30     INFO -   File "Z:\task_1595715065\build\venv\lib\site-packages\marionette_driver\marionette.py", line 573, in raise_for_port
[task 2020-07-25T22:25:30.460Z] 22:25:30     INFO -     self.host, self.port))
[task 2020-07-25T22:25:30.460Z] 22:25:30     INFO - TEST-INFO took 191434ms
[task 2020-07-25T22:25:30.460Z] 22:25:30     INFO - 
[task 2020-07-25T22:25:30.460Z] 22:25:30     INFO - SUMMARY
[task 2020-07-25T22:25:30.460Z] 22:25:30     INFO - -------
[task 2020-07-25T22:25:30.461Z] 22:25:30     INFO - passed: 8
[task 2020-07-25T22:25:30.461Z] 22:25:30     INFO - failed: 1
[task 2020-07-25T22:25:30.461Z] 22:25:30     INFO - todo: 0
[task 2020-07-25T22:25:30.461Z] 22:25:30     INFO - 
[task 2020-07-25T22:25:30.461Z] 22:25:30     INFO - FAILED TESTS
[task 2020-07-25T22:25:30.461Z] 22:25:30     INFO - -------
[task 2020-07-25T22:25:30.461Z] 22:25:30     INFO - test_restore_windows_after_windows_shutdown.py test_restore_windows_after_windows_shutdown.TestWindowsShutdownRegisterRestart.test_manual_restart
[task 2020-07-25T22:25:30.461Z] 22:25:30     INFO - SUITE-END | took 446s
[task 2020-07-25T22:25:31.447Z] 22:25:31    ERROR - Return code: 10
[task 2020-07-25T22:25:31.448Z] 22:25:31    ERROR - Got 1 unexpected statuses
[task 2020-07-25T22:25:31.448Z] 22:25:31  WARNING - # TBPL WARNING #
[task 2020-07-25T22:25:31.448Z] 22:25:31  WARNING - setting return code to 1

Comment 1

[Intermittent Failures Robot]

1 failures in 4310 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-central: 1

Platform breakdown:

• windows7-32-mingwclang: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1655294&startday=2020-07-20&endday=2020-07-26&tree=all

Comment 2

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

Missing marionette-startup-requested notification.

Comment 3

[Intermittent Failures Robot]

1 failures in 4100 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 1

Platform breakdown:

• windows10-64: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1655294&startday=2020-08-17&endday=2020-08-23&tree=all

Comment 4

[BugBot [:suhaib / :marco/ :calixte]]

https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
For more information, please visit auto_nag documentation.

Comment 7

[BugBot [:suhaib / :marco/ :calixte]]

https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
For more information, please visit auto_nag documentation.