Add more info to Feature Flag error logging (#1579)

* More FF evaluation logging
* Include more detailed message on exceptions returned via Result.failure, too
* Add case to log connection errors with a descriptive message
* Bubble up status codes from DeferredResolver

Author: jyaganeh

urbanairship-core/src/main/java/com/urbanairship/deferred/DeferredResolver.kt

@@ -73,33 +73,40 @@ public class DeferredResolver internal constructor(
             return DeferredResult.TimedOut()
         }
 
-        when (response.status) {
+        when (val statusCode = response.status) {
             200 -> {
-                val value = response.value ?: return DeferredResult.RetriableError()
-                if (value.isNull) {
-                    return DeferredResult.RetriableError()
+                val value = response.value
+                // Check for null value or null JsonValue
+                if (value == null || value.isNull) {
+                    return DeferredResult.RetriableError(statusCode = statusCode)
                 }
                 return try {
                     DeferredResult.Success(resultParser(value))
                 } catch (ex: Exception) {
-                    UALog.e(ex) { "Failed ot parse deferred" }
-                    DeferredResult.RetriableError()
+                    UALog.e(ex) { "Failed to parse deferred!" }
+                    DeferredResult.RetriableError(statusCode = statusCode)
                 }
             }
             404 -> return DeferredResult.NotFound()
             409 -> return DeferredResult.OutOfDate()
             429 -> {
                 response.locationHeader?.let { locationMap.put(uri, it) }
-                return DeferredResult.RetriableError<T>(response.getRetryAfterHeader(TimeUnit.MILLISECONDS, 0))
+                return DeferredResult.RetriableError(
+                    retryAfter = response.getRetryAfterHeader(TimeUnit.MILLISECONDS, 0),
+                    statusCode = statusCode
+                )
             }
             307 -> {
                 val redirect = response.locationHeader
-                    ?: return DeferredResult.RetriableError<T>(response.getRetryAfterHeader(TimeUnit.MILLISECONDS, 0))
+                    ?: return DeferredResult.RetriableError(
+                        retryAfter = response.getRetryAfterHeader(TimeUnit.MILLISECONDS, 0),
+                        statusCode = statusCode
+                    )
                 locationMap[uri] = redirect
 
                 val retryDelay = response.getRetryAfterHeader(TimeUnit.MILLISECONDS, -1)
                 if (retryDelay > 0) {
-                    return DeferredResult.RetriableError<T>(retryDelay)
+                    return DeferredResult.RetriableError(retryDelay, statusCode = statusCode)
                 }
 
                 if (allowRetry) {
@@ -115,9 +122,9 @@ public class DeferredResolver internal constructor(
                     )
                 }
 
-                return DeferredResult.RetriableError<T>()
+                return DeferredResult.RetriableError(statusCode = statusCode)
             }
-            else -> return DeferredResult.RetriableError<T>()
+            else -> return DeferredResult.RetriableError(statusCode = statusCode)
         }
     }
 }

urbanairship-core/src/main/java/com/urbanairship/deferred/DeferredResult.kt

@@ -23,7 +23,11 @@ import kotlinx.coroutines.launch
 @RestrictTo(RestrictTo.Scope.LIBRARY_GROUP)
 public sealed class DeferredResult<T> {
     public class Success<T>(public val result: T) : DeferredResult<T>()
-    public class RetriableError<T>(public val retryAfter: Long? = null) : DeferredResult<T>()
+    public class RetriableError<T>(
+        public val retryAfter: Long? = null,
+        public val statusCode: Int? = null,
+        public val errorDescription: String? = null
+    ) : DeferredResult<T>()
     public class TimedOut<T>() : DeferredResult<T>()
     public class OutOfDate<T>() : DeferredResult<T>()
     public class NotFound<T>() : DeferredResult<T>()

urbanairship-core/src/test/java/com/urbanairship/deferred/DeferredResolverTest.kt

@@ -10,8 +10,15 @@ import com.urbanairship.json.JsonValue
 import io.mockk.every
 import io.mockk.mockk
 import java.util.Locale
+import kotlinx.coroutines.Dispatchers
+import kotlinx.coroutines.ExperimentalCoroutinesApi
+import kotlinx.coroutines.test.StandardTestDispatcher
+import kotlinx.coroutines.test.TestDispatcher
 import kotlinx.coroutines.test.TestResult
+import kotlinx.coroutines.test.resetMain
 import kotlinx.coroutines.test.runTest
+import kotlinx.coroutines.test.setMain
+import org.junit.After
 import org.junit.Assert.assertEquals
 import org.junit.Assert.assertNotNull
 import org.junit.Assert.assertNull
@@ -20,20 +27,30 @@ import org.junit.Before
 import org.junit.Test
 import org.junit.runner.RunWith
 
+@OptIn(ExperimentalCoroutinesApi::class)
 @RunWith(AndroidJUnit4::class)
 public class DeferredResolverTest {
+    public val testDispatcher: TestDispatcher = StandardTestDispatcher()
+
     public lateinit var resolver: DeferredResolver
     internal val requestSession = TestRequestSession()
 
     @Before
     public fun setup() {
+        Dispatchers.setMain(testDispatcher)
+
         val config: AirshipRuntimeConfig = mockk()
         every { config.requestSession } returns requestSession
         every { config.platform } returns UAirship.ANDROID_PLATFORM
 
         resolver = DeferredResolver(config, AudienceOverridesProvider())
     }
 
+    @After
+    public fun tearDown() {
+        Dispatchers.resetMain()
+    }
+
     @Test
     public fun testSuccess(): TestResult = runTest {
         val expected = JsonValue.wrap("body")

urbanairship-feature-flag/src/main/java/com/urbanairship/featureflag/FeatureFlagException.kt

@@ -6,11 +6,34 @@ package com.urbanairship.featureflag
  * Thrown when a feature flag data is stale or outdated.
  */
 public sealed class FeatureFlagException(override val message: String) : Exception(message) {
-    public class FailedToFetch() : FeatureFlagException("failed to fetch data")
+    public class FailedToFetch(message: String) : FeatureFlagException(message)
 }
 
 internal sealed class FeatureFlagEvaluationException(override val message: String) : Exception(message) {
-    class ConnectionError() : FeatureFlagEvaluationException("Unable to fetch data")
+    class ConnectionError(
+        val statusCode: Int? = null,
+        val errorDescription: String? = null,
+    ) : FeatureFlagEvaluationException(makeMessage(statusCode, errorDescription)) {
+
+        private companion object {
+            @JvmStatic
+            private fun makeMessage(statusCode: Int? = null, errorDescription: String? = null): String {
+                var msg = "Unable to fetch data"
+
+                msg += if (statusCode != null) {
+                    " ($statusCode)."
+                } else {
+                    "."
+                }
+
+                if (errorDescription != null) {
+                    msg += " $errorDescription"
+                }
+
+                return msg
+            }
+        }
+    }
     class OutOfDate() : FeatureFlagEvaluationException("Remote data is outdated")
     class StaleNotAllowed() : FeatureFlagEvaluationException("Stale data is not allowed")
 }

urbanairship-feature-flag/src/main/java/com/urbanairship/featureflag/FeatureFlagManager.kt

@@ -91,7 +91,9 @@ public class FeatureFlagManager internal constructor(
 
     private suspend fun flag(name: String, allowRefresh: Boolean): Result<FeatureFlag> {
         if (!privacyManager.isEnabled(PrivacyManager.Feature.FEATURE_FLAGS)) {
-            return Result.failure(IllegalStateException("Feature flags are disabled"))
+            val msg = "Failed to fetch feature flag: '$name'! Feature flags are disabled."
+            UALog.e(msg)
+            return Result.failure(IllegalStateException(msg))
         }
 
         val remoteDataInfo = remoteData.fetchFlagRemoteInfo(name)
@@ -100,15 +102,17 @@ public class FeatureFlagManager internal constructor(
             return result
         }
 
-        return when (result.exceptionOrNull()) {
+        return when (val e = result.exceptionOrNull()) {
             is FeatureFlagEvaluationException.OutOfDate -> {
                 remoteData.notifyOutOfDate(remoteDataInfo.remoteDataInfo)
 
                 if (allowRefresh) {
                     remoteData.waitForRemoteDataRefresh()
                     flag(name = name, allowRefresh = false)
                 } else {
-                    Result.failure(FeatureFlagException.FailedToFetch())
+                    val msg = "Failed to fetch feature flag: '$name'! Remote data is outdated."
+                    UALog.e(e, msg)
+                    Result.failure(FeatureFlagException.FailedToFetch(msg).apply { initCause(e) })
                 }
             }
 
@@ -117,11 +121,25 @@ public class FeatureFlagManager internal constructor(
                     remoteData.waitForRemoteDataRefresh()
                     flag(name = name, allowRefresh = false)
                 } else {
-                    Result.failure(FeatureFlagException.FailedToFetch())
+                    val msg = "Failed to fetch feature flag: '$name'! Stale data is not allowed."
+                    UALog.e(e, msg)
+                    Result.failure(FeatureFlagException.FailedToFetch(msg).apply { initCause(e) })
                 }
             }
 
-            else -> Result.failure(FeatureFlagException.FailedToFetch())
+            is FeatureFlagEvaluationException.ConnectionError -> {
+                val msg = "Failed to fetch feature flag: '$name'! Network error" +
+                        "${e.statusCode?.let { " ($it)" }}." +
+                        "${e.errorDescription?.let { " $it" }}"
+                UALog.e(e, msg)
+                Result.failure(FeatureFlagException.FailedToFetch(msg).apply { initCause(e) })
+            }
+
+            else -> {
+                val msg = "Failed to fetch feature flag: '$name'!"
+                UALog.e(msg)
+                Result.failure(FeatureFlagException.FailedToFetch(msg))
+            }
         }
     }
 
@@ -199,7 +217,7 @@ public class FeatureFlagManager internal constructor(
                 }
             }
 
-            /// If we have an error, flag is eligible, or the last flag return
+            // If we have an error, flag is eligible, or the last flag return
             if (result.isFailure || result.getOrNull()?.isEligible == true || isLast) {
                 return evaluatedControl(result, info, deviceInfoProvider)
             }

urbanairship-feature-flag/src/main/java/com/urbanairship/featureflag/FlagDeferredResolver.kt

@@ -107,7 +107,14 @@ internal class FlagDeferredResolver(
                 val backOff = result.retryAfter ?: DEFAULT_BACKOFF_MS
                 if (!allowRetry || backOff > IMMEDIATE_BACKOFF_RETRY_MS) {
                     backOffIntervals[requestId] = clock.currentTimeMillis() + backOff
-                    return Result.failure(FeatureFlagEvaluationException.ConnectionError())
+                    return Result.failure(FeatureFlagEvaluationException.ConnectionError(
+                        statusCode = result.statusCode,
+                        errorDescription = if (!allowRetry) {
+                            "Retries are not allowed"
+                        } else {
+                            "Unable to immediately retry. Try again in $backOff ms."
+                        }
+                    ))
                 }
 
                 if (backOff > 0) {