Improve logging in clientTests

ktor-client/ktor-client-tests/common/src/io/ktor/client/tests/utils/ClientLoader.kt

@@ -9,6 +9,8 @@ import io.ktor.test.*
 import kotlinx.coroutines.test.TestResult
 import kotlin.time.Duration
 import kotlin.time.Duration.Companion.minutes
+import kotlin.time.Duration.Companion.seconds
+import kotlin.time.DurationUnit
 
 internal expect val enginesToTest: Iterable<HttpClientEngineFactory<HttpClientEngineConfig>>
 internal expect val platformName: String
@@ -18,7 +20,7 @@ internal expect fun platformWaitForAllCoroutines()
 private typealias ClientTestFailure = TestFailure<HttpClientEngineFactory<*>>
 
 /**
- * Helper interface to test client.
+ * Helper interface to test clients.
  */
 abstract class ClientLoader(private val timeout: Duration = 1.minutes) {
     /**
@@ -34,27 +36,27 @@ abstract class ClientLoader(private val timeout: Duration = 1.minutes) {
         val skipPatterns = skipEngines.map(SkipEnginePattern::parse)
         val (selectedEngines, skippedEngines) = enginesToTest
             .partition { shouldRun(it.engineName, skipPatterns, onlyWithEngine) }
-        if (skippedEngines.isNotEmpty()) println("Skipped engines: ${skippedEngines.joinToString { it.engineName }}")
 
         return runTestWithData(
             selectedEngines,
             timeout = timeout,
             retries = retries,
+            afterEach = { result -> TestLogger.testResult(result, retries) },
+            afterAll = { TestLogger.skippedEngines(skippedEngines) },
             handleFailures = ::aggregatedAssertionError,
         ) { (engine, retry) ->
-            val retrySuffix = if (retry > 0) " [$retry]" else ""
-            println("Run test with engine ${engine.engineName}$retrySuffix")
+            TestLogger.testTry(engine, retry, retries)
             performTestWithEngine(engine, this@ClientLoader, block)
         }
     }
 
     private fun aggregatedAssertionError(failures: List<ClientTestFailure>): Nothing {
         val message = buildString {
-            val engineNames = failures.map { it.data.engineName }
+            val engineNames = failures.map { it.testCase.data.engineName }
             if (failures.size > 1) {
                 appendLine("Test failed for engines: ${engineNames.joinToString()}")
             }
-            failures.forEachIndexed { index, (cause, _) ->
+            failures.forEachIndexed { index, (_, cause) ->
                 appendLine("Test failed for engine '$platformName:${engineNames[index]}' with:")
                 appendLine(cause.stackTraceToString().prependIndent("  "))
             }
@@ -133,3 +135,45 @@ private data class SkipEnginePattern(
         }
     }
 }
+
+private object TestLogger {
+    private const val PASSED = "✓ PASSED"
+    private const val FAILED = "✕ FAILED"
+    private const val RETRY =  "• FAILED"
+    private const val DESCRIPTION_COLUMN_WIDTH = 20
+
+    fun skippedEngines(skippedEngines: List<HttpClientEngineFactory<*>>) {
+        if (skippedEngines.isNotEmpty()) println("⊘ Skipped engines: ${skippedEngines.joinToString { it.engineName }}")
+    }
+
+    fun testTry(engine: HttpClientEngineFactory<*>, retry: Int, retries: Int) {
+        if (retry == 0) {
+            print("▶ Run with ${engine.engineName}".padEnd(DESCRIPTION_COLUMN_WIDTH))
+        } else {
+            printTriesCounter(retry, retries)
+        }
+    }
+
+    fun testResult(testResult: TestExecutionResult<*>, maxRetries: Int) {
+        val retry = testResult.testCase.retry
+        val status = when {
+            testResult is TestSuccess -> PASSED
+            retry == maxRetries -> FAILED
+            else -> RETRY
+        } + " (${testResult.duration.format()})"
+
+        val cause = (testResult as? TestFailure<*>)?.cause
+        if (cause != null && retry == 0 && maxRetries > 0) {
+            println()
+            printTriesCounter(retry, maxRetries)
+        }
+        println(status)
+        if (cause != null) println("    └─ ${cause.message}")
+    }
+
+    private fun Duration.format(): String = if (this < 1.seconds) toString(DurationUnit.MILLISECONDS) else toString()
+
+    private fun printTriesCounter(retry: Int, maxRetries: Int) {
+        print("  [${retry + 1}/${maxRetries + 1}]".padEnd(DESCRIPTION_COLUMN_WIDTH))
+    }
+}

ktor-shared/ktor-test-base/common/src/io/ktor/test/runTestWithData.kt

@@ -11,6 +11,8 @@ import kotlin.coroutines.CoroutineContext
 import kotlin.coroutines.EmptyCoroutineContext
 import kotlin.time.Duration
 import kotlin.time.Duration.Companion.minutes
+import kotlin.time.TimeMark
+import kotlin.time.TimeSource
 
 /**
  * Represents a test case with associated data and retry attempt information.
@@ -20,13 +22,28 @@ import kotlin.time.Duration.Companion.minutes
  */
 data class TestCase<T>(val data: T, val retry: Int)
 
+/** Represents a failed test execution with the [cause] of failure. */
+data class TestFailure<T>(
+    override val testCase: TestCase<T>,
+    val cause: Throwable,
+    override val duration: Duration,
+) : TestExecutionResult<T>
+
+/** Represents a successful test execution. */
+data class TestSuccess<T>(
+    override val testCase: TestCase<T>,
+    override val duration: Duration,
+) : TestExecutionResult<T>
+
 /**
- * Represents a failure that occurred during the execution of a test case, along with the associated test data.
- *
- * @param cause The exception that caused the test to fail.
- * @param data The data associated with the test case that failed.
+ * The result of a test execution. Can be [TestFailure] or [TestSuccess].
+ * @property testCase The test case associated with this execution.
+ * @property duration The duration of the test execution.
  */
-data class TestFailure<T>(val cause: Throwable, val data: T)
+sealed interface TestExecutionResult<T> {
+    val testCase: TestCase<T>
+    val duration: Duration
+}
 
 /**
  * Executes multiple test cases with retry capabilities and timeout control.
@@ -70,29 +87,34 @@ fun <T> runTestWithData(
     context: CoroutineContext = EmptyCoroutineContext,
     timeout: Duration = 1.minutes,
     retries: Int = 1,
-    afterEach: (TestCase<T>, Throwable?) -> Unit = { _, _ -> },
+    afterEach: (TestExecutionResult<T>) -> Unit = {},
     handleFailures: (List<TestFailure<T>>) -> Unit = ::defaultAggregatedError,
     afterAll: () -> Unit = {},
     test: suspend TestScope.(TestCase<T>) -> Unit,
 ): TestResult {
     check(retries >= 0) { "Retries count shouldn't be negative but it is $retries" }
 
+    val timeSource = TimeSource.Monotonic
+    var start: TimeMark? = null
+
     val failures = mutableListOf<TestFailure<T>>()
     return runTestForEach(testCases) { data ->
         retryTest(retries) { retry ->
             val testCase = TestCase(data, retry)
 
             testWithRecover(
                 recover = { cause ->
-                    afterEach(testCase, cause)
+                    val failure = TestFailure(testCase, cause, start?.elapsedNow() ?: Duration.ZERO)
+                    afterEach(failure)
                     // Don't rethrow the exception on the last retry,
                     // save it instead to pass in handleFailures later
-                    if (retry == retries) failures += TestFailure(cause, data) else throw cause
+                    if (retry == retries) failures += failure else throw cause
                 }
             ) {
                 runTest(context, timeout = timeout) {
+                    start = timeSource.markNow()
                     test(testCase)
-                    afterEach(testCase, null)
+                    afterEach(TestSuccess(testCase, start?.elapsedNow() ?: Duration.ZERO))
                 }
             }
         }
@@ -105,8 +127,8 @@ fun <T> runTestWithData(
 private fun defaultAggregatedError(failures: List<TestFailure<*>>): Nothing {
     val message = buildString {
         appendLine("Test execution failed:")
-        for ((cause, data) in failures) {
-            appendLine("  Test case '$data' failed:")
+        for ((testCase, cause) in failures) {
+            appendLine("  Test case '${testCase.data}' failed:")
             appendLine(cause.stackTraceToString().prependIndent("    "))
         }
     }

ktor-shared/ktor-test-base/common/test/io/ktor/test/RunTestWithDataTest.kt

@@ -36,7 +36,7 @@ class RunTestWithDataTest {
     fun testEmptyTestCases() = runTestWithData(
         testCases = emptyList<Int>(),
         test = { fail("Should not be called") },
-        afterEach = { _, _ -> fail("Should not be called") },
+        afterEach = { fail("Should not be called") },
         handleFailures = { fail("Should not be called") },
     )
     //endregion
@@ -128,7 +128,7 @@ class RunTestWithDataTest {
             },
             handleFailures = {
                 assertEquals(1, it.size)
-                assertEquals(1, it.single().data)
+                assertEquals(1, it.single().testCase.data)
                 assertEquals(2, successfulItem)
             },
         )
@@ -142,9 +142,9 @@ class RunTestWithDataTest {
             testCases = 1..3,
             retries = 1,
             timeout = 15.milliseconds,
-            afterEach = { (id, retry), error ->
-                val status = if (error == null) "succeeded" else "failed: ${error.message}"
-                executionLog.add("Test $id: attempt $retry $status")
+            afterEach = { result ->
+                val status = if (result is TestFailure) "failed: ${result.cause.message}" else "succeeded"
+                executionLog.add("Test ${result.testCase.data}: attempt ${result.testCase.retry} $status")
             },
             test = { (id, retry) ->
                 println("${id}x$retry")