Closed Bug 1849376 Opened 2 years ago Closed 1 year ago

Intermittent firefox-android java.security.ProviderException: Keystore operation failed, results.MissingResultsError: Browsertime cycle missing firstPaint measurement

Categories

(Testing :: Raptor, defect, P5)

Product:
Testing
Component:
Raptor
Type:
defect

Tracking

(Not tracked)

Status:
RESOLVED INCOMPLETE

People

(Reporter: intermittent-bug-filer, Unassigned)

References

Details

(Keywords: intermittent-failure)

Filed by: gmierz2 [at] outlook.com
Parsed log: https://treeherder.mozilla.org/logviewer?job_id=426445897&repo=firefox-android
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/W-iYvSsHTtiYQskvqAH_CQ/runs/0/artifacts/public/logs/live_backing.log

These are caused by a crash that can be found in the logcat logs:

08-18 05:41:49.734 6082 15775 I FirefoxAccountStateMachine: Processing event 'mozilla.components.service.fxa.manager.Event$Progress$AccountNotFound@75e1ca7' for state Active(progressState=Initializing). Next state is Idle(accountState=NotAuthenticated)
08-18 05:41:49.736 6082 15694 I service-pocket: Scheduling sponsored stories background refresh
08-18 05:41:49.738 4941 6565 D PackageManager: setEnabledSetting : userId = 0 packageName = org.mozilla.fenix cmp = androidx.work.impl.background.systemalarm.RescheduleReceiver newState = 1 callingPackage = 10261/org.mozilla.fenix
08-18 05:41:49.740 6082 15705 E ExceptionHandler: Uncaught exception handled:
08-18 05:41:49.740 6082 15705 E ExceptionHandler: java.security.ProviderException: Keystore operation failed
08-18 05:41:49.740 6082 15705 E ExceptionHandler: at android.security.keystore.AndroidKeyStoreKeyGeneratorSpi.engineGenerateKey(AndroidKeyStoreKeyGeneratorSpi.java:395)
08-18 05:41:49.740 6082 15705 E ExceptionHandler: at javax.crypto.KeyGenerator.generateKey(KeyGenerator.java:612)
08-18 05:41:49.740 6082 15705 E ExceptionHandler: at mozilla.components.lib.dataprotect.KeyStoreWrapper.makeKeyFor(Keystore.kt:58)
08-18 05:41:49.740 6082 15705 E ExceptionHandler: at mozilla.components.lib.dataprotect.Keystore.generateKey(Keystore.kt:24)
08-18 05:41:49.740 6082 15705 E ExceptionHandler: at mozilla.components.lib.dataprotect.SecurePreferencesImpl23.getString(SecureAbove22Preferences.kt:28)
08-18 05:41:49.740 6082 15705 E ExceptionHandler: at mozilla.components.lib.dataprotect.SecureAbove22Preferences.getString(SecureAbove22Preferences.kt:3)
08-18 05:41:49.740 6082 15705 E ExceptionHandler: at mozilla.components.service.sync.logins.SyncableLoginsStorage.access$migrateSQLCipherDBIfNeeded(SyncableLoginsStorage.kt:77)
08-18 05:41:49.740 6082 15705 E ExceptionHandler: at mozilla.components.service.sync.logins.SyncableLoginsStorage$conn$2$1.invokeSuspend(SyncableLoginsStorage.kt:29)
08-18 05:41:49.740 6082 15705 E ExceptionHandler: at kotlin.coroutines.jvm.internal.BaseContinuationImpl.resumeWith(ContinuationImpl.kt:9)
08-18 05:41:49.740 6082 15705 E ExceptionHandler: at kotlinx.coroutines.DispatchedTask.run(DispatchedTask.kt:112)
08-18 05:41:49.740 6082 15705 E ExceptionHandler: at kotlinx.coroutines.internal.LimitedDispatcher$Worker.run(LimitedDispatcher.kt:4)
08-18 05:41:49.740 6082 15705 E ExceptionHandler: at kotlinx.coroutines.scheduling.TaskImpl.run(Tasks.kt:3)
08-18 05:41:49.740 6082 15705 E ExceptionHandler: at kotlinx.coroutines.scheduling.CoroutineScheduler$Worker.run(CoroutineScheduler.kt:96)
08-18 05:41:49.740 6082 15705 E ExceptionHandler: Suppressed: kotlinx.coroutines.internal.DiagnosticCoroutineContextException: [StandaloneCoroutine{Cancelling}@4bcc9d8, Dispatchers.IO]
08-18 05:41:49.740 6082 15705 E ExceptionHandler: Caused by: android.security.KeyStoreException: 16
08-18 05:41:49.740 6082 15705 E ExceptionHandler: at android.security.KeyStore.getKeyStoreException(KeyStore.java:1440)
08-18 05:41:49.740 6082 15705 E ExceptionHandler: ... 13 more
08-18 05:41:49.756 4655 4655 I keystore: del USRPKEY_org.mozilla.fenix 10261 0
08-18 05:41:49.757 4655 4655 I keystore: del USRSKEY_org.mozilla.fenix 10261 0
08-18 05:41:49.758 4655 4655 I keystore: del USRCERT_org.mozilla.fenix 10261 0
08-18 05:41:49.759 4655 4655 I keystore: del CACERT_org.mozilla.fenix 10261 0
08-18 05:41:49.759 4941 4966 D PackageManager: setEnabledSetting : userId = 0 packageName = org.mozilla.fenix cmp = androidx.work.impl.background.systemalarm.RescheduleReceiver newState = 1 callingPackage = 10261/org.mozilla.fenix

See Also: → 1849378
See Also: → 1842596

From :royang in bug 1842596 about what might trigger this:

No idea. This is to generate a key through Android keystore. Unless our configuration is incorrect, it should never fail. We know our configuration works because we don't see this on real users.

:aerickson, would you know if Bitbar changes anything that's related to the android keystore for these devices?

Flags: needinfo?(aerickson)

I see something new in the logs for a newer failure that just happened:

08-18 17:23:30.620 11641 21140 E ExceptionHandler: Uncaught exception handled: 
08-18 17:23:30.620 11641 21140 E ExceptionHandler: java.security.InvalidKeyException: unknown label: org.mozilla.fenix
08-18 17:23:30.620 11641 21140 E ExceptionHandler: 	at mozilla.components.lib.dataprotect.SecurePreferencesImpl23.putString(SecureAbove22Preferences.kt:177)
08-18 17:23:30.620 11641 21140 E ExceptionHandler: 	at mozilla.components.lib.dataprotect.SecureAbove22Preferences.putString(SecureAbove22Preferences.kt:8)
08-18 17:23:30.620 11641 21140 E ExceptionHandler: 	at mozilla.components.service.sync.logins.LoginsCrypto.storeKeyAndCanary(LoginsCrypto.kt:10)
08-18 17:23:30.620 11641 21140 E ExceptionHandler: 	at mozilla.components.concept.storage.KeyManager.getManagedKey(KeyManager.kt:98)
08-18 17:23:30.620 11641 21140 E ExceptionHandler: 	at mozilla.components.concept.storage.KeyManager.getOrGenerateKey$suspendImpl(KeyManager.kt:94)
08-18 17:23:30.620 11641 21140 E ExceptionHandler: 	at mozilla.components.service.sync.logins.SyncableLoginsStorage$list$2.invokeSuspend(SyncableLoginsStorage.kt:36)
08-18 17:23:30.620 11641 21140 E ExceptionHandler: 	at mozilla.components.service.sync.logins.SyncableLoginsStorage$list$2.invoke(SyncableLoginsStorage.kt:13)
08-18 17:23:30.620 11641 21140 E ExceptionHandler: 	at kotlinx.coroutines.intrinsics.UndispatchedKt.startUndispatchedOrReturn(Undispatched.kt:5)
08-18 17:23:30.620 11641 21140 E ExceptionHandler: 	at kotlinx.coroutines.BuildersKt.withContext(Unknown Source:76)
08-18 17:23:30.620 11641 21140 E ExceptionHandler: 	at mozilla.components.service.sync.logins.SyncableLoginsStorage.list(SyncableLoginsStorage.kt:11)
08-18 17:23:30.620 11641 21140 E ExceptionHandler: 	at org.mozilla.fenix.FenixApplication$setStartupMetrics$4.invokeSuspend(FenixApplication.kt:168)
08-18 17:23:30.620 11641 21140 E ExceptionHandler: 	at kotlin.coroutines.jvm.internal.BaseContinuationImpl.resumeWith(ContinuationImpl.kt:9)
08-18 17:23:30.620 11641 21140 E ExceptionHandler: 	at kotlinx.coroutines.DispatchedTask.run(DispatchedTask.kt:112)
08-18 17:23:30.620 11641 21140 E ExceptionHandler: 	at kotlinx.coroutines.internal.LimitedDispatcher$Worker.run(LimitedDispatcher.kt:4)
08-18 17:23:30.620 11641 21140 E ExceptionHandler: 	at kotlinx.coroutines.scheduling.TaskImpl.run(Tasks.kt:3)
08-18 17:23:30.620 11641 21140 E ExceptionHandler: 	at kotlinx.coroutines.scheduling.CoroutineScheduler$Worker.run(CoroutineScheduler.kt:96)
08-18 17:23:30.620 11641 21140 E ExceptionHandler: 	Suppressed: kotlinx.coroutines.internal.DiagnosticCoroutineContextException: [StandaloneCoroutine{Cancelling}@13315c3, Dispatchers.IO]
08-18 17:23:30.623  4912  6710 I ActivityManager: DSS OFF for org.mozilla.fenix
08-18 17:23:30.625  4912  6710 D ActivityManager: attachApplicationLocked() app=ProcessRecord{992ff51 21256:org.mozilla.fenix:gpu/u0a279} app.isolatedEntryPoint=null instr2=null
08-18 17:23:30.626  4912  6710 D CompatibilityChangeReporter: Compat change id reported: 136274596; UID 10279; state: ENABLED
08-18 17:23:30.630 21256 21256 D ActivityThread: handleBindApplication()++ app=org.mozilla.fenix:gpu
08-18 17:23:30.635 11641 21239 I FirefoxAccount: Registering persistence callback
08-18 17:23:30.635 11641 21239 I FirefoxAccountStateMachine: Ran 'mozilla.components.service.fxa.manager.Event$Account$Start@71d9e83' side-effects for state Active(progressState=Initializing), got successive event mozilla.components.service.fxa.manager.Event$Progress$AccountNotFound@735eca5
08-18 17:23:30.635 11641 21239 I FirefoxAccountStateMachine: Processing event 'mozilla.components.service.fxa.manager.Event$Progress$AccountNotFound@735eca5' for state Active(progressState=Initializing). Next state is Idle(accountState=NotAuthenticated)
08-18 17:23:30.641 11641 21183 W logins::schema: user_version: 0
08-18 17:23:30.655 11641 21140 I mozac/CrashReporter: Received crash: UncaughtExceptionCrash(timestamp=1692379410620, throwable=java.security.InvalidKeyException: unknown label: org.mozilla.fenix, breadcrumbs=[Breadcrumb(message=onCreate(), data={recreated=false, intent=android.intent.action.VIEW, instance=13123279}, category=HomeActivity, level=INFO, type=DEFAULT, date=Fri Aug 18 17:23:30 UTC 2023), Breadcrumb(message=Changing to fragment browserFragment, isCustomTab: false, data={}, category=DestinationChanged, level=INFO, type=DEFAULT, date=Fri Aug 18 17:23:30 UTC 2023)], uuid=b1eb4680-c336-4f9b-8ef3-4934bbf29bed)

It came from this task: https://treeherder.mozilla.org/jobs?repo=firefox-android&revision=ee9216d8e4f5e7d6a3a59f8a6efe72fd927e8bbf&searchStr=android-hw-a51-11-0-aarch64-shippable-qr%2Fopt-allrecipes-fenix-nightly-simulation-armeabi-v7a-nofis&selectedTaskRun=Iuo1h3I1TdOU0BOO2BD7FA.0

Checking with Bitbar. Will report back.

Bitbar doesn't change anything regarding the Android keystore.

Flags: needinfo?(aerickson)

Thanks for checking :aerickson. I'm wondering if our adb code here has something to do with this: https://searchfox.org/mozilla-central/source/testing/mozbase/mozdevice/mozdevice/adb.py#3951

https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
For more information, please visit BugBot documentation.

Status: NEW → RESOLVED
Closed: 2 years ago
Resolution: --- → INCOMPLETE

New failure instance: https://treeherder.mozilla.org/logviewer?job_id=441804832&repo=firefox-android

Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---

https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
For more information, please visit BugBot documentation.

Status: REOPENED → RESOLVED
Closed: 2 years ago → 1 year ago
Resolution: --- → INCOMPLETE
You need to log in before you can comment on or make changes to this bug.