Fix the flaky "metrics" scheduler tests

This raises the timeout value for the testing API
from 250ms to 5seconds, since the CI infrastructure
could be under stress or slow. This additionally
adds more logging to the "metrics" ping scheduler
in order to make it easier to diagnose startup
problems.

Author: Dexterp37

components/service/glean/src/main/java/mozilla/components/service/glean/CommonMetricData.kt

@@ -44,7 +44,10 @@ interface CommonMetricData {
 
     companion object {
         internal const val DEFAULT_STORAGE_NAME = "default"
-        private const val JOB_TIMEOUT_MS = 250L
+        // The job timeout is useful in tests, which are usually running on CI
+        // infrastructure. The timeout needs to be reasonably high to account for
+        // slow or under-stress hardware.
+        private const val JOB_TIMEOUT_MS = 5000L
     }
 
     fun shouldRecord(logger: Logger): Boolean {

components/service/glean/src/main/java/mozilla/components/service/glean/ping/PingMaker.kt

@@ -119,6 +119,7 @@ internal class PingMaker(
      * @return a string holding the data for the ping, or null if there is no data to send.
      */
     fun collect(storage: String): String? {
+        logger.debug("Collecting $storage")
         val jsonPing = storageManager.collect(storage)
 
         // Return null if there is nothing in the jsonPing object so that this can be used by

components/service/glean/src/main/java/mozilla/components/service/glean/scheduler/MetricsPingScheduler.kt

@@ -201,6 +201,7 @@ internal class MetricsPingScheduler(val applicationContext: Context) {
             // The ping wasn't already sent today. Are we overdue or just waiting for
             // the right time?
             isAfterDueTime(now) -> {
+                logger.info("The 'metrics' ping is scheduled for immediate collection")
                 // The reason why we're collecting the "metrics" ping in the `Dispatchers.API`
                 // context is that we want to make sure no other metric API adds data before
                 // the ping is collected. All the exposed metrics API dispatch calls to the
@@ -214,6 +215,7 @@ internal class MetricsPingScheduler(val applicationContext: Context) {
             }
             else -> {
                 // This covers (3).
+                logger.info("The 'metrics' collection scheduled for the next calendar day")
                 schedulePingCollection(now, sendTheNextCalendarDay = false)
             }
         }

components/service/glean/src/main/java/mozilla/components/service/glean/storages/PingStorageEngine.kt

@@ -52,6 +52,7 @@ internal class PingStorageEngine(context: Context) {
      * @param ping Serialized JSON string representing the ping payload
      */
     fun store(uuidFileName: UUID, pingPath: String, pingData: String): Job {
+        logger.debug("Storing ping $uuidFileName in $pingPath")
         return GlobalScope.launch(KotlinDispatchers.IO) {
             // Check that the director exists and create it if needed
             ensureDirectoryExists(storageDirectory)

components/service/glean/src/test/java/mozilla/components/service/glean/GleanTest.kt

@@ -12,6 +12,7 @@ import androidx.test.core.app.ApplicationProvider
 import androidx.work.testing.WorkManagerTestInitHelper
 import kotlinx.coroutines.ExperimentalCoroutinesApi
 import kotlinx.coroutines.ObsoleteCoroutinesApi
+import kotlinx.coroutines.runBlocking
 import mozilla.components.service.glean.storages.StringsStorageEngine
 import mozilla.components.service.glean.scheduler.GleanLifecycleObserver
 import mozilla.components.service.glean.scheduler.PingUploadWorker
@@ -237,24 +238,29 @@ class GleanTest {
         val gleanSpy = spy<GleanInternalAPI>(GleanInternalAPI::class.java)
 
         gleanSpy.initialized = false
-        gleanSpy.handleBackgroundEvent()
+        runBlocking {
+            gleanSpy.handleBackgroundEvent()
+        }
         assertFalse(isWorkScheduled(PingUploadWorker.PING_WORKER_TAG))
     }
 
     @Test
     fun `Don't schedule pings if metrics disabled`() {
         Glean.setUploadEnabled(false)
 
-        Glean.handleBackgroundEvent()
-
+        runBlocking {
+            Glean.handleBackgroundEvent()
+        }
         assertFalse(isWorkScheduled(PingUploadWorker.PING_WORKER_TAG))
     }
 
     @Test
     fun `Don't schedule pings if there is no ping content`() {
         resetGlean(getContextWithMockedInfo())
 
-        Glean.handleBackgroundEvent()
+        runBlocking {
+            Glean.handleBackgroundEvent()
+        }
 
         // We should only have a baseline ping and no events or metrics pings since nothing was
         // recorded

components/service/glean/src/test/java/mozilla/components/service/glean/TestUtil.kt

@@ -180,7 +180,8 @@ internal fun isWorkScheduled(tag: String): Boolean {
  */
 internal fun triggerWorkManager() {
     // Check that the work is scheduled
-    Assert.assertTrue(isWorkScheduled(PingUploadWorker.PING_WORKER_TAG))
+    Assert.assertTrue("A scheduled PingUploadWorker must exist",
+        isWorkScheduled(PingUploadWorker.PING_WORKER_TAG))
 
     // Since WorkManager does not properly run in tests, simulate the work being done
     GlobalScope.launch(Dispatchers.IO) {

components/service/glean/src/test/java/mozilla/components/service/glean/scheduler/MetricsPingSchedulerTest.kt

@@ -262,7 +262,7 @@ class MetricsPingSchedulerTest {
 
             val expectedValue = "test-only metric"
             testMetric.set(expectedValue)
-            assertTrue(testMetric.testHasValue())
+            assertTrue("The initial test data must have been recorded", testMetric.testHasValue())
 
             // Manually call the function to trigger the collection.
             Glean.metricsPingScheduler.collectPingAndReschedule(Calendar.getInstance())
@@ -272,14 +272,15 @@ class MetricsPingSchedulerTest {
 
             // Fetch the ping from the server and decode its JSON body.
             val request = server.takeRequest(20L, AndroidTimeUnit.SECONDS)
-            assertEquals("POST", request.method)
             val metricsJsonData = request.body.readUtf8()
             val metricsJson = JSONObject(metricsJsonData)
 
             // Validate the received data.
             checkPingSchema(metricsJson)
-            assertEquals("metrics", metricsJson.getJSONObject("ping_info")["ping_type"])
+            assertEquals("The received ping must be a 'metrics' ping",
+                "metrics", metricsJson.getJSONObject("ping_info")["ping_type"])
             assertEquals(
+                "The reported metric must contain the expected value",
                 expectedValue,
                 metricsJson.getJSONObject("metrics")
                     .getJSONObject("string")
@@ -420,7 +421,7 @@ class MetricsPingSchedulerTest {
         // Record the data we expect to be in the final metrics ping.
         val expectedValue = "expected_data!"
         stringMetric.set(expectedValue)
-        assertTrue(stringMetric.testHasValue())
+        assertTrue("The initial expected data must be recorded", stringMetric.testHasValue())
 
         // Pretend glean is disabled. This is used so that any API call will be discarded and
         // glean will init again.
@@ -477,14 +478,15 @@ class MetricsPingSchedulerTest {
             }
 
             // Parse the received ping payload to a JSON object.
-            assertEquals("POST", request.method)
             val metricsJsonData = request.body.readUtf8()
             val metricsJson = JSONObject(metricsJsonData)
 
             // Validate the received data.
             checkPingSchema(metricsJson)
-            assertEquals("metrics", metricsJson.getJSONObject("ping_info")["ping_type"])
+            assertEquals("The received ping must be a 'metrics' ping",
+                "metrics", metricsJson.getJSONObject("ping_info")["ping_type"])
             assertEquals(
+                "The reported metric must contain the expected value",
                 expectedValue,
                 metricsJson.getJSONObject("metrics")
                     .getJSONObject("string")