Wrap EncryptedSharedPreferences initialization in a retry mechanism (EXPOSUREAPP-1851) #1235

d4rken · 2020-09-25T14:17:51Z

New PR to merge into 1.4.x instead of 1.5.x

Description

Wrapped the EncryptedSharedPreferences initialization in an exponential backoff mechanism with randomized delay, to mitigate issues caused by the system's keystore being busy. The idea is that after a few retries the congestion has cleared and we can get access to the system's keystore.

We'll retry for a maximum of 15s, delay at least 25ms and at most 3s between tries.

Should mitigate #642, possibly also #1214, #1121.

Bug description:

How to test

Difficult to reproduce ☹️
Understand the bug as described above (see links), review the code.
Add a test exception in the preference creation code, observe behavior.

Example log output

2020-09-23 00:34:12.839 4424-4424/de.rki.coronawarnapp.dev V/RetryMechanism: Executing attempt: Attempt(count=1, totalDelay=0, lastDelay=0, exception=null)
2020-09-23 00:34:12.839 4424-4424/de.rki.coronawarnapp.dev D/EncryptedPreferencesFactory$create: Creating EncryptedSharedPreferences instance.
2020-09-23 00:34:13.138 4424-4424/de.rki.coronawarnapp.dev V/RetryMechanism: Executing attempt: Attempt(count=2, totalDelay=25, lastDelay=25, exception=java.security.KeyException)
2020-09-23 00:34:13.139 4424-4424/de.rki.coronawarnapp.dev D/EncryptedPreferencesFactory$create: Creating EncryptedSharedPreferences instance.
2020-09-23 00:34:13.255 4424-4424/de.rki.coronawarnapp.dev V/RetryMechanism: Executing attempt: Attempt(count=3, totalDelay=50, lastDelay=25, exception=java.security.KeyException)
2020-09-23 00:34:13.255 4424-4424/de.rki.coronawarnapp.dev D/EncryptedPreferencesFactory$create: Creating EncryptedSharedPreferences instance.
2020-09-23 00:34:13.368 4424-4424/de.rki.coronawarnapp.dev V/RetryMechanism: Executing attempt: Attempt(count=4, totalDelay=75, lastDelay=25, exception=java.security.KeyException)
2020-09-23 00:34:13.368 4424-4424/de.rki.coronawarnapp.dev D/EncryptedPreferencesFactory$create: Creating EncryptedSharedPreferences instance.
2020-09-23 00:34:13.476 4424-4424/de.rki.coronawarnapp.dev V/RetryMechanism: Executing attempt: Attempt(count=5, totalDelay=100, lastDelay=25, exception=java.security.KeyException)
2020-09-23 00:34:13.477 4424-4424/de.rki.coronawarnapp.dev D/EncryptedPreferencesFactory$create: Creating EncryptedSharedPreferences instance.
2020-09-23 00:34:13.604 4424-4424/de.rki.coronawarnapp.dev V/RetryMechanism: Executing attempt: Attempt(count=6, totalDelay=144, lastDelay=44, exception=java.security.KeyException)
2020-09-23 00:34:13.604 4424-4424/de.rki.coronawarnapp.dev D/EncryptedPreferencesFactory$create: Creating EncryptedSharedPreferences instance.
2020-09-23 00:34:13.769 4424-4424/de.rki.coronawarnapp.dev V/RetryMechanism: Executing attempt: Attempt(count=7, totalDelay=208, lastDelay=64, exception=java.security.KeyException)
2020-09-23 00:34:13.769 4424-4424/de.rki.coronawarnapp.dev D/EncryptedPreferencesFactory$create: Creating EncryptedSharedPreferences instance.
2020-09-23 00:34:13.976 4424-4424/de.rki.coronawarnapp.dev V/RetryMechanism: Executing attempt: Attempt(count=8, totalDelay=331, lastDelay=123, exception=java.security.KeyException)
2020-09-23 00:34:13.977 4424-4424/de.rki.coronawarnapp.dev D/EncryptedPreferencesFactory$create: Creating EncryptedSharedPreferences instance.
2020-09-23 00:34:14.231 4424-4424/de.rki.coronawarnapp.dev V/RetryMechanism: Executing attempt: Attempt(count=9, totalDelay=490, lastDelay=159, exception=java.security.KeyException)
2020-09-23 00:34:14.231 4424-4424/de.rki.coronawarnapp.dev D/EncryptedPreferencesFactory$create: Creating EncryptedSharedPreferences instance.
2020-09-23 00:34:14.669 4424-4424/de.rki.coronawarnapp.dev V/RetryMechanism: Executing attempt: Attempt(count=10, totalDelay=849, lastDelay=359, exception=java.security.KeyException)
2020-09-23 00:34:14.670 4424-4424/de.rki.coronawarnapp.dev D/EncryptedPreferencesFactory$create: Creating EncryptedSharedPreferences instance.
2020-09-23 00:34:15.554 4424-4424/de.rki.coronawarnapp.dev V/RetryMechanism: Executing attempt: Attempt(count=11, totalDelay=1655, lastDelay=806, exception=java.security.KeyException)
2020-09-23 00:34:15.554 4424-4424/de.rki.coronawarnapp.dev D/EncryptedPreferencesFactory$create: Creating EncryptedSharedPreferences instance.
2020-09-23 00:34:18.114 4424-4424/de.rki.coronawarnapp.dev V/RetryMechanism: Executing attempt: Attempt(count=12, totalDelay=4136, lastDelay=2481, exception=java.security.KeyException)
2020-09-23 00:34:18.115 4424-4424/de.rki.coronawarnapp.dev D/EncryptedPreferencesFactory$create: Creating EncryptedSharedPreferences instance.
2020-09-23 00:34:20.963 4424-4424/de.rki.coronawarnapp.dev V/RetryMechanism: Executing attempt: Attempt(count=13, totalDelay=6775, lastDelay=2639, exception=java.security.KeyException)
2020-09-23 00:34:20.964 4424-4424/de.rki.coronawarnapp.dev D/EncryptedPreferencesFactory$create: Creating EncryptedSharedPreferences instance.
2020-09-23 00:34:24.171 4424-4424/de.rki.coronawarnapp.dev V/RetryMechanism: Executing attempt: Attempt(count=14, totalDelay=9775, lastDelay=3000, exception=java.security.KeyException)
2020-09-23 00:34:24.172 4424-4424/de.rki.coronawarnapp.dev D/EncryptedPreferencesFactory$create: Creating EncryptedSharedPreferences instance.
2020-09-23 00:34:27.382 4424-4424/de.rki.coronawarnapp.dev V/RetryMechanism: Executing attempt: Attempt(count=15, totalDelay=12775, lastDelay=3000, exception=java.security.KeyException)
2020-09-23 00:34:27.382 4424-4424/de.rki.coronawarnapp.dev D/EncryptedPreferencesFactory$create: Creating EncryptedSharedPreferences instance.
2020-09-23 00:34:30.534 4424-4424/de.rki.coronawarnapp.dev V/RetryMechanism: Executing attempt: Attempt(count=16, totalDelay=15775, lastDelay=3000, exception=java.security.KeyException)
2020-09-23 00:34:30.535 4424-4424/de.rki.coronawarnapp.dev D/EncryptedPreferencesFactory$create: Creating EncryptedSharedPreferences instance.
2020-09-23 00:34:30.778 4424-4424/de.rki.coronawarnapp.dev W/RetryMechanism$createDelayCalculator: Max retry duration exceeded.
2020-09-23 00:34:30.780 4424-4424/de.rki.coronawarnapp.dev W/RetryMechanism: Retrycondition exceeded: Attempt(count=16, totalDelay=15775, lastDelay=3000, exception=java.security.KeyException)
2020-09-23 00:34:30.782 4424-4424/de.rki.coronawarnapp.dev D/AndroidRuntime: Shutting down VM
2020-09-23 00:34:30.785 4424-4424/de.rki.coronawarnapp.dev E/AndroidRuntime: FATAL EXCEPTION: main
    Process: de.rki.coronawarnapp.dev, PID: 4424
    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:6717)
        at android.app.ActivityThread.access$1300(ActivityThread.java:237)
        at android.app.ActivityThread$H.handleMessage(ActivityThread.java:1913)
        at android.os.Handler.dispatchMessage(Handler.java:106)
        at android.os.Looper.loop(Looper.java:223)
        at android.app.ActivityThread.main(ActivityThread.java:7656)
        at java.lang.reflect.Method.invoke(Native Method)
        at com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run(RuntimeInit.java:592)
        at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:947)
     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.withSecurityCatch(SecurityHelper.kt:97)
        at de.rki.coronawarnapp.util.security.SecurityHelper$globalEncryptedSharedPreferencesInstance$2.invoke(SecurityHelper.kt:41)
        at de.rki.coronawarnapp.util.security.SecurityHelper$globalEncryptedSharedPreferencesInstance$2.invoke(SecurityHelper.kt:37)
        at kotlin.SynchronizedLazyImpl.getValue(LazyJVM.kt:74)
        at de.rki.coronawarnapp.util.security.SecurityHelper.getGlobalEncryptedSharedPreferencesInstance(Unknown Source:2)
        at de.rki.coronawarnapp.storage.LocalData.getSharedPreferenceInstance(LocalData.kt:715)
        at de.rki.coronawarnapp.storage.LocalData.backgroundNotification(LocalData.kt:706)
        at de.rki.coronawarnapp.worker.BackgroundWorkHelper.sendDebugNotification(BackgroundWorkHelper.kt:95)
        at de.rki.coronawarnapp.CoronaWarnApplication.onCreate(CoronaWarnApplication.kt:99)
        at android.app.Instrumentation.callApplicationOnCreate(Instrumentation.java:1192)
        at android.app.ActivityThread.handleBindApplication(ActivityThread.java:6712)
        at android.app.ActivityThread.access$1300(ActivityThread.java:237) 
        at android.app.ActivityThread$H.handleMessage(ActivityThread.java:1913) 
        at android.os.Handler.dispatchMessage(Handler.java:106) 
        at android.os.Looper.loop(Looper.java:223) 
        at android.app.ActivityThread.main(ActivityThread.java:7656) 
        at java.lang.reflect.Method.invoke(Native Method) 
        at com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run(RuntimeInit.java:592) 
        at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:947) 
     Caused by: java.security.KeyException: Permantly failed to instantiate encrypted preferences
        at de.rki.coronawarnapp.util.security.EncryptedPreferencesFactory.create(EncryptedPreferencesFactory.kt:39)
        at de.rki.coronawarnapp.util.security.SecurityHelper$globalEncryptedSharedPreferencesInstance$2$1.invoke(SecurityHelper.kt:42)
        at de.rki.coronawarnapp.util.security.SecurityHelper$globalEncryptedSharedPreferencesInstance$2$1.invoke(SecurityHelper.kt:37)
        at de.rki.coronawarnapp.util.security.SecurityHelper.withSecurityCatch(SecurityHelper.kt:95)
        at de.rki.coronawarnapp.util.security.SecurityHelper$globalEncryptedSharedPreferencesInstance$2.invoke(SecurityHelper.kt:41) 
        at de.rki.coronawarnapp.util.security.SecurityHelper$globalEncryptedSharedPreferencesInstance$2.invoke(SecurityHelper.kt:37) 
        at kotlin.SynchronizedLazyImpl.getValue(LazyJVM.kt:74) 
        at de.rki.coronawarnapp.util.security.SecurityHelper.getGlobalEncryptedSharedPreferencesInstance(Unknown Source:2) 
        at de.rki.coronawarnapp.storage.LocalData.getSharedPreferenceInstance(LocalData.kt:715) 
        at de.rki.coronawarnapp.storage.LocalData.backgroundNotification(LocalData.kt:706) 
        at de.rki.coronawarnapp.worker.BackgroundWorkHelper.sendDebugNotification(BackgroundWorkHelper.kt:95) 
        at de.rki.coronawarnapp.CoronaWarnApplication.onCreate(CoronaWarnApplication.kt:99) 
        at android.app.Instrumentation.callApplicationOnCreate(Instrumentation.java:1192) 
        at android.app.ActivityThread.handleBindApplication(ActivityThread.java:6712) 
        at android.app.ActivityThread.access$1300(ActivityThread.java:237) 
        at android.app.ActivityThread$H.handleMessage(ActivityThread.java:1913) 
        at android.os.Handler.dispatchMessage(Handler.java:106) 
        at android.os.Looper.loop(Looper.java:223) 
        at android.app.ActivityThread.main(ActivityThread.java:7656) 
        at java.lang.reflect.Method.invoke(Native Method) 
        at com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run(RuntimeInit.java:592) 
        at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:947) 
     Caused by: java.security.KeyException
        at de.rki.coronawarnapp.util.security.EncryptedPreferencesFactory$create$1.invoke(EncryptedPreferencesFactory.kt:34)
        at de.rki.coronawarnapp.util.security.EncryptedPreferencesFactory$create$1.invoke(EncryptedPreferencesFactory.kt:14)
        at de.rki.coronawarnapp.util.RetryMechanism.retryWithBackOff(RetryMechanism.kt:19)
        at de.rki.coronawarnapp.util.RetryMechanism.retryWithBackOff$default(RetryMechanism.kt:12)
        at de.rki.coronawarnapp.util.security.EncryptedPreferencesFactory.create(EncryptedPreferencesFactory.kt:31)
        at de.rki.coronawarnapp.util.security.SecurityHelper$globalEncryptedSharedPreferencesInstance$2$1.invoke(SecurityHelper.kt:42) 
        at de.rki.coronawarnapp.util.security.SecurityHelper$globalEncryptedSharedPreferencesInstance$2$1.invoke(SecurityHelper.kt:37) 
        at de.rki.coronawarnapp.util.security.SecurityHelper.withSecurityCatch(SecurityHelper.kt:95) 
        at de.rki.coronawarnapp.util.security.SecurityHelper$globalEncryptedSharedPreferencesInstance$2.invoke(SecurityHelper.kt:41) 
        at de.rki.coronawarnapp.util.security.SecurityHelper$globalEncryptedSharedPreferencesInstance$2.invoke(SecurityHelper.kt:37) 
        at kotlin.SynchronizedLazyImpl.getValue(LazyJVM.kt:74) 
        at de.rki.coronawarnapp.util.security.SecurityHelper.getGlobalEncryptedSharedPreferencesInstance(Unknown Source:2) 
        at de.rki.coronawarnapp.storage.LocalData.getSharedPreferenceInstance(LocalData.kt:715) 
        at de.rki.coronawarnapp.storage.LocalData.backgroundNotification(LocalData.kt:706) 
        at de.rki.coronawarnapp.worker.BackgroundWorkHelper.sendDebugNotification(BackgroundWorkHelper.kt:95) 
        at de.rki.coronawarnapp.CoronaWarnApplication.onCreate(CoronaWarnApplication.kt:99) 
        at android.app.Instrumentation.callApplicationOnCreate(Instrumentation.java:1192) 
        at android.app.ActivityThread.handleBindApplication(ActivityThread.java:6712) 
        at android.app.ActivityThread.access$1300(ActivityThread.java:237) 
        at android.app.ActivityThread$H.handleMessage(ActivityThread.java:1913) 
        at android.os.Handler.dispatchMessage(Handler.java:106) 
        at android.os.Looper.loop(Looper.java:223) 
        at android.app.ActivityThread.main(ActivityThread.java:7656) 
        at java.lang.reflect.Method.invoke(Native Method) 
        at com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run(RuntimeInit.java:592) 
        at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:947) 
2020-09-23 00:34:30.823 4424-4424/de.rki.coronawarnapp.dev I/Process: Sending signal. PID: 4424 SIG: 9

…between the last and the new delay.

vaubaehn · 2020-09-25T15:35:08Z

New PR to merge into 1.4.x instead of 1.5.x

very good decision.

vaubaehn · 2020-09-26T07:49:41Z

Hi @d4rken ,
nice to see that mitigation more soon.
However, from your dev's perspective, do you think it makes sense to provide support to users who run into app crash by linking from a new entry in FAQ to a guide provided here => #1053 (comment) until that mitigation is deployed? If no, why?

And related to #642 (comment) : Chapeau! Looks like a very thorough and nice research and analysis.

[preceeding comment accidently pinged wrong person. Sorry for that.]

d4rken · 2020-09-28T06:46:40Z

However, from your dev's perspective, do you think it makes sense to provide support to users who run into app crash by linking from a new entry in FAQ to a guide provided here => #1053 (comment) until that mitigation is deployed? If no, why?

It will probably make sense to have that FAQ entry even after the mitigation is deployed. My fix will only prevent it from affecting new users. There is no recovery for anyone already affected by this as the original encryption key is lost. The only thing that could be done for existing users affected by this issue, is to possibly automate the recovery procedure. Simply resetting the necessary data is not enough though, we don't want to surprise the user with suddenly "reset" app, so there would have to be additional UI components to inform the user about what happened too. 🤔

ralfgehrer · 2020-09-28T09:22:04Z

Corona-Warn-App/src/main/java/de/rki/coronawarnapp/util/RetryMechanism.kt

+        }
+    }
+
+    private const val DEFAULT_TOTAL_MAX_RETRY = 15 * 1000L // 15 seconds total delay


Minor, but shouldn't constants be on top of the class

Good question. For classes they should be in the companion object which are supposed to be at the end of the class according to KotlinStyleGuide. Here this is an object already. I placed it where it is so it is close to where it is used. I would go with your suggestion if it were used in other locations too. Here it seems beneficial to view it all without scrolling, what do you think?

…1.4.x

AlexanderAlferov

All testes passed, no formatting issues, smoke test passed.

vaubaehn · 2020-09-28T14:26:21Z

However, from your dev's perspective, do you think it makes sense to provide support to users who run into app crash by linking from a new entry in FAQ to a guide provided here => #1053 (comment) until that mitigation is deployed? If no, why?

It will probably make sense to have that FAQ entry even after the mitigation is deployed. My fix will only prevent it from affecting new users. There is no recovery for anyone already affected by this as the original encryption key is lost. The only thing that could be done for existing users affected by this issue, is to possibly automate the recovery procedure. Simply resetting the necessary data is not enough though, we don't want to surprise the user with suddenly "reset" app, so there would have to be additional UI components to inform the user about what happened too. thinking

Hi @d4rken , thanks very much for your response.
FAQ-entry is online now.
Automatic recovery would be nice for sure, but I'm copying your reservations according necessary UI additions.
Both thumbs pressed for your fix being effective in almost all cases!
Have a good week.

sonarqubecloud · 2020-09-28T14:29:38Z

Kudos, SonarCloud Quality Gate passed!

0 Bugs
0 Vulnerabilities (and 0 Security Hotspots to review)
0 Code Smells

59.2% Coverage
0.0% Duplication

d4rken added 6 commits September 25, 2020 16:14

Add retry mechanism with backoff to EncryptedSharedPreferences creation.

e02ba4c

Increase default delays and make the actual delay a randomized value …

75768f6

…between the last and the new delay.

Upgrade to "androidx.security:security-crypto:1.0.0-rc03"

0d41cc2

Further space retry delays.

0085045

Unit tests for retry mechanism and factory init.

b05cc33

klint

5503ed7

d4rken added bug Something isn't working maintainers Tag pull requests created by maintainers 1.4.0 labels Sep 25, 2020

d4rken requested a review from a team September 25, 2020 14:17

d4rken mentioned this pull request Sep 25, 2020

Wrap EncryptedSharedPreferences initialization in a retry mechanism (EXPOSUREAPP-1851) #1226

Closed

This was referenced Sep 26, 2020

GeneralSecurityException #1239

Closed

Corona-Warn wird wiederholt beendet #1121

Closed

Fixed flaky test.

02492f6

ralfgehrer approved these changes Sep 28, 2020

View reviewed changes

harambasicluka added 2 commits September 28, 2020 14:23

Merge branch 'release/1.4.x' into fix/encryption-retry-mechanism-for-…

e2222c2

…1.4.x

Merge branch 'release/1.4.x' into fix/encryption-retry-mechanism-for-…

7c8b6df

…1.4.x

AlexanderAlferov approved these changes Sep 28, 2020

View reviewed changes

d4rken merged commit 7106941 into release/1.4.x Sep 28, 2020

d4rken deleted the fix/encryption-retry-mechanism-for-1.4.x branch September 28, 2020 14:42

d4rken mentioned this pull request Sep 29, 2020

Perform data reset for users already affected by the encryption issues (EXPOSUREAPP-1851/EXPOSUREAPP-2958) #1256

Merged

d4rken added this to the 1.4.0 milestone Oct 7, 2020

daimpi mentioned this pull request Oct 7, 2020

Instant app crash on opening, SQLiteException: file is not a database #1344

Closed

3 tasks

daimpi mentioned this pull request Oct 18, 2020

Cause 9002: file is not a database: , while compiling: select count(*) from sqlite_master; #642

Closed

stephankn mentioned this pull request Oct 24, 2020

Only splash displayed, then app closes. java.security.KeyException: Permantly failed to instantiate encrypted preferences #1469

Closed

3 tasks

grigoryk mentioned this pull request Jan 20, 2021

AndroidKeyStore issues mozilla-mobile/android-components#9459

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Wrap EncryptedSharedPreferences initialization in a retry mechanism (EXPOSUREAPP-1851) #1235

Wrap EncryptedSharedPreferences initialization in a retry mechanism (EXPOSUREAPP-1851) #1235

d4rken commented Sep 25, 2020

vaubaehn commented Sep 25, 2020

vaubaehn commented Sep 26, 2020 •

edited

Loading

d4rken commented Sep 28, 2020 •

edited

Loading

ralfgehrer Sep 28, 2020

d4rken Sep 28, 2020

AlexanderAlferov left a comment

vaubaehn commented Sep 28, 2020 •

edited

Loading

sonarqubecloud bot commented Sep 28, 2020

Wrap EncryptedSharedPreferences initialization in a retry mechanism (EXPOSUREAPP-1851) #1235

Wrap EncryptedSharedPreferences initialization in a retry mechanism (EXPOSUREAPP-1851) #1235

Conversation

d4rken commented Sep 25, 2020

Description

How to test

vaubaehn commented Sep 25, 2020

vaubaehn commented Sep 26, 2020 • edited Loading

d4rken commented Sep 28, 2020 • edited Loading

ralfgehrer Sep 28, 2020

Choose a reason for hiding this comment

d4rken Sep 28, 2020

Choose a reason for hiding this comment

AlexanderAlferov left a comment

Choose a reason for hiding this comment

vaubaehn commented Sep 28, 2020 • edited Loading

sonarqubecloud bot commented Sep 28, 2020

vaubaehn commented Sep 26, 2020 •

edited

Loading

d4rken commented Sep 28, 2020 •

edited

Loading

vaubaehn commented Sep 28, 2020 •

edited

Loading