Improve analytics error handling (DEV) (#2413)

* Catch exceptions produced by donor modules and allow the process to continue.
On tester builds log these background issues in the bug reporter.

* Add small logging test case.

Co-authored-by: Ralf Gehrer <ralfgehrer@users.noreply.github.com>
Co-authored-by: harambasicluka <64483219+harambasicluka@users.noreply.github.com>

Corona-Warn-App/src/deviceForTesters/java/de/rki/coronawarnapp/bugreporting/reporter/DefaultBugReporter.kt

@@ -20,7 +20,7 @@ class DefaultBugReporter @Inject constructor(
 ) : BugReporter {
 
     override fun report(throwable: Throwable, tag: String?, info: String?) {
-        Timber.e(throwable, "Processing reported bug (info=$info) from $tag.")
+        Timber.v("Processing reported bug (info=$info) from $tag: $throwable")
         scope.launch(context = dispatcherProvider.IO) {
             val event = processor.processor(throwable, tag, info)
             repository.save(event)

Corona-Warn-App/src/deviceForTesters/java/de/rki/coronawarnapp/test/crash.ui/CrashReportAdapter.kt

@@ -37,8 +37,8 @@ class CrashReportAdapter(private val itemClickListener: (bugEvent: BugEvent) ->
     class CrashHolder(private val binding: ViewCrashreportListItemBinding) :
         RecyclerView.ViewHolder(binding.root) {
         fun bind(bugEvent: BugEvent, pos: Int) {
-            binding.crashReportTitle = "Error #${pos + 1}"
-            binding.message = bugEvent.exceptionMessage
+            binding.crashReportTitle = "#${pos + 1} ${bugEvent.exceptionClass}"
+            binding.message = bugEvent.info ?: bugEvent.exceptionMessage
             binding.crashReportDateFormatted =
                 bugEvent.createdAt.toDateTime(DateTimeZone.getDefault()).toString()
                     .replace("T", "  ")

Corona-Warn-App/src/deviceForTesters/res/layout/view_crashreport_list_item.xml

@@ -57,13 +57,13 @@
 
             <TextView
                 android:id="@+id/textViewCrashReportShortMessage"
-                style="@style/body1"
+                style="@style/TextAppearance.MaterialComponents.Caption"
                 android:layout_width="0dp"
                 android:layout_height="wrap_content"
-                android:layout_marginTop="24dp"
+                android:layout_marginTop="4dp"
                 android:ellipsize="end"
                 android:inputType="none"
-                android:maxLines="1"
+                android:maxLines="4"
                 android:text="@{message}"
                 app:layout_constraintEnd_toEndOf="parent"
                 app:layout_constraintStart_toStartOf="parent"

Corona-Warn-App/src/main/java/de/rki/coronawarnapp/bugreporting/BugReporter.kt

@@ -9,7 +9,7 @@ interface BugReporter {
 }
 
 fun Throwable.reportProblem(tag: String? = null, info: String? = null) {
-    Timber.tag("BugReporter").v(this, "report(tag=$tag, info=$info)")
+    Timber.tag(tag ?: "BugReporter").e(this, info)
 
     if (CWADebug.isAUnitTest) return
     val reporter = AppInjector.component.bugReporter

Corona-Warn-App/src/main/java/de/rki/coronawarnapp/datadonation/analytics/Analytics.kt

@@ -63,11 +63,8 @@ class Analytics @Inject constructor(
 
             return true
         } catch (err: Exception) {
-            err.reportProblem(
-                tag = TAG,
-                info = "An error occurred during analytics submission"
-            )
             Timber.e(err, "Error during analytics submission")
+            err.reportProblem(tag = TAG, info = "An error occurred during analytics submission")
             return false
         }
     }
@@ -75,14 +72,25 @@ class Analytics @Inject constructor(
     suspend fun collectContributions(ppaDataBuilder: PpaData.PPADataAndroid.Builder): List<DonorModule.Contribution> {
         val request: DonorModule.Request = object : DonorModule.Request {}
 
-        val contributions = donorModules.map {
-            Timber.d("Beginning donation for module: %s", it::class.simpleName)
-            it.beginDonation(request)
+        val contributions = donorModules.mapNotNull {
+            val moduleName = it::class.simpleName
+            Timber.d("Beginning donation for module: %s", moduleName)
+            try {
+                it.beginDonation(request)
+            } catch (e: Exception) {
+                e.reportProblem(TAG, "beginDonation($request): $moduleName failed")
+                null
+            }
         }
 
         contributions.forEach {
-            Timber.d("Injecting contribution: %s", it::class.simpleName)
-            it.injectData(ppaDataBuilder)
+            val moduleName = it::class.simpleName
+            Timber.d("Injecting contribution: %s", moduleName)
+            try {
+                it.injectData(ppaDataBuilder)
+            } catch (e: Exception) {
+                e.reportProblem(TAG, "injectData($ppaDataBuilder): $moduleName failed")
+            }
         }
 
         return contributions
@@ -101,8 +109,13 @@ class Analytics @Inject constructor(
         val success = trySubmission(analyticsConfig, analyticsProto)
 
         contributions.forEach {
-            Timber.d("Finishing contribution: %s", it::class.simpleName)
-            it.finishDonation(success)
+            val moduleName = it::class.simpleName
+            Timber.d("Finishing contribution: %s", moduleName)
+            try {
+                it.finishDonation(success)
+            } catch (e: Exception) {
+                e.reportProblem(TAG, "finishDonation($success): $moduleName failed")
+            }
         }
 
         if (success) {
@@ -142,8 +155,7 @@ class Analytics @Inject constructor(
     @VisibleForTesting(otherwise = VisibleForTesting.PRIVATE)
     fun stopDueToTimeSinceOnboarding(): Boolean {
         val onboarding = LocalData.onboardingCompletedTimestamp()?.let { Instant.ofEpochMilli(it) } ?: return true
-        return onboarding.plus(Hours.hours(ONBOARDING_DELAY_HOURS).toStandardDuration())
-            .isAfter(timeStamper.nowUTC)
+        return onboarding.plus(Hours.hours(ONBOARDING_DELAY_HOURS).toStandardDuration()).isAfter(timeStamper.nowUTC)
     }
 
     suspend fun submitIfWanted() = submissionLockoutMutex.withLock {

Corona-Warn-App/src/test/java/de/rki/coronawarnapp/bugreporting/BugReporterTest.kt

+package de.rki.coronawarnapp.bugreporting
+
+import org.junit.jupiter.api.Test
+import testhelpers.BaseTest
+
+class BugReporterTest : BaseTest() {
+
+    @Test
+    fun `test emtpy tag`() {
+        // This just tests the timber statement
+        Exception().reportProblem(info = "info")
+    }
+
+    @Test
+    fun `test empty info and tag`() {
+        // This just tests the timber statement
+        Exception().reportProblem()
+    }
+}

Corona-Warn-App/src/test/java/de/rki/coronawarnapp/datadonation/analytics/AnalyticsTest.kt

@@ -7,6 +7,7 @@ import de.rki.coronawarnapp.appconfig.SafetyNetRequirements
 import de.rki.coronawarnapp.appconfig.SafetyNetRequirementsContainer
 import de.rki.coronawarnapp.datadonation.analytics.modules.DonorModule
 import de.rki.coronawarnapp.datadonation.analytics.modules.exposureriskmetadata.ExposureRiskMetadataDonor
+import de.rki.coronawarnapp.datadonation.analytics.modules.usermetadata.UserMetadataDonor
 import de.rki.coronawarnapp.datadonation.analytics.server.DataDonationAnalyticsServer
 import de.rki.coronawarnapp.datadonation.analytics.storage.AnalyticsSettings
 import de.rki.coronawarnapp.datadonation.analytics.storage.LastAnalyticsSubmissionLogger
@@ -24,8 +25,10 @@ import io.mockk.coVerify
 import io.mockk.every
 import io.mockk.impl.annotations.MockK
 import io.mockk.just
+import io.mockk.mockk
 import io.mockk.mockkObject
 import io.mockk.spyk
+import kotlinx.coroutines.test.runBlockingTest
 import org.joda.time.Days
 import org.joda.time.Instant
 import org.junit.jupiter.api.AfterEach
@@ -71,6 +74,8 @@ class AnalyticsTest : BaseTest() {
         every { LocalData.onboardingCompletedTimestamp() } returns twoDaysAgo.millis
 
         every { analyticsConfig.safetyNetRequirements } returns SafetyNetRequirementsContainer()
+
+        coEvery { dataDonationAnalyticsServer.uploadAnalyticsData(any()) } just Runs
     }
 
     @AfterEach
@@ -78,14 +83,12 @@ class AnalyticsTest : BaseTest() {
         clearAllMocks()
     }
 
-    private fun createDonorModules(): Set<DonorModule> = setOf(exposureRiskMetadataDonor)
-
-    private fun createInstance() = spyk(
+    private fun createInstance(modules: Set<DonorModule> = setOf(exposureRiskMetadataDonor)) = spyk(
         Analytics(
             dataDonationAnalyticsServer = dataDonationAnalyticsServer,
             appConfigProvider = appConfigProvider,
             deviceAttestation = deviceAttestation,
-            donorModules = createDonorModules(),
+            donorModules = modules,
             settings = settings,
             logger = lastAnalyticsSubmissionLogger,
             timeStamper = timeStamper
@@ -233,8 +236,6 @@ class AnalyticsTest : BaseTest() {
                 override fun requirePass(requirements: SafetyNetRequirements) {}
             }
 
-        coEvery { dataDonationAnalyticsServer.uploadAnalyticsData(any()) } just Runs
-
         val analytics = createInstance()
 
         runBlockingTest2 {
@@ -246,4 +247,84 @@ class AnalyticsTest : BaseTest() {
             dataDonationAnalyticsServer.uploadAnalyticsData(analyticsRequest)
         }
     }
+
+    @Test
+    fun `despite error on beginDonation modules can still cleanup`() {
+        val userMetadataDonor = mockk<UserMetadataDonor>().apply {
+            coEvery { beginDonation(any()) } throws Exception("KABOOM!")
+        }
+        val modules = setOf(exposureRiskMetadataDonor, userMetadataDonor)
+
+        val mockExposureRisk = mockk<DonorModule.Contribution>().apply {
+            coEvery { injectData(any()) } just Runs
+            coEvery { finishDonation(any()) } just Runs
+        }
+        coEvery { exposureRiskMetadataDonor.beginDonation(any()) } returns mockExposureRisk
+
+        coEvery { deviceAttestation.attest(any()) } returns object : DeviceAttestation.Result {
+            override val accessControlProtoBuf: PpacAndroid.PPACAndroid
+                get() = PpacAndroid.PPACAndroid.getDefaultInstance()
+
+            override fun requirePass(requirements: SafetyNetRequirements) {}
+        }
+
+        val analytics = createInstance(modules = modules)
+
+        runBlockingTest {
+            analytics.submitIfWanted()
+        }
+
+        coVerify(exactly = 1) {
+            userMetadataDonor.beginDonation(any())
+
+            exposureRiskMetadataDonor.beginDonation(any())
+            mockExposureRisk.injectData(any())
+            mockExposureRisk.finishDonation(true)
+
+            analytics.submitAnalyticsData(any())
+        }
+    }
+
+    @Test
+    fun `despite errors during donation modules can still cleanup`() {
+        val userMetaDataDonation = mockk<DonorModule.Contribution>().apply {
+            coEvery { injectData(any()) } throws Exception("KAPOW!")
+            coEvery { finishDonation(any()) } throws Exception("CRUNCH!")
+        }
+        val userMetadataDonor = mockk<UserMetadataDonor>().apply {
+            coEvery { beginDonation(any()) } returns userMetaDataDonation
+        }
+        val modules = setOf(exposureRiskMetadataDonor, userMetadataDonor)
+
+        val exposureRiskDonation = mockk<ExposureRiskMetadataDonor.ExposureRiskMetadataContribution>().apply {
+            coEvery { injectData(any()) } just Runs
+            coEvery { finishDonation(any()) } just Runs
+        }
+        coEvery { exposureRiskMetadataDonor.beginDonation(any()) } returns exposureRiskDonation
+
+        coEvery { deviceAttestation.attest(any()) } returns object : DeviceAttestation.Result {
+            override val accessControlProtoBuf: PpacAndroid.PPACAndroid
+                get() = PpacAndroid.PPACAndroid.getDefaultInstance()
+
+            override fun requirePass(requirements: SafetyNetRequirements) {}
+        }
+
+        val analytics = createInstance(modules = modules)
+
+        runBlockingTest {
+            analytics.submitIfWanted()
+        }
+
+        coVerify(exactly = 1) {
+            exposureRiskMetadataDonor.beginDonation(any())
+            exposureRiskDonation.injectData(any())
+            exposureRiskDonation.finishDonation(true)
+
+            userMetadataDonor.beginDonation(any())
+            userMetaDataDonation.injectData(any())
+            userMetaDataDonation.finishDonation(true)
+
+            analytics.submitAnalyticsData(any())
+        }
+    }
 }