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

[d4rken]

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:

• Cause 9002: file is not a database: , while compiling: select count(*) from sqlite_master; #642 (comment)
• https://issuetracker.google.com/issues/158234058
• GeneralSecurityException: decryption failed tink-crypto/tink#321

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

[sonarqubecloud]

Kudos, SonarCloud Quality Gate passed!

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

58.6% Coverage
0.0% Duplication

[jakobmoellerdev]

lgtm

[d4rken]

Replaced by #1235 (which is based on 1.4.x to allow for merge into next RC).