Closed Bug 1846976 Opened 1 year ago Closed 7 months ago

Intermittent FATAL ERROR: Non-local network connections are disabled and a connection attempt to aus5.mozilla.org (35.244.181.201) was made. | mozilla::net::nsHttpChannel::OnStartRequest(nsIRequest*) /builds/worker/checkouts/gecko/netwerk/protocol/http/ns

Categories

(Toolkit :: Application Update, defect, P5)

defect

Tracking

()

RESOLVED INCOMPLETE

People

(Reporter: intermittent-bug-filer, Unassigned)

References

Details

(Keywords: good-first-bug, intermittent-failure, Whiteboard: [fidedi-ope])

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


[task 2023-08-03T10:15:18.241Z] 10:15:18     INFO - TEST-START | browser/components/enterprisepolicies/tests/browser/browser_policy_app_update.js
[task 2023-08-03T10:15:18.575Z] 10:15:18     INFO - GECKO(4564) | FATAL ERROR: Non-local network connections are disabled and a connection attempt to aus5.mozilla.org (35.244.181.201) was made.
[task 2023-08-03T10:15:18.575Z] 10:15:18     INFO - GECKO(4564) | 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 2023-08-03T10:15:18.576Z] 10:15:18     INFO - GECKO(4564) | ThreadSanitizer:DEADLYSIGNAL
[task 2023-08-03T10:15:18.576Z] 10:15:18     INFO - GECKO(4564) | ==4564==ERROR: ThreadSanitizer: SEGV on unknown address 0x000000000000 (pc 0x7fce38a19c05 bp 0x000000000003 sp 0x7ffc589c5e00 T4564)
[task 2023-08-03T10:15:18.576Z] 10:15:18     INFO - GECKO(4564) | ==4564==The signal is caused by a WRITE memory access.
[task 2023-08-03T10:15:18.577Z] 10:15:18     INFO - GECKO(4564) | ==4564==Hint: address points to the zero page.
[task 2023-08-03T10:15:18.919Z] 10:15:18     INFO - GECKO(4564) |     #0 MOZ_Crash /builds/worker/workspace/obj-build/dist/include/mozilla/Assertions.h:281:3 (libxul.so+0x4340c05) (BuildId: 0ea0bb28d38c66b1375b8011daf87abc8093e11c)
[task 2023-08-03T10:15:18.919Z] 10:15:18     INFO - GECKO(4564) |     #1 mozilla::net::nsHttpChannel::OnStartRequest(nsIRequest*) /builds/worker/checkouts/gecko/netwerk/protocol/http/nsHttpChannel.cpp:7035:5 (libxul.so+0x4340c05)
[task 2023-08-03T10:15:18.920Z] 10:15:18     INFO - GECKO(4564) |     #2 non-virtual thunk to mozilla::net::nsHttpChannel::OnStartRequest(nsIRequest*) /builds/worker/checkouts/gecko/netwerk/protocol/http/nsHttpChannel.cpp (libxul.so+0x4340f95) (BuildId: 0ea0bb28d38c66b1375b8011daf87abc8093e11c)
[task 2023-08-03T10:15:18.921Z] 10:15:18     INFO - GECKO(4564) |     #3 nsInputStreamPump::OnStateStart() /builds/worker/checkouts/gecko/netwerk/base/nsInputStreamPump.cpp:503:20 (libxul.so+0x3d74e2d) (BuildId: 0ea0bb28d38c66b1375b8011daf87abc8093e11c)
[task 2023-08-03T10:15:18.923Z] 10:15:18     INFO - GECKO(4564) |     #4 nsInputStreamPump::OnInputStreamReady(nsIAsyncInputStream*) /builds/worker/checkouts/gecko/netwerk/base/nsInputStreamPump.cpp:408:21 (libxul.so+0x3d74990) (BuildId: 0ea0bb28d38c66b1375b8011daf87abc8093e11c)
[task 2023-08-03T10:15:18.923Z] 10:15:18     INFO - GECKO(4564) |     #5 non-virtual thunk to nsInputStreamPump::OnInputStreamReady(nsIAsyncInputStream*) /builds/worker/checkouts/gecko/netwerk/base/nsInputStreamPump.cpp (libxul.so+0x3d75bc9) (BuildId: 0ea0bb28d38c66b1375b8011daf87abc8093e11c)
[task 2023-08-03T10:15:18.923Z] 10:15:18     INFO - GECKO(4564) |     #6 operator() /builds/worker/checkouts/gecko/xpcom/io/nsPipe3.cpp:73:47 (libxul.so+0x3b547c1) (BuildId: 0ea0bb28d38c66b1375b8011daf87abc8093e11c)
[task 2023-08-03T10:15:18.924Z] 10:15:18     INFO - GECKO(4564) |     #7 already_AddRefed<mozilla::CancelableRunnable> NS_NewCancelableRunnableFunction<CallbackHolder::CallbackHolder(nsIAsyncInputStream*, nsIInputStreamCallback*, unsigned int, nsIEventTarget*)::'lambda'()>(char const*, CallbackHolder::CallbackHolder(nsIAsyncInputStream*, nsIInputStreamCallback*, unsigned int, nsIEventTarget*)::'lambda'()&&)::FuncCancelableRunnable::Run() /builds/worker/workspace/obj-build/dist/include/nsThreadUtils.h:667:9 (libxul.so+0x3b547c1)
[task 2023-08-03T10:15:18.924Z] 10:15:18     INFO - GECKO(4564) |     #8 mozilla::RunnableTask::Run() /builds/worker/checkouts/gecko/xpcom/threads/TaskController.cpp:559:16 (libxul.so+0x3b8b802) (BuildId: 0ea0bb28d38c66b1375b8011daf87abc8093e11c)
[task 2023-08-03T10:15:18.924Z] 10:15:18     INFO - GECKO(4564) |     #9 mozilla::TaskController::DoExecuteNextTaskOnlyMainThreadInternal(mozilla::detail::BaseAutoLock<mozilla::Mutex&> const&) /builds/worker/checkouts/gecko/xpcom/threads/TaskController.cpp:886:26 (libxul.so+0x3b82113) (BuildId: 0ea0bb28d38c66b1375b8011daf87abc8093e11c)
[task 2023-08-03T10:15:18.925Z] 10:15:18     INFO - GECKO(4564) |     #10 mozilla::TaskController::ExecuteNextTaskOnlyMainThreadInternal(mozilla::detail::BaseAutoLock<mozilla::Mutex&> const&) /builds/worker/checkouts/gecko/xpcom/threads/TaskController.cpp:709:15 (libxul.so+0x3b80856) (BuildId: 0ea0bb28d38c66b1375b8011daf87abc8093e11c)
[task 2023-08-03T10:15:18.926Z] 10:15:18     INFO - GECKO(4564) |     #11 mozilla::TaskController::ProcessPendingMTTask(bool) /builds/worker/checkouts/gecko/xpcom/threads/TaskController.cpp:495:36 (libxul.so+0x3b80c4f) (BuildId: 0ea0bb28d38c66b1375b8011daf87abc8093e11c)
[task 2023-08-03T10:15:18.926Z] 10:15:18     INFO - GECKO(4564) |     #12 operator() /builds/worker/checkouts/gecko/xpcom/threads/TaskController.cpp:221:37 (libxul.so+0x3b8e727) (BuildId: 0ea0bb28d38c66b1375b8011daf87abc8093e11c)
[task 2023-08-03T10:15:18.927Z] 10:15:18     INFO - GECKO(4564) |     #13 mozilla::detail::RunnableFunction<mozilla::TaskController::TaskController()::$_1>::Run() /builds/worker/checkouts/gecko/xpcom/threads/nsThreadUtils.h:548:5 (libxul.so+0x3b8e727)
[task 2023-08-03T10:15:18.927Z] 10:15:18     INFO - GECKO(4564) |     #14 nsThread::ProcessNextEvent(bool, bool*) /builds/worker/checkouts/gecko/xpcom/threads/nsThread.cpp:1199:16 (libxul.so+0x3ba41ea) (BuildId: 0ea0bb28d38c66b1375b8011daf87abc8093e11c)
[task 2023-08-03T10:15:18.927Z] 10:15:18     INFO - GECKO(4564) |     #15 NS_ProcessNextEvent(nsIThread*, bool) /builds/worker/checkouts/gecko/xpcom/threads/nsThreadUtils.cpp:480:10 (libxul.so+0x3baa706) (BuildId: 0ea0bb28d38c66b1375b8011daf87abc8093e11c)
[task 2023-08-03T10:15:18.927Z] 10:15:18     INFO - GECKO(4564) |     #16 mozilla::ipc::MessagePump::Run(base::MessagePump::Delegate*) /builds/worker/checkouts/gecko/ipc/glue/MessagePump.cpp:107:5 (libxul.so+0x469da36) (BuildId: 0ea0bb28d38c66b1375b8011daf87abc8093e11c)
[task 2023-08-03T10:15:18.928Z] 10:15:18     INFO - GECKO(4564) |     #17 RunInternal /builds/worker/checkouts/gecko/ipc/chromium/src/base/message_loop.cc:370:10 (libxul.so+0x4617fb8) (BuildId: 0ea0bb28d38c66b1375b8011daf87abc8093e11c)
[task 2023-08-03T10:15:18.928Z] 10:15:18     INFO - GECKO(4564) |     #18 RunHandler /builds/worker/checkouts/gecko/ipc/chromium/src/base/message_loop.cc:363:3 (libxul.so+0x4617fb8)
[task 2023-08-03T10:15:18.928Z] 10:15:18     INFO - GECKO(4564) |     #19 MessageLoop::Run() /builds/worker/checkouts/gecko/ipc/chromium/src/base/message_loop.cc:345:3 (libxul.so+0x4617fb8)
[task 2023-08-03T10:15:18.929Z] 10:15:18     INFO - GECKO(4564) |     #20 nsBaseAppShell::Run() /builds/worker/checkouts/gecko/widget/nsBaseAppShell.cpp:148:27 (libxul.so+0x8452403) (BuildId: 0ea0bb28d38c66b1375b8011daf87abc8093e11c)
[task 2023-08-03T10:15:18.929Z] 10:15:18     INFO - GECKO(4564) |     #21 nsAppStartup::Run() /builds/worker/checkouts/gecko/toolkit/components/startup/nsAppStartup.cpp:295:30 (libxul.so+0xa679e12) (BuildId: 0ea0bb28d38c66b1375b8011daf87abc8093e11c)
[task 2023-08-03T10:15:18.929Z] 10:15:18     INFO - GECKO(4564) |     #22 XREMain::XRE_mainRun() /builds/worker/checkouts/gecko/toolkit/xre/nsAppRunner.cpp:5672:22 (libxul.so+0xa7ba8f4) (BuildId: 0ea0bb28d38c66b1375b8011daf87abc8093e11c)
[task 2023-08-03T10:15:18.930Z] 10:15:18     INFO - GECKO(4564) |     #23 XREMain::XRE_main(int, char**, mozilla::BootstrapConfig const&) /builds/worker/checkouts/gecko/toolkit/xre/nsAppRunner.cpp:5873:8 (libxul.so+0xa7bb53e) (BuildId: 0ea0bb28d38c66b1375b8011daf87abc8093e11c)
[task 2023-08-03T10:15:18.930Z] 10:15:18     INFO - GECKO(4564) |     #24 XRE_main(int, char**, mozilla::BootstrapConfig const&) /builds/worker/checkouts/gecko/toolkit/xre/nsAppRunner.cpp:5929:21 (libxul.so+0xa7bbc11) (BuildId: 0ea0bb28d38c66b1375b8011daf87abc8093e11c)
[task 2023-08-03T10:15:18.930Z] 10:15:18     INFO - GECKO(4564) |     #25 mozilla::BootstrapImpl::XRE_main(int, char**, mozilla::BootstrapConfig const&) /builds/worker/checkouts/gecko/toolkit/xre/Bootstrap.cpp:45:12 (libxul.so+0xa7caa62) (BuildId: 0ea0bb28d38c66b1375b8011daf87abc8093e11c)
[task 2023-08-03T10:15:18.931Z] 10:15:18     INFO - GECKO(4564) |     #26 do_main /builds/worker/checkouts/gecko/browser/app/nsBrowserApp.cpp:227:22 (firefox-bin+0x13495e) (BuildId: a0e855486f4a83c3af85044b314f3f50aae527cf)
[task 2023-08-03T10:15:18.931Z] 10:15:18     INFO - GECKO(4564) |     #27 main /builds/worker/checkouts/gecko/browser/app/nsBrowserApp.cpp:445:16 (firefox-bin+0x13495e)
[task 2023-08-03T10:15:18.931Z] 10:15:18     INFO - GECKO(4564) |     #28 __libc_start_main /tmp/glibc/csu/../csu/libc-start.c:310 (libc.so.6+0x21b96) (BuildId: 3247775c25514939b9a5ffa9d3be63f3a4cb9641)
[task 2023-08-03T10:15:18.931Z] 10:15:18     INFO - GECKO(4564) |     #29 _start <null> (firefox-bin+0x7e7f8) (BuildId: a0e855486f4a83c3af85044b314f3f50aae527cf)
[task 2023-08-03T10:15:18.932Z] 10:15:18     INFO - GECKO(4564) | ThreadSanitizer can not provide additional info.
[task 2023-08-03T10:15:18.932Z] 10:15:18     INFO - GECKO(4564) | SUMMARY: ThreadSanitizer: SEGV /builds/worker/workspace/obj-build/dist/include/mozilla/Assertions.h:281:3 in MOZ_Crash
[task 2023-08-03T10:15:18.932Z] 10:15:18     INFO - GECKO(4564) | ==4564==ABORTING
[task 2023-08-03T10:15:18.974Z] 10:15:18     INFO - GECKO(4564) | Exiting due to channel error.
[task 2023-08-03T10:15:18.974Z] 10:15:18     INFO - GECKO(4564) | Exiting due to channel error.
[task 2023-08-03T10:15:18.974Z] 10:15:18     INFO - GECKO(4564) | Exiting due to channel error.
[task 2023-08-03T10:15:18.974Z] 10:15:18     INFO - GECKO(4564) | Exiting due to channel error.
[task 2023-08-03T10:15:18.974Z] 10:15:18     INFO - GECKO(4564) | Crash Annotation GraphicsCriticalError: |[C0][GFX1-]: CompositorBridgeChild receives IPC close with reason=AbnormalShutdown (t=19.8956) Exiting due to channel error.
[task 2023-08-03T10:15:18.974Z] 10:15:18     INFO - GECKO(4564) | Exiting due to channel error.
[task 2023-08-03T10:15:18.975Z] 10:15:18     INFO - GECKO(4564) | Crash Annotation GraphicsCriticalError: |[C0][GFX1-]: CompositorBridgeChild receives IPC close with reason=AbnormalShutdown (t=17.5024) Crash Annotation GraphicsCriticalError: |[C0][GFX1-]: CompositorBridgeChild receives IPC close with reason=AbnormalShutdown (t=18.0773) Exiting due to channel error.
[task 2023-08-03T10:15:19.992Z] 10:15:19     INFO - GECKO(4564) | Crash Annotation GraphicsCriticalError: |[C0][GFX1-]: CompositorBridgeChild receives IPC close with reason=AbnormalShutdown (t=27.404) Crash Annotation GraphicsCriticalError: |[C0][GFX1-]: CompositorBridgeChild receives IPC close with reason=AbnormalShutdown (t=28.1332)
[task 2023-08-03T10:15:19.993Z] 10:15:19     INFO - TEST-INFO | Main app process: killed by SIGIOT
[task 2023-08-03T10:15:19.993Z] 10:15:19     INFO - Buffered messages logged at 10:15:18
[task 2023-08-03T10:15:19.993Z] 10:15:19     INFO - Entering setup bound policies_headjs_startWithCleanSlate
[task 2023-08-03T10:15:19.994Z] 10:15:19     INFO - TEST-PASS | browser/components/enterprisepolicies/tests/browser/browser_policy_app_update.js | Engine is inactive at the start of the test - 
[task 2023-08-03T10:15:19.994Z] 10:15:19     INFO - Leaving setup bound policies_headjs_startWithCleanSlate
[task 2023-08-03T10:15:19.995Z] 10:15:19     INFO - Entering test bound test_updates_pre_policy
[task 2023-08-03T10:15:19.995Z] 10:15:19     INFO - TEST-PASS | browser/components/enterprisepolicies/tests/browser/browser_policy_app_update.js | Since no policies have been set, appUpdate should be allowed by default - 
[task 2023-08-03T10:15:19.997Z] 10:15:19     INFO - TEST-PASS | browser/components/enterprisepolicies/tests/browser/browser_policy_app_update.js | Should be able to check for updates before any policies are in effect. - 
[task 2023-08-03T10:15:19.997Z] 10:15:19     INFO - Leaving test bound test_updates_pre_policy
[task 2023-08-03T10:15:19.997Z] 10:15:19     INFO - TEST-PASS | browser/components/enterprisepolicies/tests/browser/browser_policy_app_update.js | Engine is inactive at the end of the test - 
[task 2023-08-03T10:15:19.997Z] 10:15:19     INFO - Buffered messages finished
[task 2023-08-03T10:15:19.997Z] 10:15:19     INFO - runtests.py | Application ran for: 0:00:34.540988

Not sure why we're seeing a bunch of these assertions related to updates recently.
Either this is some bad state from browser_policy_app_auto_update.js that ran before, or this line isn't working properly:
https://searchfox.org/mozilla-central/rev/503938c13ef2dd174705dc0f6d0683ae43074ccc/browser/components/enterprisepolicies/tests/browser/browser_policy_app_update.js#21

await UpdateUtils.setAppUpdateAutoEnabled(false);

Or maybe this is actually the same as 1754363? 🤷
At worst, we could add a DNS override for aus5.mozilla.org to 127.0.0.1 like we do in other places

Component: Networking: HTTP → Application Update
Product: Core → Toolkit
See Also: → 1754363

I see that I wrote this test, but I'm not sure that it's written correctly. It seems to be concerned (correctly) with not applying an update. But it doesn't seem to be all that concerned with checking for an update, which would still hit the network. Probably this test needs to override the update URL so that this doesn't happen.

We have a bunch of good examples of changing the update URL in testing (for example). This should be easy to fix.

Keywords: good-first-bug
Whiteboard: [fidedi-ope]

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

We have a bunch of good examples of changing the update URL in testing (for example). This should be easy to fix.

This is interesting! Should we actually do that for Marionette and Remote Agent by default? Tests that actually need the real URL might have to reset it. It would not solve all the issues with bug 1754363 but would be a good start. What do you think?

Flags: needinfo?(bytesized)

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

This is interesting! Should we actually do that for Marionette and Remote Agent by default? Tests that actually need the real URL might have to reset it. It would not solve all the issues with bug 1754363 but would be a good start. What do you think?

I'm not super keen on this, but I'm also not totally opposed to it. These are the concerns that come to mind:

  • We would effectively be disabling updates in two separate ways, which seems confusing, especially to people not deeply steeped in Application Update and/or Marionette.
  • I don't generally love disabling update in a way that has to be done at runtime (rather than prior to application launch). Though rereading our conversation in Bug 1754363, I guess that is kind of already the case in this test configuration.
  • I don't know of any good way to check if the update URL has been changed this way, which I don't love for something that would essentially be happening implicitly.
  • The mechanism that I know of for doing this replaces the entirety of Services.appinfo. I don't know of any ways that the replacement appinfo differs from the original (other than the update URL change), but maybe some subtle differences exist? Potentially this could cause problems for some tests. I'm also not sure if any other tests override appinfo this way and if there are any problems making a copy of a copy.
Flags: needinfo?(bytesized)

Ok, that sounds risky so lets drop that idea. Maybe the best might then be to update the related test as mentioned above to make use of that local URL. Or does it fail before Marionette is ready during startup or after it has been disabled during shutdown? This is not possible to see in the log files. To know about that trace logging (preference "remote.log.level = Trace") should be enabled.

I suspect that we are checking for an update right after app.update.disabledForTesting is turned off. But I don't really have evidence for that. It just seems likely that a test that turns off the pref preventing it from checking for updates is accessing the update check URL as a result of that.

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

Or does it fail before Marionette is ready during startup or after it has been disabled during shutdown?

I believe that this is a browser-chrome mochitest, not a Marionette test. I don't think Marionette being ready or disabled factors into it.

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

Or does it fail before Marionette is ready during startup or after it has been disabled during shutdown?

I believe that this is a browser-chrome mochitest, not a Marionette test. I don't think Marionette being ready or disabled factors into it.

Right, but note that Marionette is used for Mochitest to bootstrap the harness (installing both the mochitest and special powers addons). As such there might be side-effects.

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