Open Bug 1727691 Opened 3 years ago Updated 2 years ago

Intermittent Windows browser/component/sessionstore/test/marionette/test_restore_windows_after_windows_shutdown.py TestWindowsShutdown.test_with_variety | AssertionError: Items in the first set but not the second:

Categories

(Firefox :: Session Restore, defect, P5)

Desktop
Windows
defect

Tracking

()

Tracking Status
firefox-esr78 --- unaffected
firefox-esr91 --- disabled
firefox91 --- unaffected
firefox92 --- unaffected
firefox93 --- disabled
firefox94 --- affected

People

(Reporter: intermittent-bug-filer, Unassigned)

References

(Regression)

Details

(5 keywords)

Attachments

(1 file)

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


[task 2021-08-26T04:59:40.724Z] 04:59:40     INFO - TEST-START | testing/firefox-ui/tests/functional/sessionstore/test_restore_windows_after_windows_shutdown.py TestWindowsShutdown.test_with_variety
[task 2021-08-26T04:59:40.724Z] 04:59:40     INFO -  1629953980724	Marionette	DEBUG	Accepted connection 2 from 127.0.0.1:50335
[task 2021-08-26T04:59:40.746Z] 04:59:40     INFO -  1629953980747	Marionette	DEBUG	2 -> [0,1,"WebDriver:NewSession",{"strictFileInteractability":true}]
[task 2021-08-26T04:59:40.749Z] 04:59:40     INFO -  1629953980748	Marionette	DEBUG	2 <- [1,1,null,{"sessionId":"c2e550cc-6782-42f8-8769-4f4b4faf1552","capabilities":{"browserName":"firefox","browserVersion":"93.0a ... x.mozrunner","moz:shutdownTimeout":60000,"moz:useNonSpecCompliantPointerOrigin":false,"moz:webdriverClick":true,"proxy":{}}}]
[task 2021-08-26T04:59:40.749Z] 04:59:40     INFO -  1629953980749	Marionette	DEBUG	2 -> [0,2,"WebDriver:SetTimeouts",{"script":30000}]
[task 2021-08-26T04:59:40.750Z] 04:59:40     INFO -  1629953980749	Marionette	DEBUG	2 <- [1,2,null,{"value":null}]
[task 2021-08-26T04:59:40.750Z] 04:59:40     INFO -  1629953980750	Marionette	DEBUG	2 -> [0,3,"WebDriver:SetTimeouts",{"pageLoad":300000}]
[task 2021-08-26T04:59:40.750Z] 04:59:40     INFO -  1629953980750	Marionette	DEBUG	2 <- [1,3,null,{"value":null}]
[task 2021-08-26T04:59:40.751Z] 04:59:40     INFO -  1629953980750	Marionette	DEBUG	2 -> [0,4,"WebDriver:SetTimeouts",{"implicit":0}]
[task 2021-08-26T04:59:40.751Z] 04:59:40     INFO -  1629953980751	Marionette	DEBUG	2 <- [1,4,null,{"value":null}]
[task 2021-08-26T04:59:40.752Z] 04:59:40     INFO -  1629953980751	Marionette	DEBUG	2 -> [0,5,"WebDriver:GetChromeWindowHandle",{}]
[task 2021-08-26T04:59:40.752Z] 04:59:40     INFO -  1629953980751	Marionette	DEBUG	2 <- [1,5,null,{"value":"e5319773-391f-4744-b6fc-0422f58ed248"}]
[task 2021-08-26T04:59:40.752Z] 04:59:40     INFO -  1629953980752	Marionette	DEBUG	2 -> [0,6,"WebDriver:GetChromeWindowHandles",{}]
[task 2021-08-26T04:59:40.753Z] 04:59:40     INFO -  1629953980752	Marionette	DEBUG	2 <- [1,6,null,["e5319773-391f-4744-b6fc-0422f58ed248"]]
[task 2021-08-26T04:59:40.753Z] 04:59:40     INFO -  1629953980753	Marionette	DEBUG	2 -> [0,7,"WebDriver:GetWindowHandle",{}]
[task 2021-08-26T04:59:40.753Z] 04:59:40     INFO -  1629953980753	Marionette	DEBUG	2 <- [1,7,null,{"value":"fb1e92e3-c39a-47a1-adb4-47ab199b4557"}]
[task 2021-08-26T04:59:40.754Z] 04:59:40     INFO -  1629953980753	Marionette	DEBUG	2 -> [0,8,"WebDriver:GetWindowHandles",{}]
[task 2021-08-26T04:59:40.754Z] 04:59:40     INFO -  1629953980754	Marionette	DEBUG	2 <- [1,8,null,["fb1e92e3-c39a-47a1-adb4-47ab199b4557"]]
[task 2021-08-26T04:59:40.754Z] 04:59:40     INFO -  1629953980754	Marionette	DEBUG	2 -> [0,9,"Marionette:SetContext",{"value":"chrome"}]
[task 2021-08-26T04:59:40.755Z] 04:59:40     INFO -  1629953980754	Marionette	DEBUG	2 <- [1,9,null,{"value":null}]
[task 2021-08-26T04:59:40.755Z] 04:59:40     INFO -  1629953980755	Marionette	DEBUG	2 -> [0,10,"Marionette:GetContext",{}]
[task 2021-08-26T04:59:40.755Z] 04:59:40     INFO -  1629953980755	Marionette	DEBUG	2 <- [1,10,null,{"value":"chrome"}]
[task 2021-08-26T04:59:40.756Z] 04:59:40     INFO -  1629953980755	Marionette	DEBUG	2 -> [0,11,"Marionette:SetContext",{"value":"chrome"}]
[task 2021-08-26T04:59:40.756Z] 04:59:40     INFO -  1629953980756	Marionette	DEBUG	2 <- [1,11,null,{"value":null}]
[task 2021-08-26T04:59:40.757Z] 04:59:40     INFO -  1629953980757	Marionette	DEBUG	2 -> [0,12,"WebDriver:ExecuteScript",{"script":"let prefInterface = Components.classes[\"@mozilla.org/preferences-service;1\"]\n   ... efault","line":878,"filename":"Z:\\task_162995339425193\\build\\venv\\lib\\site-packages\\marionette_driver\\marionette.py"}]
[task 2021-08-26T04:59:40.758Z] 04:59:40     INFO -  1629953980758	Marionette	TRACE	[7] MarionetteCommands actor created for window id 2
[task 2021-08-26T04:59:40.760Z] 04:59:40     INFO -  1629953980759	Marionette	DEBUG	2 <- [1,12,null,{"value":false}]
[task 2021-08-26T04:59:40.760Z] 04:59:40     INFO -  1629953980760	Marionette	DEBUG	2 -> [0,13,"Marionette:SetContext",{"value":"chrome"}]
[task 2021-08-26T04:59:40.760Z] 04:59:40     INFO -  1629953980760	Marionette	DEBUG	2 <- [1,13,null,{"value":null}]
[task 2021-08-26T04:59:40.760Z] 04:59:40     INFO -  1629953980760	Marionette	DEBUG	2 -> [0,14,"Marionette:GetContext",{}]
[task 2021-08-26T04:59:40.761Z] 04:59:40     INFO -  1629953980760	Marionette	DEBUG	2 <- [1,14,null,{"value":"chrome"}]
[task 2021-08-26T04:59:40.761Z] 04:59:40     INFO -  1629953980761	Marionette	DEBUG	2 -> [0,15,"WebDriver:DeleteSession",{}]
[task 2021-08-26T04:59:40.761Z] 04:59:40     INFO -  1629953980761	Marionette	DEBUG	2 <- [1,15,null,{"value":null}]
[task 2021-08-26T04:59:40.762Z] 04:59:40     INFO -  1629953980761	Marionette	DEBUG	Closed connection 2
[task 2021-08-26T04:59:40.837Z] 04:59:40     INFO - Application command: Z:\task_162995339425193\build\application\firefox\firefox.exe -no-remote -marionette --wait-for-browser -profile Z:\task_162995339425193\build\tmpnj8yxmt8.mozrunner
[task 2021-08-26T04:59:41.128Z] 04:59:41     INFO -  1629953981141	Marionette	INFO	Marionette enabled
[task 2021-08-26T04:59:41.185Z] 04:59:41     INFO -  1629953981195	Marionette	TRACE	Received observer notification toplevel-window-ready
[task 2021-08-26T04:59:42.438Z] 04:59:42     INFO -  console.warn: SearchSettings: "get: No settings file exists, new profile?" (new NotFoundError("Could not open the file at Z:\\task_162995339425193\\build\\tmpnj8yxmt8.mozrunner\\search.json.mozlz4", (void 0)))
[task 2021-08-26T04:59:43.163Z] 04:59:43     INFO -  1629953983170	Marionette	TRACE	Received observer notification marionette-startup-requested
[task 2021-08-26T04:59:43.171Z] 04:59:43     INFO -  1629953983170	Marionette	TRACE	Waiting until startup recorder finished recording startup scripts...
[task 2021-08-26T04:59:43.200Z] 04:59:43     INFO -  1629953983211	Marionette	TRACE	All scripts recorded.
[task 2021-08-26T04:59:43.212Z] 04:59:43     INFO -  1629953983213	Marionette	INFO	Listening on port 2828
[task 2021-08-26T04:59:43.213Z] 04:59:43     INFO -  1629953983213	Marionette	DEBUG	Marionette is listening
[task 2021-08-26T04:59:43.288Z] 04:59:43     INFO -  1629953983294	Marionette	DEBUG	Accepted connection 0 from 127.0.0.1:50365
[task 2021-08-26T04:59:43.296Z] 04:59:43     INFO -  1629953983296	Marionette	DEBUG	Closed connection 0
[task 2021-08-26T04:59:43.296Z] 04:59:43     INFO -  1629953983296	Marionette	DEBUG	Accepted connection 1 from 127.0.0.1:50366
[task 2021-08-26T04:59:43.300Z] 04:59:43     INFO -  1629953983300	Marionette	DEBUG	1 -> [0,1,"WebDriver:NewSession",{"strictF
<...>
[task 2021-08-26T04:59:45.115Z] 04:59:45     INFO -  1629953985115	Marionette	DEBUG	Marionette stopped listening
[task 2021-08-26T04:59:45.128Z] 04:59:45     INFO -  JavaScript error: resource:///modules/Interactions.jsm, line 230: NS_ERROR_FAILURE: Component returned failure code: 0x80004005 (NS_ERROR_FAILURE) [nsIUserIdleService.removeIdleObserver]
[task 2021-08-26T04:59:45.140Z] 04:59:45     INFO -  JavaScript error: chrome://remote/content/marionette/cert.js, line 55: NS_ERROR_NOT_AVAILABLE: Component returned failure code: 0x80040111 (NS_ERROR_NOT_AVAILABLE) [nsICertOverrideService.setDisableAllSecurityChecksAndLetAttackersInterceptMyData]
[task 2021-08-26T04:59:45.153Z] 04:59:45     INFO -  ###!!! [Child][MessageChannel] Error: (msgtype=0x390156,name=PContent::Msg_InsertNewFocusActionId) Closed channel: cannot send/recv
[task 2021-08-26T04:59:45.168Z] 04:59:45     INFO -  ###!!! [Child][MessageChannel] Error: (msgtype=0x390156,name=PContent::Msg_InsertNewFocusActionId) Closed channel: cannot send/recv
[task 2021-08-26T04:59:45.168Z] 04:59:45     INFO -  ###!!! [Child][MessageChannel] Error: (msgtype=0x390156,name=PContent::Msg_InsertNewFocusActionId) Closed channel: cannot send/recv
[task 2021-08-26T04:59:45.170Z] 04:59:45     INFO -  ###!!! [Child][MessageChannel] Error: (msgtype=0x390156,name=PContent::Msg_InsertNewFocusActionId) Closed channel: cannot send/recv
[task 2021-08-26T04:59:45.170Z] 04:59:45     INFO -  ###!!! [Child][MessageChannel] Error: (msgtype=0x390156,name=PContent::Msg_InsertNewFocusActionId) Closed channel: cannot send/recv
[task 2021-08-26T04:59:45.170Z] 04:59:45     INFO -  ###!!! [Child][MessageChannel] Error: (msgtype=0x390156,name=PContent::Msg_InsertNewFocusActionId) Closed channel: cannot send/recv
[task 2021-08-26T04:59:45.170Z] 04:59:45     INFO -  ###!!! [Child][MessageChannel] Error: (msgtype=0x390156,name=PContent::Msg_InsertNewFocusActionId) Closed channel: cannot send/recv
[task 2021-08-26T04:59:45.170Z] 04:59:45     INFO -  ###!!! [Child][MessageChannel] Error: (msgtype=0x390156,name=PContent::Msg_InsertNewFocusActionId) Closed channel: cannot send/recv
[task 2021-08-26T04:59:45.170Z] 04:59:45     INFO -  ###!!! [Child][MessageChannel] Error: (msgtype=0x390156,name=PContent::Msg_InsertNewFocusActionId) Closed channel: cannot send/recv
[task 2021-08-26T04:59:45.248Z] 04:59:45     INFO -  Assertion failure
[task 2021-08-26T04:59:45.250Z] 04:59:45     INFO -  assert@resource:///modules/AsyncTabSwitcher.jsm:499:36
[task 2021-08-26T04:59:45.250Z] 04:59:45     INFO -  finish@resource:///modules/AsyncTabSwitcher.jsm:331:10
[task 2021-08-26T04:59:45.250Z] 04:59:45     INFO -  postActions@resource:///modules/AsyncTabSwitcher.jsm:697:12
[task 2021-08-26T04:59:45.251Z] 04:59:45     INFO -  handleEvent@resource:///modules/AsyncTabSwitcher.jsm:1116:12
[task 2021-08-26T04:59:45.251Z] 04:59:45     INFO -  onQueueUnload/this.unloadTimer<@resource:///modules/AsyncTabSwitcher.jsm:1060:18
[task 2021-08-26T04:59:45.251Z] 04:59:45     INFO -  observe@resource://gre/modules/AsyncShutdown.jsm:575:16
[task 2021-08-26T04:59:45.480Z] 04:59:45     INFO - Application command: Z:\task_162995339425193\build\application\firefox\firefox.exe -no-remote -marionette --wait-for-browser -profile Z:\task_162995339425193\build\tmpnj8yxmt8.mozrunner
[task 2021-08-26T04:59:45.750Z] 04:59:45     INFO -  1629953985749	Marionette	INFO	Marionette enabled
[task 2021-08-26T04:59:46.740Z] 04:59:46     INFO -  1629953986745	Marionette	TRACE	Received observer notification toplevel-window-ready
[task 2021-08-26T04:59:46.748Z] 04:59:46     INFO -  1629953986748	Marionette	TRACE	Received observer notification toplevel-window-ready
[task 2021-08-26T04:59:47.596Z] 04:59:47     INFO -  1629953987600	Marionette	TRACE	Received observer notification marionette-startup-requested
[task 2021-08-26T04:59:47.601Z] 04:59:47     INFO -  1629953987600	Marionette	TRACE	Waiting until startup recorder finished recording startup scripts...
[task 2021-08-26T04:59:47.614Z] 04:59:47     INFO -  1629953987619	Marionette	TRACE	All scripts recorded.
[task 2021-08-26T04:59:47.620Z] 04:59:47     INFO -  1629953987620	Marionette	INFO	Listening on port 2828
[task 2021-08-26T04:59:47.620Z] 04:59:47     INFO -  1629953987620	Marionette	DEBUG	Marionette is listening
[task 2021-08-26T04:59:47.812Z] 04:59:47     INFO -  1629953987821	Marionette	DEBUG	Accepted connection 0 from 127.0.0.1:50432
[task 2021-08-26T04:59:47.839Z] 04:59:47     INFO -  1629953987840	Marionette	DEBUG	Closed connection 0
[task 2021-08-26T04:59:47.941Z] 04:59:47     INFO -  1629953987942	Marionette	DEBUG	Accepted connection 1 from 127.0.0.1:50435
[task 2021-08-26T04:59:47.943Z] 04:59:47     INFO -  1629953987943	Marionette	DEBUG	Closed connection 1
[task 2021-08-26T04:59:47.943Z] 04:59:47     INFO -  1629953987943	Marionette	DEBUG	Accepted connection 2 from 127.0.0.1:50436
[task 2021-08-26T04:59:47.947Z] 04:59:47     INFO -  1629953987947	Marionette	DEBUG	2 -> [0,1,"WebDriver:NewSession",{"strictFileInteractability":true}]
[task 2021-08-26T04:59:47.953Z] 04:59:47     INFO -  1629953987953	Marionette	DEBUG	2 <- [1,1,null,{"sessionId":"a0c53d38-e624-4b70-82c6-169142f13dbb","capabilities":{"browserName":"firefox","browserVersion":"93.0a ... 8.mozrunner","moz:shutdownTimeout":60000,"moz:useNonSpecCompliantPointerOrigin":false,"moz:webdriverClick":true,"proxy":{}}}]
[task 2021-08-26T04:59:47.954Z] 04:59:47     INFO -  1629953987954	Marionette	DEBUG	2 -> [0,2,"Marionette:SetContext",{"value":"chrome"}]
[task 2021-08-26T04:59:47.954Z] 04:59:47     INFO -  1629953987954	Marionette	DEBUG	2 <- [1,2,null,{"value":null}]
[task 2021-08-26T04:59:47.954Z] 04:59:47     INFO -  1629953987954	Marionette	DEBUG	2 -> [0,3,"WebDriver:GetChromeWindowHandles",{}]
[task 2021-08-26T04:59:47.955Z] 04:59:47     INFO -  1629953987955	Marionette	DEBUG	2 <- [1,3,null,["cbb27d08-06ec-44a4-baad-f435d3618a4d","eb521717-794b-4105-b9a9-71bac98f2465","403c4b1f-60ba-4c1a-aa10-074162665ba9"]]
[task 2021-08-26T04:59:47.955Z] 04:59:47     INFO -  1629953987955	Marionette	DEBUG	2 -> [0,4,"WebDriver:GetChromeWindowHandle",{}]
[task 2021-08-26T04:59:47.955Z] 04:59:47     INFO -  1629953987955	Marionette	DEBUG	2 <- [1,4,null,{"value":"403c4b1f-60ba-4c1a-aa10-074162665ba9"}]
[task 2021-08-26T04:59:47.956Z] 04:59:47     INFO -  1629953987956	Marionette	DEBUG	2 -> [0,5,"Marionette:GetContext",{}]
[task 2021-08-26T04:59:47.956Z] 04:59:47     INFO -  1629953987956	Marionette	DEBUG	2 <- [1,5,null,{"value":"chrome"}]
[task 2021-08-26T04:59:47.956Z] 04:59:47     INFO -  1629953987957	Marionette	DEBUG	2 -> [0,6,"Marionette:SetContext",{"value":"chrome"}]
[task 2021-08-26T04:59:47.957Z] 04:59:47     INFO -  1629953987957	Marionette	DEBUG	2 <- [1,6,null,{"value":null}]
[task 2021-08-26T04:59:47.957Z] 04:59:47     INFO -  1629953987957	Marionette	DEBUG	2 -> [0,7,"WebDriver:SwitchToWindow",{"handle":"cbb27d08-06ec-44a4-baad-f435d3618a4d","focus":true}]
[task 2021-08-26T04:59:47.961Z] 04:59:47     INFO -  1629953987961	Marionette	TRACE	Received DOM event activate for [object Window]
[task 2021-08-26T04:59:47.961Z] 04:59:47     INFO -  1629953987961	Marionette	TRACE	Received DOM event focus for [object HTMLDocument]
[task 2021-08-26T04:59:47.964Z] 04:59:47     INFO -  1629953987964	Marionette	DEBUG	2 <- [1,7,null,{"value":null}]
[task 2021-08-26T04:59:47.966Z] 04:59:47     INFO -  1629953987966	Marionette	DEBUG	2 -> [0,8,"WebDriver:ExecuteScript",{"script":"return gBrowser.tabs.map(tab => {\n                    return tab.linkedBrowser.cur ... 9425193\\build\\tests\\firefox-ui\\tests\\testing\\firefox-ui\\tests\\functional\\sessionstore\\session_store_test_case.py"}]
[task 2021-08-26T04:59:47.968Z] 04:59:47     INFO -  1629953987968	Marionette	TRACE	[1] MarionetteCommands actor created for window id 2
[task 2021-08-26T04:59:47.969Z] 04:59:47     INFO -  1629953987969	Marionette	DEBUG	2 <- [1,8,null,{"value":["http://127.0.0.1:49817/layout/mozilla_governance.html","http://127.0.0.1:49817/layout/mozilla_grants.html"]}]
[task 2021-08-26T04:59:47.970Z] 04:59:47     INFO -  1629953987970	Marionette	DEBUG	2 -> [0,9,"Marionette:SetContext",{"value":"chrome"}]
[task 2021-08-26T04:59:47.970Z] 04:59:47     INFO -  1629953987970	Marionette	DEBUG	2 <- [1,9,null,{"value":null}]
[task 2021-08-26T04:59:47.970Z] 04:59:47     INFO -  1629953987970	Marionette	DEBUG	2 -> [0,10,"WebDriver:SwitchToWindow",{"handle":"403c4b1f-60ba-4c1a-aa10-074162665ba9","focus":true}]
[task 2021-08-26T04:59:47.975Z] 04:59:47     INFO -  1629953987975	Marionette	TRACE	Received DOM event activate for [object Window]
[task 2021-08-26T04:59:47.975Z] 04:59:47     INFO -  1629953987975	Marionette	TRACE	Received DOM event focus for [object HTMLDocument]
[task 2021-08-26T04:59:47.979Z] 04:59:47     INFO -  1629953987979	Marionette	DEBUG	2 <- [1,10,null,{"value":null}]
[task 2021-08-26T04:59:47.980Z] 04:59:47     INFO -  1629953987980	Marionette	DEBUG	2 -> [0,11,"WebDriver:GetChromeWindowHandle",{}]
[task 2021-08-26T04:59:47.981Z] 04:59:47     INFO -  1629953987981	Marionette	DEBUG	2 <- [1,11,null,{"value":"403c4b1f-60ba-4c1a-aa10-074162665ba9"}]
[task 2021-08-26T04:59:47.981Z] 04:59:47     INFO -  1629953987981	Marionette	DEBUG	2 -> [0,12,"Marionette:GetContext",{}]
[task 2021-08-26T04:59:47.981Z] 04:59:47     INFO -  1629953987981	Marionette	DEBUG	2 <- [1,12,null,{"value":"chrome"}]
[task 2021-08-26T04:59:47.982Z] 04:59:47     INFO -  1629953987982	Marionette	DEBUG	2 -> [0,13,"Marionette:SetContext",{"value":"chrome"}]
[task 2021-08-26T04:59:47.982Z] 04:59:47     INFO -  1629953987982	Marionette	DEBUG	2 <- [1,13,null,{"value":null}]
[task 2021-08-26T04:59:47.982Z] 04:59:47     INFO -  1629953987983	Marionette	DEBUG	2 -> [0,14,"WebDriver:SwitchToWindow",{"handle":"eb521717-794b-4105-b9a9-71bac98f2465","focus":true}]
[task 2021-08-26T04:59:47.986Z] 04:59:47     INFO -  1629953987986	Marionette	TRACE	Received DOM event activate for [object Window]
[task 2021-08-26T04:59:47.986Z] 04:59:47     INFO -  1629953987986	Marionette	TRACE	Received DOM event focus for [object HTMLDocument]
[task 2021-08-26T04:59:47.988Z] 04:59:47     INFO -  1629953987988	Marionette	DEBUG	2 <- [1,14,null,{"value":null}]
[task 2021-08-26T04:59:47.992Z] 04:59:47     INFO -  1629953987992	Marionette	DEBUG	2 -> [0,15,"WebDriver:ExecuteScript",{"script":"return gBrowser.tabs.map(tab => {\n                    return tab.linkedBrowser.cu ... 9425193\\build\\tests\\firefox-ui\\tests\\testing\\firefox-ui\\tests\\functional\\sessionstore\\session_store_test_case.py"}]
[task 2021-08-26T04:59:47.993Z] 04:59:47     INFO -  1629953987993	Marionette	TRACE	[31] MarionetteCommands actor created for window id 10
[task 2021-08-26T04:59:47.994Z] 04:59:47     INFO -  1629953987994	Marionette	DEBUG	2 <- [1,15,null,{"value":["http://127.0.0.1:49817/layout/mozilla.html"]}]
[task 2021-08-26T04:59:47.995Z] 04:59:47     INFO -  1629953987995	Marionette	DEBUG	2 -> [0,16,"Marionette:SetContext",{"value":"chrome"}]
[task 2021-08-26T04:59:47.995Z] 04:59:47     INFO -  1629953987995	Marionette	DEBUG	2 <- [1,16,null,{"value":null}]
[task 2021-08-26T04:59:47.995Z] 04:59:47     INFO -  1629953987995	Marionette	DEBUG	2 -> [0,17,"WebDriver:SwitchToWindow",{"handle":"403c4b1f-60ba-4c1a-aa10-074162665ba9","focus":true}]
[task 2021-08-26T04:59:47.999Z] 04:59:47     INFO -  1629953987999	Marionette	TRACE	Received DOM event activate for [object Window]
[task 2021-08-26T04:59:47.999Z] 04:59:47     INFO -  1629953987999	Marionette	TRACE	Received DOM event focus for [object HTMLDocument]
[task 2021-08-26T04:59:48.000Z] 04:59:48     INFO -  1629953988000	Marionette	DEBUG	2 <- [1,17,null,{"value":null}]

[task 2021-08-26T04:59:48.001Z] 04:59:48     INFO -  1629953988001	Marionette	DEBUG	2 -> [0,18,"WebDriver:GetChromeWindowHandle",{}]
[task 2021-08-26T04:59:48.001Z] 04:59:48     INFO -  1629953988001	Marionette	DEBUG	2 <- [1,18,null,{"value":"403c4b1f-60ba-4c1a-aa10-074162665ba9"}]
[task 2021-08-26T04:59:48.002Z] 04:59:48     INFO -  1629953988002	Marionette	DEBUG	2 -> [0,19,"Marionette:GetContext",{}]
[task 2021-08-26T04:59:48.002Z] 04:59:48     INFO -  1629953988002	Marionette	DEBUG	2 <- [1,19,null,{"value":"chrome"}]
[task 2021-08-26T04:59:48.002Z] 04:59:48     INFO -  1629953988002	Marionette	DEBUG	2 -> [0,20,"Marionette:SetContext",{"value":"chrome"}]
[task 2021-08-26T04:59:48.003Z] 04:59:48     INFO -  1629953988003	Marionette	DEBUG	2 <- [1,20,null,{"value":null}]
[task 2021-08-26T04:59:48.003Z] 04:59:48     INFO -  1629953988003	Marionette	DEBUG	2 -> [0,21,"WebDriver:SwitchToWindow",{"handle":"403c4b1f-60ba-4c1a-aa10-074162665ba9","focus":true}]
[task 2021-08-26T04:59:48.003Z] 04:59:48     INFO -  1629953988003	Marionette	DEBUG	2 <- [1,21,null,{"value":null}]
[task 2021-08-26T04:59:48.004Z] 04:59:48     INFO -  1629953988004	Marionette	DEBUG	2 -> [0,22,"WebDriver:ExecuteScript",{"script":"return gBrowser.tabs.map(tab => {\n                    return tab.linkedBrowser.cu ... 9425193\\build\\tests\\firefox-ui\\tests\\testing\\firefox-ui\\tests\\functional\\sessionstore\\session_store_test_case.py"}]
[task 2021-08-26T04:59:48.005Z] 04:59:48     INFO -  1629953988005	Marionette	TRACE	[32] MarionetteCommands actor created for window id 12
[task 2021-08-26T04:59:48.006Z] 04:59:48     INFO -  1629953988006	Marionette	DEBUG	2 <- [1,22,null,{"value":["http://127.0.0.1:49817/layout/mozilla_organizations.html","about:blank"]}]
[task 2021-08-26T04:59:48.006Z] 04:59:48     INFO -  1629953988006	Marionette	DEBUG	2 -> [0,23,"Marionette:SetContext",{"value":"chrome"}]
[task 2021-08-26T04:59:48.006Z] 04:59:48     INFO -  1629953988006	Marionette	DEBUG	2 <- [1,23,null,{"value":null}]
[task 2021-08-26T04:59:48.007Z] 04:59:48     INFO -  1629953988007	Marionette	DEBUG	2 -> [0,24,"WebDriver:SwitchToWindow",{"handle":"403c4b1f-60ba-4c1a-aa10-074162665ba9","focus":true}]
[task 2021-08-26T04:59:48.007Z] 04:59:48     INFO -  1629953988007	Marionette	DEBUG	2 <- [1,24,null,{"value":null}]
[task 2021-08-26T04:59:48.008Z] 04:59:48     INFO -  1629953988008	Marionette	DEBUG	2 -> [0,25,"Marionette:GetContext",{}]
[task 2021-08-26T04:59:48.008Z] 04:59:48     INFO -  1629953988008	Marionette	DEBUG	2 <- [1,25,null,{"value":"chrome"}]
[task 2021-08-26T04:59:48.008Z] 04:59:48     INFO -  1629953988008	Marionette	DEBUG	2 -> [0,26,"Marionette:SetContext",{"value":"chrome"}]
[task 2021-08-26T04:59:48.008Z] 04:59:48     INFO -  1629953988008	Marionette	DEBUG	2 <- [1,26,null,{"value":null}]
[task 2021-08-26T04:59:48.009Z] 04:59:48     INFO -  1629953988009	Marionette	DEBUG	2 -> [0,27,"WebDriver:TakeScreenshot",{"id":null,"full":true,"hash":false,"scroll":true}]
[task 2021-08-26T04:59:48.053Z] 04:59:48     INFO -  1629953988060	Marionette	DEBUG	2 <- [1,27,null,{"value":"iVBORw0KGgoAAAANSUhEUgAABAAAAAMHCAYAAACnvyW1AAAgAElEQVR4nO3d329c9Z038Fyu1L+gN+19lN5yuzeoF4SLIHqDskVZEXia ... AABQAAAAAEoAAAAACAABQAAAAAEIACAAAAAAJQAAAAAEAACgAAAAAIQAEAAAAAASgAAAAAIAAFAAAAAASgAAAAAIAA/j/GBcsIKBu/UgAAAABJRU5ErkJggg=="}]
[task 2021-08-26T04:59:48.063Z] 04:59:48     INFO -  1629953988064	Marionette	DEBUG	2 -> [0,28,"Marionette:SetContext",{"value":"chrome"}]
[task 2021-08-26T04:59:48.064Z] 04:59:48     INFO -  1629953988064	Marionette	DEBUG	2 <- [1,28,null,{"value":null}]
[task 2021-08-26T04:59:48.064Z] 04:59:48     INFO -  1629953988065	Marionette	DEBUG	2 -> [0,29,"Marionette:GetContext",{}]
[task 2021-08-26T04:59:48.064Z] 04:59:48     INFO -  1629953988065	Marionette	DEBUG	2 <- [1,29,null,{"value":"chrome"}]
[task 2021-08-26T04:59:48.065Z] 04:59:48     INFO -  1629953988065	Marionette	DEBUG	2 -> [0,30,"Marionette:SetContext",{"value":"content"}]
[task 2021-08-26T04:59:48.065Z] 04:59:48     INFO -  1629953988066	Marionette	DEBUG	2 <- [1,30,null,{"value":null}]
[task 2021-08-26T04:59:48.066Z] 04:59:48     INFO -  1629953988066	Marionette	DEBUG	2 -> [0,31,"WebDriver:GetPageSource",{}]
[task 2021-08-26T04:59:48.068Z] 04:59:48     INFO -  1629953988068	Marionette	TRACE	[37] MarionetteCommands actor created for window id 6442450945
[task 2021-08-26T04:59:48.069Z] 04:59:48     INFO -  1629953988070	Marionette	DEBUG	2 <- [1,31,null,{"value":"<html><head></head><body></body></html>"}]
[task 2021-08-26T04:59:48.070Z] 04:59:48     INFO -  1629953988070	Marionette	DEBUG	2 -> [0,32,"Marionette:SetContext",{"value":"chrome"}]
[task 2021-08-26T04:59:48.070Z] 04:59:48     INFO -  1629953988071	Marionette	DEBUG	2 <- [1,32,null,{"value":null}]
[task 2021-08-26T04:59:48.084Z] 04:59:48     INFO - TEST-UNEXPECTED-FAIL | testing/firefox-ui/tests/functional/sessionstore/test_restore_windows_after_windows_shutdown.py TestWindowsShutdown.test_with_variety | AssertionError: Items in the first set but not the second:
[task 2021-08-26T04:59:48.092Z] 04:59:48     INFO - ('http://127.0.0.1:49817/layout/mozilla_organizations.html', 'about:blank')
[task 2021-08-26T04:59:48.092Z] 04:59:48     INFO - Items in the second set but not the first:
[task 2021-08-26T04:59:48.092Z] 04:59:48     INFO - ('http://127.0.0.1:49817/layout/mozilla_organizations.html', 'http://127.0.0.1:49817/layout/mozilla_community.html') : Non private browsing windows should have
[task 2021-08-26T04:59:48.092Z] 04:59:48     INFO -                              been restored. Expected {('http://127.0.0.1:49817/layout/mozilla_governance.html', 'http://127.0.0.1:49817/layout/mozilla_grants.html'), ('http://127.0.0.1:49817/layout/mozilla.html',), ('http://127.0.0.1:49817/layout/mozilla_organizations.html', 'http://127.0.0.1:49817/layout/mozilla_community.html')}, got {('http://127.0.0.1:49817/layout/mozilla_organizations.html', 'about:blank'), ('http://127.0.0.1:49817/layout/mozilla_governance.html', 'http://127.0.0.1:49817/layout/mozilla_grants.html'), ('http://127.0.0.1:49817/layout/mozilla.html',)}.
[task 2021-08-26T04:59:48.092Z] 04:59:48     INFO - Traceback (most recent call last):
[task 2021-08-26T04:59:48.092Z] 04:59:48     INFO -   File "Z:\task_162995339425193\build\venv\lib\site-packages\marionette_harness\marionette_test\testcases.py", line 202, in run
[task 2021-08-26T04:59:48.092Z] 04:59:48     INFO -     testMethod()
[task 2021-08-26T04:59:48.092Z] 04:59:48     INFO -   File "Z:\task_162995339425193\build\tests\firefox-ui\tests\testing\firefox-ui\tests\functional\sessionstore\test_restore_windows_after_windows_shutdown.py", line 32, in test_with_variety
[task 2021-08-26T04:59:48.092Z] 04:59:48     INFO -     self.windows_shutdown_with_variety(restart_by_os=False, expect_restore=True)
[task 2021-08-26T04:59:48.092Z] 04:59:48     INFO -   File "Z:\task_162995339425193\build\tests\firefox-ui\tests\testing\firefox-ui\tests\functional\sessionstore\session_store_test_case.py", line 381, in windows_shutdown_with_variety
[task 2021-08-26T04:59:48.092Z] 04:59:48     INFO -     self.assertEqual(
[task 2021-08-26T04:59:48.092Z] 04:59:48     INFO - TEST-INFO took 7348ms
[task 2021-08-26T04:59:48.093Z] 04:59:48     INFO -  1629953988088	Marionette	DEBUG	2 -> [0,33,"Marionette:GetContext",{}]
[task 2021-08-26T04:59:48.093Z] 04:59:48     INFO -  1629953988088	Marionette	DEBUG	2 <- [1,33,null,{"value":"chrome"}]
[task 2021-08-26T04:59:48.093Z] 04:59:48     INFO -  1629953988088	Marionette	DEBUG	2 -> [0,34,"WebDriver:DeleteSession",{}]
[task 2021-08-26T04:59:48.094Z] 04:59:48     INFO -  1629953988089	Marionette	DEBUG	2 <- [1,34,null,{"value":null}]
[task 2021-08-26T04:59:48.094Z] 04:59:48     INFO -  1629953988089	Marionette	DEBUG	Closed connection 2
[task 2021-08-26T04:59:48.198Z] 04:59:48     INFO - Application command: Z:\task_162995339425193\build\application\firefox\firefox.exe -no-remote -marionette --wait-for-browser -profile Z:\task_162995339425193\build\tmp09m1hd98.mozrunner
[task 2021-08-26T04:59:48.500Z] 04:59:48     INFO -  1629953988509	Marionette	INFO	Marionette enabled
[task 2021-08-26T04:59:48.553Z] 04:59:48     INFO -  1629953988563	Marionette	TRACE	Received observer notification toplevel-window-ready
[task 2021-08-26T04:59:49.826Z] 04:59:49     INFO -  console.warn: SearchSettings: "get: No settings file exists, new profile?" (new NotFoundError("Could not open the file at Z:\\task_162995339425193\\build\\tmp09m1hd98.mozrunner\\search.json.mozlz4", (void 0)))
[task 2021-08-26T04:59:50.311Z] 04:59:50     INFO -  1629953990321	Marionette	TRACE	Received observer notification marionette-startup-requested
[task 2021-08-26T04:59:50.322Z] 04:59:50     INFO -  1629953990321	Marionette	TRACE	Waiting until startup recorder finished recording startup scripts...
[task 2021-08-26T04:59:50.329Z] 04:59:50     INFO -  1629953990329	Marionette	TRACE	All scripts recorded.
[task 2021-08-26T04:59:50.330Z] 04:59:50     INFO -  1629953990330	Marionette	INFO	Listening on port 2828
[task 2021-08-26T04:59:50.331Z] 04:59:50     INFO -  1629953990330	Marionette	DEBUG	Marionette is listening
[task 2021-08-26T04:59:50.528Z] 04:59:50     INFO -  1629953990534	Marionette	DEBUG	Accepted connection 0 from 127.0.0.1:50450
[task 2021-08-26T04:59:50.536Z] 04:59:50     INFO -  1629953990536	Marionette	DEBUG	Closed connection 0
[task 2021-08-26T04:59:50.643Z] 04:59:50     INFO -  1629953990644	Marionette	DEBUG	Accepted connection 1 from 127.0.0.1:50469
[task 2021-08-26T04:59:50.673Z] 04:59:50     INFO -  1629953990675	Marionette	DEBUG	Accepted connection 2 from 127.0.0.1:50473
[task 2021-08-26T04:59:50.676Z] 04:59:50     INFO -  1629953990675	Marionette	DEBUG	Closed connection 1
[task 2021-08-26T04:59:50.681Z] 04:59:50     INFO -  1629953990681	Marionette	DEBUG	2 -> [0,1,"WebDriver:NewSession",{"strictFileInteractability":true}]
[task 2021-08-26T04:59:50.689Z] 04:59:50     INFO -  1629953990688	Marionette	DEBUG	2 <- [1,1,null,{"sessionId":"2146e5f0-76ab-4d4d-85cf-f6e18ba008a0","capabilities":{"browserName":"firefox","browserVersion":"93.0a ... 8.mozrunner","moz:shutdownTimeout":60000,"moz:useNonSpecCompliantPointerOrigin":false,"moz:webdriverClick":true,"proxy":{}}}]
[task 2021-08-26T04:59:50.693Z] 04:59:50     INFO -  1629953990693	Marionette	DEBUG	2 -> [0,2,"Marionette:SetContext",{"value":"chrome"}]
[task 2021-08-26T04:59:50.694Z] 04:59:50     INFO -  1629953990693	Marionette	DEBUG	2 <- [1,2,null,{"value":null}]
[task 2021-08-26T04:59:50.694Z] 04:59:50     INFO -  1629953990694	Marionette	DEBUG	2 -> [0,3,"WebDriver:GetChromeWindowHandles",{}]
[task 2021-08-26T04:59:50.694Z] 04:59:50     INFO -  1629953990694	Marionette	DEBUG	2 <- [1,3,null,["ea2cd343-b7c7-4ad0-ae7a-45797b1618de"]]
[task 2021-08-26T04:59:50.695Z] 04:59:50     INFO -  1629953990695	Marionette	DEBUG	2 -> [0,4,"WebDriver:GetWindowHandles",{}]
[task 2021-08-26T04:59:50.695Z] 04:59:50     INFO -  1629953990695	Marionette	DEBUG	2 <- [1,4,null,["69bc5f42-b084-4f04-8b5e-f50c33cc221f"]]
[task 2021-08-26T04:59:50.697Z] 04:59:50     INFO -  1629953990696	Marionette	DEBUG	2 -> [0,5,"WebDriver:DeleteSession",{}]
[task 2021-08-26T04:59:50.698Z] 04:59:50     INFO -  1629953990698	Marionette	DEBUG	2 <- [1,5,null,{"value":null}]
[task 2021-08-26T04:59:50.699Z] 04:59:50     INFO -  1629953990698	Marionette	DEBUG	Closed connection 2
[task 2021-08-26T04:59:50.699Z] 04:59:50     INFO - TEST-START | testing/firefox-ui/tests/functional/sessionstore/test_restore_windows_after_windows_shutdown.py TestWindowsShutdownForcedSessionRestore.test_manual_restart
Has Regression Range: --- → yes
Assignee: nobody → michelle
Status: NEW → ASSIGNED
Flags: needinfo?(michelle)
Pushed by michelle@masterwayz.nl:
https://hg.mozilla.org/integration/autoland/rev/52ec40f7b85d
Disable test_restore_windows_after_windows_shutdown.py for intermittent failures r=intermittent-reviewers,webdriver-reviewers,jmaher
Status: ASSIGNED → RESOLVED
Closed: 3 years ago
Resolution: --- → DUPLICATE
Assignee: michelle → nobody
Status: RESOLVED → REOPENED
Keywords: test-disabled
Resolution: DUPLICATE → ---

This intermittent failure is only happening on Windows since the CI has been changed from AWS to Azure. And it seems like that session restore doesn't correctly keep the opened windows/tabs from the former session after a shutdown.

Component: Firefox UI Tests → Session Restore
OS: Unspecified → Windows
Product: Testing → Firefox
QA Contact: hskupin
Hardware: Unspecified → Desktop
Summary: Intermittent testing/firefox-ui/tests/functional/sessionstore/test_restore_windows_after_windows_shutdown.py TestWindowsShutdown.test_with_variety | AssertionError: Items in the first set but not the second: → Intermittent Windows testing/firefox-ui/tests/functional/sessionstore/test_restore_windows_after_windows_shutdown.py TestWindowsShutdown.test_with_variety | AssertionError: Items in the first set but not the second:

Kashav, could someone from the session restore team could take a look at this failure? Note that this test has been disabled. Thanks.

Flags: needinfo?(kmadan)
Flags: needinfo?(kshvmdn+bugs) → needinfo?(dao+bmo)

Redirecting NI to Adam Gashlin who wrote this test.

Flags: needinfo?(dao+bmo) → needinfo?(agashlin)

One of the tabs is sometimes about:blank after session restore (first set), instead of the document that was there on shutdown (second set). Within a given job, if a document is missing it's always the same one, the last one opened in a non-private window; this could be one of 3 given how the set of windows was initialized, but within a test it's the same for every subtest. I checked these jobs to establish the pattern: 1, 2, 3, 4, 5.

There's also this assertion failure when the first session is shutting down:

Assertion failure
assert@resource:///modules/AsyncTabSwitcher.jsm:499:36
finish@resource:///modules/AsyncTabSwitcher.jsm:331:10
postActions@resource:///modules/AsyncTabSwitcher.jsm:697:12
handleEvent@resource:///modules/AsyncTabSwitcher.jsm:1116:12
onQueueUnload/this.unloadTimer<@resource:///modules/AsyncTabSwitcher.jsm:1060:18
observe@resource://gre/modules/AsyncShutdown.jsm:575:16

This happens in failing jobs like this but not successful jobs like this. That AsyncTabSwitcher.finish() line is an assertion !this.blankTab.


The Windows-only test_restore_windows_after_windows_shutdown.py which was disabled is meant to test a particular shutdown path (which had some issues, see bug 1466071 and bug 1458119 comment 7). But I don't think these failures are exclusive to that; there are similar recent failures in test_restore_windows_after_restart_and_quit.py on OS X (1, 2, 3, 4). The only difference is that it's the first, not the last, tab that isn't restored, and there's no AsyncTabSwitcher assertion. Maybe a different root cause with a similar symptom?


I don't understand enough about the guts of session restore to investigate further. :dao, does this suggest anything?

Flags: needinfo?(agashlin) → needinfo?(dao+bmo)

Set release status flags based on info from the regressing bug 1727610

As we have seen during the last days for wdspec tests (geckodriver/marionette), running tests on the Azure machines is slower than on AWS. Maybe this causes session restore to misbehave, or being slower too in restoring the tabs. As Joel mentioned there is work going on to improve the performance by switching to a faster disk setup. Work for that is being done on bug 1733505. Maybe it will fix the problem.

Status: REOPENED → NEW
Depends on: 1733505
Flags: needinfo?(dao+bmo)

Also note that in all the cases where the list of tabs is asserted, we expect that the restoration has been done:

https://searchfox.org/mozilla-central/rev/2c4b830b924f42283632b70f39a60fd36433dd4d/testing/firefox-ui/tests/functional/sessionstore/session_store_test_case.py#381,391,396

Maybe we should instead use Wait.until() and have a timeout of maybe 5s or so? Here an example for safebrowsing:

https://searchfox.org/mozilla-central/rev/2c4b830b924f42283632b70f39a60fd36433dd4d/testing/firefox-ui/tests/functional/safebrowsing/test_initial_download.py#130-133

But I find this strange given that Marionette isn't enabled before the session is fully restored:

https://searchfox.org/mozilla-central/rev/2c4b830b924f42283632b70f39a60fd36433dd4d/browser/components/BrowserGlue.jsm#2659

Or is that no longer the case?

Flags: needinfo?(dao+bmo)

Sheriffs, all the recent failure classifications are incorrectly set for this bug. Note that this bug is Windows only, and tests are currently disabled. Can you please correct that? Thanks.

Some improvements have been done recently, which might have fixed this failure. So we should do a try build with the landed disable patch backed out.

(In reply to Henrik Skupin (:whimboo) [⌚️UTC+1] from comment #23)

Sheriffs, all the recent failure classifications are incorrectly set for this bug. Note that this bug is Windows only, and tests are currently disabled. Can you please correct that? Thanks.

This still applies and all the failures from the last two weeks are also wrongly classified. This bug is Windows only as the summary reflects.

Flags: needinfo?(sheriff)
Flags: needinfo?(sheriff)
Flags: needinfo?(dao+bmo)

With the upcoming changes on bug 1726465 we might get this intermittent fixed.

Depends on: 1726465

The work on bug 1759574 should actually fix that intermittent failure.

Depends on: 1759574
No longer depends on: 1726465

Actually the failures here should be related to Windows hardware workers. Whenever the tests are run on such machines, the tests will fail. With the changes on bug 1759705 to let Marionette jobs run on virtualized machines we at least skip them now correctly.

Dao, after my patches from bug 1759574 landed I wonder if it would make sense to check why these tests are completely broken? Not sure how important these tests are for sure.

Flags: needinfo?(dao+bmo)

(In reply to Henrik Skupin (:whimboo) [⌚️UTC+1] from comment #39)

Actually the failures here should be related to Windows hardware workers. Whenever the tests are run on such machines, the tests will fail. With the changes on bug 1759705 to let Marionette jobs run on virtualized machines we at least skip them now correctly.

Dao, after my patches from bug 1759574 landed I wonder if it would make sense to check why these tests are completely broken? Not sure how important these tests are for sure.

I don't think they're hugely important. Session Store tests can more or less trigger the Session Restore parts of a restart without having to actually restart. That said, having at least minimal test coverage for an actual restart would be nice.

Flags: needinfo?(dao+bmo)
Summary: Intermittent Windows testing/firefox-ui/tests/functional/sessionstore/test_restore_windows_after_windows_shutdown.py TestWindowsShutdown.test_with_variety | AssertionError: Items in the first set but not the second: → Intermittent Windows browser/component/sessionstore/test/marionette/test_restore_windows_after_windows_shutdown.py TestWindowsShutdown.test_with_variety | AssertionError: Items in the first set but not the second:
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Created:
Updated:
Size: