From 9615bad7552f3f34b12b433b5c31ea08acf7c301 Mon Sep 17 00:00:00 2001 From: Ivan Dlugos <6349682+vaind@users.noreply.github.com> Date: Fri, 16 Aug 2024 20:10:44 +0200 Subject: [PATCH] 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 --- CHANGELOG.md | 6 + src/test/kotlin/StartupTimeTest.kt | 231 ++++++++++++++++------------- src/test/kotlin/TestBase.kt | 23 ++- 3 files changed, 154 insertions(+), 106 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 666dd37..27bc0dc 100644 --- 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 index 579f985..c529043 100644 --- 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>() for (j in apps.indices) { @@ -95,141 +99,166 @@ class StartupTimeTest : TestBase() { private fun collectStartupTimes(): List> { val measuredTimes = mutableListOf>() - 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 { + private fun collectAppStartupTimes(app: AppInfo): MutableList { + // clear logcat before test runs + if (baseOptions.platform == TestOptions.Platform.Android) { + withDriver { it.manage().logs().get("logcat") } + } + val appTimes = mutableListOf() 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 + ) { + 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 index 1ac4f63..ebc0870 100644 --- 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 withDriver(cb: (driver: AppiumDriver) -> T) : T { try { - cb(driver) - } finally { - driver.quit() + return cb(driver) + } catch (e: Exception) { + closeDriver() + throw e } } }