2025031 - Failure to get preference data from Gecko under rapid `nimbus-cli` conditions

Status: RESOLVED FIXED

(Firefox for Android :: Experimentation and Telemetry, task)

Description

[Olivia Hall [:olivia]]

This error is correctly handled:

03-20 15:25:19.379 14247 14247 E service/Nimbus/GeckoPrefHandlerExt: java.util.NoSuchElementException: Key browser.autofocus is missing in the map.
03-20 15:25:19.379 14247 14247 E service/Nimbus/GeckoPrefHandlerExt: 	at kotlin.collections.MapsKt__MapWithDefaultKt.getOrImplicitDefaultNullable(MapWithDefault.kt:24)
03-20 15:25:19.379 14247 14247 E service/Nimbus/GeckoPrefHandlerExt: 	at kotlin.collections.MapsKt__MapsKt.getValue(Maps.kt:371)
03-20 15:25:19.379 14247 14247 E service/Nimbus/GeckoPrefHandlerExt: 	at org.mozilla.fenix.experiments.prefhandling.NimbusGeckoUtilsKt.createSettersFromGeckoPrefStates(NimbusGeckoUtils.kt:191)
03-20 15:25:19.379 14247 14247 E service/Nimbus/GeckoPrefHandlerExt: 	at org.mozilla.fenix.experiments.prefhandling.NimbusGeckoPrefHandler$setGeckoPrefsState$1.invokeSuspend(NimbusGeckoPrefHandler.kt:248)
03-20 15:25:19.379 14247 14247 E service/Nimbus/GeckoPrefHandlerExt: 	at kotlin.coroutines.jvm.internal.BaseContinuationImpl.resumeWith(ContinuationImpl.kt:34)
03-20 15:25:19.379 14247 14247 E service/Nimbus/GeckoPrefHandlerExt: 	at kotlinx.coroutines.DispatchedTask.run(DispatchedTask.kt:100)
03-20 15:25:19.379 14247 14247 E service/Nimbus/GeckoPrefHandlerExt: 	at android.os.Handler.handleCallback(Handler.java:958)
03-20 15:25:19.379 14247 14247 E service/Nimbus/GeckoPrefHandlerExt: 	at android.os.Handler.dispatchMessage(Handler.java:99)
03-20 15:25:19.379 14247 14247 E service/Nimbus/GeckoPrefHandlerExt: 	at android.os.Looper.loopOnce(Looper.java:205)
03-20 15:25:19.379 14247 14247 E service/Nimbus/GeckoPrefHandlerExt: 	at android.os.Looper.loop(Looper.java:294)
03-20 15:25:19.379 14247 14247 E service/Nimbus/GeckoPrefHandlerExt: 	at android.app.ActivityThread.main(ActivityThread.java:8177)
03-20 15:25:19.379 14247 14247 E service/Nimbus/GeckoPrefHandlerExt: 	at java.lang.reflect.Method.invoke(Native Method)
03-20 15:25:19.379 14247 14247 E service/Nimbus/GeckoPrefHandlerExt: 	at com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run(RuntimeInit.java:552)
03-20 15:25:19.379 14247 14247 E service/Nimbus/GeckoPrefHandlerExt: 	at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:971)
03-20 15:25:19.380 14247 14247 E service/Nimbus/GeckoPrefHandlerExt: Enrollment value "#FFFFFF" cannot be cast to correct pref type for pref browser.anchor_color.dark
03-20 15:25:19.380 14247 14247 E service/Nimbus/GeckoPrefHandlerExt: java.util.NoSuchElementException: Key browser.anchor_color.dark is missing in the map.
03-20 15:25:19.380 14247 14247 E service/Nimbus/GeckoPrefHandlerExt: 	at kotlin.collections.MapsKt__MapWithDefaultKt.getOrImplicitDefaultNullable(MapWithDefault.kt:24)
03-20 15:25:19.380 14247 14247 E service/Nimbus/GeckoPrefHandlerExt: 	at kotlin.collections.MapsKt__MapsKt.getValue(Maps.kt:371)
03-20 15:25:19.380 14247 14247 E service/Nimbus/GeckoPrefHandlerExt: 	at org.mozilla.fenix.experiments.prefhandling.NimbusGeckoUtilsKt.createSettersFromGeckoPrefStates(NimbusGeckoUtils.kt:191)
03-20 15:25:19.380 14247 14247 E service/Nimbus/GeckoPrefHandlerExt: 	at org.mozilla.fenix.experiments.prefhandling.NimbusGeckoPrefHandler$setGeckoPrefsState$1.invokeSuspend(NimbusGeckoPrefHandler.kt:248)
03-20 15:25:19.380 14247 14247 E service/Nimbus/GeckoPrefHandlerExt: 	at kotlin.coroutines.jvm.internal.BaseContinuationImpl.resumeWith(ContinuationImpl.kt:34)
03-20 15:25:19.380 14247 14247 E service/Nimbus/GeckoPrefHandlerExt: 	at kotlinx.coroutines.DispatchedTask.run(DispatchedTask.kt:100)
03-20 15:25:19.380 14247 14247 E service/Nimbus/GeckoPrefHandlerExt: 	at android.os.Handler.handleCallback(Handler.java:958)
03-20 15:25:19.380 14247 14247 E service/Nimbus/GeckoPrefHandlerExt: 	at android.os.Handler.dispatchMessage(Handler.java:99)
03-20 15:25:19.380 14247 14247 E service/Nimbus/GeckoPrefHandlerExt: 	at android.os.Looper.loopOnce(Looper.java:205)
03-20 15:25:19.380 14247 14247 E service/Nimbus/GeckoPrefHandlerExt: 	at android.os.Looper.loop(Looper.java:294)
03-20 15:25:19.380 14247 14247 E service/Nimbus/GeckoPrefHandlerExt: 	at android.app.ActivityThread.main(ActivityThread.java:8177)
03-20 15:25:19.380 14247 14247 E service/Nimbus/GeckoPrefHandlerExt: 	at java.lang.reflect.Method.invoke(Native Method)
03-20 15:25:19.380 14247 14247 E service/Nimbus/GeckoPrefHandlerExt: 	at com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run(RuntimeInit.java:552)
03-20 15:25:19.380 14247 14247 E service/Nimbus/GeckoPrefHandlerExt: 	at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:971)

It happens when there is missing information about a pref.

I can cause it by rapidly spawning one nimbus-cli experiment rapidly after another, especially on the multi-pref experiment, but on others as well.

I'd like to double check more that this is a product of rapidly spawning a bunch of requests and not something that needs more scrutiny.

Comment 1

[Olivia Hall [:olivia]]

I saw this once under non-rapid conditions when retesting on bug 2001415.

Comment 2

[Olivia Hall [:olivia]]

Have some new insight with this log of No listener for GeckoView:Preferences:GetPref:

04-01 10:06:10.258 23402 23402 E GeckoPreference: GeckoPreferenceController.getGeckoPrefs: error retrieving 5 prefs [browser.cache.disk.enable, browser.bookmarks.max_backups, browser.autofocus, browser.anchor_color.dark, browser.anchor_color] exceptionType=QueryException msg=null queryData=No listener for GeckoView:Preferences:GetPref

We aren't getting information using getPreferenceStateFromGecko sometime from a race with Gecko being ready.

Comment 3

[Olivia Hall [:olivia]]

Attachment: Bug 2025031 - Prevent race condition by always registering Gecko Preferences

Before this patch, the GeckoViewPreferences were lazily initialized on the
JavaScript side.

Nimbus needs to call these APIs very early in startup and was seeing a
delay in registration due to initializing the listener and a race condition.

The race condition was observed when two of the same API calls happened in
quick succession, for example setting a preference and then another immediately
following. When this happened, there could be a gap where initialization was
underway and the second call would hit the gap. When the gap was hit, the
listener would log as not being available because it was in an indeterminate state.

Comment 4

[Pulsebot]

Pushed by [e-mail]:
https://github.com/mozilla-firefox/firefox/commit/34116282a9b6
https://hg.mozilla.org/integration/autoland/rev/c930104f7c9c
Prevent race condition by always registering Gecko Preferences r=geckoview-reviewers,m_kato

Comment 5

[rperta]

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