Refactor logging

badoo · Dec 12, 2024 · 8183467 · 8183467
1 parent 497d2a3
commit 8183467
Show file tree

Hide file tree

Showing 51 changed files with 382 additions and 578 deletions.
diff --git a/core/build.gradle.kts b/core/build.gradle.kts
@@ -25,13 +25,11 @@ dependencies {
     implementation(libs.apache.commons.io)
     implementation(libs.apache.commons.text)
     implementation(libs.gson)
-    implementation(libs.kotlin.logging)
     implementation(libs.kotlinx.coroutines.core)
     implementation(libs.ktor.client.core)
     implementation(libs.ktor.client.auth)
     implementation(libs.ktor.client.apache)
     implementation(libs.jackson.annotations)
-    implementation(libs.logback.classic)
     implementation(libs.slf4j.api)
     api(libs.koin.core)
 

diff --git a/core/src/main/kotlin/com/malinskiy/marathon/Marathon.kt b/core/src/main/kotlin/com/malinskiy/marathon/Marathon.kt
@@ -18,7 +18,6 @@ import com.malinskiy.marathon.execution.StrictRunProcessor
 import com.malinskiy.marathon.execution.TestParser
 import com.malinskiy.marathon.execution.TestShard
 import com.malinskiy.marathon.execution.progress.ProgressReporter
-import com.malinskiy.marathon.log.MarathonLogConfigurator
 import com.malinskiy.marathon.log.MarathonLogging
 import com.malinskiy.marathon.report.logs.LogsProvider
 import com.malinskiy.marathon.test.Test
@@ -38,13 +37,12 @@ class Marathon(
     private val cachedTestsReporter: CacheTestReporter,
     private val progressReporter: ProgressReporter,
     private val strictRunChecker: StrictRunChecker,
-    private val logConfigurator: MarathonLogConfigurator,
     private val logsProvider: LogsProvider,
     private val track: Track,
     private val timer: Timer
 ) : MarathonRunner {
 
-    private val logger = MarathonLogging.logger("Marathon")
+    private val logger = MarathonLogging.getLogger(Marathon::class.java)
 
     private val configurationValidator = LogicalConfigurationValidator()
     private val strictRunProcessor = StrictRunProcessor(configuration.strictRunConfiguration)
@@ -54,14 +52,18 @@ class Marathon(
     override suspend fun start() {
         logger.debug("Starting Marathon")
 
-        MarathonLogging.debug = configuration.debug
-        logConfigurator.configure()
+        configurationValidator.validate(configuration)
 
+        logger.debug("Initializing device provider")
         deviceProvider.initialize()
-        logger.debug("Finished loading device provider")
 
-        configurationValidator.validate(configuration)
+        if (configuration.outputDir.exists()) {
+            logger.info("Cleaning output directory ${configuration.outputDir}")
+            configuration.outputDir.deleteRecursively()
+        }
+        configuration.outputDir.mkdirs()
 
+        logger.debug("Initializing scheduler")
         val currentCoroutineContext = coroutineContext
         scheduler = Scheduler(
             deviceProvider,
@@ -77,38 +79,28 @@ class Marathon(
             timer,
             currentCoroutineContext
         )
-
-        logger.debug("Created scheduler")
-
-        if (configuration.outputDir.exists()) {
-            logger.info("Output directory ${configuration.outputDir} already exists")
-            configuration.outputDir.deleteRecursively()
-        }
-        configuration.outputDir.mkdirs()
-
         scheduler.initialize()
     }
 
     override suspend fun scheduleTests(componentInfo: ComponentInfo) {
         val parsedTests = testParser.extract(componentInfo)
         val tests = applyTestFilters(parsedTests)
 
-        logger.info("Scheduling ${tests.size} tests for $componentInfo")
-        logger.debug(tests.joinToString(", ") { it.toTestName() })
+        logger.info("Scheduling {} tests for {} component: {}", tests.size, componentInfo.name, tests.joinToString(", ") { it.toTestName() })
 
         val shard = prepareTestShard(tests, analytics)
         scheduler.addTests(shard)
     }
 
     override suspend fun stopAndWaitForCompletion(): Boolean {
-        logger.debug("Waiting for completion")
+        logger.debug("Waiting for test run to complete")
 
         try {
             scheduler.stopAndWaitForCompletion()
             onFinish()
         } catch (@Suppress("TooGenericExceptionCaught") e: Throwable) {
             // We don't want to catch these. If an exception was thrown, we should fail the execution
-            logger.error("Error occurred while finishing tests run", e)
+            logger.error("An error occurred while finishing test run", e)
             throw e
         }
         return progressReporter.aggregateResult()
@@ -125,7 +117,7 @@ class Marathon(
         try {
             tracker.finish()
         } catch (@Suppress("TooGenericExceptionCaught") e: Throwable) {
-            throw ReportGenerationException("Failed to generate test run report with exception", e)
+            throw ReportGenerationException("Failed to generate test run report", e)
         }
     }
 

diff --git a/core/src/main/kotlin/com/malinskiy/marathon/cache/gradle/GradleHttpCacheService.kt b/core/src/main/kotlin/com/malinskiy/marathon/cache/gradle/GradleHttpCacheService.kt
@@ -29,23 +29,23 @@ class GradleHttpCacheService(private val configuration: RemoteCacheConfiguration
 
     private val httpClient = createClient()
 
-    private val logger = MarathonLogging.logger("GradleHttpCacheService")
+    private val logger = MarathonLogging.getLogger(GradleHttpCacheService::class.java)
 
     override suspend fun load(key: CacheKey, reader: CacheEntryReader): Boolean =
         withContext(Dispatchers.IO) {
             try {
                 val response = httpClient.get(key.key)
                 if (response.status != HttpStatusCode.OK) {
                     if (response.status != HttpStatusCode.NotFound) {
-                        logger.warn("Got response status when loading cache entry for ${key.key} : ${response.status}")
+                        logger.warn("Got response status {} when loading cache entry for {}", response.status, key.key)
                     }
                     false
                 } else {
                     reader.readFrom(response.bodyAsChannel())
                     true
                 }
             } catch (exception: IOException) {
-                logger.warn("Error during loading cache entry for ${key.key}", exception)
+                logger.warn("Error loading cache entry for {}", key.key, exception)
                 false
             }
         }
@@ -59,10 +59,10 @@ class GradleHttpCacheService(private val configuration: RemoteCacheConfiguration
                     setBody(ByteArrayContent(stream.toByteArray()))
                 }
                 if (!response.status.isSuccess()) {
-                    logger.warn("Got response status when storing cache entry for ${key.key} : ${response.status}")
+                    logger.warn("Got response status {} when storing cache entry for {}", response.status, key.key)
                 }
             } catch (exception: IOException) {
-                logger.warn("Error during storing cache entry for ${key.key}", exception)
+                logger.warn("Error storing cache entry for {}", key.key, exception)
             } finally {
                 stream.close()
             }

diff --git a/core/src/main/kotlin/com/malinskiy/marathon/cache/test/TestCacheLoader.kt b/core/src/main/kotlin/com/malinskiy/marathon/cache/test/TestCacheLoader.kt
@@ -24,7 +24,7 @@ class TestCacheLoader(
     private val cacheKeyFactory: TestCacheKeyFactory
 ) {
 
-    private val logger = MarathonLogging.logger("TestCacheLoader")
+    private val logger = MarathonLogging.getLogger(TestCacheLoader::class.java)
 
     private val _results: Channel<CacheResult> = unboundedChannel()
     val results: ReceiveChannel<CacheResult>
@@ -49,13 +49,11 @@ class TestCacheLoader(
                     _results.send(result!!)
                 }
 
-                logger.debug {
-                    val hitOrMiss = when (result!!) {
-                        is Hit -> "hit"
-                        is Miss -> "miss"
-                    }
-                    "Cache $hitOrMiss for ${test.test.toSimpleSafeTestName()}, took $timeMillis milliseconds"
+                val hitOrMiss = when (result!!) {
+                    is Hit -> "hit"
+                    is Miss -> "miss"
                 }
+                logger.debug("Cache {} for {} took {}ms", hitOrMiss, test.test.toSimpleSafeTestName(), timeMillis)
             }
         }
     }
@@ -67,12 +65,12 @@ class TestCacheLoader(
                 if (configuration.strictRunConfiguration.filter.matches(test)) {
                     testCacheBlackList.add(test)
                 } else {
-                    testsToCheck.send(TestToCheck(poolId, test, isStrictRun = false))
+                    testsToCheck.send(TestToCheck(poolId, test))
                 }
             }
 
             if (testCacheBlackList.isNotEmpty()) {
-                logger.debug { "Cache miss for test in blacklist: ${testCacheBlackList.map { it.toSimpleSafeTestName() }} " }
+                logger.debug("Cache miss for tests in blacklist: {}", testCacheBlackList.map { it.toSimpleSafeTestName() })
                 _results.send(Miss(poolId, TestShard(testCacheBlackList)))
             }
         } else {
@@ -84,8 +82,8 @@ class TestCacheLoader(
         testsToCheck.close()
         cacheCheckCompleted.await()
         _results.close()
-        logger.debug { "Cache loader is terminated" }
+        logger.debug("Cache loader is terminated")
     }
 
-    private class TestToCheck(val poolId: DevicePoolId, val test: Test, val isStrictRun: Boolean)
+    private class TestToCheck(val poolId: DevicePoolId, val test: Test)
 }
diff --git a/core/src/main/kotlin/com/malinskiy/marathon/cache/test/TestCacheSaver.kt b/core/src/main/kotlin/com/malinskiy/marathon/cache/test/TestCacheSaver.kt
@@ -16,7 +16,7 @@ class TestCacheSaver(
     private val testCacheKeyProvider: TestCacheKeyFactory
 ) {
 
-    private val logger = MarathonLogging.logger("TestCacheSaver")
+    private val logger = MarathonLogging.getLogger(TestCacheSaver::class.java)
 
     private val tasks: Channel<SaveTask> = unboundedChannel()
     private lateinit var completableDeferred: Deferred<Unit>
@@ -38,7 +38,7 @@ class TestCacheSaver(
     suspend fun terminate() {
         tasks.close()
         completableDeferred.await()
-        logger.debug { "Cache saver is terminated" }
+        logger.debug("Cache saver is terminated")
     }
 
     private class SaveTask(val poolId: DevicePoolId, val result: TestResult)

diff --git a/core/src/main/kotlin/com/malinskiy/marathon/cache/test/TestResultsCache.kt b/core/src/main/kotlin/com/malinskiy/marathon/cache/test/TestResultsCache.kt
@@ -18,7 +18,7 @@ class TestResultsCache(
     private val track: Track
 ) {
 
-    private val logger = MarathonLogging.logger("TestResultsCache")
+    private val logger = MarathonLogging.getLogger(TestResultsCache::class.java)
 
     suspend fun load(key: CacheKey, test: Test): TestResult? {
         val start = Instant.now()
@@ -28,8 +28,8 @@ class TestResultsCache(
                 return null
             }
             return reader.testResult
-        } catch (exception: Throwable) {
-            logger.warn("Error during loading cache entry for ${test.toSimpleSafeTestName()}", exception)
+        } catch (e: Throwable) {
+            logger.warn("Error during loading cache entry for {}", test.toSimpleSafeTestName(), e)
             return null
         } finally {
             val finish = Instant.now()
@@ -42,8 +42,8 @@ class TestResultsCache(
         try {
             val writer = TestResultEntryWriter(testResult)
             cacheService.store(key, writer)
-        } catch (exception: Throwable) {
-            logger.warn("Error during storing cache entry for ${testResult.test.toSimpleSafeTestName()}", exception)
+        } catch (e: Throwable) {
+            logger.warn("Error during storing cache entry for {}", testResult.test.toSimpleSafeTestName(), e)
         } finally {
             val finish = Instant.now()
             track.cacheStore(start, finish, testResult.test)

diff --git a/core/src/main/kotlin/com/malinskiy/marathon/device/DevicePoolId.kt b/core/src/main/kotlin/com/malinskiy/marathon/device/DevicePoolId.kt
@@ -1,3 +1,5 @@
 package com.malinskiy.marathon.device
 
-data class DevicePoolId(val name: String)
+data class DevicePoolId(val name: String) {
+    override fun toString(): String = name
+}
diff --git a/core/src/main/kotlin/com/malinskiy/marathon/di/Modules.kt b/core/src/main/kotlin/com/malinskiy/marathon/di/Modules.kt
@@ -68,7 +68,7 @@ fun coreModule(timer: Timer?) = module {
     single<Timer> { timer ?: SystemTimer(get()) }
     single<ProgressReporter> { ProgressReporter(get()) }
     single<StrictRunChecker> { ConfigurationStrictRunChecker(get()) }
-    single<Marathon> { Marathon(get(), get(), get(), get(), get(), get(), get(), get(), get(), get(), get(), get(), get(), get(), get()) }
+    single<Marathon> { Marathon(get(), get(), get(), get(), get(), get(), get(), get(), get(), get(), get(), get(), get(), get()) }
 }
 
 fun KoinApplication.marathonConfiguration(configuration: Configuration): KoinApplication {

diff --git a/core/src/main/kotlin/com/malinskiy/marathon/exceptions/NoDevicesException.kt b/core/src/main/kotlin/com/malinskiy/marathon/exceptions/NoDevicesException.kt
@@ -1,3 +1,3 @@
 package com.malinskiy.marathon.exceptions
 
-class NoDevicesException(message: String) : RuntimeException(message)
+class NoDevicesException(message: String = "No devices found") : RuntimeException(message)
diff --git a/core/src/main/kotlin/com/malinskiy/marathon/execution/Configuration.kt b/core/src/main/kotlin/com/malinskiy/marathon/execution/Configuration.kt
@@ -32,7 +32,6 @@ data class Configuration(
     val filteringConfiguration: FilteringConfiguration,
     val strictRunConfiguration: StrictRunConfiguration,
 
-    val debug: Boolean,
     val ignoreFailures: Boolean,
     val strictMode: Boolean,
     val uncompletedTestRetryQuota: Int,
@@ -64,7 +63,6 @@ data class Configuration(
         filteringConfiguration: FilteringConfiguration?,
         strictRunConfiguration: StrictRunConfiguration?,
 
-        debug: Boolean?,
         ignoreFailures: Boolean?,
         strictMode: Boolean?,
         uncompletedTestRetryQuota: Int?,
@@ -94,7 +92,6 @@ data class Configuration(
             retryStrategy = retryStrategy ?: NoRetryStrategy(),
             filteringConfiguration = filteringConfiguration ?: FilteringConfiguration(),
             strictRunConfiguration = strictRunConfiguration ?: StrictRunConfiguration(),
-            debug = debug ?: true,
             ignoreFailures = ignoreFailures ?: false,
             strictMode = strictMode ?: false,
             uncompletedTestRetryQuota = uncompletedTestRetryQuota ?: Integer.MAX_VALUE,
@@ -122,7 +119,6 @@ data class Configuration(
             "retry" to retryStrategy.toString(),
             "filtering" to filteringConfiguration.toString(),
             "strictRun" to strictRunConfiguration.toString(),
-            "debug" to debug.toString(),
             "ignoreFailures" to ignoreFailures.toString(),
             "strictMode" to strictMode.toString(),
             "includeSerialRegexes" to includeSerialRegexes.toString(),

diff --git a/core/src/main/kotlin/com/malinskiy/marathon/execution/DevicePoolActor.kt b/core/src/main/kotlin/com/malinskiy/marathon/execution/DevicePoolActor.kt
@@ -41,7 +41,7 @@ class DevicePoolActor(
 ) :
     Actor<DevicePoolMessage>(parent = parent, context = context) {
 
-    private val logger = MarathonLogging.logger("DevicePoolActor[${poolId.name}]")
+    private val logger = MarathonLogging.getLogger("DevicePoolActor[$poolId]")
 
     override suspend fun receive(msg: DevicePoolMessage) {
         when (msg) {
@@ -82,7 +82,7 @@ class DevicePoolActor(
     private var noDevicesTimeoutDeferred: Deferred<Unit>? = null
 
     private suspend fun notifyDevices() {
-        logger.debug { "Notify devices" }
+        logger.debug("Notifying devices")
         devices.values.forEach {
             it.safeSend(DeviceEvent.WakeUp)
         }
@@ -146,19 +146,19 @@ class DevicePoolActor(
     }
 
     private suspend fun removeDevice(device: Device) {
-        logger.debug { "remove device ${device.serialNumber}" }
+        logger.debug("[{}] Removing from pool {}", device.serialNumber, poolId)
         val actor = devices.remove(device.serialNumber)
         actor?.safeSend(DeviceEvent.Terminate)
-        logger.debug { "devices.size = ${devices.size}" }
+        logger.debug("devices.size = {}", devices.size)
         if (noActiveDevices()) {
             if (!queue.stopRequested) return // we may receive new tests in the future
 
             noDevicesTimeoutDeferred?.cancel()
 
-            logger.debug { "scheduling terminating of device pool actor as no devices found" }
+            logger.debug("Scheduling termination of device pool actor as no devices found")
             noDevicesTimeoutDeferred = async(poolJob) {
                 delay(TimeUnit.MINUTES.toMillis(NO_DEVICES_IN_POOL_TIMEOUT_MINUTES))
-                logger.debug { "terminating device pool actor as no devices found after timeout" }
+                logger.debug("Terminating device pool actor as no devices found after timeout")
                 terminate()
             }
         }
@@ -170,11 +170,11 @@ class DevicePoolActor(
 
     private suspend fun addDevice(device: Device) {
         if (devices.containsKey(device.serialNumber)) {
-            logger.warn { "device ${device.serialNumber} already present in pool ${poolId.name}" }
+            logger.warn("[{}] Already present in pool {}. Skipping", device.serialNumber, poolId)
             return
         }
 
-        logger.debug { "add device ${device.serialNumber}" }
+        logger.debug("[{}] Adding to pool {}", device.serialNumber, poolId)
 
         noDevicesTimeoutDeferred?.cancel()