Closed Bug 1851744 Opened 1 year ago Closed 1 month ago

Intermittent FATAL ERROR: Non-local network connections are disabled and a connection attempt to www.mozilla.org (18.239.112.164) was made. | Hit MOZ_CRASH(Attempting to connect to non-local address! opener is [unknown], uri is [https://www.mozilla.org/co

Categories

(Remote Protocol :: Agent, defect, P5)

defect

Tracking

(Not tracked)

RESOLVED INCOMPLETE

People

(Reporter: intermittent-bug-filer, Unassigned)

References

Details

(Keywords: intermittent-failure)

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


[task 2023-09-06T01:54:55.766Z] 01:54:55     INFO -  TEST-START | testing/marionette/harness/marionette_harness/tests/unit/test_crash.py TestCrash.test_crash_chrome_process
[task 2023-09-06T01:54:55.767Z] 01:54:55     INFO -  Suppressing GECKO output. To view, add `print(self.new_out.getvalue())` to the end of this test.
[task 2023-09-06T01:54:55.768Z] 01:54:55     INFO -  1693965295768	Marionette	DEBUG	Accepted connection 114 from 127.0.0.1:63165
[task 2023-09-06T01:54:55.777Z] 01:54:55     INFO -  1693965295780	Marionette	DEBUG	114 -> [0,1,"WebDriver:NewSession",{"strictFileInteractability":true}]
[task 2023-09-06T01:54:55.783Z] 01:54:55     INFO -  1693965295781	Marionette	DEBUG	Waiting for initial application window
[task 2023-09-06T01:54:55.784Z] 01:54:55     INFO -  1693965295783	RemoteAgent	TRACE	[131] ProgressListener Start: expectNavigation=false resolveWhenStarted=false unloadTimeout=40000 waitForExplicitStart=false
[task 2023-09-06T01:54:55.784Z] 01:54:55     INFO -  1693965295783	RemoteAgent	TRACE	[131] ProgressListener Setting unload timer (40000ms)
[task 2023-09-06T01:54:55.784Z] 01:54:55     INFO -  1693965295783	RemoteAgent	TRACE	[131] Document already finished loading: http://127.0.0.1:62774/test.html
[task 2023-09-06T01:54:55.785Z] 01:54:55     INFO -  1693965295783	RemoteAgent	TRACE	[131] ProgressListener Stop: has error=false
[task 2023-09-06T01:54:55.787Z] 01:54:55     INFO -  1693965295786	Marionette	DEBUG	114 <- [1,1,null,{"sessionId":"b35285be-ea1e-44db-be78-3104971d6aba","capabilities":{"browserName":"firefox","browserVersion":"119.0a1","platformName":"windows","acceptInsecureCerts":false,"pageLoadStrategy":"normal","setWindowRect":true,"timeouts":{"implicit":0,"pageLoad":300000,"script":30000},"strictFileInteractability":true,"unhandledPromptBehavior":"dismiss and notify","moz:accessibilityChecks":false,"moz:buildID":"20230906010613","moz:headless":false,"moz:platformVersion":"10.0","moz:processID":10220,"moz:profile":"C:\\Users\\task_169396314393606\\AppData\\Local\\Temp\\tmpzkib7_d0.mozrunner","moz:shutdownTimeout":60000,"moz:webdriverClick":true,"moz:windowless":false,"proxy":{}}}]
[task 2023-09-06T01:54:55.788Z] 01:54:55     INFO -  1693965295788	Marionette	DEBUG	114 -> [0,2,"WebDriver:SetTimeouts",{"script":30000}]
[task 2023-09-06T01:54:55.789Z] 01:54:55     INFO -  1693965295788	Marionette	DEBUG	114 <- [1,2,null,{"value":null}]
[task 2023-09-06T01:54:55.790Z] 01:54:55     INFO -  1693965295790	Marionette	DEBUG	114 -> [0,3,"WebDriver:SetTimeouts",{"pageLoad":300000}]
[task 2023-09-06T01:54:55.790Z] 01:54:55     INFO -  1693965295790	Marionette	DEBUG	114 <- [1,3,null,{"value":null}]
[task 2023-09-06T01:54:55.792Z] 01:54:55     INFO -  1693965295791	Marionette	DEBUG	114 -> [0,4,"WebDriver:SetTimeouts",{"implicit":0}]
[task 2023-09-06T01:54:55.792Z] 01:54:55     INFO -  1693965295792	Marionette	DEBUG	114 <- [1,4,null,{"value":null}]
[task 2023-09-06T01:54:55.798Z] 01:54:55     INFO -  1693965295798	Marionette	DEBUG	114 -> [0,5,"Marionette:GetContext",{}]
[task 2023-09-06T01:54:55.798Z] 01:54:55     INFO -  1693965295798	Marionette	DEBUG	114 <- [1,5,null,{"value":"content"}]
[task 2023-09-06T01:54:55.799Z] 01:54:55     INFO -  1693965295799	Marionette	DEBUG	114 -> [0,6,"Marionette:SetContext",{"value":"chrome"}]
[task 2023-09-06T01:54:55.800Z] 01:54:55     INFO -  1693965295799	Marionette	DEBUG	114 <- [1,6,null,{"value":null}]
[task 2023-09-06T01:54:55.802Z] 01:54:55     INFO -  1693965295801	Marionette	DEBUG	114 -> [0,7,"WebDriver:ExecuteScript",{"script":"const { AppConstants } = ChromeUtils.importESModule(\n                  \"resource://gre/modules/AppConstants.sys.mjs\"\n                );\n                return AppConstants.MOZ_CRASHREPORTER;","args":[],"newSandbox":true,"sandbox":"default","line":32,"filename":"Z:\\task_169396314393606\\build\\tests\\marionette\\tests\\testing\\marionette\\harness\\marionette_harness\\tests\\unit\\test_crash.py"}]
[task 2023-09-06T01:54:55.805Z] 01:54:55     INFO -  1693965295805	RemoteAgent	TRACE	WebDriverProcessData actor created for PID 10220
[task 2023-09-06T01:54:55.805Z] 01:54:55     INFO -  1693965295805	Marionette	TRACE	[1] MarionetteCommands actor created for window id 2
[task 2023-09-06T01:54:55.811Z] 01:54:55     INFO -  1693965295810	Marionette	DEBUG	114 <- [1,7,null,{"value":true}]
[task 2023-09-06T01:54:55.811Z] 01:54:55     INFO -  DEBUG: Adding blocker Transaction (46) for phase protections.sqlite#0: waiting for clients
[task 2023-09-06T01:54:55.813Z] 01:54:55     INFO -  1693965295813	Marionette	DEBUG	114 -> [0,8,"Marionette:SetContext",{"value":"content"}]
[task 2023-09-06T01:54:55.814Z] 01:54:55     INFO -  1693965295813	Marionette	DEBUG	114 <- [1,8,null,{"value":null}]
[task 2023-09-06T01:54:55.814Z] 01:54:55     INFO -  DEBUG: Completed blocker Transaction (46) for phase protections.sqlite#0: waiting for clients
[task 2023-09-06T01:54:55.815Z] 01:54:55     INFO -  DEBUG: Adding blocker Transaction (47) for phase protections.sqlite#0: waiting for clients
[task 2023-09-06T01:54:55.816Z] 01:54:55     INFO -  1693965295816	Marionette	DEBUG	114 -> [0,9,"Marionette:SetContext",{"value":"content"}]
[task 2023-09-06T01:54:55.816Z] 01:54:55     INFO -  1693965295816	Marionette	DEBUG	114 <- [1,9,null,{"value":null}]
[task 2023-09-06T01:54:55.817Z] 01:54:55     INFO -  DEBUG: Completed blocker Transaction (47) for phase protections.sqlite#0: waiting for clients
[task 2023-09-06T01:54:55.818Z] 01:54:55     INFO -  1693965295818	Marionette	DEBUG	114 -> [0,10,"WebDriver:Navigate",{"url":"about:crashparent"}]
[task 2023-09-06T01:54:55.820Z] 01:54:55     INFO -  1693965295821	Marionette	TRACE	[131] Received event beforeunload for http://127.0.0.1:62774/test.html
[task 2023-09-06T01:54:55.825Z] 01:54:55     INFO -  Hit MOZ_CRASH(Crash via about:crashparent) at /builds/worker/checkouts/gecko/docshell/base/nsAboutRedirector.cpp:39
[task 2023-09-06T01:54:55.981Z] 01:54:55     INFO -  #01: DumpBidiLine[Z:\task_169396314393606\build\application\firefox\xul.dll +0x6bc577a]
[task 2023-09-06T01:54:55.993Z] 01:54:55     INFO -  #02: ???[Z:\task_169396314393606\build\application\firefox\xul.dll +0x5eb41f]
[task 2023-09-06T01:54:55.993Z] 01:54:55     INFO -  #03: ???[Z:\task_169396314393606\build\application\firefox\xul.dll +0x5dfbb8]
[task 2023-09-06T01:54:55.993Z] 01:54:55     INFO -  #04: ???[Z:\task_169396314393606\build\application\firefox\xul.dll +0xccf321]
[task 2023-09-06T01:54:55.994Z] 01:54:55     INFO -  #05: ???[Z:\task_169396314393606\build\application\firefox\xul.dll +0xcca90e]
[task 2023-09-06T01:54:55.994Z] 01:54:55     INFO -  #06: ???[Z:\task_169396314393606\build\application\firefox\xul.dll +0xcc99a3]
[task 2023-09-06T01:54:55.994Z] 01:54:55     INFO -  #07: ???[Z:\task_169396314393606\build\application\firefox\xul.dll +0xcdf6cc]
[task 2023-09-06T01:54:55.994Z] 01:54:55     INFO -  #08: ???[Z:\task_169396314393606\build\application\firefox\xul.dll +0xd5c2c9]
[task 2023-09-06T01:54:55.994Z] 01:54:55     INFO -  #09: VR_RuntimePath[Z:\task_169396314393606\build\application\firefox\xul.dll +0x4a33c0d]
[task 2023-09-06T01:54:55.994Z] 01:54:55     INFO -  #10: ???[Z:\task_169396314393606\build\application\firefox\xul.dll +0xee87af]
[task 2023-09-06T01:54:55.994Z] 01:54:55     INFO -  #11: ???[Z:\task_169396314393606\build\application\firefox\xul.dll +0xee6b38]
[task 2023-09-06T01:54:55.995Z] 01:54:55     INFO -  #12: ???[Z:\task_169396314393606\build\application\firefox\xul.dll +0xee7364]
[task 2023-09-06T01:54:55.995Z] 01:54:55     INFO -  #13: ???[Z:\task_169396314393606\build\application\firefox\xul.dll +0xee795e]
[task 2023-09-06T01:54:55.995Z] 01:54:55     INFO -  #14: ???[Z:\task_169396314393606\build\application\firefox\xul.dll +0x3de1ae]
[task 2023-09-06T01:54:55.995Z] 01:54:55     INFO -  #15: ???[Z:\task_169396314393606\build\application\firefox\xul.dll +0x3d18b5]
[task 2023-09-06T01:54:55.995Z] 01:54:55     INFO -  #16: ???[Z:\task_169396314393606\build\application\firefox\xul.dll +0x3cfb48]
[task 2023-09-06T01:54:55.995Z] 01:54:55     INFO -  #17: ???[Z:\task_169396314393606\build\application\firefox\xul.dll +0x3cffba]
[task 2023-09-06T01:54:55.996Z] 01:54:55     INFO -  #18: ???[Z:\task_169396314393606\build\application\firefox\xul.dll +0x3e0b77]
[task 2023-09-06T01:54:55.996Z] 01:54:55     INFO -  #19: ???[Z:\task_169396314393606\build\application\firefox\xul.dll +0x3f8f87]
[task 2023-09-06T01:54:55.996Z] 01:54:55     INFO -  #20: ???[Z:\task_169396314393606\build\application\firefox\xul.dll +0x4004d5]
[task 2023-09-06T01:54:55.996Z] 01:54:55     INFO -  #21: ???[Z:\task_169396314393606\build\application\firefox\xul.dll +0xeeccda]
[task 2023-09-06T01:54:55.996Z] 01:54:55     INFO -  #22: ???[Z:\task_169396314393606\build\application\firefox\xul.dll +0xe6f310]
[task 2023-09-06T01:54:55.996Z] 01:54:55     INFO -  #23: ???[Z:\task_169396314393606\build\application\firefox\xul.dll +0xe6f1cf]
[task 2023-09-06T01:54:55.996Z] 01:54:55     INFO -  #24: VR_RuntimePath[Z:\task_169396314393606\build\application\firefox\xul.dll +0x50b80c8]
[task 2023-09-06T01:54:55.997Z] 01:54:55     INFO -  #25: VR_RuntimePath[Z:\task_169396314393606\build\application\firefox\xul.dll +0x5195c4a]
[task 2023-09-06T01:54:55.997Z] 01:54:55     INFO -  #26: GIFFT_TimingDistributionCancel[Z:\task_169396314393606\build\application\firefox\xul.dll +0x7210da8]
[task 2023-09-06T01:54:55.997Z] 01:54:55     INFO -  #27: GIFFT_TimingDistributionCancel[Z:\task_169396314393606\build\application\firefox\xul.dll +0x73ae22a]
[task 2023-09-06T01:54:55.997Z] 01:54:55     INFO -  #28: GIFFT_TimingDistributionCancel[Z:\task_169396314393606\build\application\firefox\xul.dll +0x73b1281]
[task 2023-09-06T01:54:55.997Z] 01:54:55     INFO -  #29: GIFFT_TimingDistributionCancel[Z:\task_169396314393606\build\application\firefox\xul.dll +0x73b1e17]
[task 2023-09-06T01:54:55.997Z] 01:54:55     INFO -  #30: ???[Z:\task_169396314393606\build\application\firefox\firefox.exe +0x17d8]
[task 2023-09-06T01:54:55.998Z] 01:54:55     INFO -  #31: ???[Z:\task_169396314393606\build\application\firefox\firefox.exe +0x120f]
[task 2023-09-06T01:54:55.998Z] 01:54:55     INFO -  #32: TargetNtUnmapViewOfSection[Z:\task_169396314393606\build\application\firefox\firefox.exe +0x963c8]
[task 2023-09-06T01:54:55.998Z] 01:54:55     INFO -  #33: BaseThreadInitThunk[C:\Windows\System32\KERNEL32.DLL +0x1269d]
[task 2023-09-06T01:54:55.998Z] 01:54:55     INFO -  #34: RtlUserThreadStart[C:\Windows\SYSTEM32\ntdll.dll +0x5a9f8]
[task 2023-09-06T01:54:56.216Z] 01:54:56     INFO -  [GPU 6244, IPC I/O Child] WARNING: [8AE50F1C6D228547.1A5F44160998D608]: Ignoring message 'EVENT_MESSAGE' to peer 1.1 due to a missing broker: file /builds/worker/checkouts/gecko/ipc/glue/NodeController.cpp:352
[task 2023-09-06T01:54:56.216Z] 01:54:56     INFO -  [GPU 6244, IPC I/O Child] WARNING: [8AE50F1C6D228547.1A5F44160998D608]: Ignoring message 'EVENT_MESSAGE' to peer 1.1 due to a missing broker: file /builds/worker/checkouts/gecko/ipc/glue/NodeController.cpp:352
[task 2023-09-06T01:54:56.223Z] 01:54:56     INFO -  [GPU 6244, IPC I/O Child] WARNING: [8AE50F1C6D228547.1A5F44160998D608]: Ignoring message 'EVENT_MESSAGE' to peer 1.1 due to a missing broker: file /builds/worker/checkouts/gecko/ipc/glue/NodeController.cpp:352
[task 2023-09-06T01:54:56.223Z] 01:54:56     INFO -  [GPU 6244, IPC I/O Child] WARNING: [8AE50F1C6D228547.1A5F44160998D608]: Ignoring message 'EVENT_MESSAGE' to peer 1.1 due to a missing broker: file /builds/worker/checkouts/gecko/ipc/glue/NodeController.cpp:352
[task 2023-09-06T01:54:56.223Z] 01:54:56     INFO -  [GPU 6244, IPC I/O Child] WARNING: [8AE50F1C6D228547.1A5F44160998D608]: Ignoring message 'EVENT_MESSAGE' to peer 1.1 due to a missing broker: file /builds/worker/checkouts/gecko/ipc/glue/NodeController.cpp:352
[task 2023-09-06T01:54:56.223Z] 01:54:56     INFO -  [GPU 6244, IPC I/O Child] WARNING: [8AE50F1C6D228547.1A5F44160998D608]: Ignoring message 'EVENT_MESSAGE' to peer 1.1 due to a missing broker: file /builds/worker/checkouts/gecko/ipc/glue/NodeController.cpp:352
[task 2023-09-06T01:54:56.223Z] 01:54:56     INFO -  [GPU 6244, IPC I/O Child] WARNING: [8AE50F1C6D228547.1A5F44160998D608]: Ignoring message 'EVENT_MESSAGE' to peer 1.1 due to a missing broker: file /builds/worker/checkouts/gecko/ipc/glue/NodeController.cpp:352
[task 2023-09-06T01:54:56.223Z] 01:54:56     INFO -  [Child 9480, IPC I/O Child] WARNING: [4E0BF3F4484C6EE7.608D82CB05786359]: Ignoring message 'EVENT_MESSAGE' to peer 1.1 due to a missing broker: file /builds/worker/checkouts/gecko/ipc/glue/NodeController.cpp:352
[task 2023-09-06T01:54:56.223Z] 01:54:56     INFO -  Exiting due to channel error.
[task 2023-09-06T01:54:56.223Z] 01:54:56     INFO -  [Utility 9016, IPC I/O Child] WARNING: [5B3777893C907225.73395C5B49D407D7]: Ignoring message 'EVENT_MESSAGE' to peer 1.1 due to a missing broker: file /builds/worker/checkouts/gecko/ipc/glue/NodeController.cpp:352
[task 2023-09-06T01:54:56.223Z] 01:54:56     INFO -  [Utility 9016, IPC I/O Child] WARNING: [5B3777893C907225.73395C5B49D407D7]: Ignoring message 'EVENT_MESSAGE' to peer 1.1 due to a missing broker: file /builds/worker/checkouts/gecko/ipc/glue/NodeController.cpp:352
[task 2023-09-06T01:54:56.279Z] 01:54:56     INFO -  Application command: Z:\task_169396314393606\build\application\firefox\firefox.exe -no-remote -marionette --wait-for-browser -profile C:\Users\task_169396314393606\AppData\Local\Temp\tmpzkib7_d0.mozrunner
[task 2023-09-06T01:55:00.230Z] 01:55:00     INFO -  TEST-PASS | testing/marionette/harness/marionette_harness/tests/unit/test_crash.py TestCrash.test_crash_chrome_process | took 4466ms
[task 2023-09-06T01:55:00.241Z] 01:55:00     INFO -  TEST-START | testing/marionette/harness/marionette_harness/tests/unit/test_crash.py TestCrash.test_crash_content_process

The full crash line here is:
Hit MOZ_CRASH(Attempting to connect to non-local address! opener is [unknown], uri is [https://www.mozilla.org/contribute/?utm_medium=firefox-desktop&utm_source=bookmarks-toolbar&utm_campaign=new-users-nightly&utm_content=-global]) at /builds/worker/checkouts/gecko/netwerk/protocol/http/nsHttpChannel.cpp:7046

This is actually a crash as triggered by the browser/components/migration/tests/marionette/test_refresh_firefox.py test. It looks like there is some kind of campaign specific for Firefox users, and Firefox tries to reach an external network address.

Not sure yet if that is specific to the test, or if we need to set a new preference to disallow / disable campaigns at all.

Gijs, do you maybe know what that is? Searchfox isn't pretty helpful here.

Flags: needinfo?(gijskruitbosch+bugs)

The URL looks like it's from https://searchfox.org/mozilla-central/rev/a4cb813cd4026cc24b45e843222e6a08204bae47/browser/base/content/default-bookmarks.html#47 .

But I don't know why we would actually load that URL, or why it'd be intermittent, and the crash stack is no help. The test hasn't meaningfully changed in a long time. There were some mechanical changes relating to API changes in logins code, but logins code isn't directly related to the default bookmarks and such.

If this happens more frequently, the next step would probably be reproducing with pernosco or locally to be able to work out what is triggering the network request.

Flags: needinfo?(gijskruitbosch+bugs)

Thanks for your feedback! It is indeed suspicious especially that this link would have been opened.

From our side there was only a single change recently in https://hg.mozilla.org/integration/autoland/rev/57929c2e184a but that's only changing prefs to make sure we do not crash when running under Cu.isInAutomation. Nothing stands our for me here.

So I agree lets observe the failure rate for now and if it increases we can have a deeper look.

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