Closed Bug 1754363 Opened 3 years ago Closed 1 month ago

Intermittent Mn | after FATAL ERROR: Non-local network connections [...] aus5.mozilla.org (35.244.181.201) was made.

Categories

(Remote Protocol :: Agent, defect, P5)

defect

Tracking

(firefox-esr91 unaffected, firefox-esr115 wontfix, firefox-esr128 unaffected, firefox97 unaffected, firefox98 unaffected, firefox99 wontfix, firefox100 wontfix, firefox101 wontfix, firefox114 wontfix, firefox115 wontfix, firefox116 wontfix, firefox130 unaffected, firefox131 unaffected, firefox132 unaffected)

RESOLVED WORKSFORME
Tracking Status
firefox-esr91 --- unaffected
firefox-esr115 --- wontfix
firefox-esr128 --- unaffected
firefox97 --- unaffected
firefox98 --- unaffected
firefox99 --- wontfix
firefox100 --- wontfix
firefox101 --- wontfix
firefox114 --- wontfix
firefox115 --- wontfix
firefox116 --- wontfix
firefox130 --- unaffected
firefox131 --- unaffected
firefox132 --- unaffected

People

(Reporter: intermittent-bug-filer, Unassigned)

References

(Regression)

Details

(Keywords: intermittent-failure, regression)

Crash Data

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


[task 2022-02-09T05:07:37.146Z] 05:07:37     INFO - TEST-START | testing/marionette/harness/marionette_harness/tests/unit/test_switch_window_chrome.py TestSwitchToWindowContent.test_switch_to_unloaded_tab
[task 2022-02-09T05:07:37.147Z] 05:07:37     INFO -  1644383257146	Marionette	DEBUG	Closed connection 18
[task 2022-02-09T05:07:37.148Z] 05:07:37     INFO -  1644383257147	Marionette	DEBUG	Accepted connection 19 from 127.0.0.1:57148
[task 2022-02-09T05:07:37.149Z] 05:07:37     INFO -  1644383257149	Marionette	DEBUG	19 -> [0,1,"WebDriver:NewSession",{"strictFileInteractability":true}]
[task 2022-02-09T05:07:37.153Z] 05:07:37     INFO -  1644383257152	RemoteAgent	TRACE	[18] Document already finished loading: http://127.0.0.1:35807/test_iframe.html
[task 2022-02-09T05:07:37.154Z] 05:07:37     INFO -  1644383257153	Marionette	DEBUG	19 <- [1,1,null,{"sessionId":"00d5d358-1530-4f73-9358-537b5df36aae","capabilities":{"browserName":"firefox","browserVersion":"99.0a ... .mozrunner","moz:shutdownTimeout":300000,"moz:useNonSpecCompliantPointerOrigin":false,"moz:webdriverClick":true,"proxy":{}}}]
[task 2022-02-09T05:07:37.155Z] 05:07:37     INFO -  1644383257155	Marionette	DEBUG	19 -> [0,2,"WebDriver:SetTimeouts",{"script":30000}]
[task 2022-02-09T05:07:37.156Z] 05:07:37     INFO -  1644383257155	Marionette	DEBUG	19 <- [1,2,null,{"value":null}]
[task 2022-02-09T05:07:37.157Z] 05:07:37     INFO -  1644383257157	Marionette	DEBUG	19 -> [0,3,"WebDriver:SetTimeouts",{"pageLoad":300000}]
[task 2022-02-09T05:07:37.158Z] 05:07:37     INFO -  1644383257157	Marionette	DEBUG	19 <- [1,3,null,{"value":null}]
[task 2022-02-09T05:07:37.159Z] 05:07:37     INFO -  1644383257159	Marionette	DEBUG	19 -> [0,4,"WebDriver:SetTimeouts",{"implicit":0}]
[task 2022-02-09T05:07:37.160Z] 05:07:37     INFO -  1644383257159	Marionette	DEBUG	19 <- [1,4,null,{"value":null}]
[task 2022-02-09T05:07:37.161Z] 05:07:37     INFO -  1644383257161	Marionette	DEBUG	19 -> [0,5,"Marionette:GetContext",{}]
[task 2022-02-09T05:07:37.162Z] 05:07:37     INFO -  1644383257161	Marionette	DEBUG	19 <- [1,5,null,{"value":"content"}]
[task 2022-02-09T05:07:37.163Z] 05:07:37     INFO -  1644383257163	Marionette	DEBUG	19 -> [0,6,"Marionette:SetContext",{"value":"chrome"}]
[task 2022-02-09T05:07:37.164Z] 05:07:37     INFO -  1644383257163	Marionette	DEBUG	19 <- [1,6,null,{"value":null}]
[task 2022-02-09T05:07:37.165Z] 05:07:37     INFO -  1644383257165	Marionette	DEBUG	19 -> [0,7,"WebDriver:GetWindowHandle",{}]
[task 2022-02-09T05:07:37.166Z] 05:07:37     INFO -  1644383257165	Marionette	DEBUG	19 <- [1,7,null,{"value":"a2f09c1b-25b8-47f5-8e94-1eef113ca4aa"}]
[task 2022-02-09T05:07:37.167Z] 05:07:37     INFO -  1644383257166	Marionette	DEBUG	19 -> [0,8,"Marionette:SetContext",{"value":"content"}]
[task 2022-02-09T05:07:37.168Z] 05:07:37     INFO -  1644383257167	Marionette	DEBUG	19 <- [1,8,null,{"value":null}]
[task 2022-02-09T05:07:37.169Z] 05:07:37     INFO -  1644383257169	Marionette	DEBUG	19 -> [0,9,"Marionette:GetContext",{}]
[task 2022-02-09T05:07:37.170Z] 05:07:37     INFO -  1644383257169	Marionette	DEBUG	19 <- [1,9,null,{"value":"content"}]
[task 2022-02-09T05:07:37.172Z] 05:07:37     INFO -  1644383257171	Marionette	DEBUG	19 -> [0,10,"Marionette:SetContext",{"value":"chrome"}]
[task 2022-02-09T05:07:37.172Z] 05:07:37     INFO -  1644383257172	Marionette	DEBUG	19 <- [1,10,null,{"value":null}]
[task 2022-02-09T05:07:37.174Z] 05:07:37     INFO -  1644383257173	Marionette	DEBUG	19 -> [0,11,"WebDriver:GetWindowHandles",{}]
[task 2022-02-09T05:07:37.175Z] 05:07:37     INFO -  1644383257174	Marionette	DEBUG	19 <- [1,11,null,["a2f09c1b-25b8-47f5-8e94-1eef113ca4aa"]]
[task 2022-02-09T05:07:37.176Z] 05:07:37     INFO -  1644383257176	Marionette	DEBUG	19 -> [0,12,"Marionette:SetContext",{"value":"content"}]
[task 2022-02-09T05:07:37.177Z] 05:07:37     INFO -  1644383257176	Marionette	DEBUG	19 <- [1,12,null,{"value":null}]
[task 2022-02-09T05:07:37.178Z] 05:07:37     INFO -  1644383257177	Marionette	DEBUG	19 -> [0,13,"Marionette:GetContext",{}]
[task 2022-02-09T05:07:37.179Z] 05:07:37     INFO -  1644383257178	Marionette	DEBUG	19 <- [1,13,null,{"value":"content"}]
[task 2022-02-09T05:07:37.180Z] 05:07:37     INFO -  1644383257179	Marionette	DEBUG	19 -> [0,14,"Marionette:SetContext",{"value":"content"}]
[task 2022-02-09T05:07:37.181Z] 05:07:37     INFO -  1644383257180	Marionette	DEBUG	19 <- [1,14,null,{"value":null}]
[task 2022-02-09T05:07:37.182Z] 05:07:37     INFO -  1644383257182	Marionette	DEBUG	19 -> [0,15,"WebDriver:GetWindowHandle",{}]
[task 2022-02-09T05:07:37.184Z] 05:07:37     INFO -  1644383257183	Marionette	DEBUG	19 <- [1,15,null,{"value":"d1cfb9b3-2465-43b0-9f20-ee9455ceb03c"}]
[task 2022-02-09T05:07:37.185Z] 05:07:37     INFO -  1644383257184	Marionette	DEBUG	19 -> [0,16,"Marionette:SetContext",{"value":"content"}]
[task 2022-02-09T05:07:37.185Z] 05:07:37     INFO -  1644383257185	Marionette	DEBUG	19 <- [1,16,null,{"value":null}]
[task 2022-02-09T05:07:37.187Z] 05:07:37     INFO -  1644383257186	Marionette	DEBUG	19 -> [0,17,"Marionette:GetContext",{}]
[task 2022-02-09T05:07:37.188Z] 05:07:37     INFO -  1644383257186	Marionette	DEBUG	19 <- [1,17,null,{"value":"content"}]
[task 2022-02-09T05:07:37.189Z] 05:07:37     INFO -  1644383257189	Marionette	DEBUG	19 -> [0,18,"Marionette:SetContext",{"value":"content"}]
[task 2022-02-09T05:07:37.190Z] 05:07:37     INFO -  1644383257189	Marionette	DEBUG	19 <- [1,18,null,{"value":null}]
[task 2022-02-09T05:07:37.191Z] 05:07:37     INFO -  1644383257191	Marionette	DEBUG	19 -> [0,19,"WebDriver:GetWindowHandles",{}]
[task 2022-02-09T05:07:37.192Z] 05:07:37     INFO -  1644383257192	Marionette	DEBUG	19 <- [1,19,null,["d1cfb9b3-2465-43b0-9f20-ee9455ceb03c"]]
[task 2022-02-09T05:07:37.193Z] 05:07:37     INFO -  1644383257193	Marionette	DEBUG	19 -> [0,20,"Marionette:SetContext",{"value":"content"}]
[task 2022-02-09T05:07:37.194Z] 05:07:37     INFO -  1644383257194	Marionette	DEBUG	19 <- [1,20,null,{"value":null}]
[task 2022-02-09T05:07:37.195Z] 05:07:37     INFO -  1644383257195	Marionette	DEBUG	19 -> [0,21,"Marionette:GetContext",{}]
[task 2022-02-09T05:07:37.196Z] 05:07:37     INFO -  1644383257195	Marionette	DEBUG	19 <- [1,21,null,{"value":"content"}]
[task 2022-02-09T05:07:37.197Z] 05:07:37     INFO -  1644383257197	Marionette	DEBUG	19 -> [0,22,"Marionette:SetContext",{"value":"chrome"}]
[task 2022-02-09T05:07:37.198Z] 05:07:37     INFO -  1644383257197	Marionette	DEBUG	19 <- [1,22,null,{"value":null}]
[task 2022-02-09T05:07:37.200Z] 05:07:37     INFO -  1644383257199	Marionette	DEBUG	19 -> [0,23,"WebDriver:ExecuteScript",{"script":"Components.utils.import(\"resource://gre/modules/AppConstants.jsm\");\n\n          ... efault","line":76,"filename":"tests/testing/marionette/harness/marionette_harness/tests/unit/test_switch_window_content.py"}]
[task 2022-02-09T05:07:37.201Z] 05:07:37     INFO -  1644383257201	Marionette	TRACE	[1] MarionetteCommands actor created for window id 2
[task 2022-02-09T05:07:37.205Z] 05:07:37     INFO -  1644383257205	Marionette	DEBUG	19 <- [1,23,null,{"value":0}]
[task 2022-02-09T05:07:37.207Z] 05:07:37     INFO -  1644383257207	Marionette	DEBUG	19 -> [0,24,"Marionette:SetContext",{"value":"content"}]
[task 2022-02-09T05:07:37.208Z] 05:07:37     INFO -  1644383257207	Marionette	DEBUG	19 <- [1,24,null,{"value":null}]
[task 2022-02-09T05:07:37.209Z] 05:07:37     INFO -  1644383257209	Marionette	DEBUG	19 -> [0,25,"Marionette:GetContext",{}]
[task 2022-02-09T05:07:37.210Z] 05:07:37     INFO -  1644383257210	Marionette	DEBUG	19 <- [1,25,null,{"value":"content"}]
[task 2022-02-09T05:07:37.248Z] 05:07:37     INFO -  1644383257247	Marionette	DEBUG	19 -> [0,26,"Marionette:SetContext",{"value":"content"}]
[task 2022-02-09T05:07:37.249Z] 05:07:37     INFO -  1644383257247	Marionette	DEBUG	19 <- [1,26,null,{"value":null}]
[task 2022-02-09T05:07:37.251Z] 05:07:37     INFO -  1644383257251	Marionette	DEBUG	19 -> [0,27,"WebDriver:GetWindowHandles",{}]
[task 2022-02-09T05:07:37.252Z] 05:07:37     INFO -  1644383257252	Marionette	DEBUG	19 <- [1,27,null,["d1cfb9b3-2465-43b0-9f20-ee9455ceb03c"]]
[task 2022-02-09T05:07:37.256Z] 05:07:37     INFO -  1644383257255	Marionette	DEBUG	19 -> [0,28,"Marionette:SetContext",{"value":"content"}]
[task 2022-02-09T05:07:37.256Z] 05:07:37     INFO -  1644383257256	Marionette	DEBUG	19 <- [1,28,null,{"value":null}]
[task 2022-02-09T05:07:37.259Z] 05:07:37     INFO -  1644383257259	Marionette	DEBUG	19 -> [0,29,"WebDriver:Navigate",{"url":"data:text/html;charset=utf-8,%3Cp%3Efoo"}]
[task 2022-02-09T05:07:37.267Z] 05:07:37     INFO -  1644383257267	Marionette	TRACE	[18] Received event beforeunload for http://127.0.0.1:35807/test_iframe.html
[task 2022-02-09T05:07:37.382Z] 05:07:37     INFO -  1644383257381	Marionette	TRACE	[18] Received event pagehide for http://127.0.0.1:35807/test_iframe.html
[task 2022-02-09T05:07:37.422Z] 05:07:37     INFO -  DEBUG: Adding blocker Transaction (3) for phase content-prefs.sqlite#0: waiting for clients
[task 2022-02-09T05:07:37.441Z] 05:07:37     INFO -  1644383257441	Marionette	TRACE	[18] Received event DOMContentLoaded for data:text/html;charset=utf-8,%3Cp%3Efoo
[task 2022-02-09T05:07:37.449Z] 05:07:37     INFO -  1644383257448	Marionette	TRACE	[18] Received event pageshow for data:text/html;charset=utf-8,%3Cp%3Efoo
[task 2022-02-09T05:07:37.452Z] 05:07:37     INFO -  1644383257452	Marionette	DEBUG	19 <- [1,29,null,{"value":null}]
[task 2022-02-09T05:07:37.477Z] 05:07:37     INFO -  DEBUG: Completed blocker Transaction (3) for phase content-prefs.sqlite#0: waiting for clients
[task 2022-02-09T05:07:37.498Z] 05:07:37     INFO -  1644383257497	Marionette	DEBUG	19 -> [0,30,"Marionette:GetContext",{}]
[task 2022-02-09T05:07:37.500Z] 05:07:37     INFO -  1644383257500	Marionette	DEBUG	19 <- [1,30,null,{"value":"content"}]
[task 2022-02-09T05:07:37.508Z] 05:07:37     INFO -  1644383257507	Marionette	DEBUG	19 -> [0,31,"Marionette:SetContext",{"value":"content"}]
[task 2022-02-09T05:07:37.509Z] 05:07:37     INFO -  1644383257509	Marionette	DEBUG	19 <- [1,31,null,{"value":null}]
[task 2022-02-09T05:07:37.511Z] 05:07:37     INFO -  1644383257511	Marionette	DEBUG	19 -> [0,32,"WebDriver:GetWindowHandles",{}]
[task 2022-02-09T05:07:37.513Z] 05:07:37     INFO -  1644383257512	Marionette	DEBUG	19 <- [1,32,null,["d1cfb9b3-2465-43b0-9f20-ee9455ceb03c"]]
[task 2022-02-09T05:07:37.551Z] 05:07:37     INFO -  1644383257550	Marionette	DEBUG	19 -> [0,33,"Marionette:SetContext",{"value":"content"}]
[task 2022-02-09T05:07:37.552Z] 05:07:37     INFO -  1644383257550	Marionette	DEBUG	19 <- [1,33,null,{"value":null}]
[task 2022-02-09T05:07:37.569Z] 05:07:37     INFO -  1644383257569	Marionette	DEBUG	19 -> [0,34,"WebDriver:NewWindow",{"type":"tab","focus":false,"private":false}]
[task 2022-02-09T05:07:37.587Z] 05:07:37     INFO -  1644383257586	Marionette	TRACE	Received DOM event TabOpen for [object XULElement]
[task 2022-02-09T05:07:37.698Z] 05:07:37     INFO -  1644383257697	RemoteAgent	TRACE	[60] ProgressListener state=start: about:blank
[task 2022-02-09T05:07:37.800Z] 05:07:37     INFO -  1644383257799	RemoteAgent	TRACE	[60] ProgressListener state=stop: about:blank
[task 2022-02-09T05:07:37.804Z] 05:07:37     INFO -  1644383257803	Marionette	DEBUG	19 <- [1,34,null,{"handle":"1f07a81a-b7f8-4513-ae85-8653e49155e9","type":"tab"}]
[task 2022-02-09T05:07:37.815Z] 05:07:37     INFO -  1644383257814	Marionette	DEBUG	19 -> [0,35,"Marionette:GetContext",{}]
[task 2022-02-09T05:07:37.816Z] 05:07:37     INFO -  1644383257815	Marionette	DEBUG	19 <- [1,35,null,{"value":"content"}]
[task 2022-02-09T05:07:37.818Z] 05:07:37     INFO -  1644383257818	Marionette	DEBUG	19 -> [0,36,"Marionette:SetContext",{"value":"content"}]
[task 2022-02-09T05:07:37.819Z] 05:07:37     INFO -  1644383257819	Marionette	DEBUG	19 <- [1,36,null,{"value":null}]
[task 2022-02-09T05:07:37.828Z] 05:07:37     INFO -  1644383257826	Marionette	DEBUG	19 -> [0,37,"WebDriver:GetWindowHandles",{}]
[task 2022-02-09T05:07:37.828Z] 05:07:37     INFO -  1644383257827	Marionette	DEBUG	19 <- [1,37,null,["d1cfb9b3-2465-43b0-9f20-ee9455ceb03c","1f07a81a-b7f8-4513-ae85-8653e49155e9"]]
[task 2022-02-09T05:07:37.830Z] 05:07:37     INFO -  1644383257829	Marionette	DEBUG	19 -> [0,38,"Marionette:SetContext",{"value":"content"}]
[task 2022-02-09T05:07:37.831Z] 05:07:37     INFO -  1644383257830	Marionette	DEBUG	19 <- [1,38,null,{"value":null}]
[task 2022-02-09T05:07:37.833Z] 05:07:37     INFO -  1644383257832	Marionette	DEBUG	19 -> [0,39,"Marionette:GetContext",{}]
[task 2022-02-09T05:07:37.834Z] 05:07:37     INFO -  1644383257833	Marionette	DEBUG	19 <- [1,39,null,{"value":"content"}]
[task 2022-02-09T05:07:37.837Z] 05:07:37     INFO -  1644383257837	Marionette	DEBUG	19 -> [0,40,"Marionette:SetContext",{"value":"content"}]
[task 2022-02-09T05:07:37.839Z] 05:07:37     INFO -  1644383257838	Marionette	DEBUG	19 <- [1,40,null,{"value":null}]
[task 2022-02-09T05:07:37.844Z] 05:07:37     INFO -  1644383257844	Marionette	DEBUG	19 -> [0,41,"WebDriver:GetWindowHandles",{}]
[task 2022-02-09T05:07:37.845Z] 05:07:37     INFO -  1644383257845	Marionette	DEBUG	19 <- [1,41,null,["d1cfb9b3-2465-43b0-9f20-ee9455ceb03c","1f07a81a-b7f8-4513-ae85-8653e49155e9"]]
[task 2022-02-09T05:07:37.847Z] 05:07:37     INFO -  1644383257847	Marionette	DEBUG	19 -> [0,42,"Marionette:SetContext",{"value":"content"}]
[task 2022-02-09T05:07:37.849Z] 05:07:37     INFO -  1644383257848	Marionette	DEBUG	19 <- [1,42,null,{"value":null}]
[task 2022-02-09T05:07:37.850Z] 05:07:37     INFO -  1644383257850	Marionette	DEBUG	19 -> [0,43,"Marionette:GetContext",{}]
[task 2022-02-09T05:07:37.851Z] 05:07:37     INFO -  1644383257851	Marionette	DEBUG	19 <- [1,43,null,{"value":"content"}]
[task 2022-02-09T05:07:37.854Z] 05:07:37     INFO -  1644383257852	Marionette	DEBUG	19 -> [0,44,"Marionette:SetContext",{"value":"content"}]
[task 2022-02-09T05:07:37.855Z] 05:07:37     INFO -  1644383257853	Marionette	DEBUG	19 <- [1,44,null,{"value":null}]
[task 2022-02-09T05:07:37.858Z] 05:07:37     INFO -  1644383257855	Marionette	DEBUG	19 -> [0,45,"WebDriver:GetWindowHandle",{}]
[task 2022-02-09T05:07:37.860Z] 05:07:37     INFO -  1644383257856	Marionette	DEBUG	19 <- [1,45,null,{"value":"d1cfb9b3-2465-43b0-9f20-ee9455ceb03c"}]
[task 2022-02-09T05:07:37.862Z] 05:07:37     INFO -  1644383257858	Marionette	DEBUG	19 -> [0,46,"Marionette:SetContext",{"value":"content"}]
[task 2022-02-09T05:07:37.864Z] 05:07:37     INFO -  1644383257858	Marionette	DEBUG	19 <- [1,46,null,{"value":null}]
[task 2022-02-09T05:07:37.866Z] 05:07:37     INFO -  1644383257860	Marionette	DEBUG	19 -> [0,47,"Marionette:GetContext",{}]
[task 2022-02-09T05:07:37.869Z] 05:07:37     INFO -  1644383257861	Marionette	DEBUG	19 <- [1,47,null,{"value":"content"}]
[task 2022-02-09T05:07:37.872Z] 05:07:37     INFO -  1644383257862	Marionette	DEBUG	19 -> [0,48,"Marionette:SetContext",{"value":"chrome"}]
[task 2022-02-09T05:07:37.873Z] 05:07:37     INFO -  1644383257863	Marionette	DEBUG	19 <- [1,48,null,{"value":null}]
[task 2022-02-09T05:07:37.874Z] 05:07:37     INFO -  1644383257866	Marionette	DEBUG	19 -> [0,49,"WebDriver:ExecuteScript",{"script":"Components.utils.import(\"resource://gre/modules/AppConstants.jsm\");\n\n          ... efault","line":76,"filename":"tests/testing/marionette/harness/marionette_harness/tests/unit/test_switch_window_content.py"}]
[task 2022-02-09T05:07:37.876Z] 05:07:37     INFO -  1644383257876	Marionette	DEBUG	19 <- [1,49,null,{"value":0}]
[task 2022-02-09T05:07:37.879Z] 05:07:37     INFO -  1644383257878	Marionette	DEBUG	19 -> [0,50,"Marionette:SetContext",{"value":"content"}]
[task 2022-02-09T05:07:37.880Z] 05:07:37     INFO -  1644383257879	Marionette	DEBUG	19 <- [1,50,null,{"value":null}]
[task 2022-02-09T05:07:37.882Z] 05:07:37     INFO -  1644383257881	Marionette	DEBUG	19 -> [0,51,"WebDriver:SwitchToWindow",{"handle":"1f07a81a-b7f8-4513-ae85-8653e49155e9","focus":true}]
[task 2022-02-09T05:07:37.896Z] 05:07:37     INFO -  1644383257896	Marionette	TRACE	Received DOM event TabSelect for [object XULElement]
[task 2022-02-09T05:07:37.929Z] 05:07:37     INFO -  1644383257929	Marionette	DEBUG	19 <- [1,51,null,{"value":null}]
[task 2022-02-09T05:07:37.934Z] 05:07:37     INFO -  1644383257934	Marionette	DEBUG	19 -> [0,52,"Marionette:GetContext",{}]
[task 2022-02-09T05:07:37.935Z] 05:07:37     INFO -  1644383257934	Marionette	DEBUG	19 <- [1,52,null,{"value":"content"}]
[task 2022-02-09T05:07:37.938Z] 05:07:37     INFO -  1644383257938	Marionette	DEBUG	19 -> [0,53,"Marionette:SetContext",{"value":"content"}]
[task 2022-02-09T05:07:37.939Z] 05:07:37     INFO -  1644383257939	Marionette	DEBUG	19 <- [1,53,null,{"value":null}]
[task 2022-02-09T05:07:37.941Z] 05:07:37     INFO -  1644383257941	Marionette	DEBUG	19 -> [0,54,"WebDriver:GetWindowHandle",{}]
[task 2022-02-09T05:07:37.943Z] 05:07:37     INFO -  1644383257942	Marionette	DEBUG	19 <- [1,54,null,{"value":"1f07a81a-b7f8-4513-ae85-8653e49155e9"}]
[task 2022-02-09T05:07:37.945Z] 05:07:37     INFO -  1644383257944	Marionette	DEBUG	19 -> [0,55,"Marionette:SetContext",{"value":"content"}]
[task 2022-02-09T05:07:37.946Z] 05:07:37     INFO -  1644383257945	Marionette	DEBUG	19 <- [1,55,null,{"value":null}]
[task 2022-02-09T05:07:37.948Z] 05:07:37     INFO -  1644383257947	Marionette	DEBUG	19 -> [0,56,"Marionette:GetContext",{}]
[task 2022-02-09T05:07:37.949Z] 05:07:37     INFO -  1644383257948	Marionette	DEBUG	19 <- [1,56,null,{"value":"content"}]
[task 2022-02-09T05:07:37.951Z] 05:07:37     INFO -  1644383257950	Marionette	DEBUG	19 -> [0,57,"Marionette:SetContext",{"value":"chrome"}]
[task 2022-02-09T05:07:37.951Z] 05:07:37     INFO -  1644383257951	Marionette	DEBUG	19 <- [1,57,null,{"value":null}]
[task 2022-02-09T05:07:37.955Z] 05:07:37     INFO -  1644383257954	Marionette	DEBUG	19 -> [0,58,"WebDriver:ExecuteScript",{"script":"Components.utils.import(\"resource://gre/modules/AppConstants.jsm\");\n\n          ... efault","line":76,"filename":"tests/testing/marionette/harness/marionette_harness/tests/unit/test_switch_window_content.py"}]
[task 2022-02-09T05:07:37.962Z] 05:07:37     INFO -  1644383257961	Marionette	DEBUG	19 <- [1,58,null,{"value":1}]
[task 2022-02-09T05:07:37.964Z] 05:07:37     INFO -  1644383257964	Marionette	DEBUG	19 -> [0,59,"Marionette:SetContext",{"value":"content"}]
[task 2022-02-09T05:07:37.965Z] 05:07:37     INFO -  1644383257965	Marionette	DEBUG	19 <- [1,59,null,{"value":null}]
[task 2022-02-09T05:07:37.968Z] 05:07:37     INFO -  1644383257968	Marionette	DEBUG	19 -> [0,60,"WebDriver:Navigate",{"url":"data:text/html;charset=utf-8,%3Cp%3Ebar"}]
[task 2022-02-09T05:07:37.977Z] 05:07:37     INFO -  1644383257976	Marionette	TRACE	[60] Received event beforeunload for about:blank
[task 2022-02-09T05:07:38.014Z] 05:07:38     INFO -  1644383258013	Marionette	TRACE	Remoteness change detected. Set new top-level browsing context to 60
[task 2022-02-09T05:07:38.062Z] 05:07:38     INFO -  1644383258061	Marionette	TRACE	[60] Received event pagehide for about:blank
[task 2022-02-09T05:07:38.109Z] 05:07:38     INFO -  1644383258108	Marionette	TRACE	[60] Received event beforeunload for about:blank
[task 2022-02-09T05:07:38.130Z] 05:07:38     INFO -  1644383258130	Marionette	TRACE	[60] Received event pagehide for about:blank
[task 2022-02-09T05:07:38.162Z] 05:07:38     INFO -  DEBUG: Adding blocker Transaction (4) for phase content-prefs.sqlite#0: waiting for clients
[task 2022-02-09T05:07:38.260Z] 05:07:38     INFO -  1644383258259	Marionette	TRACE	[60] Received event DOMContentLoaded for data:text/html;charset=utf-8,%3Cp%3Ebar
[task 2022-02-09T05:07:38.266Z] 05:07:38     INFO -  DEBUG: Completed blocker Transaction (4) for phase content-prefs.sqlite#0: waiting for clients
[task 2022-02-09T05:07:38.268Z] 05:07:38     INFO -  1644383258267	Marionette	TRACE	[60] Received event pageshow for data:text/html;charset=utf-8,%3Cp%3Ebar
[task 2022-02-09T05:07:38.279Z] 05:07:38     INFO -  1644383258279	Marionette	DEBUG	19 <- [1,60,null,{"value":null}]
[task 2022-02-09T05:07:38.289Z] 05:07:38     INFO -  1644383258288	Marionette	DEBUG	19 -> [0,61,"Marionette:GetContext",{}]
[task 2022-02-09T05:07:38.294Z] 05:07:38     INFO -  1644383258289	Marionette	DEBUG	19 <- [1,61,null,{"value":"content"}]
[task 2022-02-09T05:07:38.299Z] 05:07:38     INFO -  1644383258290	Marionette	DEBUG	19 -> [0,62,"Marionette:AcceptConnections",{"value":false}]
[task 2022-02-09T05:07:38.303Z] 05:07:38     INFO -  1644383258290	Marionette	INFO	Stopped listening on port 2828
[task 2022-02-09T05:07:38.306Z] 05:07:38     INFO -  1644383258290	Marionette	DEBUG	19 <- [1,62,null,{"value":null}]
[task 2022-02-09T05:07:38.309Z] 05:07:38     INFO -  1644383258296	Marionette	DEBUG	19 -> [0,63,"Marionette:Quit",{"flags":["eRestart"]}]
[task 2022-02-09T05:07:38.338Z] 05:07:38     INFO -  DEBUG: Adding blocker SessionStore: flushing all windows for phase quit-application-granted
[task 2022-02-09T05:07:38.352Z] 05:07:38     INFO -  DEBUG: Adding blocker ShieldRecipeClient: Cleaning up for phase profile-before-change
[task 2022-02-09T05:07:38.357Z] 05:07:38     INFO -  DEBUG: Starting phase quit-application-granted
[task 2022-02-09T05:07:38.363Z] 05:07:38     INFO -  DEBUG: Spinning the event loop
[task 2022-02-09T05:07:38.368Z] 05:07:38     INFO -  DEBUG: Adding blocker Extension shutdown: wikipedia@search.mozilla.org for phase profile-change-teardown
[task 2022-02-09T05:07:38.369Z] 05:07:38     INFO -  DEBUG: Adding blocker Extension shutdown: webcompat@mozilla.org for phase profile-change-teardown
[task 2022-02-09T05:07:38.371Z] 05:07:38     INFO -  DEBUG: Adding blocker Extension shutdown: webcompat-reporter@mozilla.org for phase profile-change-teardown
[task 2022-02-09T05:07:38.372Z] 05:07:38     INFO -  DEBUG: Adding blocker Extension shutdown: screenshots@mozilla.org for phase profile-change-teardown
[task 2022-02-09T05:07:38.373Z] 05:07:38     INFO -  DEBUG: Adding blocker Extension shutdown: pictureinpicture@mozilla.org for phase profile-change-teardown
[task 2022-02-09T05:07:38.374Z] 05:07:38     INFO -  DEBUG: Adding blocker Extension shutdown: google@search.mozilla.org for phase profile-change-teardown
[task 2022-02-09T05:07:38.376Z] 05:07:38     INFO -  DEBUG: Adding blocker Extension shutdown: formautofill@mozilla.org for phase profile-change-teardown
[task 2022-02-09T05:07:38.377Z] 05:07:38     INFO -  DEBUG: Adding blocker Extension shutdown: doh-rollout@mozilla.org for phase profile-change-teardown
[task 2022-02-09T05:07:38.378Z] 05:07:38     INFO -  DEBUG: Adding blocker Extension shutdown: default-theme@mozilla.org for phase profile-change-teardown
[task 2022-02-09T05:07:38.380Z] 05:07:38     INFO -  DEBUG: Adding blocker Extension shutdown: ddg@search.mozilla.org for phase profile-change-teardown
[task 2022-02-09T05:07:38.382Z] 05:07:38     INFO -  DEBUG: Adding blocker Extension shutdown: bing@search.mozilla.org for phase profile-change-teardown
[task 2022-02-09T05:07:38.383Z] 05:07:38     INFO -  DEBUG: Adding blocker Extension shutdown: amazondotcom@search.mozilla.org for phase profile-change-teardown
[task 2022-02-09T05:07:38.385Z] 05:07:38     INFO -  DEBUG: Adding blocker Extension shutdown: addons-search-detection@mozilla.com for phase profile-change-teardown
[task 2022-02-09T05:07:38.526Z] 05:07:38     INFO -  DEBUG: Completed blocker XPIProvider shutdown for phase quit-application-granted
[task 2022-02-09T05:07:38.658Z] 05:07:38     INFO -  DEBUG: Completed blocker ShieldRecipeClient: Cleaning up for phase profile-before-change
[task 2022-02-09T05:07:38.679Z] 05:07:38     INFO -  DEBUG: Completed blocker SessionStore: flushing all windows for phase quit-application-granted
[task 2022-02-09T05:07:38.682Z] 05:07:38     INFO -  DEBUG: Finished phase quit-application-granted
[task 2022-02-09T05:07:38.684Z] 05:07:38     INFO -  DEBUG: Completed blocker Extension shutdown: wikipedia@search.mozilla.org for phase profile-change-teardown
[task 2022-02-09T05:07:38.686Z] 05:07:38     INFO -  DEBUG: Completed blocker Extension shutdown: webcompat@mozilla.org for phase profile-change-teardown
[task 2022-02-09T05:07:38.687Z] 05:07:38     INFO -  DEBUG: Completed blocker Extension shutdown: webcompat-reporter@mozilla.org for phase profile-change-teardown
[task 2022-02-09T05:07:38.689Z] 05:07:38     INFO -  DEBUG: Completed blocker Extension shutdown: screenshots@mozilla.org for phase profile-change-teardown
[task 2022-02-09T05:07:38.691Z] 05:07:38     INFO -  DEBUG: Completed blocker Extension shutdown: pictureinpicture@mozilla.org for phase profile-change-teardown
[task 2022-02-09T05:07:38.692Z] 05:07:38     INFO -  DEBUG: Completed blocker Extension shutdown: google@search.mozilla.org for phase profile-change-teardown
[task 2022-02-09T05:07:38.699Z] 05:07:38     INFO -  DEBUG: Completed blocker Extension shutdown: formautofill@mozilla.org for phase profile-change-teardown
[task 2022-02-09T05:07:38.701Z] 05:07:38     INFO -  DEBUG: Completed blocker Extension shutdown: doh-rollout@mozilla.org for phase profile-change-teardown
[task 2022-02-09T05:07:38.705Z] 05:07:38     INFO -  DEBUG: Completed blocker Extension shutdown: default-theme@mozilla.org for phase profile-change-teardown
[task 2022-02-09T05:07:38.707Z] 05:07:38     INFO -  DEBUG: Completed blocker Extension shutdown: ddg@search.mozilla.org for phase profile-change-teardown
[task 2022-02-09T05:07:38.707Z] 05:07:38     INFO -  DEBUG: Completed blocker Extension shutdown: bing@search.mozilla.org for phase profile-change-teardown
[task 2022-02-09T05:07:38.709Z] 05:07:38     INFO -  DEBUG: Completed blocker Extension shutdown: amazondotcom@search.mozilla.org for phase profile-change-teardown
[task 2022-02-09T05:07:38.709Z] 05:07:38     INFO -  DEBUG: Completed blocker Extension shutdown: addons-search-detection@mozilla.com for phase profile-change-teardown
[task 2022-02-09T05:07:38.964Z] 05:07:38     INFO -  1644383258963	Marionette	TRACE	Received observer notification quit-application
[task 2022-02-09T05:07:38.966Z] 05:07:38     INFO -  1644383258964	Marionette	TRACE	Received observer notification quit-application
[task 2022-02-09T05:07:38.966Z] 05:07:38     INFO -  1644383258964	Marionette	DEBUG	Marionette stopped listening
[task 2022-02-09T05:07:38.970Z] 05:07:38     INFO -  DEBUG: Adding blocker SessionFile: Finish writing Session Restore data for phase IOUtils: waiting for profileBeforeChange IO to complete
[task 2022-02-09T05:07:38.972Z] 05:07:38     INFO -  1644383258972	Marionette	DEBUG	19 <- [1,63,null,{"cause":"restart","forced":false}]
[task 2022-02-09T05:07:38.990Z] 05:07:38     INFO -  JavaScript error: resource://gre/modules/URLQueryStrippingListService.jsm, line 90: TypeError: can't access property "removeEventListener", Services.cpmm.sharedData is null
[task 2022-02-09T05:07:38.994Z] 05:07:38     INFO -  ###!!! [Parent][PCompositorManagerParent] Error: RunMessage(msgname=PCompositorBridge::Msg___delete__) Channel closing: too late to send/recv, messages will be lost
[task 2022-02-09T05:07:38.996Z] 05:07:38     INFO -  ###!!! [Parent][PImageBridgeParent] Error: RunMessage(msgname=PImageBridge::Msg_WillClose) Channel closing: too late to send/recv, messages will be lost
[task 2022-02-09T05:07:39.159Z] 05:07:39     INFO -  DEBUG: Completed blocker SessionFile: Finish writing Session Restore data for phase IOUtils: waiting for profileBeforeChange IO to complete
[task 2022-02-09T05:07:39.172Z] 05:07:39     INFO -  DEBUG: Starting phase xpcom-will-shutdown
[task 2022-02-09T05:07:39.175Z] 05:07:39     INFO -  DEBUG: Spinning the event loop
[task 2022-02-09T05:07:39.177Z] 05:07:39     INFO -  DEBUG: Finished phase xpcom-will-shutdown
[task 2022-02-09T05:07:39.181Z] 05:07:39     INFO -  JavaScript error: resource://gre/modules/URLQueryStrippingListService.jsm, line 90: TypeError: can't access property "removeEventListener", Services.cpmm.sharedData is null
[task 2022-02-09T05:07:39.268Z] 05:07:39     INFO -  FATAL ERROR: Non-local network connections are disabled and a connection attempt to aus5.mozilla.org (35.244.181.201) was made.
[task 2022-02-09T05:07:39.270Z] 05:07:39     INFO -  You should only access hostnames available via the test networking proxy (if running mochitests) or from a test-specific httpd.js server (if running xpcshell tests). Browser services should be disabled or redirected to a local server.
[task 2022-02-09T05:07:39.271Z] 05:07:39     INFO -  AddressSanitizer:DEADLYSIGNAL
[task 2022-02-09T05:07:39.272Z] 05:07:39     INFO -  =================================================================
[task 2022-02-09T05:07:39.273Z] 05:07:39    ERROR -  ==5161==ERROR: AddressSanitizer: SEGV on unknown address 0x000000000001 (pc 0x7f81eae775aa bp 0x7f81e0646cf0 sp 0x7f81e0646500 T4)
[task 2022-02-09T05:07:39.274Z] 05:07:39     INFO -  ==5161==The signal is caused by a WRITE memory access.
[task 2022-02-09T05:07:39.274Z] 05:07:39     INFO -  ==5161==Hint: address points to the zero page.
[task 2022-02-09T05:07:39.322Z] 05:07:39     INFO -  DEBUG: Adding blocker ContentParent: id=619000732380 for phase xpcom-will-shutdown
[task 2022-02-09T05:07:39.326Z] 05:07:39     INFO -  DEBUG: Adding blocker ContentParent: id=619000732380 for phase profile-before-change
[task 2022-02-09T05:07:39.619Z] 05:07:39     INFO -  llvm-symbolizer: Unknown command line argument '--inlines'.  Try: '/usr/bin/llvm-symbolizer -help'
[task 2022-02-09T05:07:39.619Z] 05:07:39     INFO -  llvm-symbolizer: Did you mean '-inlining'?
[task 2022-02-09T05:07:39.623Z] 05:07:39     INFO -  ==5161==WARNING: Can't read from symbolizer at fd 41
[task 2022-02-09T05:07:39.723Z] 05:07:39     INFO -  llvm-symbolizer: Unknown command line argument '--inlines'.  Try: '/usr/bin/llvm-symbolizer -help'
[task 2022-02-09T05:07:39.723Z] 05:07:39     INFO -  llvm-symbolizer: Did you mean '-inlining'?
[task 2022-02-09T05:07:39.725Z] 05:07:39     INFO -  ==5161==WARNING: Can't read from symbolizer at fd 41
[task 2022-02-09T05:07:39.784Z] 05:07:39     INFO -  llvm-symbolizer: Unknown command line argument '--inlines'.  Try: '/usr/bin/llvm-symbolizer -help'
[task 2022-02-09T05:07:39.785Z] 05:07:39     INFO -  llvm-symbolizer: Did you mean '-inlining'?
[task 2022-02-09T05:07:39.786Z] 05:07:39     INFO -  ==5161==WARNING: Can't read from symbolizer at fd 41
[task 2022-02-09T05:07:39.846Z] 05:07:39     INFO -  llvm-symbolizer: Unknown command line argument '--inlines'.  Try: '/usr/bin/llvm-symbolizer -help'
[task 2022-02-09T05:07:39.847Z] 05:07:39     INFO -  llvm-symbolizer: Did you mean '-inlining'?
[task 2022-02-09T05:07:39.849Z] 05:07:39     INFO -  ==5161==WARNING: Can't read from symbolizer at fd 41
[task 2022-02-09T05:07:39.876Z] 05:07:39     INFO -  ==5161==WARNING: Failed to use and restart external symbolizer!
[task 2022-02-09T05:07:39.878Z] 05:07:39     INFO -      #0 0x7f81eae775aa  (/builds/worker/workspace/build/application/firefox/libxul.so+0x44c15aa)
[task 2022-02-09T05:07:39.880Z] 05:07:39     INFO -      #1 0x7f81eae7c5d1  (/builds/worker/workspace/build/application/firefox/libxul.so+0x44c65d1)
[task 2022-02-09T05:07:39.880Z] 05:07:39     INFO -      #2 0x7f81eaec7cda  (/builds/worker/workspace/build/application/firefox/libxul.so+0x4511cda)
[task 2022-02-09T05:07:39.885Z] 05:07:39     INFO -      #3 0x7f81eaacfd3b  (/builds/worker/workspace/build/application/firefox/libxul.so+0x4119d3b)
[task 2022-02-09T05:07:39.886Z] 05:07:39     INFO -      #4 0x7f81eaadaa2c  (/builds/worker/workspace/build/application/firefox/libxul.so+0x4124a2c)
[task 2022-02-09T05:07:39.886Z] 05:07:39     INFO -      #5 0x7f81eae8d391  (/builds/worker/workspace/build/application/firefox/libxul.so+0x44d7391)
[task 2022-02-09T05:07:39.886Z] 05:07:39     INFO -      #6 0x7f81eae8efec  (/builds/worker/workspace/build/application/firefox/libxul.so+0x44d8fec)
[task 2022-02-09T05:07:39.886Z] 05:07:39     INFO -      #7 0x7f81eaacfd3b  (/builds/worker/workspace/build/application/firefox/libxul.so+0x4119d3b)
[task 2022-02-09T05:07:39.887Z] 05:07:39     INFO -      #8 0x7f81eaadaa2c  (/builds/worker/workspace/build/application/firefox/libxul.so+0x4124a2c)
[task 2022-02-09T05:07:39.887Z] 05:07:39     INFO -      #9 0x7f81ebc7f958  (/builds/worker/workspace/build/application/firefox/libxul.so+0x52c9958)
[task 2022-02-09T05:07:39.887Z] 05:07:39     INFO -      #10 0x7f81ebb900c1  (/builds/worker/workspace/build/application/firefox/libxul.so+0x51da0c1)
[task 2022-02-09T05:07:39.887Z] 05:07:39     INFO -      #11 0x7f81eaac7d14  (/builds/worker/workspace/build/application/firefox/libxul.so+0x4111d14)
[task 2022-02-09T05:07:39.887Z] 05:07:39     INFO -      #12 0x7f820e2c2ade  (/builds/worker/workspace/build/application/firefox/libnspr4.so+0x7eade)
[task 2022-02-09T05:07:39.888Z] 05:07:39     INFO -      #13 0x7f820df016da  (/lib/x86_64-linux-gnu/libpthread.so.0+0x76da)
[task 2022-02-09T05:07:39.888Z] 05:07:39     INFO -      #14 0x7f820cedfa3e  (/lib/x86_64-linux-gnu/libc.so.6+0x121a3e)
[task 2022-02-09T05:07:39.888Z] 05:07:39     INFO -  AddressSanitizer can not provide additional info.
[task 2022-02-09T05:07:39.888Z] 05:07:39     INFO -  SUMMARY: AddressSanitizer: SEGV (/builds/worker/workspace/build/application/firefox/libxul.so+0x44c15aa)
[task 2022-02-09T05:07:39.889Z] 05:07:39     INFO -  Thread T4 (Socket Thread) created by T0 here:
[task 2022-02-09T05:07:39.889Z] 05:07:39     INFO -      #0 0x555e7409a46c  (/builds/worker/workspace/build/application/firefox/firefox+0xbe46c)
[task 2022-02-09T05:07:39.889Z] 05:07:39     INFO -      #1 0x7f820e2b2b74  (/builds/worker/workspace/build/application/firefox/libnspr4.so+0x6eb74)
[task 2022-02-09T05:07:39.889Z] 05:07:39     INFO -      #2 0x7f820e2a3e1e  (/builds/worker/workspace/build/application/firefox/libnspr4.so+0x5fe1e)
[task 2022-02-09T05:07:39.890Z] 05:07:39     INFO -      #3 0x7f81eaacb035  (/builds/worker/workspace/build/application/firefox/libxul.so+0x4115035)
[task 2022-02-09T05:07:39.890Z] 05:07:39     INFO -      #4 0x7f81eaad880f  (/builds/worker/workspace/build/application/firefox/libxul.so+0x412280f)
[task 2022-02-09T05:07:39.890Z] 05:07:39     INFO -      #5 0x7f81eaae41b1  (/builds/worker/workspace/build/application/firefox/libxul.so+0x412e1b1)
[task 2022-02-09T05:07:39.890Z] 05:07:39     INFO -      #6 0x7f81eae8ade1  (/builds/worker/workspace/build/application/firefox/libxul.so+0x44d4de1)
[task 2022-02-09T05:07:39.890Z] 05:07:39     INFO -      #7 0x7f81eaa43704  (/builds/worker/workspace/build/application/firefox/libxul.so+0x408d704)
[task 2022-02-09T05:07:39.891Z] 05:07:39     INFO -      #8 0x7f81eaa7d677  (/builds/worker/workspace/build/application/firefox/libxul.so+0x40c7677)
[task 2022-02-09T05:07:39.891Z] 05:07:39     INFO -      #9 0x7f81eaa7f4f4  (/builds/worker/workspace/build/application/firefox/libxul.so+0x40c94f4)
[task 2022-02-09T05:07:39.891Z] 05:07:39     INFO -      #10 0x7f81eaa84742  (/builds/worker/workspace/build/application/firefox/libxul.so+0x40ce742)
[task 2022-02-09T05:07:39.891Z] 05:07:39     INFO -      #11 0x7f81ea8f3e5d  (/builds/worker/workspace/build/application/firefox/libxul.so+0x3f3de5d)
[task 2022-02-09T05:07:39.891Z] 05:07:39     INFO -      #12 0x7f81eaddfe0b  (/builds/worker/workspace/build/application/firefox/libxul.so+0x4429e0b)
[task 2022-02-09T05:07:39.891Z] 05:07:39     INFO -      #13 0x7f81eade9eb0  (/builds/worker/workspace/build/application/firefox/libxul.so+0x4433eb0)
[task 2022-02-09T05:07:39.891Z] 05:07:39     INFO -      #14 0x7f81eaddd8ac  (/builds/worker/workspace/build/application/firefox/libxul.so+0x44278ac)
[task 2022-02-09T05:07:39.891Z] 05:07:39     INFO -      #15 0x7f81eade0a9b  (/builds/worker/workspace/build/application/firefox/libxul.so+0x442aa9b)
[task 2022-02-09T05:07:39.892Z] 05:07:39     INFO -      #16 0x7f81eaa416da  (/builds/worker/workspace/build/application/firefox/libxul.so+0x408b6da)
[task 2022-02-09T05:07:39.892Z] 05:07:39     INFO -      #17 0x7f81eaa7d677  (/builds/worker/workspace/build/application/firefox/libxul.so+0x40c7677)
[task 2022-02-09T05:07:39.892Z] 05:07:39     INFO -      #18 0x7f81eaa7f4f4  (/builds/worker/workspace/build/application/firefox/libxul.so+0x40c94f4)
[task 2022-02-09T05:07:39.892Z] 05:07:39     INFO -      #19 0x7f81ec9851b3  (/builds/worker/workspace/build/application/firefox/libxul.so+0x5fcf1b3)
[task 2022-02-09T05:07:39.893Z] 05:07:39     INFO -      #20 0x7f81ec985629  (/builds/worker/workspace/build/application/firefox/libxul.so+0x5fcf629)
[task 2022-02-09T05:07:39.893Z] 05:07:39     INFO -      #21 0x7f81ec72cec0  (/builds/worker/workspace/build/application/firefox/libxul.so+0x5d76ec0)
[task 2022-02-09T05:07:39.894Z] 05:07:39     INFO -      #22 0x7f81ec6bf538  (/builds/worker/workspace/build/application/firefox/libxul.so+0x5d09538)
[task 2022-02-09T05:07:39.894Z] 05:07:39     INFO -      #23 0x7f81f2b7b02c  (/builds/worker/workspace/build/application/firefox/libxul.so+0xc1c502c)
[task 2022-02-09T05:07:39.895Z] 05:07:39     INFO -      #24 0x7f81eaa754e6  (/builds/worker/workspace/build/application/firefox/libxul.so+0x40bf4e6)
[task 2022-02-09T05:07:39.895Z] 05:07:39     INFO -      #25 0x7f81eab3f4b3  (/builds/worker/workspace/build/application/firefox/libxul.so+0x41894b3)
[task 2022-02-09T05:07:39.896Z] 05:07:39     INFO -      #26 0x7f81f610b3d6  (/builds/worker/workspace/build/application/firefox/libxul.so+0xf7553d6)
[task 2022-02-09T05:07:39.897Z] 05:07:39     INFO -      #27 0x7f81f612187e  (/builds/worker/workspace/build/application/firefox/libxul.so+0xf76b87e)
[task 2022-02-09T05:07:39.897Z] 05:07:39     INFO -      #28 0x7f81f61225d3  (/builds/worker/workspace/build/application/firefox/libxul.so+0xf76c5d3)
[task 2022-02-09T05:07:39.898Z] 05:07:39     INFO -      #29 0x555e740e5034  (/builds/worker/workspace/build/application/firefox/firefox+0x109034)
[task 2022-02-09T05:07:39.898Z] 05:07:39     INFO -      #30 0x7f820cddfb96  (/lib/x86_64-linux-gnu/libc.so.6+0x21b96)
[task 2022-02-09T05:07:39.898Z] 05:07:39     INFO -  ==5161==ABORTING
[task 2022-02-09T05:07:39.920Z] 05:07:39     INFO -  llvm-symbolizer: Unknown command line argument '--inlines'.  Try: '/usr/bin/llvm-symbolizer -help'
[task 2022-02-09T05:07:39.920Z] 05:07:39     INFO -  llvm-symbolizer: Did you mean '-inlining'?
[task 2022-02-09T05:07:39.967Z] 05:07:39     INFO -  Exiting due to channel error.
[task 2022-02-09T05:07:39.969Z] 05:07:39     INFO -  Exiting due to channel error.
[task 2022-02-09T05:07:39.971Z] 05:07:39     INFO -  Crash Annotation GraphicsCriticalError: |[C0][GFX1-]: Receive IPC close with reason=AbnormalShutdown (t=0.59042) Exiting due to channel error.
[task 2022-02-09T05:14:49.213Z] 05:14:49     INFO - TEST-UNEXPECTED-ERROR | testing/marionette/harness/marionette_harness/tests/unit/test_switch_window_chrome.py TestSwitchToWindowContent.test_switch_to_unloaded_tab | OSError: Process has been unexpectedly closed (Exit code: 1) (Reason: Process unexpectedly quit without restarting (exit code: 1))
[task 2022-02-09T05:14:49.213Z] 05:14:49     INFO - Traceback (most recent call last):
[task 2022-02-09T05:14:49.213Z] 05:14:49     INFO -   File "/builds/worker/workspace/build/venv/lib/python3.6/site-packages/marionette_harness/marionette_test/testcases.py", line 202, in run
[task 2022-02-09T05:14:49.214Z] 05:14:49     INFO -     testMethod()
[task 2022-02-09T05:14:49.214Z] 05:14:49     INFO -   File "/builds/worker/workspace/build/tests/marionette/tests/testing/marionette/harness/marionette_harness/tests/unit/test_switch_window_content.py", line 179, in test_switch_to_unloaded_tab
[task 2022-02-09T05:14:49.214Z] 05:14:49     INFO -     self.marionette.restart(in_app=True)
[task 2022-02-09T05:14:49.215Z] 05:14:49     INFO -   File "/builds/worker/workspace/build/venv/lib/python3.6/site-packages/marionette_driver/decorators.py", line 37, in _
[task 2022-02-09T05:14:49.215Z] 05:14:49     INFO -     m._handle_socket_failure()
[task 2022-02-09T05:14:49.215Z] 05:14:49     INFO -   File "/builds/worker/workspace/build/venv/lib/python3.6/site-packages/marionette_driver/marionette.py", line 758, in _handle_socket_failure
[task 2022-02-09T05:14:49.216Z] 05:14:49     INFO -     IOError, IOError(message.format(returncode=returncode, reason=exc)), tb
[task 2022-02-09T05:14:49.216Z] 05:14:49     INFO -   File "/builds/worker/workspace/build/venv/lib/python3.6/site-packages/six.py", line 702, in reraise
[task 2022-02-09T05:14:49.216Z] 05:14:49     INFO -     raise value.with_traceback(tb)
[task 2022-02-09T05:14:49.217Z] 05:14:49     INFO -   File "/builds/worker/workspace/build/venv/lib/python3.6/site-packages/marionette_driver/decorators.py", line 27, in _
[task 2022-02-09T05:14:49.217Z] 05:14:49     INFO -     return func(*args, **kwargs)
[task 2022-02-09T05:14:49.217Z] 05:14:49     INFO -   File "/builds/worker/workspace/build/venv/lib/python3.6/site-packages/marionette_driver/marionette.py", line 1150, in restart
[task 2022-02-09T05:14:49.218Z] 05:14:49     INFO -     tb,
[task 2022-02-09T05:14:49.218Z] 05:14:49     INFO -   File "/builds/worker/workspace/build/venv/lib/python3.6/site-packages/six.py", line 702, in reraise
[task 2022-02-09T05:14:49.218Z] 05:14:49     INFO -     raise value.with_traceback(tb)
[task 2022-02-09T05:14:49.219Z] 05:14:49     INFO -   File "/builds/worker/workspace/build/venv/lib/python3.6/site-packages/marionette_driver/marionette.py", line 1130, in restart
[task 2022-02-09T05:14:49.219Z] 05:14:49     INFO -     self.raise_for_port(timeout=timeout_restart, check_process_status=False)
[task 2022-02-09T05:14:49.219Z] 05:14:49     INFO -   File "/builds/worker/workspace/build/venv/lib/python3.6/site-packages/marionette_driver/marionette.py", line 638, in raise_for_port
[task 2022-02-09T05:14:49.220Z] 05:14:49     INFO -     self.host, self.port
[task 2022-02-09T05:14:49.220Z] 05:14:49     INFO - TEST-INFO took 432062ms
[task 2022-02-09T05:14:49.221Z] 05:14:49    ERROR - test_end for testing/marionette/harness/marionette_harness/tests/unit/test_switch_window_chrome.py TestSwitchToWindowContent.test_switch_to_unloaded_tab logged while not in progress. Logged with data: {"message": "marionette_driver.errors.InvalidSessionIdException: Please start a session", "expected": "PASS", "stack": "Traceback (most recent call last):\n  File \"/builds/worker/workspace/build/venv/lib/python3.6/site-packages/marionette_harness/marionette_test/testcases.py\", line 235, in run\n    self.tearDown()\n  File \"/builds/worker/workspace/build/tests/marionette/tests/testing/marionette/harness/marionette_harness/tests/unit/test_switch_window_content.py\", line 37, in tearDown\n    self.close_all_tabs()\n  File \"/builds/worker/workspace/build/venv/lib/python3.6/site-packages/marionette_harness/runner/mixins/window_manager.py\", line 33, in close_all_tabs\n    current_window_handles = self.marionette.window_handles\n  File \"/builds/worker/workspace/build/venv/lib/python3.6/site-packages/marionette_driver/marionette.py\", line 1373, in window_handles\n    with self.using_context(\"content\"):\n  File \"/usr/lib/python3.6/contextlib.py\", line 81, in __enter__\n    return next(self.gen)\n  File \"/builds/worker/workspace/build/venv/lib/python3.6/site-packages/marionette_driver/marionette.py\", line 1454, in using_context\n    scope = self._send_message(\"Marionette:GetContext\", key=\"value\")\n  File \"/builds/worker/workspace/build/venv/lib/python3.6/site-packages/marionette_driver/decorators.py\", line 27, in _\n    return func(*args, **kwargs)\n  File \"/builds/worker/workspace/build/venv/lib/python3.6/site-packages/marionette_driver/marionette.py\", line 658, in _send_message\n    raise errors.InvalidSessionIdException(\"Please start a session\")\n", "extra": {"class_name": "test_switch_window_content.TestSwitchToWindowContent", "method_name": "test_switch_to_unloaded_tab"}, "test": "testing/marionette/harness/marionette_harness/tests/unit/test_switch_window_chrome.py TestSwitchToWindowContent.test_switch_to_unloaded_tab", "status": "ERROR"}
[task 2022-02-09T05:14:49.221Z] 05:14:49     INFO - TEST-START | testing/marionette/harness/marionette_harness/tests/unit/test_switch_window_chrome.py TestSwitchToWindowContent.test_switch_to_window_after_remoteness_change
Summary: Intermittent testing/marionette/harness/marionette_harness/tests/unit/test_switch_window_chrome.py TestSwitchToWindowContent.test_switch_to_unloaded_tab | OSError: Process has been unexpectedly closed (Exit code: 1) (Reason: Process unexpectedly quit with → Intermittent testing/marionette/harness/marionette_harness/tests/unit/test_switch_window_chrome.py TestSwitchToWindowContent.test_switch_to_unloaded_tab | after FATAL ERROR: Non-local network connections [...] aus5.mozilla.org (35.244.181.201) was made.

Regressed by bug 1272255. We are now crashing if Firefox is trying to access some non-local addresses. Here it's aus5.mozilla.org that Firefox usually uses for update checks. about:config shows the following entries:

extensions.systemAddon.update.url
media.gmp-manager.certs.1.commonName
media.gmp-manager.certs.2.commonName
media.gmp-manager.url

The extensions.systemAddon.update.url we replace and for gmp-manager we set media.gmp-manager.updateEnabled to false so that it basically should not check for updates. And the latter is also what other harnesses do in testing/profile. But I cannot find settings that modify extensions.systemAddon.update.url. Maybe that's related here? Generally it would be great if the crash message would contain the full URL.

So far it happened only once for a Linux ASAN build and I'm not able to reproduce locally.

Keywords: regression
OS: Unspecified → Linux
Regressed by: 1272255
Hardware: Unspecified → x86_64
Summary: Intermittent testing/marionette/harness/marionette_harness/tests/unit/test_switch_window_chrome.py TestSwitchToWindowContent.test_switch_to_unloaded_tab | after FATAL ERROR: Non-local network connections [...] aus5.mozilla.org (35.244.181.201) was made. → Intermittent Mn | after FATAL ERROR: Non-local network connections [...] aus5.mozilla.org (35.244.181.201) was made.
Has Regression Range: --- → yes

I agree that having better logs for such crashes would make investigations much easier.

Valentin, do you know why we only print the host and IP for such a triggered crash in Firefox?

05:07:39 INFO - FATAL ERROR: Non-local network connections are disabled and a connection attempt to aus5.mozilla.org (35.244.181.201) was made.

It would be great to see the full URL so that it will become much easier to actually investigate the issue. Maybe it's just the host/ip due to privacy issues, so that we do not leak API keys or similar in log files?

Flags: needinfo?(valentin.gosu)

We only show the IP because the crash is happens in nsSocketTransport2.cpp. The socket isn't aware of the upper layers.
Presumably this happens because any of the background requests (update, gmp, extensions) may happen during the test run.

An easy fix for this is to simply add an IP override for that (like here
Or you could set network.dns.native-is-localhost=true pref for the duration of the test.

Flags: needinfo?(valentin.gosu)

Thanks Valentin. Interesting pointer regarding the DNS override but I think that we wanna try to catch all of that via a correctly updated list of preferences for these jobs running in our CI and locally via mach.

Given that this failure here happened only once so far, I don't see a need to further investigate this bug anytime soon. Once we see an increased amount of failures we will have a look.

The aus5.mozilla.org is used for media.gmp-manager.url at https://searchfox.org/mozilla-central/rev/f8db81665dc2833fff09dc7eef200539ac1fd351/modules/libpref/init/all.js#4102

We do not override this pref for now, but most test harness do via media.gmp-manager.url.override https://searchfox.org/mozilla-central/search?path=&q=media.gmp-manager.url

Note also that the failures usually happen during a restart in test_switch_to_unloaded_tab

Hmm even though we don't set this preference, we do set media.gmp-manager.updateEnabled to false. Looking at the code, this should disable all usage of media.gmp-manager.url.

(In reply to Julian Descottes [:jdescottes] from comment #13)

The aus5.mozilla.org is used for media.gmp-manager.url at https://searchfox.org/mozilla-central/rev/f8db81665dc2833fff09dc7eef200539ac1fd351/modules/libpref/init/all.js#4102

aus5.mozilla.org is used for various update checks including extensions and general Firefox updates. So it's not only for the GMP manager. But all of them we have turned off. So it's really interesting what exactly tries to connect this server in ASAN builds only.

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

aus5.mozilla.org is used for various update checks including extensions and general Firefox updates.

Yes, but I was looking at the ones we didn't override explicitly with mock URLs. This one stood out because it's turned off via another pref.

Status: NEW → RESOLVED
Closed: 2 years ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
Status: REOPENED → RESOLVED
Closed: 2 years ago2 years ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
Status: REOPENED → RESOLVED
Closed: 2 years ago2 years ago
Resolution: --- → INCOMPLETE
Product: Testing → Remote Protocol
Moving bug to Testing::Marionette Client and Harness component per bug 1815831.
Component: Marionette → Marionette Client and Harness
Product: Remote Protocol → Testing
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---

Copying crash signatures from duplicate bugs.

Crash Signature: [@ mozilla::net::nsHttpChannel::OnStartRequest]

I can actually reproduce that bug permanently locally when applying the patch from D177134 to my local tree and adding a throw new Error() after new lazy.ServerSocket(this.port, flags, backlog);.

That surprises me given that we disable automatic updates via the app.update.disabledForTesting preference in geckoinstance.py. This means the preference is set before Firefox gets started.

Why does Firefox still try to reach aus5.mozilla.org to look for updates?

Here the updater log output:

1683897262575	Marionette	DEBUG	Could not bind to port 2828 (Error)
1683897262892	Marionette	DEBUG	Could not bind to port 2828 (NS_ERROR_SOCKET_ADDRESS_IN_USE)
[GFX1-]: RenderCompositorSWGL failed mapping default framebuffer, no dt
*** UTM:SVC TimerManager:registerTimer - timerID: browser-cleanup-thumbnails interval: 3600 skipFirst: false
console.error: (new Error("Unexpected content-type \"text/plain;charset=US-ASCII\"", "resource://services-settings/Utils.sys.mjs", 399))
console.error: (new Error("Unexpected content-type \"text/plain;charset=US-ASCII\"", "resource://services-settings/Utils.sys.mjs", 399))
*** UTM:SVC TimerManager:registerTimer - timerID: region-update-timer interval: 604800 skipFirst: false
console.error: (new Error("Unexpected content-type \"text/plain;charset=US-ASCII\"", "resource://services-settings/Utils.sys.mjs", 399))
console.error: (new Error("Unexpected content-type \"text/plain;charset=US-ASCII\"", "resource://services-settings/Utils.sys.mjs", 399))
console.error: (new Error("Unexpected content-type \"text/plain;charset=US-ASCII\"", "resource://services-settings/Utils.sys.mjs", 399))
console.error: (new Error("Unexpected content-type \"text/plain;charset=US-ASCII\"", "resource://services-settings/Utils.sys.mjs", 399))
*** AUS:SVC RestartOnLastWindowClosed.#maybeEnableOrDisable - Enabling
*** AUS:SVC Creating UpdateService
*** AUS:SVC Logging current UpdateService status:
*** AUS:SVC UpdateService.canUsuallyCheckForUpdates - able to check for updates
*** AUS:SVC UpdateService.canCheckForUpdates - able to check for updates
*** AUS:SVC getCanApplyUpdates - testing write access /Users/henrik/Library/Caches/Mozilla/updates/Users/henrik/code/gecko-obj/opt/dist/Nightly/update.test
*** AUS:SVC getCanApplyUpdates - bypass the write since elevation can be used on Mac OS X
*** AUS:SVC getElevationRequired - recursively testing write access on /Users/henrik/code/gecko-obj/opt/dist/Nightly.app
*** AUS:SVC getElevationRequired - able to write to application bundle, elevation not required
*** AUS:SVC gCanStageUpdatesSession - testing write access /Users/henrik/Library/Caches/Mozilla/updates/Users/henrik/code/gecko-obj/opt/dist/Nightly/update.test
*** AUS:SVC gCanStageUpdatesSession - able to stage updates
*** AUS:SVC getElevationRequired - recursively testing write access on /Users/henrik/code/gecko-obj/opt/dist/Nightly.app
*** AUS:SVC getElevationRequired - able to write to application bundle, elevation not required
*** AUS:SVC Elevation required: false
*** AUS:SVC Other instance of the application currently running: false
*** AUS:SVC Downloading: false
*** AUS:SVC End of UpdateService status
*** AUS:SVC UpdateService.canUsuallyCheckForUpdates - able to check for updates
*** AUS:SVC UpdateService.canCheckForUpdates - able to check for updates
*** AUS:SVC CheckerService:checkForUpdates - checkType: 2
*** AUS:SVC CheckerService:checkForUpdates - Making new check request for check id 1.
*** AUS:SVC waitForOtherInstances - beginning polling
*** AUS:SVC waitForOtherInstances - no other instances found, exiting
*** AUS:SVC CheckerService:getUpdateURL - checkType: 2
1683897263456	Marionette	DEBUG	Could not bind to port 2828 (NS_ERROR_SOCKET_ADDRESS_IN_USE)
*** AUS:SVC CheckerService:getUpdateURL - update URL: https://aus5.mozilla.org/update/6/Firefox/115.0a1/20230511094802/Darwin_aarch64-gcc3/en-US/default/Darwin%2022.4.0/ISET:NEON,MEM:32768/default/default/update.xml?force=1
*** AUS:SVC CheckerService:#updateCheck - sending request to: https://aus5.mozilla.org/update/6/Firefox/115.0a1/20230511094802/Darwin_aarch64-gcc3/en-US/default/Darwin%2022.4.0/ISET:NEON,MEM:32768/default/default/update.xml?force=1
1683897263579	Marionette	TRACE	Received observer notification browser-idle-startup-tasks-finished
Flags: needinfo?(bytesized)

Oh wait. We are not enabling Marionette and as such the nsIMarionette interface returns false for the running property. That means the app.update.disabledForTesting preference has no affect at this time.

This actually seems to be a race condition and maybe the first check for an update has to be post-poned even more? Or is there a way to actually completely disable update checks? That might be a better choice for us.

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

Oh wait. We are not enabling Marionette and as such the nsIMarionette interface returns false for the running property. That means the app.update.disabledForTesting preference has no affect at this time.

Ah, that would do it.

This actually seems to be a race condition and maybe the first check for an update has to be post-poned even more? Or is there a way to actually completely disable update checks? That might be a better choice for us.

Can you set an enterprise policy? You could use DisableAppUpdate.

Flags: needinfo?(bytesized)

(In reply to Robin Steuber (they/them) [:bytesized] from comment #52)

This actually seems to be a race condition and maybe the first check for an update has to be post-poned even more? Or is there a way to actually completely disable update checks? That might be a better choice for us.

Can you set an enterprise policy? You could use DisableAppUpdate.

No, that's something we cannot do. When I read the the enterprise documentation it looks like the policy needs to be set as file and it has to be located within the application folder which we may not have access to. Also given that such a Firefox instance can run on a users or CI system (even in parallel to an already running Firefox instance) I would be against using that technique. If something goes wrong (in the case we have access) with removing this file we would leave the system under some policy and that's not acceptable.

I'm afraid that we very intentionally don't allow update checks to be disabled without either (a) administrator privileges and/or direct access to the installation directory (i.e. Enterprise Policies) or (b) the Application Update Service being able to verify that it is running within a test framework.


(In reply to Henrik Skupin [:whimboo][⌚️UTC+1] from comment #51)
Oh wait. We are not enabling Marionette and as such the nsIMarionette interface returns false for the running property.

How are the tests being conducted if not by Marionette? Is there something that the update service could do to check that such a test is running? Then we could add that to the get UpdateService.disabledForTesting() implementation.

(In reply to Robin Steuber (they/them) [:bytesized] from comment #54)

(In reply to Henrik Skupin [:whimboo][⌚️UTC+1] from comment #51)
Oh wait. We are not enabling Marionette and as such the nsIMarionette interface returns false for the running property.

How are the tests being conducted if not by Marionette? Is there something that the update service could do to check that such a test is running? Then we could add that to the get UpdateService.disabledForTesting() implementation.

The problem here is actually the delay until Marionette has created its server socket and we consider it to be running. This particular flag is currently already checked. In case there are port conflicts we actually retry to create the server socket again on the previously selected port. As such there can be a delay. As such I'm not sure how much users of WebDriver might actually run into this issue that a update check is performed. Important is that it's not getting applied - but here we haven't heard anything yet.

Regarding this bug the failure only happens in our CI and when running Marionette via mach marionette-test because we do not allow remote connections by setting the MOZ_DISABLE_NONLOCAL_CONNECTIONS environment variable.

Robin, would it already help to maybe set the next update check to some minutes into the future so that there is enough time for Firefox to get started, and Marionette / Remote Agent to be enabled?

I also filed bug 1834306 so that we get the Marionette and Remote Agent checks added to Cu.isInAutomation directly given that some components don't take it into account at all.

Flags: needinfo?(bytesized)

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

Robin, would it already help to maybe set the next update check to some minutes into the future so that there is enough time for Firefox to get started, and Marionette / Remote Agent to be enabled?

Would two minutes be long enough? I believe that a two minute delay could be achieved just by setting some prefs.

First you would want to bypass the out-of-date check by setting app.update.checkInstallTime to false so that we bypass this whole block.

Then you could delay the first UpdateTimerManager timer by setting app.update.timerFirstInterval to 120000 (2 minutes in milliseconds). We currently cap that value at 2 minutes though, so if that isn't long enough we will either need to raise the cap or consider some other ways of delaying UpdateTimerManager.

Flags: needinfo?(bytesized)

Oh yes, two minutes would be absolutely fine but we would actually have to set this before starting Firefox. Also when running restart tests we might run into the same problem for the new Firefox instance. Maybe for the latter case we can update the timer again before requesting Firefox to shutdown for a restart.

The number of failures is still low here so maybe for now we could simply ignore it.

But for users of our protocols in general would app.update.autodownload help to at least stop downloading the update automatically? We really don't want to see an update getting applied.

Flags: needinfo?(bytesized)

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

But for users of our protocols in general would app.update.autodownload help to at least stop downloading the update automatically? We really don't want to see an update getting applied.

I wouldn't really recommend this route, but I'll describe what would be involved.

You are probably looking for app.update.auto. But that setting is actually no longer (consistently) stored as a regular pref. It now needs to be set via UpdateUtils.setAppUpdateAutoEnabled. This would not prevent update checks, but Firefox wouldn't download updates unless the user accepted the update prompt.

It's also worth mentioning that the reason that this pref is like this is that the setting is installation-specific, not profile-specific. I have generally tried to make most of the things that involve Application Update installation-specific since updating the application inherently affects the whole installation, not just a single profile. Also this allows update settings to apply to the Background Update Agent. This seems like it might be a problem given that you previously said this may be running on a shared installation.

It also sounds like you may be hoping to change this pref before Firefox starts, which would be kind of a problem. On non-Windows, it could be set how a normal pref is set, but we may be changing that in the future. On Windows, it's stored in a JSON file in the update directory. This means that (a) you would have to actually find the installation's update directory, which is a little tricky since it involves computing a CITY hash of the lower-cased wide string of the installation directory, and (b) that file isn't exactly meant to be an API and I don't think I would call its format "stable".

Flags: needinfo?(bytesized)

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

Maybe for the latter case we can update the timer again before requesting Firefox to shutdown for a restart.

If I'm understanding what you are saying here, I don't think that that is necessary. app.update.timerFirstInterval is a static pref that controls how long until the UpdateTimerManager starts on every startup. There should be no need change it again unless you create a new profile.

Sorry that I don't have a ton of good news for you here, but we try pretty hard to prevent local malware from preventing Firefox from updating. And what you are trying to do is fairly indistinguishable from that, really.

(In reply to Robin Steuber (they/them) [:bytesized] from comment #62)

If I'm understanding what you are saying here, I don't think that that is necessary. app.update.timerFirstInterval is a static pref that controls how long until the UpdateTimerManager starts on every startup. There should be no need change it again unless you create a new profile.

This is great to know and I think that using this preference would be fine to at least workaround the startup issues.

There is one thing through which I have seen recently. During shutdown which means after quit-application-granted we are still firing this timer which we probably should avoid. For an example see these lines of a Marionette test that fails regarding the ping:

https://treeherder.mozilla.org/logviewer?job_id=418135920&repo=autoland&lineNumber=92602-92632

Flags: needinfo?(bytesized)

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

During shutdown which means after quit-application-granted we are still firing this timer which we probably should avoid.

It looks to me like we shut down UpdateTimerManager on profile-before-change, but perhaps it ought to be earlier than that? Do you know if quit-application-granted is before that? I'm not super clear on the order of events during shutdown or at what point we know that the shutdown definitely won't abort.

Flags: needinfo?(bytesized) → needinfo?(hskupin)

That's a good question and I cannot really answer it. But I would say that you are doing it right and that maybe Marionette should also delay the shutdown of the server socket until profile-before-change and not do it already for quit-application. As such the socket would stay around longer and also nsIMarionette.running would report true. That probably would avoid running an application check during shutdown.

Gijs, maybe you could tell us if profile-before-change is the right point during shutdown to also shutdown certain components? Thanks a lot!

Flags: needinfo?(hskupin) → needinfo?(gijskruitbosch+bugs)

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

That's a good question and I cannot really answer it. But I would say that you are doing it right and that maybe Marionette should also delay the shutdown of the server socket until profile-before-change and not do it already for quit-application. As such the socket would stay around longer and also nsIMarionette.running would report true. That probably would avoid running an application check during shutdown.

Gijs, maybe you could tell us if profile-before-change is the right point during shutdown to also shutdown certain components? Thanks a lot!

This question is not one I can really answer straightforwardly - it depends what those components are doing?

Our shutdown phases are what I believe is technically called "a mess". Certainly quit-application is one of the earlier phases where you could start shutting things down. I think there's a list here:

https://searchfox.org/mozilla-central/rev/962a843f6d96283c45162c788dc72bf217fca7df/xpcom/base/ShutdownPhase.h

Which corresponds to observer topics here:

https://searchfox.org/mozilla-central/rev/962a843f6d96283c45162c788dc72bf217fca7df/xpcom/base/AppShutdown.cpp#47-60

Typically, you'd want to make sure that whatever phase/topic you pick, you (a) make sure it's before (or latest at the same time) as things you depend on (e.g. don't leave your component running until after, say, indexeddb code shuts down, if your component depends on said indexeddb code), and (b) ensure that there's no possibility after that point of re-starting-up in response to some API call, after which your component will never shut down (because the thing you're hooking to shut down has already happened). The AppShutdown (Services.startup from JS) code can help with this.

(In reply to Robin Steuber (they/them) [:bytesized] from comment #54)

How are the tests being conducted if not by Marionette? Is there something that the update service could do to check that such a test is running? Then we could add that to the get UpdateService.disabledForTesting() implementation.

Can we not "just" use Cu.isInAutomation(), rather than checking marionette or changing when it shuts down? That would be a less invasive change.

Despite the method name, that method (which returns a bool) really just checks (a) that the MOZ_DISABLE_NONLOCAL_CONNECTIONS thing is set (coincidentally, the thing that is more directly causing the crashes here!) and that (b) the turn_off_all_security_so_that_viruses_can_take_over_this_computer pref is set (which is also test-specific). If for some reason we need to support a case where the second is not true, you could check xpc::AreNonLocalConnectionsDisabled() in C++, or manually check the env var - but that's a little more expensive (and the xpc method has some read-only-page defense in depth stuff) so may not want to be something you do.

Flags: needinfo?(hskupin)
Flags: needinfo?(gijskruitbosch+bugs)
Flags: needinfo?(bytesized)

(In reply to :Gijs (he/him) from comment #69)

Can we not "just" use Cu.isInAutomation(), rather than checking marionette or changing when it shuts down? That would be a less invasive change.

The update system does check Cu.isInAutomation().

Flags: needinfo?(bytesized)

(In reply to Robin Steuber (they/them) [:bytesized] from comment #70)

(In reply to :Gijs (he/him) from comment #69)

Can we not "just" use Cu.isInAutomation(), rather than checking marionette or changing when it shuts down? That would be a less invasive change.

The update system does check Cu.isInAutomation().

Huh. So why is that insufficient here - :whimboo, do you know?

So Cu.isInAutomation() only checks the mTurnOffAllSecurityPref (as mentioned above) and then asserts that non-local connections are disabled. Note that this is not enough for Marionette and Remote Agent which are used by WebDriver clients to run automated tests for web pages. As such we added particular checks for both separately.

But that is not optimal given that we cannot keep up with any component in tree that checks the Cu.isInAutomation flag. As such I filed bug 1834306 recently to update the check, whereby I'm not sure how easy it will actually be. The mTurnOffAllSecurityPref will never be set by Marionette / geckodriver given that tests are run on beta / release builds, and no check for non-local connections can be performed because tests run against live web pages. Only in our own CI both should be taken care of.

I'm happy to continue the discussion for Cu.isInAutomation on the other bug, and keep this bug for a potential fix for the update checks.

Flags: needinfo?(hskupin)

Another alternative to fix our CI failures would be if the Marionette unit tests would use a pre-configured profile from testing/profiles similar to other tests, but this would not prevent Firefox to check for updates under such a situation for consumers of Webdriver.

Status: REOPENED → NEW
Component: Marionette Client and Harness → Agent
OS: Linux → All
Product: Testing → Remote Protocol
Hardware: x86_64 → All
No longer duplicate of this bug: 1840347
See Also: → 1851376
See Also: → 1851744
Status: NEW → RESOLVED
Closed: 2 years ago4 months ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
Status: REOPENED → RESOLVED
Closed: 4 months ago2 months ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---

As it looks like it is only ESR115 which is still affected. Tomorrow we have the last ESR 115.15 release so I think that we can actually close this bug.

Status: REOPENED → RESOLVED
Closed: 2 months ago1 month ago
Resolution: --- → WORKSFORME
You need to log in before you can comment on or make changes to this bug.