I added some logging to the `SERVER_URL` function, and got some logging during a failure here: https://treeherder.mozilla.org/logviewer?job_id=386313801&repo=try&lineNumber=4506 https://firefoxci.taskcluster-artifacts.net/ExTDYv7WRuiZieoAfhsi_w/0/public/logs/live_backing.log Look in particular at the logging for PID 2916: ``` [task 2022-08-03T20:37:43.045Z] 20:37:43 INFO - TEST-INFO | started process GECKO(2916) [task 2022-08-03T20:37:46.105Z] 20:37:46 INFO - GECKO(2916) | 1659559066104 Marionette INFO Marionette enabled [task 2022-08-03T20:37:46.116Z] 20:37:46 INFO - GECKO(2916) | 1659559066115 Marionette TRACE Received observer notification final-ui-startup [task 2022-08-03T20:37:46.126Z] 20:37:46 INFO - GECKO(2916) | 1659559066124 Marionette INFO Listening on port 2828 [task 2022-08-03T20:37:46.127Z] 20:37:46 INFO - GECKO(2916) | 1659559066125 Marionette DEBUG Marionette is listening [task 2022-08-03T20:37:46.902Z] 20:37:46 INFO - GECKO(2916) | 1659559066900 Marionette DEBUG Accepted connection 0 from 127.0.0.1:41700 [task 2022-08-03T20:37:47.143Z] 20:37:47 INFO - GECKO(2916) | 1659559067142 Marionette DEBUG Closed connection 0 [task 2022-08-03T20:37:47.152Z] 20:37:47 INFO - GECKO(2916) | 1659559067151 Marionette DEBUG Accepted connection 1 from 127.0.0.1:41702 [task 2022-08-03T20:37:47.355Z] 20:37:47 INFO - GECKO(2916) | ###dholbert-logging: In SERVER_URL; lazy.allowServerURLOverride is true. Returning lazy.gServerURL: http://127.0.0.1:8888/dummy-kinto/v1 [task 2022-08-03T20:37:47.378Z] 20:37:47 INFO - GECKO(2916) | 1659559067377 Marionette DEBUG Closed connection 1 [task 2022-08-03T20:37:47.381Z] 20:37:47 INFO - GECKO(2916) | 1659559067379 Marionette DEBUG Accepted connection 2 from 127.0.0.1:41704 [task 2022-08-03T20:37:48.802Z] 20:37:48 INFO - GECKO(2916) | 1659559068800 Marionette DEBUG 2 -> [0,1,"WebDriver:NewSession",{"strictFileInteractability":true}] [task 2022-08-03T20:37:48.828Z] 20:37:48 INFO - GECKO(2916) | 1659559068826 Marionette DEBUG Waiting for initial application window [task 2022-08-03T20:37:53.090Z] 20:37:53 INFO - GECKO(2916) | console.warn: SearchSettings: "get: No settings file exists, new profile?" (new NotFoundError("Could not open the file at /tmp/tmpn9l63ksl.mozrunner/search.json.mozlz4", (void 0))) [task 2022-08-03T20:37:53.295Z] 20:37:53 INFO - GECKO(2916) | ###dholbert-logging: In SERVER_URL; lazy.allowServerURLOverride is true. Returning lazy.gServerURL: http://127.0.0.1:8888/dummy-kinto/v1 [task 2022-08-03T20:37:53.298Z] 20:37:53 INFO - GECKO(2916) | ###dholbert-logging: In SERVER_URL; lazy.allowServerURLOverride is true. Returning lazy.gServerURL: http://127.0.0.1:8888/dummy-kinto/v1 [task 2022-08-03T20:37:53.329Z] 20:37:53 INFO - GECKO(2916) | ###dholbert-logging: In SERVER_URL; lazy.allowServerURLOverride is true. Returning lazy.gServerURL: http://127.0.0.1:8888/dummy-kinto/v1 [task 2022-08-03T20:37:53.389Z] 20:37:53 INFO - GECKO(2916) | ###dholbert-logging: In SERVER_URL; lazy.allowServerURLOverride is true. Returning lazy.gServerURL: http://127.0.0.1:8888/dummy-kinto/v1 [task 2022-08-03T20:37:53.468Z] 20:37:53 INFO - GECKO(2916) | ###dholbert-logging: In SERVER_URL; lazy.allowServerURLOverride is true. Returning lazy.gServerURL: http://127.0.0.1:8888/dummy-kinto/v1 [task 2022-08-03T20:37:54.680Z] 20:37:54 INFO - GECKO(2916) | ###dholbert-logging: In SERVER_URL; lazy.allowServerURLOverride is true. Returning lazy.gServerURL: http://127.0.0.1:8888/dummy-kinto/v1 [task 2022-08-03T20:37:55.306Z] 20:37:55 INFO - GECKO(2916) | ###dholbert-logging: In SERVER_URL; lazy.allowServerURLOverride is true. Returning lazy.gServerURL: http://127.0.0.1:8888/dummy-kinto/v1 [task 2022-08-03T20:37:58.519Z] 20:37:58 INFO - GECKO(2916) | ###dholbert-logging: In SERVER_URL; lazy.allowServerURLOverride is true. Returning lazy.gServerURL: http://127.0.0.1:8888/dummy-kinto/v1 [task 2022-08-03T20:37:59.514Z] 20:37:59 INFO - GECKO(2916) | 1659559079512 Marionette TRACE Received observer notification browser-idle-startup-tasks-finished [task 2022-08-03T20:37:59.564Z] 20:37:59 INFO - GECKO(2916) | 1659559079562 RemoteAgent TRACE [24] Document already finished loading: about:blank [...] [task 2022-08-03T20:38:01.848Z] 20:38:01 INFO - *** Start BrowserChrome Test Results *** [task 2022-08-03T20:38:02.100Z] 20:38:02 INFO - checking window state [task 2022-08-03T20:38:02.277Z] 20:38:02 INFO - TEST-START | browser/components/newtab/test/browser/browser_aboutwelcome_configurable_ui.js [task 2022-08-03T20:38:03.801Z] 20:38:03 INFO - GECKO(2916) | console.debug: AboutWelcomeChild: [...] [task 2022-08-03T20:38:04.831Z] 20:38:04 INFO - GECKO(2916) | ###dholbert-logging: In SERVER_URL; lazy.allowServerURLOverride is true. Returning lazy.gServerURL: http://127.0.0.1:8888/dummy-kinto/v1 [...] [task 2022-08-03T20:41:42.661Z] 20:41:42 INFO - TEST-OK | browser/components/newtab/test/browser/browser_remote_l10n.js | took 366ms [task 2022-08-03T20:41:42.741Z] 20:41:42 INFO - checking window state [task 2022-08-03T20:41:42.809Z] 20:41:42 INFO - TEST-START | browser/components/newtab/test/browser/browser_topsites_annotation.js [task 2022-08-03T20:42:16.407Z] 20:42:16 INFO - GECKO(2916) | ###dholbert-logging: In SERVER_URL; lazy.allowServerURLOverride is true. Returning lazy.gServerURL: https://firefox.settings.services.mozilla.com/v1 [task 2022-08-03T20:42:16.486Z] 20:42:16 INFO - GECKO(2916) | FATAL ERROR: Non-local network connections are disabled and a connection attempt to firefox.settings.services.mozilla.com (18.160.225.118) was made. ``` That last SERVER_URL access (still in the same process ID) is getting a different `lazy.gServerURL` value for some reason (the problematic "real" value, `https://firefox.settings.services.mozilla.com/v1`).
Bug 1714615 Comment 83 Edit History
Note: The actual edited comment in the bug view page will always show the original commenter’s name and original timestamp.
I added some logging to the `SERVER_URL` function, and got some logging during a failure here: https://treeherder.mozilla.org/logviewer?job_id=386313801&repo=try&lineNumber=4506 https://firefoxci.taskcluster-artifacts.net/ExTDYv7WRuiZieoAfhsi_w/0/public/logs/live_backing.log Look in particular at the logging for PID 2916 in that log: ``` [task 2022-08-03T20:37:43.045Z] 20:37:43 INFO - TEST-INFO | started process GECKO(2916) [task 2022-08-03T20:37:46.105Z] 20:37:46 INFO - GECKO(2916) | 1659559066104 Marionette INFO Marionette enabled [task 2022-08-03T20:37:46.116Z] 20:37:46 INFO - GECKO(2916) | 1659559066115 Marionette TRACE Received observer notification final-ui-startup [task 2022-08-03T20:37:46.126Z] 20:37:46 INFO - GECKO(2916) | 1659559066124 Marionette INFO Listening on port 2828 [task 2022-08-03T20:37:46.127Z] 20:37:46 INFO - GECKO(2916) | 1659559066125 Marionette DEBUG Marionette is listening [task 2022-08-03T20:37:46.902Z] 20:37:46 INFO - GECKO(2916) | 1659559066900 Marionette DEBUG Accepted connection 0 from 127.0.0.1:41700 [task 2022-08-03T20:37:47.143Z] 20:37:47 INFO - GECKO(2916) | 1659559067142 Marionette DEBUG Closed connection 0 [task 2022-08-03T20:37:47.152Z] 20:37:47 INFO - GECKO(2916) | 1659559067151 Marionette DEBUG Accepted connection 1 from 127.0.0.1:41702 [task 2022-08-03T20:37:47.355Z] 20:37:47 INFO - GECKO(2916) | ###dholbert-logging: In SERVER_URL; lazy.allowServerURLOverride is true. Returning lazy.gServerURL: http://127.0.0.1:8888/dummy-kinto/v1 [task 2022-08-03T20:37:47.378Z] 20:37:47 INFO - GECKO(2916) | 1659559067377 Marionette DEBUG Closed connection 1 [task 2022-08-03T20:37:47.381Z] 20:37:47 INFO - GECKO(2916) | 1659559067379 Marionette DEBUG Accepted connection 2 from 127.0.0.1:41704 [task 2022-08-03T20:37:48.802Z] 20:37:48 INFO - GECKO(2916) | 1659559068800 Marionette DEBUG 2 -> [0,1,"WebDriver:NewSession",{"strictFileInteractability":true}] [task 2022-08-03T20:37:48.828Z] 20:37:48 INFO - GECKO(2916) | 1659559068826 Marionette DEBUG Waiting for initial application window [task 2022-08-03T20:37:53.090Z] 20:37:53 INFO - GECKO(2916) | console.warn: SearchSettings: "get: No settings file exists, new profile?" (new NotFoundError("Could not open the file at /tmp/tmpn9l63ksl.mozrunner/search.json.mozlz4", (void 0))) [task 2022-08-03T20:37:53.295Z] 20:37:53 INFO - GECKO(2916) | ###dholbert-logging: In SERVER_URL; lazy.allowServerURLOverride is true. Returning lazy.gServerURL: http://127.0.0.1:8888/dummy-kinto/v1 [task 2022-08-03T20:37:53.298Z] 20:37:53 INFO - GECKO(2916) | ###dholbert-logging: In SERVER_URL; lazy.allowServerURLOverride is true. Returning lazy.gServerURL: http://127.0.0.1:8888/dummy-kinto/v1 [task 2022-08-03T20:37:53.329Z] 20:37:53 INFO - GECKO(2916) | ###dholbert-logging: In SERVER_URL; lazy.allowServerURLOverride is true. Returning lazy.gServerURL: http://127.0.0.1:8888/dummy-kinto/v1 [task 2022-08-03T20:37:53.389Z] 20:37:53 INFO - GECKO(2916) | ###dholbert-logging: In SERVER_URL; lazy.allowServerURLOverride is true. Returning lazy.gServerURL: http://127.0.0.1:8888/dummy-kinto/v1 [task 2022-08-03T20:37:53.468Z] 20:37:53 INFO - GECKO(2916) | ###dholbert-logging: In SERVER_URL; lazy.allowServerURLOverride is true. Returning lazy.gServerURL: http://127.0.0.1:8888/dummy-kinto/v1 [task 2022-08-03T20:37:54.680Z] 20:37:54 INFO - GECKO(2916) | ###dholbert-logging: In SERVER_URL; lazy.allowServerURLOverride is true. Returning lazy.gServerURL: http://127.0.0.1:8888/dummy-kinto/v1 [task 2022-08-03T20:37:55.306Z] 20:37:55 INFO - GECKO(2916) | ###dholbert-logging: In SERVER_URL; lazy.allowServerURLOverride is true. Returning lazy.gServerURL: http://127.0.0.1:8888/dummy-kinto/v1 [task 2022-08-03T20:37:58.519Z] 20:37:58 INFO - GECKO(2916) | ###dholbert-logging: In SERVER_URL; lazy.allowServerURLOverride is true. Returning lazy.gServerURL: http://127.0.0.1:8888/dummy-kinto/v1 [task 2022-08-03T20:37:59.514Z] 20:37:59 INFO - GECKO(2916) | 1659559079512 Marionette TRACE Received observer notification browser-idle-startup-tasks-finished [task 2022-08-03T20:37:59.564Z] 20:37:59 INFO - GECKO(2916) | 1659559079562 RemoteAgent TRACE [24] Document already finished loading: about:blank [...] [task 2022-08-03T20:38:01.848Z] 20:38:01 INFO - *** Start BrowserChrome Test Results *** [task 2022-08-03T20:38:02.100Z] 20:38:02 INFO - checking window state [task 2022-08-03T20:38:02.277Z] 20:38:02 INFO - TEST-START | browser/components/newtab/test/browser/browser_aboutwelcome_configurable_ui.js [task 2022-08-03T20:38:03.801Z] 20:38:03 INFO - GECKO(2916) | console.debug: AboutWelcomeChild: [...] [task 2022-08-03T20:38:04.831Z] 20:38:04 INFO - GECKO(2916) | ###dholbert-logging: In SERVER_URL; lazy.allowServerURLOverride is true. Returning lazy.gServerURL: http://127.0.0.1:8888/dummy-kinto/v1 [...] [task 2022-08-03T20:41:42.661Z] 20:41:42 INFO - TEST-OK | browser/components/newtab/test/browser/browser_remote_l10n.js | took 366ms [task 2022-08-03T20:41:42.741Z] 20:41:42 INFO - checking window state [task 2022-08-03T20:41:42.809Z] 20:41:42 INFO - TEST-START | browser/components/newtab/test/browser/browser_topsites_annotation.js [task 2022-08-03T20:42:16.407Z] 20:42:16 INFO - GECKO(2916) | ###dholbert-logging: In SERVER_URL; lazy.allowServerURLOverride is true. Returning lazy.gServerURL: https://firefox.settings.services.mozilla.com/v1 [task 2022-08-03T20:42:16.486Z] 20:42:16 INFO - GECKO(2916) | FATAL ERROR: Non-local network connections are disabled and a connection attempt to firefox.settings.services.mozilla.com (18.160.225.118) was made. ``` That last SERVER_URL access (still in the same process ID) is getting a different `lazy.gServerURL` value for some reason (the problematic "real" value, `https://firefox.settings.services.mozilla.com/v1`).
I added some logging to the `SERVER_URL` function, and got some logging during a failure here: https://treeherder.mozilla.org/logviewer?job_id=386313801&repo=try&lineNumber=4506 https://firefoxci.taskcluster-artifacts.net/ExTDYv7WRuiZieoAfhsi_w/0/public/logs/live_backing.log Look in particular at the logging for PID 2916 in that log (the "In SERVER_URL" lines are my added logging, via dump() statements inside that JS function): ``` [task 2022-08-03T20:37:43.045Z] 20:37:43 INFO - TEST-INFO | started process GECKO(2916) [task 2022-08-03T20:37:46.105Z] 20:37:46 INFO - GECKO(2916) | 1659559066104 Marionette INFO Marionette enabled [task 2022-08-03T20:37:46.116Z] 20:37:46 INFO - GECKO(2916) | 1659559066115 Marionette TRACE Received observer notification final-ui-startup [task 2022-08-03T20:37:46.126Z] 20:37:46 INFO - GECKO(2916) | 1659559066124 Marionette INFO Listening on port 2828 [task 2022-08-03T20:37:46.127Z] 20:37:46 INFO - GECKO(2916) | 1659559066125 Marionette DEBUG Marionette is listening [task 2022-08-03T20:37:46.902Z] 20:37:46 INFO - GECKO(2916) | 1659559066900 Marionette DEBUG Accepted connection 0 from 127.0.0.1:41700 [task 2022-08-03T20:37:47.143Z] 20:37:47 INFO - GECKO(2916) | 1659559067142 Marionette DEBUG Closed connection 0 [task 2022-08-03T20:37:47.152Z] 20:37:47 INFO - GECKO(2916) | 1659559067151 Marionette DEBUG Accepted connection 1 from 127.0.0.1:41702 [task 2022-08-03T20:37:47.355Z] 20:37:47 INFO - GECKO(2916) | ###dholbert-logging: In SERVER_URL; lazy.allowServerURLOverride is true. Returning lazy.gServerURL: http://127.0.0.1:8888/dummy-kinto/v1 [task 2022-08-03T20:37:47.378Z] 20:37:47 INFO - GECKO(2916) | 1659559067377 Marionette DEBUG Closed connection 1 [task 2022-08-03T20:37:47.381Z] 20:37:47 INFO - GECKO(2916) | 1659559067379 Marionette DEBUG Accepted connection 2 from 127.0.0.1:41704 [task 2022-08-03T20:37:48.802Z] 20:37:48 INFO - GECKO(2916) | 1659559068800 Marionette DEBUG 2 -> [0,1,"WebDriver:NewSession",{"strictFileInteractability":true}] [task 2022-08-03T20:37:48.828Z] 20:37:48 INFO - GECKO(2916) | 1659559068826 Marionette DEBUG Waiting for initial application window [task 2022-08-03T20:37:53.090Z] 20:37:53 INFO - GECKO(2916) | console.warn: SearchSettings: "get: No settings file exists, new profile?" (new NotFoundError("Could not open the file at /tmp/tmpn9l63ksl.mozrunner/search.json.mozlz4", (void 0))) [task 2022-08-03T20:37:53.295Z] 20:37:53 INFO - GECKO(2916) | ###dholbert-logging: In SERVER_URL; lazy.allowServerURLOverride is true. Returning lazy.gServerURL: http://127.0.0.1:8888/dummy-kinto/v1 [task 2022-08-03T20:37:53.298Z] 20:37:53 INFO - GECKO(2916) | ###dholbert-logging: In SERVER_URL; lazy.allowServerURLOverride is true. Returning lazy.gServerURL: http://127.0.0.1:8888/dummy-kinto/v1 [task 2022-08-03T20:37:53.329Z] 20:37:53 INFO - GECKO(2916) | ###dholbert-logging: In SERVER_URL; lazy.allowServerURLOverride is true. Returning lazy.gServerURL: http://127.0.0.1:8888/dummy-kinto/v1 [task 2022-08-03T20:37:53.389Z] 20:37:53 INFO - GECKO(2916) | ###dholbert-logging: In SERVER_URL; lazy.allowServerURLOverride is true. Returning lazy.gServerURL: http://127.0.0.1:8888/dummy-kinto/v1 [task 2022-08-03T20:37:53.468Z] 20:37:53 INFO - GECKO(2916) | ###dholbert-logging: In SERVER_URL; lazy.allowServerURLOverride is true. Returning lazy.gServerURL: http://127.0.0.1:8888/dummy-kinto/v1 [task 2022-08-03T20:37:54.680Z] 20:37:54 INFO - GECKO(2916) | ###dholbert-logging: In SERVER_URL; lazy.allowServerURLOverride is true. Returning lazy.gServerURL: http://127.0.0.1:8888/dummy-kinto/v1 [task 2022-08-03T20:37:55.306Z] 20:37:55 INFO - GECKO(2916) | ###dholbert-logging: In SERVER_URL; lazy.allowServerURLOverride is true. Returning lazy.gServerURL: http://127.0.0.1:8888/dummy-kinto/v1 [task 2022-08-03T20:37:58.519Z] 20:37:58 INFO - GECKO(2916) | ###dholbert-logging: In SERVER_URL; lazy.allowServerURLOverride is true. Returning lazy.gServerURL: http://127.0.0.1:8888/dummy-kinto/v1 [task 2022-08-03T20:37:59.514Z] 20:37:59 INFO - GECKO(2916) | 1659559079512 Marionette TRACE Received observer notification browser-idle-startup-tasks-finished [task 2022-08-03T20:37:59.564Z] 20:37:59 INFO - GECKO(2916) | 1659559079562 RemoteAgent TRACE [24] Document already finished loading: about:blank [...] [task 2022-08-03T20:38:01.848Z] 20:38:01 INFO - *** Start BrowserChrome Test Results *** [task 2022-08-03T20:38:02.100Z] 20:38:02 INFO - checking window state [task 2022-08-03T20:38:02.277Z] 20:38:02 INFO - TEST-START | browser/components/newtab/test/browser/browser_aboutwelcome_configurable_ui.js [task 2022-08-03T20:38:03.801Z] 20:38:03 INFO - GECKO(2916) | console.debug: AboutWelcomeChild: [...] [task 2022-08-03T20:38:04.831Z] 20:38:04 INFO - GECKO(2916) | ###dholbert-logging: In SERVER_URL; lazy.allowServerURLOverride is true. Returning lazy.gServerURL: http://127.0.0.1:8888/dummy-kinto/v1 [...] [task 2022-08-03T20:41:42.661Z] 20:41:42 INFO - TEST-OK | browser/components/newtab/test/browser/browser_remote_l10n.js | took 366ms [task 2022-08-03T20:41:42.741Z] 20:41:42 INFO - checking window state [task 2022-08-03T20:41:42.809Z] 20:41:42 INFO - TEST-START | browser/components/newtab/test/browser/browser_topsites_annotation.js [task 2022-08-03T20:42:16.407Z] 20:42:16 INFO - GECKO(2916) | ###dholbert-logging: In SERVER_URL; lazy.allowServerURLOverride is true. Returning lazy.gServerURL: https://firefox.settings.services.mozilla.com/v1 [task 2022-08-03T20:42:16.486Z] 20:42:16 INFO - GECKO(2916) | FATAL ERROR: Non-local network connections are disabled and a connection attempt to firefox.settings.services.mozilla.com (18.160.225.118) was made. ``` That last SERVER_URL access (still in the same process ID) is getting a different `lazy.gServerURL` value for some reason (the problematic "real" value, `https://firefox.settings.services.mozilla.com/v1`).