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)
Tracking
()
Tracking | Status | |
---|---|---|
firefox-esr78 | --- | unaffected |
firefox-esr91 | --- | disabled |
firefox91 | --- | unaffected |
firefox92 | --- | unaffected |
firefox93 | --- | disabled |
firefox94 | --- | wontfix |
People
(Reporter: intermittent-bug-filer, Unassigned)
References
(Regression)
Details
(4 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
Updated•3 years ago
|
Updated•3 years ago
|
Comment 1•3 years ago
|
||
Updated•3 years ago
|
Updated•3 years ago
|
Comment hidden (Intermittent Failures Robot) |
Updated•3 years ago
|
Comment 4•3 years ago
|
||
bugherder |
Updated•3 years ago
|
Comment hidden (Intermittent Failures Robot) |
Updated•3 years ago
|
Updated•3 years ago
|
Comment 9•3 years ago
|
||
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.
Updated•3 years ago
|
Comment hidden (Intermittent Failures Robot) |
Comment 11•3 years ago
|
||
Kashav, could someone from the session restore team could take a look at this failure? Note that this test has been disabled. Thanks.
Comment hidden (Intermittent Failures Robot) |
Comment 13•3 years ago
|
||
bugherder uplift |
Updated•3 years ago
|
Comment hidden (Intermittent Failures Robot) |
Updated•3 years ago
|
Comment 15•3 years ago
|
||
Redirecting NI to Adam Gashlin who wrote this test.
Comment 16•3 years ago
•
|
||
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?
Comment hidden (Intermittent Failures Robot) |
Comment 18•3 years ago
|
||
Set release status flags based on info from the regressing bug 1727610
Comment hidden (Intermittent Failures Robot) |
Comment 20•3 years ago
|
||
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.
Comment 21•3 years ago
|
||
Also note that in all the cases where the list of tabs is asserted, we expect that the restoration has been done:
Maybe we should instead use Wait.until()
and have a timeout of maybe 5s or so? Here an example for safebrowsing:
But I find this strange given that Marionette isn't enabled before the session is fully restored:
Or is that no longer the case?
Comment hidden (Intermittent Failures Robot) |
Comment 23•3 years ago
|
||
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.
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment 26•3 years ago
|
||
(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.
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Updated•3 years ago
|
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment 36•3 years ago
|
||
With the upcoming changes on bug 1726465 we might get this intermittent fixed.
Comment hidden (Intermittent Failures Robot) |
Comment 38•3 years ago
|
||
The work on bug 1759574 should actually fix that intermittent failure.
Comment 39•3 years ago
|
||
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.
Comment 40•3 years ago
|
||
(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.
Updated•3 years ago
|
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment 43•3 months ago
|
||
https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
For more information, please visit BugBot documentation.
Updated•3 months ago
|
Comment 44•3 months ago
|
||
The test was disabled so the bug shouldn't have been closed. A fix already landed for the bot.
Description
•