Cwa-app-android: Only splash displayed, then app closes. java.security.KeyException: Permantly failed to instantiate encrypted preferences

Created on 24 Oct 2020  路  17Comments  路  Source: corona-warn-app/cwa-app-android

Avoid duplicates

  • [x] Bug is not mentioned in the FAQ
  • [x] Bug is specific for Android only, for general issues / questions that apply to iOS and Android please raise them in the documentation repository
  • [x] Bug is not already reported in another issue

Describe the bug

I tried opening the app. The splash screen with the logo comes up, but after roughly 20 seconds the app screen closes again without any message. This does not recover and can be repeated as often as I like with the same outcome.

Exposure check logs indicate that the last automatic key check by the app was executed on the 19th in the morning (and all previous days at roughly the same time). Since then (last four days) no checks are recorded in Googles logs.
App was auto-updated on the 16th to version 1.5.0.

I assume something broke in the background. Call stack (below) hints that it is an issue with encryption. It _could_ relate to the known issue with SQLite getting corrupted, but in this case the symptoms and call-stack do not correlate with existing reports.

2020-10-24 09:09:39.551 2894-8104/? I/ActivityManager: START u0 {act=android.intent.action.MAIN cat=[android.intent.category.LAUNCHER] flg=0x10200000 cmp=de.rki.coronawarnapp/.ui.LauncherActivity bnds=[540,1500][789,1814]} from uid 10030
2020-10-24 09:09:39.593 2894-2912/? I/ActivityManager: Start proc 12098:de.rki.coronawarnapp/u0a242 for activity de.rki.coronawarnapp/.ui.LauncherActivity
2020-10-24 09:09:39.598 12098-12098/? E/i.coronawarnap: Not starting debugger since process cannot load the jdwp agent.
2020-10-24 09:09:39.626 2894-11778/? I/ZTEAppProfile: apk (de.rki.coronawarnapp) at top
2020-10-24 09:09:39.628 12098-12098/? I/i.coronawarnap: GetResourceLocales CollectLocales 
2020-10-24 09:09:39.632 12098-12098/? I/i.coronawarnap: GetResourceLocales CollectLocales 
2020-10-24 09:09:39.632 12098-12098/? I/chatty: uid=10242(de.rki.coronawarnapp) identical 1 line
2020-10-24 09:09:39.640 12098-12098/? I/i.coronawarnap: GetResourceLocales CollectLocales 
2020-10-24 09:09:58.544 12098-12098/? E/AndroidRuntime: FATAL EXCEPTION: main
    Process: de.rki.coronawarnapp, PID: 12098
    java.lang.RuntimeException: Unable to create application de.rki.coronawarnapp.CoronaWarnApplication: de.rki.coronawarnapp.exception.CwaSecurityException: something went wrong during a critical part of the application ensuring security, please referto the details for more information
        at android.app.ActivityThread.handleBindApplication(ActivityThread.java:6015)
        at android.app.ActivityThread.access$1800(ActivityThread.java:218)
        at android.app.ActivityThread$H.handleMessage(ActivityThread.java:1730)
        at android.os.Handler.dispatchMessage(Handler.java:106)
        at android.os.Looper.loop(Looper.java:192)
        at android.app.ActivityThread.main(ActivityThread.java:6994)
        at java.lang.reflect.Method.invoke(Native Method)
        at com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run(RuntimeInit.java:532)
        at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:860)
     Caused by: de.rki.coronawarnapp.exception.CwaSecurityException: something went wrong during a critical part of the application ensuring security, please referto the details for more information
        at de.rki.coronawarnapp.util.security.SecurityHelper$encryptedPreferencesProvider$1.invoke(SecurityHelper.kt:9)
        at de.rki.coronawarnapp.util.security.SecurityHelper$globalEncryptedSharedPreferencesInstance$2.invoke(SecurityHelper.kt:3)
        at kotlin.SynchronizedLazyImpl.getValue(LazyJVM.kt:6)
        at de.rki.coronawarnapp.util.security.SecurityHelper.getGlobalEncryptedSharedPreferencesInstance(Unknown Source:2)
        at de.rki.coronawarnapp.storage.LocalData.getSharedPreferenceInstance(LocalData.kt:1)
        at de.rki.coronawarnapp.CoronaWarnApplication.onCreate(CoronaWarnApplication.kt:42)
        at android.app.Instrumentation.callApplicationOnCreate(Instrumentation.java:1155)
        at android.app.ActivityThread.handleBindApplication(ActivityThread.java:6010)
        at android.app.ActivityThread.access$1800(ActivityThread.java:218)聽
        at android.app.ActivityThread$H.handleMessage(ActivityThread.java:1730)聽
        at android.os.Handler.dispatchMessage(Handler.java:106)聽
        at android.os.Looper.loop(Looper.java:192)聽
        at android.app.ActivityThread.main(ActivityThread.java:6994)聽
        at java.lang.reflect.Method.invoke(Native Method)聽
        at com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run(RuntimeInit.java:532)聽
        at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:860)聽
     Caused by: java.security.KeyException: Permantly failed to instantiate encrypted preferences
        at de.rki.coronawarnapp.util.security.EncryptedPreferencesFactory.create(EncryptedPreferencesFactory.kt:2)
        at de.rki.coronawarnapp.util.security.SecurityHelper$encryptedPreferencesProvider$1$1.invoke(SecurityHelper.kt:1)
        at de.rki.coronawarnapp.util.security.SecurityHelper$encryptedPreferencesProvider$1.invoke(SecurityHelper.kt:7)
        at de.rki.coronawarnapp.util.security.SecurityHelper$globalEncryptedSharedPreferencesInstance$2.invoke(SecurityHelper.kt:3)聽
        at kotlin.SynchronizedLazyImpl.getValue(LazyJVM.kt:6)聽
        at de.rki.coronawarnapp.util.security.SecurityHelper.getGlobalEncryptedSharedPreferencesInstance(Unknown Source:2)聽
        at de.rki.coronawarnapp.storage.LocalData.getSharedPreferenceInstance(LocalData.kt:1)聽
        at de.rki.coronawarnapp.CoronaWarnApplication.onCreate(CoronaWarnApplication.kt:42)聽
        at android.app.Instrumentation.callApplicationOnCreate(Instrumentation.java:1155)聽
        at android.app.ActivityThread.handleBindApplication(ActivityThread.java:6010)聽
        at android.app.ActivityThread.access$1800(ActivityThread.java:218)聽
        at android.app.ActivityThread$H.handleMessage(ActivityThread.java:1730)聽
        at android.os.Handler.dispatchMessage(Handler.java:106)聽
        at android.os.Looper.loop(Looper.java:192)聽
        at android.app.ActivityThread.main(ActivityThread.java:6994)聽
        at java.lang.reflect.Method.invoke(Native Method)聽
        at com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run(RuntimeInit.java:532)聽
        at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:860)聽
     Caused by: java.lang.SecurityException: Could not decrypt key. decryption failed
        at androidx.security.crypto.EncryptedSharedPreferences.getAll(EncryptedSharedPreferences.java:13)
        at de.rki.coronawarnapp.util.security.EncryptedPreferencesFactory$create$1.invoke(EncryptedPreferencesFactory.kt:29)
        at de.rki.coronawarnapp.util.RetryMechanism.retryWithBackOff$default(RetryMechanism.kt:7)
        at de.rki.coronawarnapp.util.security.EncryptedPreferencesFactory.create(EncryptedPreferencesFactory.kt:1)
        at de.rki.coronawarnapp.util.security.SecurityHelper$encryptedPreferencesProvider$1$1.invoke(SecurityHelper.kt:1)聽
        at de.rki.coronawarnapp.util.security.SecurityHelper$encryptedPreferencesProvider$1.invoke(SecurityHelper.kt:7)聽
        at de.rki.coronawarnapp.util.security.SecurityHelper$globalEncryptedSharedPreferencesInstance$2.invoke(SecurityHelper.kt:3)聽
        at kotlin.SynchronizedLazyImpl.getValue(LazyJVM.kt:6)聽
        at de.rki.coronawarnapp.util.security.SecurityHelper.getGlobalEncryptedSharedPreferencesInstance(Unknown Source:2)聽
        at de.rki.coronawarnapp.storage.LocalData.getSharedPreferenceInstance(LocalData.kt:1)聽
        at de.rki.coronawarnapp.CoronaWarnApplication.onCreate(CoronaWarnApplication.kt:42)聽
        at android.app.Instrumentation.callApplicationOnCreate(Instrumentation.java:1155)聽
        at android.app.ActivityThread.handleBindApplication(ActivityThread.java:6010)聽
        at android.app.ActivityThread.access$1800(ActivityThread.java:218)聽
        at android.app.ActivityThread$H.handleMessage(ActivityThread.java:1730)聽
        at android.os.Handler.dispatchMessage(Handler.java:106)聽
        at android.os.Looper.loop(Looper.java:192)聽
        at android.app.ActivityThread.main(ActivityThread.java:6994)聽
        at java.lang.reflect.Method.invoke(Native Method)聽
        at com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run(RuntimeInit.java:532)聽
        at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:860)聽
     Caused by: java.security.GeneralSecurityException: decryption failed
        at com.google.crypto.tink.daead.DeterministicAeadWrapper$WrappedDeterministicAead.decryptDeterministically(DeterministicAeadWrapper.java:16)
        at androidx.security.crypto.EncryptedSharedPreferences.getAll(EncryptedSharedPreferences.java:8)
        at de.rki.coronawarnapp.util.security.EncryptedPreferencesFactory$create$1.invoke(EncryptedPreferencesFactory.kt:29)聽
        at de.rki.coronawarnapp.util.RetryMechanism.retryWithBackOff$default(RetryMechanism.kt:7)聽
        at de.rki.coronawarnapp.util.security.EncryptedPreferencesFactory.create(EncryptedPreferencesFactory.kt:1)聽
        at de.rki.coronawarnapp.util.security.SecurityHelper$encryptedPreferencesProvider$1$1.invoke(SecurityHelper.kt:1)聽
        at de.rki.coronawarnapp.util.security.SecurityHelper$encryptedPreferencesProvider$1.invoke(SecurityHelper.kt:7)聽
        at de.rki.coronawarnapp.util.security.SecurityHelper$globalEncryptedSharedPreferencesInstance$2.invoke(SecurityHelper.kt:3)聽
        at kotlin.SynchronizedLazyImpl.getValue(LazyJVM.kt:6)聽
        at de.rki.coronawarnapp.util.security.SecurityHelper.getGlobalEncryptedSharedPreferencesInstance(Unknown Source:2)聽
        at de.rki.coronawarnapp.storage.LocalData.getSharedPreferenceInstance(LocalData.kt:1)聽
        at de.rki.coronawarnapp.CoronaWarnApplication.onCreate(CoronaWarnApplication.kt:42)聽
        at android.app.Instrumentation.callApplicationOnCreate(Instrumentation.java:1155)聽
        at android.app.ActivityThread.handleBindApplication(ActivityThread.java:6010)聽
        at android.app.ActivityThread.access$1800(ActivityThread.java:218)聽
        at android.app.ActivityThread$H.handleMessage(ActivityThread.java:1730)聽
        at android.os.Handler.dispatchMessage(Handler.java:106)聽
        at android.os.Looper.loop(Looper.java:192)聽
        at android.app.ActivityThread.main(ActivityThread.java:6994)聽
        at java.lang.reflect.Method.invoke(Native Method)聽
        at com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run(RuntimeInit.java:532)聽
        at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:860)聽
2020-10-24 09:09:58.549 2894-4687/? W/ActivityManager:   Force finishing activity de.rki.coronawarnapp/.ui.LauncherActivity
2020-10-24 09:09:58.589 2894-11778/? I/ActivityManager: Process de.rki.coronawarnapp (pid 12098) has died: vis  +99TOP 
2020-10-24 09:09:58.590 2894-11778/? I/ZTEPoint_AI_AUTOSTART_CONTROL: died processName: de.rki.coronawarnapp
2020-10-24 09:09:58.598 715-1123/? W/SurfaceFlinger: Attempting to set client state on removed layer: Splash Screen de.rki.coronawarnapp#0
2020-10-24 09:09:58.598 715-1123/? W/SurfaceFlinger: Attempting to destroy on removed layer: Splash Screen de.rki.coronawarnapp#0
2020-10-24 09:09:58.607 715-793/? W/SurfaceFlinger: Attempting to destroy on removed layer: AppWindowToken{b51c549 token=Token{3957f50 ActivityRecord{3215113 u0 de.rki.coronawarnapp/.ui.LauncherActivity t11362}}}#0

Technical details

  • ZTE Axon 9 Pro
  • Android version: 9, Patch level July 1, 2020
  • CWA version 1.5.0, auto-updated 16th October
  • power-saving is turned off for CWA
  • background priority was enabled in setting

Possible Fix

I will try to follow the recovery mentioned in the SQLite bug.

bug
Source
picture stephankn
👀1

Most helpful comment

Recovery:

  1. stop (force stop) CWA
  2. delete data/cache
  3. disable automatic time, set time back 14 days
  4. open CWA and complete enrolling steps
  5. close CWA and set back date to current date
picture stephankn on 24 Oct 2020
👍3

All 17 comments

Recovery:

  1. stop (force stop) CWA
  2. delete data/cache
  3. disable automatic time, set time back 14 days
  4. open CWA and complete enrolling steps
  5. close CWA and set back date to current date
stephankn picture stephankn on 24 Oct 2020
👍3

@stephankn
Good that you managed to work around it!

@d4rken
It looks like there is a typo in EncryptedPreferencesFactory.kt
line 38 throw KeyException("Permantly failed to instantiate encrypted preferences", e)
where "Permantly" should be "Permanently". Maybe if you are modifying this code anyway, you could fix this minor point?

MikeMcC399 picture MikeMcC399 on 24 Oct 2020

As far as I understood PR #1235 this exception should never happen, as block is suspected to be temporary. Does this mean that the system's keystore was busy longer? But why was it persistent? Or is this the new symptom in case the retry mechanism failed once and it had lost the key?
So is there a different reaction possible, not involving to discard the key?

stephankn picture stephankn on 24 Oct 2020

Hey @stephankn

The behaviour looks similar to https://github.com/corona-warn-app/cwa-app-android/issues/1456 . Maybe the two issues are related? @vaubaehn posted a workaround (https://github.com/corona-warn-app/cwa-app-android/issues/1053#issuecomment-690614975) that doesn't delete any of the created/saved codes. Please try this solution if the error occurs again.

CH

Corona-Warn-App Open Source Team

heinezen picture heinezen on 25 Oct 2020

It looks like there is a typo in EncryptedPreferencesFactory.kt

@MikeMcC399 Thx

https://github.com/corona-warn-app/cwa-app-android/pull/1472

@stephankn

I assume something broke in the background. Call stack (below) hints that it is an issue with encryption. It could relate to the known issue with SQLite getting corrupted, but in this case the symptoms and call-stack do not correlate with existing reports.

The call-stack changed due to the changes made for 1.5.x, the underlying error is still the same.

As far as I understood PR #1235 this exception should never happen, as block is suspected to be temporary. Does this mean that the system's keystore was busy longer? But why was it persistent? Or is this the new symptom in case the retry mechanism failed once and it had lost the key?

The new mechanism can't recover from the bug if it occurred before 1.5.0, we can only prevent it from happening again. If it occurred in 1.3.0, the encryption key was lost and we can't recover that data.

I'd currently say it broke before 1.5.0 and was only noticed now. I'd need a case where 1.5.0 was working correctly and then reached this state to become suspicious :thinking: .

d4rken picture d4rken on 25 Oct 2020
👍2

@d4rken to make the timeline clear: CWA got updated automatically to 1.5.0 on the 16th of October (according to play store). In the "exposure notification settings" I had checks reported on the 17th, 18th and 19th of October. As this was after the update, I assumed that these checks had been executed with the version 1.5.0 and that also the background checks without opening the activity require the right decryption keys to open the preferences. This would be in line with the checks failing on the 20th, 21st and 22nd before I noticed that the app is no longer able to open.

@heinezen Thanks to pointing to the recovery procedure. This was exactly the process I followed and summarized here in this issue in case others facing the same problem and end up here.

stephankn picture stephankn on 26 Oct 2020

While re-reading the Google Playstore screen: I wonder whether the "Updated On" setting applies to my device update or when the App was updated in the store. So in the later case it might be that the update to 1.5.0 happened after the keystore was corrupted on 1.3.0. Can I figure out when the update on my device happened?

image

stephankn picture stephankn on 26 Oct 2020

Sound like the problem addressed in PR #1433 is matching with the call stack observed here.

stephankn picture stephankn on 26 Oct 2020

@stephankn
You are right that Google Play Store shows Corona-Warn-App updated on Friday, Oct 16, 2020 however it was not deployed to users from the store until 12:00 CEST on Monday, Oct 19, 2020.
The post https://github.com/corona-warn-app/cwa-app-android/issues/1021#issuecomment-712087379 from the Open Source Team confirms that it rolled out 7 days ago from today, Monday Oct 26, 2020.

I believe you can get the real installation and update date with the Android Debug Bridge (adb). Is this something you're familiar with?

MikeMcC399 picture MikeMcC399 on 26 Oct 2020

I am no Android developer, but the pointer that adb can read this was good enough. So by checking the dates I can confirm that the background check on the 20th early morning happened (or more specifically failed) with still the old version installed, as 1.5.0 came later that day.

> adb shell dumpsys package de.rki.coronawarnapp | grep lastUpdate
    lastUpdateTime=2020-10-20 22:53:05
stephankn picture stephankn on 26 Oct 2020
👍2

Just to point out the probably most important information from @stephankn :

In the "exposure notification settings" I had checks reported on the 17th, 18th and 19th of October. [...] checks failing on the 20th, 21st and 22nd before I noticed that the app is no longer able to open.

Means: automatic update to 1.5.0 (likely) killed the EncryptedSharedPreferences.
(to prevent misunderstandings: it's not the code of 1.5 that did any harm to the data, it's the restarting of the app and the buggy Android Keystore together with tink)

vaubaehn picture vaubaehn on 27 Oct 2020

@vaubaehn I don't think the update was causing the problem. Check at exposure API usually happens in the early morning. I am quite certain it failed with the check on 20th as well in the early morning. Update happened late night that day. Roughly 20 hours after the time checks usually happen. So it was likely the second time within three weeks that my preferences/sqlite got killed. Why it happens now and not earlier is a mystery. As root cause seems to be understood, waiting for 1.5.1

stephankn picture stephankn on 28 Oct 2020

@stephankn
CWA 1.5.1 has been available from the Google Play Store since yesterday afternoon. Good luck!

MikeMcC399 picture MikeMcC399 on 28 Oct 2020

got 1.5.1 now. Shall I close this issue myself or wait for developer to confirm that 4a6e43983e45717694bd035518cd22cf68972521 fixes this issue?

stephankn picture stephankn on 28 Oct 2020

@stephankn
It's up to you regarding closure. If you're not seeing the issue any more then you can close it.
As author if you close the issue, you have the option to re-open the issue at any time. A button appears at the bottom of the thread to do this once you've closed it.
If the issue re-appears with 1.5.1 or any later version then it may be cleaner to open a new issue anyway.
Let's hope this is fixed! 馃

MikeMcC399 picture MikeMcC399 on 28 Oct 2020

@stephankn

@vaubaehn I don't think the update was causing the problem. Check at exposure API usually happens in the early morning. I am quite certain it failed with the check on 20th as well in the early morning. Update happened late night that day.

you know what? I completely overlooked

adb shell dumpsys package de.rki.coronawarnapp | grep lastUpdate
lastUpdateTime=2020-10-20 22:53:05

You're true. I am (still) assuming that the critical point in time for breaking the EncryptedSharedPreferences is every time, CWA is re-started (after reboot, after force stop, after update), because of this discussion: https://github.com/corona-warn-app/cwa-app-android/issues/1214#issuecomment-702833494 (and the following comment).
I understood, that the problem can occur, when the object of the EncryptedSharedPreferences is instanciated, which should only happen once at the (re-)start of CWA. When I then saw, that exposure checks worked for you until Oct 19, and at Oct 19 was the update to 1.5 deployed, for me the things were clear. But your update was late on Oct 20, and the morning check on that day already didn't work. So it was bad luck, that your ESP broke one day before the update.

After 3 months of intensive volunteering here, I'm obviously getting a little bit sloppy... should make a break... long holiday would be fantastic ;) :sun_with_face: :beach_umbrella:

vaubaehn picture vaubaehn on 28 Oct 2020

Thanks all for the effort. Going to close this issue as at least the one with this call-stack is fixed with 1.5.1.

stephankn picture stephankn on 28 Oct 2020
👍1
Was this page helpful?
5 / 5 - 1 ratings

Related issues

corneliusroemer picture corneliusroemer  路  52Comments
nilsalex picture nilsalex  路  86Comments
stefan-sys picture stefan-sys  路  106Comments
Jo-Achim picture Jo-Achim  路  75Comments
schildbach picture schildbach  路  53Comments