[Native][tests] Log test process stdout/stderr when failed on timeout

2021-11-24 13:13:30 +03:00
parent 3e0761b4fc
commit 9c1c1805a3
6 changed files with 111 additions and 39 deletions
@@ -113,16 +113,7 @@ internal abstract class LoggedData {
    ) : LoggedData() {
        override fun computeText() = buildString {
            appendLine("TEST RUN:")
-            appendLine("- Exit code: ${runResult.exitCode}")
-            appendDuration(runResult.duration)
-            appendLine()
-            appendLine("========== BEGIN: TEST STDOUT ==========")
-            if (runResult.stdOut.isNotEmpty()) appendLine(runResult.stdOut.trimEnd())
-            appendLine("========== END: TEST STDOUT ==========")
-            appendLine()
-            appendLine("========== BEGIN: TEST STDERR ==========")
-            if (runResult.stdErr.isNotEmpty()) appendLine(runResult.stdErr.trimEnd())
-            appendLine("========== END: TEST STDERR ==========")
+            appendCommonRunResult(runResult)
            appendLine()
            appendLine(parameters)
        }
@@ -145,15 +136,14 @@ internal abstract class LoggedData {
        }
    }

-    class TestRunTimeoutExceeded(parameters: TestRunParameters, timeout: Duration) : TimeoutExceeded(parameters, timeout)
-
-    abstract class TimeoutExceeded(
-        private val parameters: LoggedData,
-        private val timeout: Duration
+    class TestRunTimeoutExceeded(
+        private val parameters: TestRunParameters,
+        private val runResult: RunResult.TimeoutExceeded
    ) : LoggedData() {
        override fun computeText() = buildString {
            appendLine("TIMED OUT:")
-            appendLine("- Max permitted duration: $timeout")
+            appendLine("- Max permitted duration: ${runResult.timeout}")
+            appendCommonRunResult(runResult)
            appendLine()
            appendLine(parameters)
        }
@@ -191,5 +181,19 @@ internal abstract class LoggedData {

        protected fun StringBuilder.appendDuration(duration: Duration): StringBuilder =
            append("- Duration: ").appendLine(duration.toString(DurationUnit.SECONDS, 2))
+
+        protected fun StringBuilder.appendCommonRunResult(runResult: RunResult): StringBuilder {
+            appendLine("- Exit code: ${runResult.exitCode ?: "<unknown>"}")
+            appendDuration(runResult.duration)
+            appendLine()
+            appendLine("========== BEGIN: TEST STDOUT ==========")
+            if (runResult.output.stdOut.isNotEmpty()) appendLine(runResult.output.stdOut.trimEnd())
+            appendLine("========== END: TEST STDOUT ==========")
+            appendLine()
+            appendLine("========== BEGIN: TEST STDERR ==========")
+            if (runResult.output.stdErr.isNotEmpty()) appendLine(runResult.output.stdErr.trimEnd())
+            appendLine("========== END: TEST STDERR ==========")
+            return this
+        }
    }
 }
@@ -7,6 +7,7 @@ package org.jetbrains.kotlin.konan.blackboxtest.support.runner

 import org.jetbrains.kotlin.konan.blackboxtest.support.TestExecutable
 import org.jetbrains.kotlin.konan.blackboxtest.support.runner.AbstractRunner.AbstractRun
+import org.jetbrains.kotlin.konan.blackboxtest.support.util.readOutput
 import kotlin.time.*

 internal abstract class AbstractLocalProcessRunner<R>(private val executionTimeout: Duration) : AbstractRunner<R>() {
@@ -18,32 +19,40 @@ internal abstract class AbstractLocalProcessRunner<R>(private val executionTimeo

    @OptIn(ExperimentalTime::class)
    final override fun buildRun() = AbstractRun {
-        val exitCode: Int
-
-        val stdOut: String
-        val stdErr: String
-
-        val duration = measureTime {
+        val (result, duration) = measureTimedValue {
            val process = ProcessBuilder(programArgs).directory(executable.executableFile.parentFile).start()
            customizeProcess(process)

-            val hasFinishedInTime = process.waitFor(
+            val hasFinishedOnTime = process.waitFor(
                executionTimeout.toLong(DurationUnit.MILLISECONDS),
                DurationUnit.MILLISECONDS.toTimeUnit()
            )

-            if (!hasFinishedInTime) {
-                process.destroy()
-                return@AbstractRun RunResult.TimeoutExceeded(executionTimeout)
+            process to hasFinishedOnTime
+        }
+        val (process, hasFinishedOnTime) = result
+
+        // Don't use blocking read from stdout/stderr on non-finished process. If the process is hanging this would result in hanging test.
+        val output = process.readOutput(nonBlocking = !hasFinishedOnTime)
+
+        if (hasFinishedOnTime) {
+            val exitCode: Int = process.exitValue()
+
+            RunResult.Completed(exitCode, duration, output)
+        } else {
+            process.destroy() // Initiate destroy of non-finished process.
+            Thread.sleep(5) // And give it a white to become actually destroyed.
+
+            val exitCode: Int? = try {
+                // If we are lucky enough, the process is destroyed to this moment. And it's possible to fetch exit code.
+                process.exitValue()
+            } catch (_: IllegalThreadStateException) {
+                // Still not destroyed. Let's go further.
+                null
            }

-            exitCode = process.exitValue()
-
-            stdOut = process.inputStream.bufferedReader().readText()
-            stdErr = process.errorStream.bufferedReader().readText()
+            RunResult.TimeoutExceeded(executionTimeout, exitCode, duration, output)
        }
-
-        RunResult.Completed(exitCode, duration, stdOut, stdErr)
    }

    abstract override fun buildResultHandler(runResult: RunResult.Completed): ResultHandler // Narrow returned type.
@@ -21,7 +21,7 @@ internal abstract class AbstractRunner<R> {

        val resultHandler = when (val runResult = run.run()) {
            is RunResult.TimeoutExceeded -> fail {
-                LoggedData.TestRunTimeoutExceeded(getLoggedParameters(), runResult.timeout)
+                LoggedData.TestRunTimeoutExceeded(getLoggedParameters(), runResult)
                    .withErrorMessageHeader("Timeout exceeded during test execution.")
            }
            is RunResult.Completed -> buildResultHandler(runResult)
@@ -59,7 +59,7 @@ internal class LocalTestRunner(
            val cleanStdOut = StringBuilder()

            var expectStatusLine = false
-            runResult.stdOut.lines().forEach { line ->
+            runResult.output.stdOut.lines().forEach { line ->
                when {
                    expectStatusLine -> {
                        val matcher = GTEST_STATUS_LINE_REGEX.matchEntire(line)
@@ -94,10 +94,10 @@ internal class LocalTestRunner(
            val failedTests = (testStatuses - GTEST_STATUS_OK).values.sumOf { it.size }
            verifyExpectation(0, failedTests) { "There are failed tests." }

-            verifyOutputData(mergedOutput = cleanStdOut.toString() + runResult.stdErr)
+            verifyOutputData(mergedOutput = cleanStdOut.toString() + runResult.output.stdErr)
        }

-        private fun verifyPlainTest() = verifyOutputData(mergedOutput = runResult.stdOut + runResult.stdErr)
+        private fun verifyPlainTest() = verifyOutputData(mergedOutput = runResult.output.stdOut + runResult.output.stdErr)

        private fun verifyOutputData(mergedOutput: String) {
            testRun.runParameters.get<TestRunParameter.WithExpectedOutputData> {
@@ -7,7 +7,23 @@ package org.jetbrains.kotlin.konan.blackboxtest.support.runner

 import kotlin.time.Duration

-sealed interface RunResult {
-    data class Completed(val exitCode: Int, val duration: Duration, val stdOut: String, val stdErr: String) : RunResult
-    data class TimeoutExceeded(val timeout: Duration) : RunResult
+internal sealed interface RunResult {
+    val exitCode: Int?
+    val duration: Duration
+    val output: ProcessOutput
+
+    data class Completed(
+        override val exitCode: Int,
+        override val duration: Duration,
+        override val output: ProcessOutput
+    ) : RunResult
+
+    data class TimeoutExceeded(
+        val timeout: Duration,
+        override val exitCode: Int?,
+        override val duration: Duration,
+        override val output: ProcessOutput
+    ) : RunResult
 }
+
+internal class ProcessOutput(val stdOut: String, val stdErr: String)
@@ -0,0 +1,43 @@
+/*
+ * Copyright 2010-2021 JetBrains s.r.o. and Kotlin Programming Language contributors.
+ * Use of this source code is governed by the Apache 2.0 license that can be found in the license/LICENSE.txt file.
+ */
+
+package org.jetbrains.kotlin.konan.blackboxtest.support.util
+
+import org.jetbrains.kotlin.konan.blackboxtest.support.runner.ProcessOutput
+import java.io.ByteArrayOutputStream
+import java.io.InputStream
+
+/**
+ * Read bytes from the given [InputStream] without blocking.
+ *
+ * Note: This function does not guarantee that the whole [InputStream] contents is read. It only
+ * guarantees that the bytes currently available in [InputStream] are read and no I/O blocks happen.
+ */
+internal fun InputStream.readBytesNonBlocking(): ByteArray {
+    val result = ByteArrayOutputStream()
+    val buffer = ByteArray(128)
+
+    while (true) {
+        val availableBytes = available()
+        if (availableBytes == 0) break
+
+        val readBytes = read(buffer)
+        if (readBytes == 0) break
+
+        result.write(buffer, 0, readBytes)
+    }
+
+    return result.toByteArray()
+}
+
+internal fun Process.readOutput(nonBlocking: Boolean): ProcessOutput {
+    val stdOut = if (nonBlocking) inputStream.readBytesNonBlocking() else inputStream.readBytes()
+    val stdErr = if (nonBlocking) errorStream.readBytesNonBlocking() else errorStream.readBytes()
+
+    return ProcessOutput(
+        stdOut = stdOut.toString(Charsets.UTF_8),
+        stdErr = stdErr.toString(Charsets.UTF_8)
+    )
+}