feat: automatic reconnect (#22)

* tmp: test many times to reproduce the issue * tmp reduce matrix tests for now * reconnect appium driver on error * chore: update changelog * rename: resetDriver to closeDriver * roll back temporary changes * explicitly throw in case all tries fail * Apply suggestions from code review
getsentry · Aug 16, 2024 · 9615bad · 9615bad
1 parent e5087e9
commit 9615bad
Show file tree

Hide file tree

Showing 3 changed files with 154 additions and 106 deletions.
diff --git a/CHANGELOG.md b/CHANGELOG.md
@@ -1,5 +1,11 @@
 # Changelog
 
+## 1.8.0
+
+### Features
+
+* Automatically reconnect the appium client in case of startup time collection failure. ([#22](https://github.com/getsentry/action-app-sdk-overhead-metrics/pull/22))
+
 ## 1.7.0
 
 ### Features

diff --git a/src/test/kotlin/StartupTimeTest.kt b/src/test/kotlin/StartupTimeTest.kt
@@ -39,7 +39,11 @@ class StartupTimeTest : TestBase() {
     fun `startup time`() {
         Assumptions.assumeTrue(baseOptions.startupTimeTest != null)
 
-        val measuredTimes = collectStartupTimes()
+        val measuredTimes = try {
+            collectStartupTimes()
+        } finally {
+            closeDriver()
+        }
         val filteredTimes = mutableListOf<List<Long>>()
 
         for (j in apps.indices) {
@@ -95,141 +99,166 @@ class StartupTimeTest : TestBase() {
     private fun collectStartupTimes(): List<List<Long>> {
         val measuredTimes = mutableListOf<List<Long>>()
 
-        withDriver { driver ->
-            for (appIndex in apps.indices) {
-                val app = apps[appIndex]
-                val needsTimes = options.runs - ceil(options.runs * 0.1).toInt()
+        for (appIndex in apps.indices) {
+            val app = apps[appIndex]
+            val needsTimes = options.runs - ceil(options.runs * 0.1).toInt()
 
-                for (retry in 1..options.retries) {
-                    if (retry > 1) {
-                        printf(
-                            "$logAppPrefix retrying startup time collection: %d/%d",
-                            app.name,
-                            retry,
-                            options.retries
-                        )
-                    }
+            for (retry in 1..options.retries) {
+                if (retry > 1) {
+                    printf(
+                        "$logAppPrefix retrying startup time collection: %d/%d",
+                        app.name,
+                        retry,
+                        options.retries
+                    )
+                }
 
-                    // sleep before the first test to improve the first run time
-                    Thread.sleep(1_000)
+                // sleep before the first test to improve the first run time
+                Thread.sleep(1_000)
 
-                    // clear logcat before test runs
-                    if (baseOptions.platform == TestOptions.Platform.Android) {
-                        driver.manage().logs().get("logcat")
-                    }
+                val appTimes = collectAppStartupTimes(app)
+                printf(
+                    "$logAppPrefix collected %d/%d startup times (try %d/%d)",
+                    app.name,
+                    appTimes.size,
+                    options.runs,
+                    retry,
+                    options.retries
+                )
 
-                    val appTimes = collectAppStartupTimes(app, driver)
+                if (appTimes.size == 0 || appTimes.size < needsTimes) {
                     printf(
-                        "$logAppPrefix collected %d/%d startup times (try %d/%d)",
+                        "$logAppPrefix not enough startup times collected: %d/%d. Expected at least %d",
                         app.name,
                         appTimes.size,
                         options.runs,
-                        retry,
-                        options.retries
+                        needsTimes
                     )
+                    continue
+                }
 
-                    if (appTimes.size == 0 || appTimes.size < needsTimes) {
+                if (options.stdDevMax > 0) {
+                    val stdDev = Stats.of(filterOutliers(appTimes)).populationStandardDeviation()
+                    if (stdDev > options.stdDevMax.toDouble()) {
                         printf(
-                            "$logAppPrefix not enough startup times collected: %d/%d. Expected at least %d",
+                            "$logAppPrefix stddev on the filtered startup-time list is too high: %.2f, expected %.2f at most.",
                             app.name,
-                            appTimes.size,
-                            options.runs,
-                            needsTimes
+                            stdDev,
+                            options.stdDevMax.toDouble()
                         )
                         continue
                     }
+                }
 
-                    if (options.stdDevMax > 0) {
-                        val stdDev = Stats.of(filterOutliers(appTimes)).populationStandardDeviation()
-                        if (stdDev > options.stdDevMax.toDouble()) {
-                            printf(
-                                "$logAppPrefix stddev on the filtered startup-time list is too high: %.2f, expected %.2f at most.",
-                                app.name,
-                                stdDev,
-                                options.stdDevMax.toDouble()
-                            )
-                            continue
-                        }
-                    }
+                measuredTimes.add(appTimes)
+                break
+            }
 
-                    measuredTimes.add(appTimes)
-                    break
-                }
+            if (measuredTimes.size != appIndex + 1) {
+                throw Exception("$logAppPrefix - all tries to collect startup times have failed")
             }
         }
 
         return measuredTimes
     }
 
-    private fun collectAppStartupTimes(app: AppInfo, driver: AppiumDriver): MutableList<Long> {
+    private fun collectAppStartupTimes(app: AppInfo): MutableList<Long> {
+        // clear logcat before test runs
+        if (baseOptions.platform == TestOptions.Platform.Android) {
+            withDriver { it.manage().logs().get("logcat") }
+        }
+
         val appTimes = mutableListOf<Long>()
         for (i in 1..options.runs) {
-            printf("$logAppPrefix measuring startup times: %d/%d", app.name, i, options.runs)
-
-            // kill the app and sleep before running the next iteration
-            when (baseOptions.platform) {
-                TestOptions.Platform.Android -> {
-                    val androidDriver = (driver as AndroidDriver)
-                    printf("%s", "${app.name} is installed: ${driver.isAppInstalled(app.name)}")
-
-                    try {
-                        val result = androidDriver.executeScript("mobile: startActivity",
-                            ImmutableMap.of("intent", "${app.name}/.${app.activity!!}", "wait", true)).toString()
-                        val error = Regex("Error: (.*)").find(result)?.groupValues
-                        if (error != null) {
-                            throw Exception(error[0])
-                        }
-                    } catch (e: Exception) {
-                        // in case the app can't be launched or crashes on startup, print logcat output
-                        val logs = driver.manage().logs().get("logcat").all.joinToString("\n")
-                        printf("%s", logs)
-                        throw(e)
-                    }
+            try {
+                withDriver { driver ->
+                    printf("$logAppPrefix measuring startup times: %d/%d", app.name, i, options.runs)
 
-                    androidDriver.terminateApp(app.name).shouldBe(true)
-
-                    val logEntries = driver.manage().logs().get("logcat")
-                    val regex = Regex("Displayed ${app.name}/\\.${app.activity}: \\+(?:([0-9]+)s)?([0-9]+)ms")
-                    val times = logEntries.mapNotNull {
-                        val groups = regex.find(it.message)?.groupValues
-                        if (groups == null) {
-                            null
-                        } else {
-                            printf("$logAppPrefix logcat entry processed: %s", app.name, it.message)
-                            val seconds = if (groups[1].isEmpty()) 0 else groups[1].toLong()
-                            seconds * 1000 + groups[2].toLong()
-                        }
-                    }
-                    if (times.size == 1) {
-                        appTimes.add(times.first())
-                    } else {
-                        printf("Expected 1 startup time in logcat, matching Regex '%s', but found %d", regex.pattern, times.size)
-                    }
+                    collectAppStartupTime(driver, app, appTimes)
+
+                    // sleep before running the next iteration
+                    Thread.sleep(sleepTimeMs)
                 }
+            } catch (e: Exception) {
+                printf(
+                    "$logAppPrefix startup time collection failed with %s",
+                    app.name,
+                    e.toString()
+                )
+                continue
+            }
 
-                TestOptions.Platform.IOS -> {
-                    val iosDriver = (driver as IOSDriver)
-                    val countBefore = driver.events.commands.filter { it.name == "execute" }.count()
-                    iosDriver.activateApp(app.name)
-                    // Note: with Appium 9 we can no longer filter by actual command name, see https://github.com/appium/java-client/issues/2219
-                    val times = driver.events.commands
-                        .filter { it.name == "execute" }
-                        .map { it.endTimestamp - it.startTimestamp }
+        }
+        return appTimes
+    }
 
+    private fun collectAppStartupTime(
+        driver: AppiumDriver,
+        app: AppInfo,
+        appTimes: MutableList<Long>
+    ) {
+        when (baseOptions.platform) {
+            TestOptions.Platform.Android -> {
+                val androidDriver = (driver as AndroidDriver)
+                printf("%s", "${app.name} is installed: ${driver.isAppInstalled(app.name)}")
+                driver.terminateApp(app.name)
+
+                try {
+                    val result = androidDriver.executeScript(
+                        "mobile: startActivity",
+                        ImmutableMap.of("intent", "${app.name}/.${app.activity!!}", "wait", true)
+                    ).toString()
+                    val error = Regex("Error: (.*)").find(result)?.groupValues
+                    if (error != null) {
+                        throw Exception(error[0])
+                    }
+                } catch (e: Exception) {
+                    // in case the app can't be launched or crashes on startup, print logcat output
+                    val logs = driver.manage().logs().get("logcat").all.joinToString("\n")
+                    printf("%s", logs)
+                    throw (e)
+                }
 
-                    if (times.size == countBefore + 1) {
-                        appTimes.add(times.last())
+                val logEntries = driver.manage().logs().get("logcat")
+                val regex = Regex("Displayed ${app.name}/\\.${app.activity}: \\+(?:([0-9]+)s)?([0-9]+)ms")
+                val times = logEntries.mapNotNull {
+                    val groups = regex.find(it.message)?.groupValues
+                    if (groups == null) {
+                        null
                     } else {
-                        printf("Expected %d activateApp events, but found %d", countBefore + 1, times.size)
+                        printf("$logAppPrefix logcat entry processed: %s", app.name, it.message)
+                        val seconds = if (groups[1].isEmpty()) 0 else groups[1].toLong()
+                        seconds * 1000 + groups[2].toLong()
                     }
-
-                    iosDriver.terminateApp(app.name)
+                }
+                if (times.size == 1) {
+                    appTimes.add(times.first())
+                } else {
+                    printf(
+                        "Expected 1 startup time in logcat, matching Regex '%s', but found %d",
+                        regex.pattern,
+                        times.size
+                    )
                 }
             }
 
-            // sleep before the next test run
-            Thread.sleep(sleepTimeMs)
+            TestOptions.Platform.IOS -> {
+                val iosDriver = (driver as IOSDriver)
+                driver.terminateApp(app.name)
+                val countBefore = driver.events.commands.filter { it.name == "execute" }.count()
+                iosDriver.activateApp(app.name)
+                // Note: with Appium 9 we can no longer filter by actual command name, see https://github.com/appium/java-client/issues/2219
+                val times = driver.events.commands
+                    .filter { it.name == "execute" }
+                    .map { it.endTimestamp - it.startTimestamp }
+
+                if (times.size == countBefore + 1) {
+                    appTimes.add(times.last())
+                } else {
+                    printf("Expected %d activateApp events, but found %d", countBefore + 1, times.size)
+                }
+
+            }
         }
-        return appTimes
     }
 }
diff --git a/src/test/kotlin/TestBase.kt b/src/test/kotlin/TestBase.kt
@@ -8,6 +8,19 @@ abstract class TestBase(
     protected val apps = baseOptions.apps
     protected val logAppPrefix = "App %-${apps.maxOfOrNull { it.name.length }}s"
     private val results = ResultFile()
+    private var _driver: AppiumDriver? = null
+    private val driver: AppiumDriver
+        get() {
+            if (_driver == null) {
+                _driver = baseOptions.createDriver()
+            }
+            return _driver as AppiumDriver
+        }
+
+    protected fun closeDriver() {
+        _driver?.quit()
+        _driver = null
+    }
 
     @Suppress("NOTHING_TO_INLINE") // Inline ensures the logger prints the actual caller.
     protected inline fun printf(format: String, vararg args: Any?, logLevel: Level = Level.INFO) {
@@ -20,12 +33,12 @@ abstract class TestBase(
         results.builder.save()
     }
 
-    protected fun withDriver(cb: (driver: AppiumDriver) -> Any) {
-        val driver = baseOptions.createDriver()
+    protected fun <T> withDriver(cb: (driver: AppiumDriver) -> T) : T {
         try {
-            cb(driver)
-        } finally {
-            driver.quit()
+            return cb(driver)
+        } catch (e: Exception) {
+            closeDriver()
+            throw e
         }
     }
 }