1631137 - Crash in [@ [INFO] mozilla.components.feature.addons.AddonManagerException: at mozilla.components.feature.addons.AddonManager.getAddons(AddonManager.kt:57)]

Status: RESOLVED FIXED

(GeckoView :: Extensions, defect, P1)

Description

[[ex-Mozilla] Agi Sferro | :agi]

This bug is for crash report bp-5ce7a02f-f02b-45a2-b4d5-597a70200417.

Java stack trace:

[INFO] mozilla.components.feature.addons.AddonManagerException
	at mozilla.components.feature.addons.AddonManager.getAddons(AddonManager.kt:57)
	at mozilla.components.feature.addons.AddonManager$getAddons$1.invokeSuspend(Unknown Source:12)
	at kotlin.coroutines.jvm.internal.BaseContinuationImpl.resumeWith(ContinuationImpl.kt:2)
	at kotlinx.coroutines.DispatchedTask.run(DispatchedTask.kt:18)
	at kotlinx.coroutines.scheduling.CoroutineScheduler.runSafely(CoroutineScheduler.kt:1)
	at kotlinx.coroutines.scheduling.CoroutineScheduler$Worker.run(CoroutineScheduler.kt:14)

Comment 1

[[ex-Mozilla] Agi Sferro | :agi]

Message:

[INFO] mozilla.components.feature.addons.AddonManagerException: java.lang.Exception: Unexpected error: TypeError: can't access property "choices", ns.get(...) is undefined

Looks like a regression from Bug 1622917. Shane do you have an idea of could be going on here?

Comment 2

[Shane Caraveo (:mixedpuppy)]

You're probably accessing schema before it is loaded. I had the same issue in a test i just wrote. See the comment in the setup function.

https://phabricator.services.mozilla.com/D71231

Comment 3

[Shane Caraveo (:mixedpuppy)]

Essentially, schemas are lazy loaded to avoid a startup penalty.

https://searchfox.org/mozilla-central/rev/aec63591821712236a522f7f55116f582ed7c920/toolkit/components/extensions/Extension.jsm#847

Comment 4

[Arturo Mejia [:amejia]]

Below the logcat after simulating the issue.
We are seeing this after disabling an add-on with webExtensionController.disable with EnableSource#APP and then restarting the app and trying to call runtime.webExtensionController.list(). We tested using dark reader. Also Christian mentioned: the issue could be related to the schema migration. You migrate the schema the first time you need to, this may or may not finish before we call list, when it doesn't finish in time list fails, but then the next startup is fine again because the schema was migrated.

2020-04-17 19:17:18.754 26973-26973/? E/lla.fenix.debu: Unknown bits set in runtime_flags: 0x8000
2020-04-17 19:17:20.325 26973-27033/org.mozilla.fenix.debug E/GeckoLibLoad: Load sqlite start
2020-04-17 19:17:20.328 26973-27033/org.mozilla.fenix.debug E/GeckoLibLoad: Load sqlite done
2020-04-17 19:17:20.328 26973-27033/org.mozilla.fenix.debug E/GeckoLibLoad: Load nss start
2020-04-17 19:17:20.328 26973-27033/org.mozilla.fenix.debug E/GeckoLibLoad: Load nss done
2020-04-17 19:17:20.354 26973-27033/org.mozilla.fenix.debug E/GeckoLibLoad: Loaded libs in 25.111201ms total, 6ms(46ms) user, 13ms(13ms) system, 1(1) faults
2020-04-17 19:17:21.134 26973-27061/org.mozilla.fenix.debug E/libc: Access denied finding property "vendor.gralloc.disable_ahardware_buffer"
2020-04-17 19:17:21.230 26973-27033/org.mozilla.fenix.debug E/GeckoConsole: [JavaScript Error: "Schema loaded after root schema populated" {file: "resource://gre/modules/Schemas.jsm" line: 3497}]
    addSchema@resource://gre/modules/Schemas.jsm:3497:13
    load@resource://gre/modules/Schemas.jsm:3528:12
2020-04-17 19:17:21.231 26973-27033/org.mozilla.fenix.debug E/GeckoConsole: [JavaScript Error: "Schema loaded after root schema populated" {file: "resource://gre/modules/Schemas.jsm" line: 3497}]
    addSchema@resource://gre/modules/Schemas.jsm:3497:13
    load@resource://gre/modules/Schemas.jsm:3528:12
2020-04-17 19:17:21.231 26973-27033/org.mozilla.fenix.debug E/GeckoConsole: [JavaScript Error: "Schema loaded after root schema populated" {file: "resource://gre/modules/Schemas.jsm" line: 3497}]
    addSchema@resource://gre/modules/Schemas.jsm:3497:13
    load@resource://gre/modules/Schemas.jsm:3528:12
2020-04-17 19:17:21.264 26973-26973/org.mozilla.fenix.debug E/mozac-webextensions: Failed to query installed extension
    java.lang.Exception: Unexpected error: TypeError: can't access property "choices", ns.get(...) is undefined
        at org.mozilla.geckoview.CallbackResult.sendError(CallbackResult.java:14)
        at org.mozilla.gecko.EventDispatcher$JavaCallbackDelegate$1.run(EventDispatcher.java:454)
        at android.os.Handler.handleCallback(Handler.java:883)
        at android.os.Handler.dispatchMessage(Handler.java:100)
        at android.os.Looper.loop(Looper.java:214)
        at android.app.ActivityThread.main(ActivityThread.java:7356)
        at java.lang.reflect.Method.invoke(Native Method)
        at com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run(RuntimeInit.java:492)
        at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:930)
2020-04-17 19:17:21.265 26973-26973/org.mozilla.fenix.debug E/mozac-webcompat: Failed to install WebCompat webextension: [e-mail]
    java.lang.Exception: An error occurred while registering the WebExtension resource://android/assets/extensions/webcompat/: Error: Schema loaded after root schema populated.
        at org.mozilla.geckoview.CallbackResult.sendError(CallbackResult.java:14)
        at org.mozilla.gecko.EventDispatcher$JavaCallbackDelegate$1.run(EventDispatcher.java:454)
        at android.os.Handler.handleCallback(Handler.java:883)
        at android.os.Handler.dispatchMessage(Handler.java:100)
        at android.os.Looper.loop(Looper.java:214)
        at android.app.ActivityThread.main(ActivityThread.java:7356)
        at java.lang.reflect.Method.invoke(Native Method)
        at com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run(RuntimeInit.java:492)
        at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:930)
2020-04-17 19:17:21.266 26973-26973/org.mozilla.fenix.debug E/App: Could not install browser-icons extension
    java.lang.Exception: An error occurred while registering the WebExtension resource://android/assets/extensions/browser-icons/: Error: Schema loaded after root schema populated.
        at org.mozilla.geckoview.CallbackResult.sendError(CallbackResult.java:14)
        at org.mozilla.gecko.EventDispatcher$JavaCallbackDelegate$1.run(EventDispatcher.java:454)
        at android.os.Handler.handleCallback(Handler.java:883)
        at android.os.Handler.dispatchMessage(Handler.java:100)
        at android.os.Looper.loop(Looper.java:214)
        at android.app.ActivityThread.main(ActivityThread.java:7356)
        at java.lang.reflect.Method.invoke(Native Method)
        at com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run(RuntimeInit.java:492)
        at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:930)

Comment 5

[[ex-Mozilla] Agi Sferro | :agi]

Attachment: Bug 1631137 - Wait for Schema to be initialized in shouldPromptFor.

Comment 6

[[ex-Mozilla] Agi Sferro | :agi]

Attachment: Bug 1631137 - Add APP to EnableSources.

Comment 7

[[ex-Mozilla] Agi Sferro | :agi]

This is really bad on nightly, I pretty much cannot use extensions now that I reproduced it.

To reproduce on Fenix

• Have at least an extension installed
• Disable all extensions (NOT uninstall)
• restart the browser
• open addon manager

after a while you'll see an error going to the addon manager and all your addons cannot run anymore.

Comment 8

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/ae2354fc485e
Wait for Schema to be initialized in shouldPromptFor. r=esawin,mixedpuppy
https://hg.mozilla.org/integration/autoland/rev/004dc47cf853
Add APP to EnableSources. r=esawin

Comment 9

[Arthur Iakab [arthur_iakab]]

https://hg.mozilla.org/mozilla-central/rev/ae2354fc485e
https://hg.mozilla.org/mozilla-central/rev/004dc47cf853