Closed Bug 1657860 Opened 4 years ago Closed 4 years ago

Intermittent testing/firefox-ui/tests/functional/sessionstore/test_restore_windows_after_restart_and_quit.py TestSessionStoreDisabled.test_restore_with_restart | InvalidSessionIdException: Please start a session

Categories

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

Product:
Testing
Component:
Firefox UI Tests
Type:
defect

Tracking

(Not tracked)

Status:
RESOLVED INCOMPLETE

People

(Reporter: intermittent-bug-filer, Unassigned)

References

Details

(Keywords: intermittent-failure)

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

...
[task 2020-08-07T10:18:54.336Z] 10:18:54     INFO -  1596795534331	Marionette	TRACE	Received DOM event focus for [object HTMLDocument]
[task 2020-08-07T10:18:54.363Z] 10:18:54     INFO -  1596795534355	Marionette	DEBUG	3 <- [1,17,null,{"value":null}]
[task 2020-08-07T10:18:54.363Z] 10:18:54     INFO -  1596795534358	Marionette	DEBUG	3 -> [0,18,"WebDriver:GetChromeWindowHandle",{}]
[task 2020-08-07T10:18:54.363Z] 10:18:54     INFO -  1596795534358	Marionette	DEBUG	3 <- [1,18,null,{"value":"30"}]
[task 2020-08-07T10:18:54.363Z] 10:18:54     INFO -  1596795534360	Marionette	DEBUG	3 -> [0,19,"Marionette:GetContext",{}]
[task 2020-08-07T10:18:54.363Z] 10:18:54     INFO -  1596795534360	Marionette	DEBUG	3 <- [1,19,null,{"value":"chrome"}]
[task 2020-08-07T10:18:54.366Z] 10:18:54     INFO -  1596795534362	Marionette	DEBUG	3 -> [0,20,"Marionette:SetContext",{"value":"chrome"}]
[task 2020-08-07T10:18:54.366Z] 10:18:54     INFO -  1596795534362	Marionette	DEBUG	3 <- [1,20,null,{"value":null}]
[task 2020-08-07T10:18:54.369Z] 10:18:54     INFO -  1596795534364	Marionette	DEBUG	3 -> [0,21,"WebDriver:SwitchToWindow",{"handle":"30","focus":true}]
[task 2020-08-07T10:18:54.369Z] 10:18:54     INFO -  1596795534365	Marionette	DEBUG	3 <- [1,21,null,{"value":null}]
[task 2020-08-07T10:18:54.372Z] 10:18:54     INFO -  1596795534368	Marionette	DEBUG	3 -> [0,22,"WebDriver:ExecuteScript",{"script":"return gBrowser.tabs.map(tab => {\n                    return tab.linkedBrowser.cu ... ui\\tests\\testing\\firefox-ui\\tests\\functional\\sessionstore\\session_store_test_case.py","sandbox":"default","line":149}]
[task 2020-08-07T10:18:54.379Z] 10:18:54     INFO -  1596795534373	Marionette	DEBUG	3 <- [1,22,null,{"value":["http://127.0.0.1:49307/layout/mozilla_governance.html","http://127.0.0.1:49307/layout/mozilla_grants.html"]}]
[task 2020-08-07T10:18:54.379Z] 10:18:54     INFO -  1596795534374	Marionette	DEBUG	3 -> [0,23,"Marionette:SetContext",{"value":"chrome"}]
[task 2020-08-07T10:18:54.379Z] 10:18:54     INFO -  1596795534375	Marionette	DEBUG	3 <- [1,23,null,{"value":null}]
[task 2020-08-07T10:18:54.379Z] 10:18:54     INFO -  1596795534376	Marionette	DEBUG	3 -> [0,24,"WebDriver:SwitchToWindow",{"handle":"30","focus":true}]
[task 2020-08-07T10:18:54.379Z] 10:18:54     INFO -  1596795534377	Marionette	DEBUG	3 <- [1,24,null,{"value":null}]
[task 2020-08-07T10:18:54.388Z] 10:18:54     INFO -  1596795534378	Marionette	DEBUG	3 -> [0,25,"Marionette:GetContext",{}]
[task 2020-08-07T10:18:54.388Z] 10:18:54     INFO -  1596795534378	Marionette	DEBUG	3 <- [1,25,null,{"value":"chrome"}]
[task 2020-08-07T10:18:54.388Z] 10:18:54     INFO -  1596795534380	Marionette	DEBUG	3 -> [0,26,"WebDriver:DeleteSession",{}]
[task 2020-08-07T10:18:54.389Z] 10:18:54     INFO -  1596795534382	Marionette	DEBUG	3 <- [1,26,null,{"value":null}]
[task 2020-08-07T10:18:54.408Z] 10:18:54     INFO -  Exiting due to channel error.
[task 2020-08-07T10:18:54.408Z] 10:18:54     INFO -  [GFX1-]: Receive IPC close with reason=AbnormalSh[GFX1-]: Receive IPC close with reason=AbnormalShutdown
[task 2020-08-07T10:18:54.433Z] 10:18:54     INFO -  Exiting due to channel error.
[task 2020-08-07T10:18:54.433Z] 10:18:54     INFO -  Exiting due to channel error.
[task 2020-08-07T10:18:54.433Z] 10:18:54     INFO -  Exiting due to channel error.
[task 2020-08-07T10:18:54.433Z] 10:18:54     INFO -  Exiting due to channel error.
[task 2020-08-07T10:18:54.713Z] 10:18:54     INFO - Application command: Z:\task_1596795066\build\application\firefox\firefox.exe -no-remote -marionette --wait-for-browser -profile Z:\task_1596795066\build\tmphmysay.mozrunner
[task 2020-08-07T10:18:56.528Z] 10:18:56     INFO -  [2020-08-07T10:18:56Z WARN  rkv::backend::impl_safe::environment] `load_ratio()` is irrelevant for this storage backend.
[task 2020-08-07T10:18:56.743Z] 10:18:56     INFO -  [4092, 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-08-07T10:18:56.743Z] 10:18:56     INFO -  [4092, 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-08-07T10:18:56.743Z] 10:18:56     INFO -  [4092, Main Thread] WARNING: DWM not enabled, falling back to software vsync: file /builds/worker/checkouts/gecko/gfx/thebes/gfxWindowsPlatform.cpp, line 1942
[task 2020-08-07T10:18:56.758Z] 10:18:56     INFO -  [4092, Main Thread] WARNING: 'NS_FAILED(rv)', file /builds/worker/checkouts/gecko/widget/windows/nsLookAndFeel.cpp, line 902
[task 2020-08-07T10:18:56.853Z] 10:18:56     INFO -  1596795536846	Marionette	TRACE	Marionette enabled
[task 2020-08-07T10:18:56.996Z] 10:18:56     INFO -  1596795536992	Marionette	TRACE	Received observer notification toplevel-window-ready
[task 2020-08-07T10:18:57.036Z] 10:18:57     INFO -  [4092, Main Thread] WARNING: 'NS_FAILED(GetAccentColor(unused))', file /builds/worker/checkouts/gecko/widget/windows/nsLookAndFeel.cpp, line 486
[task 2020-08-07T10:18:57.036Z] 10:18:57     INFO -  [4092, Main Thread] WARNING: NS_ENSURE_TRUE(rootFrame) failed: file /builds/worker/checkouts/gecko/dom/base/nsGlobalWindowOuter.cpp, line 4240
[task 2020-08-07T10:18:57.043Z] 10:18:57     INFO -  [4092, Main Thread] WARNING: NS_ENSURE_TRUE(rootFrame) failed: file /builds/worker/checkouts/gecko/dom/base/nsGlobalWindowOuter.cpp, line 4240
[task 2020-08-07T10:18:57.218Z] 10:18:57     INFO -  [4092, 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-08-07T10:18:57.697Z] 10:18:57     INFO -  [4092, Main Thread] WARNING: NS_ENSURE_TRUE(presShell) failed: file /builds/worker/checkouts/gecko/dom/base/nsGlobalWindowOuter.cpp, line 4238
[task 2020-08-07T10:18:57.752Z] 10:18:57     INFO -  [Parent 4092, GMPThread] WARNING: Failed to delete GMP storage directory: file /builds/worker/checkouts/gecko/dom/media/gmp/GMPServiceParent.cpp, line 1562
[task 2020-08-07T10:22:05.854Z] 10:22:05     INFO - TEST-UNEXPECTED-ERROR | testing/firefox-ui/tests/functional/sessionstore/test_restore_windows_after_restart_and_quit.py TestSessionStoreDisabled.test_restore_with_restart | InvalidSessionIdException: Please start a session
[task 2020-08-07T10:22:05.854Z] 10:22:05     INFO - Traceback (most recent call last):
[task 2020-08-07T10:22:05.854Z] 10:22:05     INFO -   File "Z:\task_1596795066\build\venv\lib\site-packages\marionette_harness\marionette_test\testcases.py", line 227, in run
[task 2020-08-07T10:22:05.854Z] 10:22:05     INFO -     self.tearDown()
[task 2020-08-07T10:22:05.854Z] 10:22:05     INFO -   File "Z:\task_1596795066\build\tests\firefox-ui\tests\testing\firefox-ui\tests\functional\sessionstore\session_store_test_case.py", line 72, in tearDown
[task 2020-08-07T10:22:05.854Z] 10:22:05     INFO -     super(SessionStoreTestCase, self).tearDown()
[task 2020-08-07T10:22:05.854Z] 10:22:05     INFO -   File "Z:\task_1596795066\build\venv\lib\site-packages\marionette_harness\runner\mixins\window_manager.py", line 25, in tearDown
[task 2020-08-07T10:22:05.854Z] 10:22:05     INFO -     if len(self.marionette.chrome_window_handles) > len(self.start_windows):
[task 2020-08-07T10:22:05.854Z] 10:22:05     INFO -   File "Z:\task_1596795066\build\venv\lib\site-packages\marionette_driver\marionette.py", line 1261, in chrome_window_handles
[task 2020-08-07T10:22:05.854Z] 10:22:05     INFO -     return self._send_message("WebDriver:GetChromeWindowHandles")
[task 2020-08-07T10:22:05.854Z] 10:22:05     INFO -   File "Z:\task_1596795066\build\venv\lib\site-packages\marionette_driver\decorators.py", line 26, in _
[task 2020-08-07T10:22:05.854Z] 10:22:05     INFO -     return func(*args, **kwargs)
[task 2020-08-07T10:22:05.855Z] 10:22:05     INFO -   File "Z:\task_1596795066\build\venv\lib\site-packages\marionette_driver\marionette.py", line 591, in _send_message
[task 2020-08-07T10:22:05.855Z] 10:22:05     INFO -     raise errors.InvalidSessionIdException("Please start a session")
[task 2020-08-07T10:22:05.855Z] 10:22:05     INFO - TEST-INFO took 217797ms

The new Firefox process never emitted the marionette-startup-requested observer notification and that within 4 minutes:

[task 2020-08-07T10:18:56.996Z] 10:18:56     INFO -  1596795536992	Marionette	TRACE	Received observer notification toplevel-window-ready
[task 2020-08-07T10:18:57.036Z] 10:18:57     INFO -  [4092, Main Thread] WARNING: 'NS_FAILED(GetAccentColor(unused))', file /builds/worker/checkouts/gecko/widget/windows/nsLookAndFeel.cpp, line 486
[task 2020-08-07T10:18:57.036Z] 10:18:57     INFO -  [4092, Main Thread] WARNING: NS_ENSURE_TRUE(rootFrame) failed: file /builds/worker/checkouts/gecko/dom/base/nsGlobalWindowOuter.cpp, line 4240
[task 2020-08-07T10:18:57.043Z] 10:18:57     INFO -  [4092, Main Thread] WARNING: NS_ENSURE_TRUE(rootFrame) failed: file /builds/worker/checkouts/gecko/dom/base/nsGlobalWindowOuter.cpp, line 4240
[task 2020-08-07T10:18:57.218Z] 10:18:57     INFO -  [4092, 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-08-07T10:18:57.697Z] 10:18:57     INFO -  [4092, Main Thread] WARNING: NS_ENSURE_TRUE(presShell) failed: file /builds/worker/checkouts/gecko/dom/base/nsGlobalWindowOuter.cpp, line 4238
[task 2020-08-07T10:18:57.752Z] 10:18:57     INFO -  [Parent 4092, GMPThread] WARNING: Failed to delete GMP storage directory: file /builds/worker/checkouts/gecko/dom/media/gmp/GMPServiceParent.cpp, line 1562
[task 2020-08-07T10:22:05.854Z] 10:22:05     INFO - TEST-UNEXPECTED-ERROR | testing/firefox-ui/tests/functional/sessionstore/test_restore_windows_after_restart_and_quit.py TestSessionStoreDisabled.test_restore_with_restart | InvalidSessionIdException: Please start a session

Lets see how often that happens.

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

Status: NEW → RESOLVED
Closed: 4 years ago
Resolution: --- → INCOMPLETE
You need to log in before you can comment on or make changes to this bug.