1596616 - Intermittent testing\firefox-ui\tests\functional\sessionstore\test_restore_windows_after_restart_and_quit.py TestSessionStoreEnabledAllWindows.test_with_variety | IOError: Process killed because the connection to Marionette server is lost. Check gecko.

Status: RESOLVED INCOMPLETE

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

Description

[Treeherder Bug Filer]

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

---

[task 2019-11-14T23:14:22.062Z] 23:14:22 INFO - TEST-START | testing\firefox-ui\tests\functional\sessionstore\test_restore_windows_after_restart_and_quit.py TestSessionStoreEnabledAllWindows.test_with_variety
[task 2019-11-14T23:14:23.072Z] 23:14:23 INFO - 1573773263071 Marionette TRACE Received observer notification command-line-startup
[task 2019-11-14T23:14:23.133Z] 23:14:23 INFO - 1573773263129 Marionette TRACE Received observer notification toplevel-window-ready
[task 2019-11-14T23:17:33.709Z] 23:17:33 INFO - TEST-UNEXPECTED-ERROR | testing\firefox-ui\tests\functional\sessionstore\test_restore_windows_after_restart_and_quit.py TestSessionStoreEnabledAllWindows.test_with_variety | 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 2019-11-14T23:17:33.709Z] 23:17:33 INFO - Traceback (most recent call last):
[task 2019-11-14T23:17:33.709Z] 23:17:33 INFO - File "Z:\task_1573771055\build\venv\lib\site-packages\marionette_harness\marionette_test\testcases.py", line 140, in run
[task 2019-11-14T23:17:33.709Z] 23:17:33 INFO - self.setUp()
[task 2019-11-14T23:17:33.709Z] 23:17:33 INFO - File "Z:\task_1573771055\build\tests\firefox-ui\tests\testing\firefox-ui\tests\functional\sessionstore\test_restore_windows_after_restart_and_quit.py", line 22, in setUp
[task 2019-11-14T23:17:33.709Z] 23:17:33 INFO - include_private=include_private, startup_page=3)
[task 2019-11-14T23:17:33.709Z] 23:17:33 INFO - File "Z:\task_1573771055\build\tests\firefox-ui\tests\testing\firefox-ui\tests\functional\sessionstore\session_store_test_case.py", line 51, in setUp
[task 2019-11-14T23:17:33.709Z] 23:17:33 INFO - 'toolkit.winRegisterApplicationRestart': win_register_restart,
[task 2019-11-14T23:17:33.710Z] 23:17:33 INFO - File "Z:\task_1573771055\build\venv\lib\site-packages\marionette_driver\decorators.py", line 36, in _
[task 2019-11-14T23:17:33.710Z] 23:17:33 INFO - m._handle_socket_failure()
[task 2019-11-14T23:17:33.710Z] 23:17:33 INFO - File "Z:\task_1573771055\build\venv\lib\site-packages\marionette_driver\marionette.py", line 678, in _handle_socket_failure
[task 2019-11-14T23:17:33.710Z] 23:17:33 INFO - reraise(IOError, message.format(returncode=returncode, reason=val), tb)
[task 2019-11-14T23:17:33.710Z] 23:17:33 INFO - File "Z:\task_1573771055\build\venv\lib\site-packages\marionette_driver\decorators.py", line 26, in _
[task 2019-11-14T23:17:33.710Z] 23:17:33 INFO - return func(*args, **kwargs)
[task 2019-11-14T23:17:33.710Z] 23:17:33 INFO - File "Z:\task_1573771055\build\venv\lib\site-packages\marionette_driver\marionette.py", line 852, in enforce_gecko_prefs
[task 2019-11-14T23:17:33.710Z] 23:17:33 INFO - self.raise_for_port()
[task 2019-11-14T23:17:33.710Z] 23:17:33 INFO - File "Z:\task_1573771055\build\venv\lib\site-packages\marionette_driver\marionette.py", line 569, in raise_for_port
[task 2019-11-14T23:17:33.710Z] 23:17:33 INFO - self.host, self.port))
[task 2019-11-14T23:17:33.710Z] 23:17:33 INFO - TEST-INFO took 191645ms

Comment 1

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

Missing marionette-startup-requested notification.

Comment 2

[Intermittent Failures Robot]

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

Repository breakdown:

• mozilla-central: 1

Platform breakdown:

• windows10-64: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1596616&startday=2019-11-11&endday=2019-11-17&tree=all

Comment 3

[Intermittent Failures Robot]

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

Repository breakdown:

• try: 1

Platform breakdown:

• linux64-devedition: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1596616&startday=2019-12-02&endday=2019-12-08&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 5

[Cristina Coroiu [:ccoroiu]]

Recent failure log: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=301918048&repo=mozilla-central&lineNumber=1999

Comment 6

[Intermittent Failures Robot]

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

Repository breakdown:

• mozilla-central: 1

Platform breakdown:

• windows10-64: 1

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

Comment 7

[Intermittent Failures Robot]

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

Repository breakdown:

• autoland: 1

Platform breakdown:

• windows10-64-shippable: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1596616&startday=2020-05-25&endday=2020-05-31&tree=all

Comment 8

[Intermittent Failures Robot]

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

Repository breakdown:

• try: 1

Platform breakdown:

• linux1804-64-devedition: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1596616&startday=2020-06-15&endday=2020-06-21&tree=all

Comment 9

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

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

Comment 10

[Andreea Pavel [:apavel]]

Recent failure log: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=320155825&repo=mozilla-esr78&lineNumber=2467

[task 2020-10-29T17:16:11.298Z] 17:16:11 INFO - TEST-START | testing/firefox-ui/tests/functional/sessionstore/test_restore_windows_after_restart_and_quit.py TestSessionStoreEnabledAllWindows.test_with_variety
[task 2020-10-29T17:16:11.306Z] 17:16:11 INFO - 1603991771296 Marionette DEBUG Closed connection 1
[task 2020-10-29T17:16:11.306Z] 17:16:11 INFO - 1603991771297 Marionette DEBUG Accepted connection 2 from 127.0.0.1:44100
[task 2020-10-29T17:16:11.307Z] 17:16:11 INFO - 1603991771300 Marionette DEBUG 2 -> [0,1,"WebDriver:NewSession",{"strictFileInteractability":true}]
[task 2020-10-29T17:16:11.308Z] 17:16:11 INFO - 1603991771301 Marionette TRACE [7] Frame script loaded
[task 2020-10-29T17:16:11.308Z] 17:16:11 INFO - 1603991771302 Marionette TRACE [7] Frame script registered
[task 2020-10-29T17:16:11.309Z] 17:16:11 INFO - 1603991771303 Marionette DEBUG 2 <- [1,1,null,{"sessionId":"a93b7ed9-f1e5-481b-94f9-c479533f1546","capabilities":{"browserName":"firefox","browserVersion":"78.5. ... ld/tmpes_SrD.mozrunner","moz:shutdownTimeout":60000,"moz:useNonSpecCompliantPointerOrigin":false,"moz:webdriverClick":true}}]
[task 2020-10-29T17:16:11.310Z] 17:16:11 INFO - 1603991771303 Marionette DEBUG 2 -> [0,2,"WebDriver:SetTimeouts",{"script":30000}]
[task 2020-10-29T17:16:11.310Z] 17:16:11 INFO - 1603991771304 Marionette DEBUG 2 <- [1,2,null,{"value":null}]
[task 2020-10-29T17:16:11.310Z] 17:16:11 INFO - 1603991771304 Marionette DEBUG 2 -> [0,3,"WebDriver:SetTimeouts",{"pageLoad":300000}]
[task 2020-10-29T17:16:11.311Z] 17:16:11 INFO - 1603991771305 Marionette DEBUG 2 <- [1,3,null,{"value":null}]
[task 2020-10-29T17:16:11.319Z] 17:16:11 INFO - 1603991771313 Marionette DEBUG 2 -> [0,4,"WebDriver:SetTimeouts",{"implicit":0}]
[task 2020-10-29T17:16:11.320Z] 17:16:11 INFO - 1603991771314 Marionette DEBUG 2 <- [1,4,null,{"value":null}]
[task 2020-10-29T17:16:11.320Z] 17:16:11 INFO - 1603991771316 Marionette DEBUG 2 -> [0,5,"WebDriver:GetChromeWindowHandle",{}]
[task 2020-10-29T17:16:11.321Z] 17:16:11 INFO - 1603991771316 Marionette DEBUG 2 <- [1,5,null,{"value":"1"}]
[task 2020-10-29T17:16:11.321Z] 17:16:11 INFO - 1603991771317 Marionette DEBUG 2 -> [0,6,"WebDriver:GetChromeWindowHandles",{}]
[task 2020-10-29T17:16:11.321Z] 17:16:11 INFO - 1603991771317 Marionette DEBUG 2 <- [1,6,null,["1"]]
[task 2020-10-29T17:16:11.321Z] 17:16:11 INFO - 1603991771318 Marionette DEBUG 2 -> [0,7,"WebDriver:GetWindowHandle",{}]
[task 2020-10-29T17:16:11.322Z] 17:16:11 INFO - 1603991771318 Marionette DEBUG 2 <- [1,7,null,{"value":"7"}]
[task 2020-10-29T17:16:11.329Z] 17:16:11 INFO - 1603991771322 Marionette DEBUG 2 -> [0,8,"WebDriver:GetWindowHandles",{}]
[task 2020-10-29T17:16:11.330Z] 17:16:11 INFO - 1603991771323 Marionette DEBUG 2 <- [1,8,null,["7"]]
[task 2020-10-29T17:16:11.331Z] 17:16:11 INFO - 1603991771323 Marionette DEBUG 2 -> [0,9,"Marionette:SetContext",{"value":"chrome"}]
[task 2020-10-29T17:16:11.332Z] 17:16:11 INFO - 1603991771323 Marionette DEBUG 2 <- [1,9,null,{"value":null}]
[task 2020-10-29T17:16:11.333Z] 17:16:11 INFO - 1603991771324 Marionette DEBUG 2 -> [0,10,"Marionette:GetContext",{}]
[task 2020-10-29T17:16:11.333Z] 17:16:11 INFO - 1603991771324 Marionette DEBUG 2 <- [1,10,null,{"value":"chrome"}]
[task 2020-10-29T17:16:11.333Z] 17:16:11 INFO - 1603991771324 Marionette DEBUG 2 -> [0,11,"Marionette:SetContext",{"value":"chrome"}]
[task 2020-10-29T17:16:11.333Z] 17:16:11 INFO - 1603991771325 Marionette DEBUG 2 <- [1,11,null,{"value":null}]
[task 2020-10-29T17:16:11.334Z] 17:16:11 INFO - 1603991771325 Marionette DEBUG 2 -> [0,12,"WebDriver:ExecuteScript",{"script":"let prefInterface = Components.classes["@mozilla.org/preferences-service;1"]\n ... args":[],"filename":"../../venv/lib/python2.7/site-packages/marionette_driver/marionette.py","sandbox":"default","line":847}]
[task 2020-10-29T17:16:11.335Z] 17:16:11 INFO - 1603991771327 Marionette DEBUG 2 <- [1,12,null,{"value":false}]
[task 2020-10-29T17:16:11.336Z] 17:16:11 INFO - 1603991771329 Marionette DEBUG 2 -> [0,13,"Marionette:SetContext",{"value":"chrome"}]
[task 2020-10-29T17:16:11.336Z] 17:16:11 INFO - 1603991771329 Marionette DEBUG 2 <- [1,13,null,{"value":null}]
[task 2020-10-29T17:16:11.338Z] 17:16:11 INFO - 1603991771334 Marionette DEBUG 2 -> [0,14,"Marionette:GetContext",{}]
[task 2020-10-29T17:16:11.339Z] 17:16:11 INFO - 1603991771336 Marionette DEBUG 2 <- [1,14,null,{"value":"chrome"}]
[task 2020-10-29T17:16:11.349Z] 17:16:11 INFO - 1603991771339 Marionette DEBUG 2 -> [0,15,"WebDriver:DeleteSession",{}]
[task 2020-10-29T17:16:11.349Z] 17:16:11 INFO - 1603991771341 Marionette DEBUG 2 <- [1,15,null,{"value":null}]
[task 2020-10-29T17:16:11.401Z] 17:16:11 INFO - Application command: /builds/worker/workspace/build/application/firefox/firefox -no-remote -marionette -profile /builds/worker/workspace/build/tmpbSR_nT.mozrunner

[task 2020-10-29T17:16:20.483Z] 17:16:20 INFO - ###!!! [Child][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
[task 2020-10-29T17:16:20.483Z] 17:16:20 INFO - ###!!! [Child][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
[task 2020-10-29T17:16:20.483Z] 17:16:20 INFO - ###!!! [Child][RunMessage] Error: Channel closing: too late to send/recv, messages will be lost
[task 2020-10-29T17:16:20.504Z] 17:16:20 INFO - 1603991780500 Marionette DEBUG Closed connection 1
[task 2020-10-29T17:16:22.703Z] 17:16:22 INFO - 1603991782698 Marionette TRACE Received observer notification xpcom-will-shutdown
[task 2020-10-29T17:16:22.703Z] 17:16:22 INFO - 1603991782698 Marionette DEBUG Marionette stopped listening
[task 2020-10-29T17:16:22.868Z] 17:16:22 INFO - Application command: /builds/worker/workspace/build/application/firefox/firefox -no-remote -marionette -profile /builds/worker/workspace/build/tmpbSR_nT.mozrunner
[task 2020-10-29T17:18:22.937Z] 17:18:22 INFO - TEST-UNEXPECTED-ERROR | testing/firefox-ui/tests/functional/sessionstore/test_restore_windows_after_restart_and_quit.py TestSessionStoreEnabledAllWindows.test_with_variety | IOError: Process killed after 120s because no connection to Marionette server could be established. Check gecko.log for errors
[task 2020-10-29T17:18:22.937Z] 17:18:22 INFO - Traceback (most recent call last):
[task 2020-10-29T17:18:22.938Z] 17:18:22 INFO - File "/builds/worker/workspace/build/venv/lib/python2.7/site-packages/marionette_harness/marionette_test/testcases.py", line 191, in run
[task 2020-10-29T17:18:22.938Z] 17:18:22 INFO - testMethod()
[task 2020-10-29T17:18:22.938Z] 17:18:22 INFO - File "/builds/worker/workspace/build/tests/firefox-ui/tests/testing/firefox-ui/tests/functional/sessionstore/test_restore_windows_after_restart_and_quit.py", line 38, in test_with_variety
[task 2020-10-29T17:18:22.939Z] 17:18:22 INFO - self.marionette.start_session()
[task 2020-10-29T17:18:22.939Z] 17:18:22 INFO - File "/builds/worker/workspace/build/venv/lib/python2.7/site-packages/marionette_driver/decorators.py", line 26, in _
[task 2020-10-29T17:18:22.939Z] 17:18:22 INFO - return func(*args, **kwargs)
[task 2020-10-29T17:18:22.940Z] 17:18:22 INFO - File "/builds/worker/workspace/build/venv/lib/python2.7/site-packages/marionette_driver/marionette.py", line 1107, in start_session
[task 2020-10-29T17:18:22.940Z] 17:18:22 INFO - self.start_binary(timeout)
[task 2020-10-29T17:18:22.940Z] 17:18:22 INFO - File "/builds/worker/workspace/build/venv/lib/python2.7/site-packages/marionette_driver/marionette.py", line 493, in start_binary
[task 2020-10-29T17:18:22.940Z] 17:18:22 INFO - reraise(IOError, IOError(msg.format(timeout)), sys.exc_info()[2])
[task 2020-10-29T17:18:22.940Z] 17:18:22 INFO - File "/builds/worker/workspace/build/venv/lib/python2.7/site-packages/marionette_driver/marionette.py", line 485, in start_binary
[task 2020-10-29T17:18:22.940Z] 17:18:22 INFO - self.raise_for_port(timeout=timeout)
[task 2020-10-29T17:18:22.940Z] 17:18:22 INFO - File "/builds/worker/workspace/build/venv/lib/python2.7/site-packages/marionette_driver/marionette.py", line 573, in raise_for_port
[task 2020-10-29T17:18:22.940Z] 17:18:22 INFO - self.host, self.port))
[task 2020-10-29T17:18:22.940Z] 17:18:22 INFO - TEST-INFO took 131637ms
[task 2020-10-29T17:18:22.940Z] 17:18:22 ERROR - test_end for testing/firefox-ui/tests/functional/sessionstore/test_restore_windows_after_restart_and_quit.py TestSessionStoreEnabledAllWindows.test_with_variety logged while not in progress. Logged with data: {"status": "ERROR", "extra": {"class_name": "test_restore_windows_after_restart_and_quit.TestSessionStoreEnabledAllWindows", "method_name": "test_with_variety"}, "expected": "PASS", "test": "testing/firefox-ui/tests/functional/sessionstore/test_restore_windows_after_restart_and_quit.py TestSessionStoreEnabledAllWindows.test_with_variety", "message": "InvalidSessionIdException: Please start a session", "stack": "Traceback (most recent call last):\n File "/builds/worker/workspace/build/venv/lib/python2.7/site-packages/marionette_harness/marionette_test/testcases.py", line 222, in run\n self.tearDown()\n File "/builds/worker/workspace/build/tests/firefox-ui/tests/testing/firefox-ui/tests/functional/sessionstore/session_store_test_case.py", line 72, in tearDown\n super(SessionStoreTestCase, self).tearDown()\n File "/builds/worker/workspace/build/venv/lib/python2.7/site-packages/marionette_harness/runner/mixins/window_manager.py", line 25, in tearDown\n if len(self.marionette.chrome_window_handles) > len(self.start_windows):\n File "/builds/worker/workspace/build/venv/lib/python2.7/site-packages/marionette_driver/marionette.py", line 1261, in chrome_window_handles\n return self._send_message("WebDriver:GetChromeWindowHandles")\n File "/builds/worker/workspace/build/venv/lib/python2.7/site-packages/marionette_driver/decorators.py", line 26, in _\n return func(*args, **kwargs)\n File "/builds/worker/workspace/build/venv/lib/python2.7/site-packages/marionette_driver/marionette.py", line 591, in _send_message\n raise errors.InvalidSessionIdException("Please start a session")\n"}

Comment 11

[Intermittent Failures Robot]

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

Repository breakdown:

• mozilla-esr78: 1
• try: 1

Platform breakdown:

• linux1804-64-shippable: 1
• linux1804-64-asan: 1

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

Comment 12

[Intermittent Failures Robot]

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

Repository breakdown:

• mozilla-esr78: 1

Platform breakdown:

• linux1804-64-shippable: 1

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

Comment 13

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

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

Comment 14

[Natalia Csoregi [:nataliaCs]]

https://treeherder.mozilla.org/logviewer?job_id=331649436&repo=autoland&lineNumber=2018

Comment 15

[Intermittent Failures Robot]

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

Repository breakdown:

• autoland: 1

Platform and build breakdown:

• windows10-64: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1596616&startday=2021-03-01&endday=2021-03-07&tree=all

Comment 16

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

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