1881586 - Intermittent MOZ_ASSERT(!mInitialized) (UnloadModules() was not explicitly called before cleaning up mozJSModuleLoader) [@ mozJSModuleLoader::~mozJSModuleLoader] | single tracking bug

Status: RESOLVED FIXED

(Core :: XPConnect, defect, P5)

Description

[Treeherder Bug Filer]

Filed by: mkmelin [at] iki.fi
Parsed log: https://treeherder.mozilla.org/logviewer?job_id=448092985&repo=comm-central
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/Xkc-oIXQTTOVxIzBajxFzQ/runs/0/artifacts/public/logs/live_backing.log

---

Comment 1

[Andrew McCreight [:mccr8]]

arai, possibly a regression from your recent module loader changes? This Thunderbird test might be doing something weird with loading modules.

Comment 2

[Tooru Fujisawa [:arai]]

The assertion is the following one:

https://searchfox.org/mozilla-central/rev/da49863c3d6f34038d00f5ba701b9a2ad9cbadba/js/xpconnect/loader/mozJSModuleLoader.cpp#419-422

mozJSModuleLoader::~mozJSModuleLoader() {
  MOZ_ASSERT(!mInitialized,
             "UnloadModules() was not explicitly called before cleaning up "
             "mozJSModuleLoader");

And the stack means it's either sSelf or sDevToolsLoader:

https://searchfox.org/mozilla-central/rev/da49863c3d6f34038d00f5ba701b9a2ad9cbadba/js/xpconnect/loader/mozJSModuleLoader.cpp#484,487,489,491

void mozJSModuleLoader::ShutdownLoaders() {
...
  sSelf = nullptr;
...
  if (sDevToolsLoader) {
...
    sDevToolsLoader = nullptr;

which is called in the following path:

1. mozilla::ShutdownXPCOM
2. nsComponentManagerImpl::Shutdown
3. mozilla::xpcom::StaticComponents::Shutdown
4. mozilla::xpcom::CallUnloadFuncs
5. nsLayoutModuleDtor
6. xpcModuleDtor
7. nsXPConnect::ReleaseXPConnectSingleton
8. mozJSModuleLoader::ShutdownLoaders

Then, those module loaders are unloaded by mozJSModuleLoader::UnloadLoaders immediately before nsComponentManagerImpl::Shutdown call in mozilla::ShutdownXPCOM:

https://searchfox.org/mozilla-central/rev/da49863c3d6f34038d00f5ba701b9a2ad9cbadba/xpcom/build/XPCOMInit.cpp#584,693,719-721

nsresult ShutdownXPCOM(nsIServiceManager* aServMgr) {
...
  mozJSModuleLoader::UnloadLoaders();
...
  if (nsComponentManagerImpl::gComponentManager) {
    DebugOnly<nsresult> rv =
        (nsComponentManagerImpl::gComponentManager)->Shutdown();

and mInitialized should be set to false inside mozJSModuleLoader::UnloadLoaders:

https://searchfox.org/mozilla-central/rev/da49863c3d6f34038d00f5ba701b9a2ad9cbadba/js/xpconnect/loader/mozJSModuleLoader.cpp#466-468,470-471

void mozJSModuleLoader::UnloadLoaders() {
  if (sSelf) {
    sSelf->Unload();
...
  if (sDevToolsLoader) {
    sDevToolsLoader->Unload();

https://searchfox.org/mozilla-central/rev/da49863c3d6f34038d00f5ba701b9a2ad9cbadba/js/xpconnect/loader/mozJSModuleLoader.cpp#475-476

void mozJSModuleLoader::Unload() {
  UnloadModules();

https://searchfox.org/mozilla-central/rev/da49863c3d6f34038d00f5ba701b9a2ad9cbadba/js/xpconnect/loader/mozJSModuleLoader.cpp#1281-1282

void mozJSModuleLoader::UnloadModules() {
  mInitialized = false;

So, possible reason for the assertion failure is that mInitialized is set to true again after unload, by calling the following functions between mozJSModuleLoader::UnloadLoaders and mozJSModuleLoader::ShutdownLoaders:

• mozJSModuleLoader::IsModuleLoaded
• mozJSModuleLoader::IsJSModuleLoaded
• mozJSModuleLoader::IsESModuleLoaded
• mozJSModuleLoader::Import
• mozJSModuleLoader::ImportESModule

I'll test with some more assertions added.

Comment 3

[Tooru Fujisawa [:arai]]

https://treeherder.mozilla.org/jobs?repo=try-comm-central&revision=61c2076e15e33a23ef83db70a330553649dcd4e0&searchStr=test-linux1804-64-qr%2Fdebug-mochitest-thunderbird&group_state=expanded&selectedTaskRun=bgbQvnupRemnfXMU01fyug.0

it happens inside nsCycleCollector_shutdown.

https://searchfox.org/mozilla-central/rev/da49863c3d6f34038d00f5ba701b9a2ad9cbadba/xpcom/build/XPCOMInit.cpp#584,693,706,719-721

nsresult ShutdownXPCOM(nsIServiceManager* aServMgr) {
...
  mozJSModuleLoader::UnloadLoaders();
...
  nsCycleCollector_shutdown(shutdownCollect);
...
  if (nsComponentManagerImpl::gComponentManager) {
    DebugOnly<nsresult> rv =
        (nsComponentManagerImpl::gComponentManager)->Shutdown();

with the following stack:

#01: mozJSModuleLoader::IsESModuleLoaded(nsTSubstring<char> const&, bool*) [js/xpconnect/loader/mozJSModuleLoader.cpp:1435]
#02: nsXPCComponents_Utils::IsESModuleLoaded(nsTSubstring<char> const&, bool*) [js/xpconnect/src/XPCComponents.cpp:1574]
#03: ??? [/builds/worker/workspace/build/application/thunderbird/libxul.so + 0x38d11b6]
#04: CallMethodHelper::Call() [js/xpconnect/src/XPCWrappedNative.cpp:1174]
#05: XPCWrappedNative::CallMethod(XPCCallContext&, XPCWrappedNative::CallMode) [js/xpconnect/src/XPCWrappedNative.cpp:1120]
#06: XPC_WN_CallMethod(JSContext*, unsigned int, JS::Value*) [js/xpconnect/src/XPCWrappedNativeJSOps.cpp:966]
#07: CallJSNative(JSContext*, bool (*)(JSContext*, unsigned int, JS::Value*), js::CallReason, JS::CallArgs const&) [js/src/vm/Interpreter.cpp:480]
#08: js::InternalCallOrConstruct(JSContext*, JS::CallArgs const&, js::MaybeConstruct, js::CallReason) [js/src/vm/Interpreter.cpp:574]
#09: js::Interpret(JSContext*, js::RunState&) [js/src/vm/Interpreter.cpp:3061]
#10: js::RunScript(JSContext*, js::RunState&) [js/src/vm/Interpreter.cpp:452]
#11: js::InternalCallOrConstruct(JSContext*, JS::CallArgs const&, js::MaybeConstruct, js::CallReason) [js/src/vm/Interpreter.cpp:606]
#12: js::Call(JSContext*, JS::Handle<JS::Value>, JS::Handle<JS::Value>, js::AnyInvokeArgs const&, JS::MutableHandle<JS::Value>, js::CallReason) [js/src/vm/Interpreter.cpp:673]
#13: js::CallGetter(JSContext*, JS::Handle<JS::Value>, JS::Handle<JS::Value>, JS::MutableHandle<JS::Value>) [js/src/vm/Interpreter.cpp:796]
#14: GetExistingProperty<(js::AllowGC)1>(JSContext*, js::MaybeRooted<JS::Value, (js::AllowGC)1>::HandleType, js::MaybeRooted<js::NativeObject*, (js::AllowGC)1>::HandleType, js::MaybeRooted<JS::PropertyKey, (js::AllowGC)1>::HandleType, js::PropertyInfoBase<unsigned int>, js::MaybeRooted<JS::Value, (js::AllowGC)1>::MutableHandleType) [js/src/vm/NativeObject.cpp:2159]
#15: NativeGetPropertyInline<(js::AllowGC)1>(JSContext*, js::MaybeRooted<js::NativeObject*, (js::AllowGC)1>::HandleType, js::MaybeRooted<JS::Value, (js::AllowGC)1>::HandleType, js::MaybeRooted<JS::PropertyKey, (js::AllowGC)1>::HandleType, IsNameLookup, js::MaybeRooted<JS::Value, (js::AllowGC)1>::MutableHandleType) [js/src/vm/NativeObject.cpp:2333]
#16: js::GetProperty(JSContext*, JS::Handle<JSObject*>, JS::Handle<JS::Value>, js::PropertyName*, JS::MutableHandle<JS::Value>) [js/src/vm/ObjectOperations-inl.h:125]
#17: js::GetProperty(JSContext*, JS::Handle<JS::Value>, JS::Handle<js::PropertyName*>, JS::MutableHandle<JS::Value>) [js/src/vm/Interpreter.cpp:4512]
#18: js::Interpret(JSContext*, js::RunState&) [js/src/vm/Interpreter.cpp:2716]
#19: js::RunScript(JSContext*, js::RunState&) [js/src/vm/Interpreter.cpp:452]
#20: js::InternalCallOrConstruct(JSContext*, JS::CallArgs const&, js::MaybeConstruct, js::CallReason) [js/src/vm/Interpreter.cpp:606]
#21: js::Call(JSContext*, JS::Handle<JS::Value>, JS::Handle<JS::Value>, js::AnyInvokeArgs const&, JS::MutableHandle<JS::Value>, js::CallReason) [js/src/vm/Interpreter.cpp:673]
#22: JS::Call(JSContext*, JS::Handle<JS::Value>, JS::Handle<JS::Value>, JS::HandleValueArray const&, JS::MutableHandle<JS::Value>) [js/src/vm/CallAndConstruct.cpp:119]
#23: mozilla::dom::EventListener::HandleEvent(mozilla::dom::BindingCallContext&, JS::Handle<JS::Value>, mozilla::dom::Event&, mozilla::ErrorResult&) [s3:gecko-generated-sources-l1:6abfc13115b948309184a7e9ce543dc15ead92ad0e3ca71d0317d30e904bb6ec61f75c018d28aff86d703b76fb4e3f03c2b28e269b262119a2f0a86ea09bf0f4/dom/bindings/EventListenerBinding.cpp::62]
#24: mozilla::dom::EventListener::HandleEvent<mozilla::dom::EventTarget*>(mozilla::dom::EventTarget* const&, mozilla::dom::Event&, mozilla::ErrorResult&, char const*, mozilla::dom::CallbackObject::ExceptionHandling, JS::Realm*) [s3:gecko-generated-sources-l1:6ce01df723388c944dad872d465a7cef8b44b4d3c95ccae2972f258a811379269fccf96b88cd4c7252bb87b4ea9473f0a2e8c3b62fc0f2dc052db9b0dfb08f70/dist/include/mozilla/dom/EventListenerBinding.h::0]
#25: mozilla::EventListenerManager::HandleEventSingleListener(mozilla::EventListenerManager::Listener*, nsAtom*, mozilla::WidgetEvent*, mozilla::dom::Event*, mozilla::dom::EventTarget*, bool) [dom/events/EventListenerManager.cpp:1342]
#26: mozilla::EventListenerManager::HandleEventWithListenerArray(mozilla::EventListenerManager::ListenerArray*, nsAtom*, mozilla::EventMessage, nsPresContext*, mozilla::WidgetEvent*, mozilla::dom::Event**, mozilla::dom::EventTarget*, bool) [dom/events/EventListenerManager.cpp:1661]
#27: mozilla::EventListenerManager::HandleEventInternal(nsPresContext*, mozilla::WidgetEvent*, mozilla::dom::Event**, mozilla::dom::EventTarget*, nsEventStatus*, bool) [dom/events/EventListenerManager.cpp:1558]
#28: mozilla::EventTargetChainItem::HandleEvent(mozilla::EventChainPostVisitor&, mozilla::ELMCreationDetector&) [dom/events/EventDispatcher.cpp:367]
#29: mozilla::EventTargetChainItem::HandleEventTargetChain(nsTArray<mozilla::EventTargetChainItem>&, mozilla::EventChainPostVisitor&, mozilla::EventDispatchingCallback*, mozilla::ELMCreationDetector&) [dom/events/EventDispatcher.cpp:608]
#30: mozilla::EventTargetChainItem::HandleEventTargetChain(nsTArray<mozilla::EventTargetChainItem>&, mozilla::EventChainPostVisitor&, mozilla::EventDispatchingCallback*, mozilla::ELMCreationDetector&) [dom/events/EventDispatcher.cpp:687]
#31: mozilla::EventDispatcher::Dispatch(mozilla::dom::EventTarget*, nsPresContext*, mozilla::WidgetEvent*, mozilla::dom::Event*, nsEventStatus*, mozilla::EventDispatchingCallback*, nsTArray<mozilla::dom::EventTarget*>*) [dom/events/EventDispatcher.cpp:0]
#32: nsDocumentViewer::PageHide(bool) [layout/base/nsDocumentViewer.cpp:1372]
#33: nsDocShell::FirePageHideNotificationInternal(bool, bool) [docshell/base/nsDocShell.cpp:1224]
#34: nsDocShell::Destroy() [docshell/base/nsDocShell.cpp:4444]
#35: nsWebBrowser::SetDocShell(nsDocShell*) [toolkit/components/browser/nsWebBrowser.cpp:1155]
#36: nsWebBrowser::InternalDestroy() [toolkit/components/browser/nsWebBrowser.cpp:177]
#37: {virtual override thunk({offset(-24)}, nsWebBrowser::Destroy())} [toolkit/components/browser/nsWebBrowser.cpp:0]
#38: BrowserDestroyer::Destroy(nsIWebBrowser*) [xpfe/appshell/nsAppShellService.cpp:298]
#39: nsContentUtils::AddScriptRunner(already_AddRefed<nsIRunnable>) [dom/base/nsContentUtils.cpp:6198]
#40: WindowlessBrowser::~WindowlessBrowser() [xpfe/appshell/nsAppShellService.cpp:346]
#41: WindowlessBrowser::Release() [xpfe/appshell/nsAppShellService.cpp:358]
#42: mozilla::SegmentedVector<nsCOMPtr<nsISupports>, (unsigned long)4096, mozilla::MallocAllocPolicy>::PopLastN(unsigned int) [mfbt/SegmentedVector.h:253]
#43: mozilla::dom::DeferredFinalizerImpl<nsISupports>::DeferredFinalize(unsigned int, void*) [dom/bindings/BindingUtils.h:2784]
#44: mozilla::IncrementalFinalizeRunnable::ReleaseNow(bool) [xpcom/base/CycleCollectedJSRuntime.cpp:1678]
#45: mozilla::CycleCollectedJSRuntime::FinalizeDeferredThings(mozilla::CycleCollectedJSRuntime::DeferredFinalizeType) [xpcom/base/CycleCollectedJSRuntime.cpp:1759]
#46: mozilla::CycleCollectedJSRuntime::OnGC(JSContext*, JSGCStatus, JS::GCReason) [xpcom/base/CycleCollectedJSRuntime.cpp:1853]
#47: js::gc::GCRuntime::maybeCallGCCallback(JSGCStatus, JS::GCReason) [js/src/gc/GC.cpp:4225]
#48: js::gc::GCRuntime::gcCycle(bool, js::SliceBudget const&, JS::GCReason) [js/src/gc/GC.cpp:4313]
#49: js::gc::GCRuntime::collect(bool, js::SliceBudget const&, JS::GCReason) [js/src/gc/GC.cpp:4498]
#50: js::gc::GCRuntime::gc(JS::GCOptions, JS::GCReason) [js/src/gc/GC.cpp:4576]
#51: JS::NonIncrementalGC(JSContext*, JS::GCOptions, JS::GCReason) [js/src/gc/GCAPI.cpp:300]
#52: nsCycleCollector::FixGrayBits(bool, TimeLog&) [xpcom/base/nsCycleCollector.cpp:3335]
#53: nsCycleCollector::BeginCollection(mozilla::CCReason, ccIsManual, nsICycleCollectorListener*) [xpcom/base/nsCycleCollector.cpp:3643]
#54: nsCycleCollector::Collect(mozilla::CCReason, ccIsManual, js::SliceBudget&, nsICycleCollectorListener*, bool) [xpcom/base/nsCycleCollector.cpp:0]
#55: nsCycleCollector::ShutdownCollect() [xpcom/base/nsCycleCollector.cpp:3410]
#56: nsCycleCollector::Shutdown(bool) [xpcom/base/nsCycleCollector.cpp:3712]
#57: nsCycleCollector_shutdown(bool) [xpcom/base/nsCycleCollector.cpp:4034]
#58: mozilla::ShutdownXPCOM(nsIServiceManager*) [xpcom/build/XPCOMInit.cpp:710]
#59: ScopedXPCOMStartup::~ScopedXPCOMStartup() [toolkit/xre/nsAppRunner.cpp:1972]
#60: XREMain::XRE_main(int, char**, mozilla::BootstrapConfig const&) [toolkit/xre/nsAppRunner.cpp:5961]
#61: XRE_main(int, char**, mozilla::BootstrapConfig const&) [toolkit/xre/nsAppRunner.cpp:5997]
#62: ??? [/builds/worker/workspace/build/application/thunderbird/thunderbird + 0x3b173]
#63: __libc_start_main [/lib/x86_64-linux-gnu/libc.so.6 + 0x21b97]
#64: ??? [/builds/worker/workspace/build/application/thunderbird/thunderbird + 0x3add9]
#65: ??? (???:???)

So, there's something that touches module loader during CC shutdown.
I'll check the details, but if it's really necessary, simple option would be to fix the Is*ModuleLoaded methods to return false after unload.

Comment 4

[Tooru Fujisawa [:arai]]

So, it's custom element's unload event handler.

https://treeherder.mozilla.org/jobs?repo=try-comm-central&group_state=expanded&revision=e8689be4bd94cf45314b072b26e11447a08c87de&searchStr=test-linux1804-64-qr%2Fdebug-mochitest-thunderbird&selectedTaskRun=RUlLbD72R4W2NaJ48syyqw.0

https://searchfox.org/mozilla-central/rev/da49863c3d6f34038d00f5ba701b9a2ad9cbadba/toolkit/content/widgets/browser-custom-element.js#78-82

window.addEventListener(
  "unload",
  () => {
    for (let element of elementsToDestroyOnUnload.values()) {
      element.destroy();

https://searchfox.org/mozilla-central/rev/da49863c3d6f34038d00f5ba701b9a2ad9cbadba/toolkit/content/widgets/browser-custom-element.js#1072-1080

destroy() {
  elementsToDestroyOnUnload.delete(this);

  // If we're browsing from the tab crashed UI to a URI that causes the tab
  // to go remote again, we catch this here, because swapping out the
  // non-remote browser for a remote one doesn't cause the pagehide event
  // to be fired. Previously, we used to do this in the frame script's
  // unload handler.
  lazy.SessionStore?.maybeExitCrashedState(this);

https://searchfox.org/mozilla-central/rev/da49863c3d6f34038d00f5ba701b9a2ad9cbadba/toolkit/content/widgets/browser-custom-element.js#60-64

Object.defineProperty(lazy, "SessionStore", {
  configurable: true,
  get() {
    const kURL = "resource:///modules/sessionstore/SessionStore.sys.mjs";
    if (Cu.isESModuleLoaded(kURL)) {

the event handler is called during CC shutdown, and it touches module loader with Cu.isESModuleLoaded and possibly ChromeUtils.importESModule. Which means, just returning false from Cu.isESModuleLoaded is not sufficient, but ChromeUtils.importESModule should throw,
and also the consumer there should catch the exception. (I misread the code. ChromeUtils.importESModule is not called Cu.isESModuleLoaded returns false. but there are other access to lazy object in destroy method)

Comment 5

[Tooru Fujisawa [:arai]]

The other options is to move the mozJSModuleLoader::UnloadLoaders call after nsCycleCollector_shutdown, or maybe duplicate the call there,
so that the module loader gets unloaded again even if it's re-initialized during CC shutdown.

Then, more import question would be, whether this situation is really supposed to happen in the first place.

If nsCycleCollector_shutdown can run arbitrary JS, such as unload event handler for window-less browser in this case,
I wonder if we should enforce one of the following:

• nothing gets cleaned up before it
• such event handler shouldn't touch things that can already be cleaned up (maybe detect shutdown and then do nothing)
• such event handler should expect things already cleaned up and handle all errors

Or maybe just prevent running arbitrary JS code during nsCycleCollector_shutdown ?

(the another minor question would be whether custom-elements should be loaded into window-less browser, but it would be for separate bug)

:mccr8, can I have your opinion?

Comment 6

[Intermittent Failures Robot]

1 failures in 3382 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• comm-central: 1

Platform and build breakdown:

• linux1804-64-qr: 1
  • debug: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1881586&startday=2024-02-19&endday=2024-02-25&tree=all

Comment 7

[Intermittent Failures Robot]

5 failures in 4052 pushes (0.001 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• comm-central: 5

Platform and build breakdown:

• macosx1015-64-qr: 1
  • opt: 1
• linux1804-64-qr: 2
  • debug: 2
• windows11-32-2009-qr: 1
  • debug: 1
• windows11-64-2009-qr: 1
  • debug: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1881586&startday=2024-02-26&endday=2024-03-03&tree=all

Comment 8

[Andrew McCreight [:mccr8]]

Sorry, I missed your question there. It feels like a bad idea to have these "is module loaded" things making the module loader get reinitialized. Returning false makes sense to me.

Running random JS during CC shutdown is kind of gross, although it looks like it is not the CC per se. Instead, we're running a sync GC before we do the CC, and then the finalizer for an object we're destroying is running JS. I don't think we will be able to avoid that. Maybe it doesn't make sense to be running page hide this late in shutdown.

Comment 9

[Tooru Fujisawa [:arai]]

Thanks!
I'll make the module loader methods no-op after unload, and I'll leave the events during shutdown to followup bug.

Comment 10

[Intermittent Failures Robot]

1 failures in 4198 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• comm-central: 1

Platform and build breakdown:

• linux1804-64-qr: 1
  • debug: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1881586&startday=2024-03-04&endday=2024-03-10&tree=all

Comment 11

[Intermittent Failures Robot]

2 failures in 3849 pushes (0.001 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• comm-central: 2

Platform and build breakdown:

• linux1804-64-qr: 2
  • debug: 2

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1881586&startday=2024-03-11&endday=2024-03-17&tree=all

Comment 12

[Tooru Fujisawa [:arai]]

Attachment: Bug 1881586 - Do not re-initialize system module loader after unload. r?mccr8!

Comment 13

[Intermittent Failures Robot]

1 failures in 3791 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• comm-central: 1

Platform and build breakdown:

• linux1804-64-qr: 1
  • debug: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1881586&startday=2024-03-18&endday=2024-03-24&tree=all

Comment 14

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/c271424cd784
Do not re-initialize system module loader after unload. r=mccr8

Comment 15

[Atila Butkovits]

https://hg.mozilla.org/mozilla-central/rev/c271424cd784