ANR after biometric authentication

[alexbakker]

We received an email from a user who is encountering ANR popups after unlocking Aegis using biometric authentication (but not if they unlock using their password). They also sent over a screen recording, but since it contains some personal information, I won't share it here. I'll describe it instead:

• Aegis is launched
• The biometric prompt is shown and the user authenticates
• The biometric prompt is closed and the app then visibly hangs in AuthActivity for 5 seconds or so
• AuthActivity closes and MainActivity opens
• The user gets ANR prompts once every couple of seconds, even though the app appears to remain responsive throughout this.

They're using Aegis on a Sony XQ-DC54 running Android 13.

They've also sent us a bugreport ZIP that gives us some more insight into what is happening. Just before Android reports the ANR, the following is seen in the log:

09-08 15:59:22.658  1017   699 28594 W keystore2: keystore2::watchdog: ### Keystore Watchdog report - BEGIN ###
09-08 15:59:22.658  1017   699 28594 W keystore2: keystore2::watchdog: When extracting from a bug report, please include this header
09-08 15:59:22.658  1017   699 28594 W keystore2: keystore2::watchdog: and all 2 records below.
09-08 15:59:22.658  1017   699 28594 W keystore2: keystore2::watchdog: ThreadId(19) IKeystoreOperation::update Pending: 1.500838281s Overdue 1.000843021s
09-08 15:59:22.658  1017   699 28594 W keystore2: keystore2::watchdog: ThreadId(19) Operation::update: calling update Pending: 1.500811093s Overdue 1.00081203s
09-08 15:59:22.658  1017   699 28594 W keystore2: keystore2::watchdog: ### Keystore Watchdog report - END ###
09-08 15:59:23.659  1017   699 28594 W keystore2: keystore2::watchdog: ### Keystore Watchdog report - BEGIN ###
09-08 15:59:23.659  1017   699 28594 W keystore2: keystore2::watchdog: When extracting from a bug report, please include this header
09-08 15:59:23.659  1017   699 28594 W keystore2: keystore2::watchdog: and all 2 records below.
09-08 15:59:23.659  1017   699 28594 W keystore2: keystore2::watchdog: ThreadId(19) IKeystoreOperation::update Pending: 2.501168436s Overdue 2.001173229s
09-08 15:59:23.659  1017   699 28594 W keystore2: keystore2::watchdog: ThreadId(19) Operation::update: calling update Pending: 2.501141822s Overdue 2.001142707s
09-08 15:59:23.659  1017   699 28594 W keystore2: keystore2::watchdog: ### Keystore Watchdog report - END ###
09-08 15:59:24.659  1017   699 28594 W keystore2: keystore2::watchdog: ### Keystore Watchdog report - BEGIN ###
09-08 15:59:24.659  1017   699 28594 W keystore2: keystore2::watchdog: When extracting from a bug report, please include this header
09-08 15:59:24.660  1017   699 28594 W keystore2: keystore2::watchdog: and all 2 records below.
09-08 15:59:24.660  1017   699 28594 W keystore2: keystore2::watchdog: ThreadId(19) IKeystoreOperation::update Pending: 3.502164999s Overdue 3.002170416s
09-08 15:59:24.660  1017   699 28594 W keystore2: keystore2::watchdog: ThreadId(19) Operation::update: calling update Pending: 3.502149582s Overdue 3.002150623s
09-08 15:59:24.660  1017   699 28594 W keystore2: keystore2::watchdog: ### Keystore Watchdog report - END ###

Looking at the backtrace of the main thread at the moment of the ANR, we can see that Aegis is communicating with the Keystore service to decrypt the biometric key slot. We see something similar when they're trying to set up biometrics through Aegis' settings menu.

"main" prio=5 tid=1 Native
  | group="main" sCount=1 ucsCount=0 flags=1 obj=0x7275cae8 self=0xb400007035ab9be0
  | sysTid=20265 nice=-10 cgrp=top-app sched=0/0 handle=0x72041884f8
  | state=S schedstat=( 187068401 24628019 325 ) utm=10 stm=8 core=0 HZ=100
  | stack=0x7fdcea6000-0x7fdcea8000 stackSize=8188KB
  | held mutexes=
  native: #00 pc 00000000000a5b8c  /apex/com.android.runtime/lib64/bionic/libc.so (__ioctl+12) (BuildId: 2938f6235116cbc48464ee0f7622625e)
  native: #01 pc 000000000005c9e0  /apex/com.android.runtime/lib64/bionic/libc.so (ioctl+160) (BuildId: 2938f6235116cbc48464ee0f7622625e)
  native: #02 pc 000000000005c2a0  /system/lib64/libbinder.so (android::IPCThreadState::talkWithDriver(bool)+284) (BuildId: af2c6edea56d998ea36c11c3b4123011)
  native: #03 pc 000000000005d4fc  /system/lib64/libbinder.so (android::IPCThreadState::waitForResponse(android::Parcel*, int*)+76) (BuildId: af2c6edea56d998ea36c11c3b4123011)
  native: #04 pc 000000000005d238  /system/lib64/libbinder.so (android::IPCThreadState::transact(int, unsigned int, android::Parcel const&, android::Parcel*, unsigned int)+224) (BuildId: af2c6edea56d998ea36c11c3b4123011)
  native: #05 pc 0000000000054a44  /system/lib64/libbinder.so (android::BpBinder::transact(unsigned int, android::Parcel const&, android::Parcel*, unsigned int)+192) (BuildId: af2c6edea56d998ea36c11c3b4123011)
  native: #06 pc 0000000000175bb8  /system/lib64/libandroid_runtime.so (android_os_BinderProxy_transact(_JNIEnv*, _jobject*, int, _jobject*, _jobject*, int)+156) (BuildId: 9fd640b0990deb09d17a2a91aa61b073)
  at android.os.BinderProxy.transactNative(Native method)
  at android.os.BinderProxy.transact(BinderProxy.java:584)
  at android.system.keystore2.IKeystoreOperation$Stub$Proxy.update(IKeystoreOperation.java:191)
  at android.security.KeyStoreOperation.lambda$update$1$android-security-KeyStoreOperation(KeyStoreOperation.java:115)
  at android.security.KeyStoreOperation$$ExternalSyntheticLambda1.execute(unavailable:4)
  at android.security.KeyStoreOperation.handleExceptions(KeyStoreOperation.java:69)
  at android.security.KeyStoreOperation.update(KeyStoreOperation.java:115)
  at android.security.keystore2.KeyStoreCryptoOperationChunkedStreamer$MainDataStream.update(KeyStoreCryptoOperationChunkedStreamer.java:222)
  at android.security.keystore2.KeyStoreCryptoOperationChunkedStreamer.update(KeyStoreCryptoOperationChunkedStreamer.java:156)
  at android.security.keystore2.KeyStoreCryptoOperationChunkedStreamer.doFinal(KeyStoreCryptoOperationChunkedStreamer.java:179)
  at android.security.keystore2.AndroidKeyStoreAuthenticatedAESCipherSpi$BufferAllOutputUntilDoFinalStreamer.doFinal(AndroidKeyStoreAuthenticatedAESCipherSpi.java:396)
  at android.security.keystore2.AndroidKeyStoreCipherSpiBase.engineDoFinal(AndroidKeyStoreCipherSpiBase.java:603)
  at javax.crypto.Cipher.doFinal(Cipher.java:2056)
  at kotlin.LazyKt__LazyKt.decrypt(SourceFile:18)
  at com.beemdevelopment.aegis.vault.slots.RawSlot.getKey(SourceFile:7)
  at androidx.biometric.BiometricViewModel$1.onAuthenticationSucceeded(SourceFile:28)
  at androidx.core.app.ActivityRecreator$1.run(SourceFile:197)
  at android.os.Handler.handleCallback(Handler.java:942)
  at android.os.Handler.dispatchMessage(Handler.java:99)
  at android.os.Looper.loopOnce(Looper.java:346)
  at android.os.Looper.loop(Looper.java:475)
  at android.app.ActivityThread.main(ActivityThread.java:7950)
  at java.lang.reflect.Method.invoke(Native method)
  at com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run(RuntimeInit.java:548)
  at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:942)

It would not be a surprise that waiting for multiple seconds for a response from the Keystore service, on the main thread, is eventually going to result in Android finding that your app is not responsive. We should consider moving this off the main thread. I still don't understand why the user keeps getting ANR popups though, even after the app is responsive again.