Concrete executor rd logs (#902)

[concrete-executor-rd-logs]
1. fix #870
2. fix #848
changed concrete executor process logs: removed kotlin.logs, moved to rd
logging system, overloaded them to write to system.err, adjusted log
level of some messages to clarify log, removed useless schedulers and
some useless code

N.B.: log system will be redesigned with upcoming utbot test generator
process separation! Changes will be reflected on UtBotJava rd wiki page.

Author: Domonion

utbot-framework/src/main/kotlin/org/utbot/framework/concrete/UtExecutionInstrumentation.kt

@@ -105,6 +105,13 @@ class UtConcreteExecutionResult(
         val modelsToAssembleModels = AssembleModelGenerator(packageName).createAssembleModels(allModels)
         return updateWithAssembleModels(modelsToAssembleModels)
     }
+
+    override fun toString(): String = buildString {
+        appendLine("UtConcreteExecutionResult(")
+        appendLine("stateAfter=$stateAfter")
+        appendLine("result=$result")
+        appendLine("coverage=$coverage)")
+    }
 }
 
 object UtExecutionInstrumentation : Instrumentation<UtConcreteExecutionResult> {

utbot-instrumentation/src/main/kotlin/org/utbot/instrumentation/ConcreteExecutor.kt

@@ -16,7 +16,7 @@ import org.utbot.framework.plugin.api.util.signature
 import org.utbot.instrumentation.instrumentation.Instrumentation
 import org.utbot.instrumentation.process.ChildProcessRunner
 import org.utbot.instrumentation.rd.UtInstrumentationProcess
-import org.utbot.rd.UtRdLoggerFactory
+import org.utbot.rd.UtRdKLoggerFactory
 import org.utbot.instrumentation.rd.generated.InvokeMethodCommandParams
 import org.utbot.instrumentation.util.ChildProcessError
 import java.io.Closeable
@@ -123,7 +123,7 @@ class ConcreteExecutor<TIResult, TInstrumentation : Instrumentation<TIResult>> p
         var defaultPathsToDependencyClasses = ""
 
         init {
-            Logger.set(Lifetime.Eternal, UtRdLoggerFactory)
+            Logger.set(Lifetime.Eternal, UtRdKLoggerFactory)
             Runtime.getRuntime().addShutdownHook(thread(start = false) { defaultPool.close() })
         }
 

utbot-instrumentation/src/main/kotlin/org/utbot/instrumentation/process/ChildProcess.kt

@@ -2,17 +2,18 @@ package org.utbot.instrumentation.process
 
 import com.jetbrains.rd.framework.*
 import com.jetbrains.rd.framework.impl.RdCall
-import com.jetbrains.rd.framework.util.launchChild
 import com.jetbrains.rd.util.ILoggerFactory
 import com.jetbrains.rd.util.LogLevel
 import com.jetbrains.rd.util.Logger
 import com.jetbrains.rd.util.defaultLogFormat
 import com.jetbrains.rd.util.lifetime.Lifetime
 import com.jetbrains.rd.util.lifetime.LifetimeDefinition
 import com.jetbrains.rd.util.lifetime.plusAssign
-import com.jetbrains.rd.util.threading.SingleThreadScheduler
-import kotlinx.coroutines.*
+import kotlinx.coroutines.CompletableDeferred
 import kotlinx.coroutines.channels.Channel
+import kotlinx.coroutines.launch
+import kotlinx.coroutines.runBlocking
+import kotlinx.coroutines.withTimeoutOrNull
 import org.utbot.common.*
 import org.utbot.framework.plugin.api.util.UtContext
 import org.utbot.instrumentation.agent.Agent
@@ -26,7 +27,7 @@ import org.utbot.instrumentation.rd.obtainClientIO
 import org.utbot.instrumentation.rd.processSyncDirectory
 import org.utbot.instrumentation.rd.signalChildReady
 import org.utbot.instrumentation.util.KryoHelper
-import org.utbot.rd.UtSingleThreadScheduler
+import org.utbot.rd.UtRdCoroutineScope
 import org.utbot.rd.adviseForConditionAsync
 import java.io.File
 import java.io.OutputStream
@@ -35,7 +36,6 @@ import java.net.URLClassLoader
 import java.security.AllPermission
 import java.time.LocalDateTime
 import java.time.format.DateTimeFormatter
-import java.util.concurrent.ArrayBlockingQueue
 import java.util.concurrent.TimeUnit
 import kotlin.system.measureTimeMillis
 
@@ -63,7 +63,6 @@ private object HandlerClassesLoader : URLClassLoader(emptyArray()) {
 }
 
 private typealias ChildProcessLogLevel = LogLevel
-
 private val logLevel = ChildProcessLogLevel.Info
 
 // Logging
@@ -75,14 +74,28 @@ private fun log(level: ChildProcessLogLevel, any: () -> Any?) {
     System.err.println(LocalDateTime.now().format(dateFormatter) + " | ${any()}")
 }
 
+// errors that must be address
 private fun logError(any: () -> Any?) {
     log(ChildProcessLogLevel.Error, any)
 }
 
+private fun logException(e: Throwable) {
+    log(ChildProcessLogLevel.Error) { "$e |> ${e.stackTraceToString()}" }
+}
+
+// default log level for irregular useful messages that does not pollute log
 private fun logInfo(any: () -> Any?) {
     log(ChildProcessLogLevel.Info, any)
 }
 
+// log level for frequent messages useful for debugging
+private fun logDebug(any: () -> Any?) {
+    log(ChildProcessLogLevel.Debug, any)
+}
+
+// log level for internal rd logs and frequent messages
+// heavily pollutes log, useful only when debugging rpc
+// probably contains no info about utbot
 private fun logTrace(any: () -> Any?) {
     log(ChildProcessLogLevel.Trace, any)
 }
@@ -119,9 +132,7 @@ suspend fun main(args: Array<String>) = runBlocking {
     val pid = currentProcessPid.toInt()
     val def = LifetimeDefinition()
 
-    SingleThreadScheduler(Lifetime.Eternal, "")
-
-    launchChild(Lifetime.Eternal) {
+    launch {
         var lastState = State.STARTED
         while (true) {
             val current: State? =
@@ -177,20 +188,27 @@ private fun <T, R> RdCall<T, R>.measureExecutionForTermination(block: (T) -> R)
     this.set { it ->
         runBlocking {
             measureExecutionForTermination<R> {
-                block(it)
+                try {
+                    block(it)
+                } catch (e: Throwable) {
+                    logException(e)
+                    throw e
+                }
             }
         }
     }
 }
 
 private suspend fun ProtocolModel.setup(kryoHelper: KryoHelper, onStop: () -> Unit) {
     warmup.measureExecutionForTermination {
+        logDebug { "received warmup request" }
         val time = measureTimeMillis {
             HandlerClassesLoader.scanForClasses("").toList() // here we transform classes
         }
-        logInfo { "warmup finished in $time ms" }
+        logDebug { "warmup finished in $time ms" }
     }
     invokeMethodCommand.measureExecutionForTermination { params ->
+        logDebug { "received invokeMethod request: ${params.classname}, ${params.signature}" }
         val clazz = HandlerClassesLoader.loadClass(params.classname)
         val res = instrumentation.invoke(
             clazz,
@@ -199,31 +217,36 @@ private suspend fun ProtocolModel.setup(kryoHelper: KryoHelper, onStop: () -> Un
             kryoHelper.readObject(params.parameters)
         )
 
-        logInfo { "sent cmd: $res" }
+        logDebug { "invokeMethod result: $res" }
         InvokeMethodCommandResult(kryoHelper.writeObject(res))
     }
     setInstrumentation.measureExecutionForTermination { params ->
+        logDebug { "setInstrumentation request" }
         instrumentation = kryoHelper.readObject(params.instrumentation)
+        logTrace { "instrumentation - ${instrumentation.javaClass.name} " }
         Agent.dynamicClassTransformer.transformer = instrumentation // classTransformer is set
         Agent.dynamicClassTransformer.addUserPaths(pathsToUserClasses)
         instrumentation.init(pathsToUserClasses)
     }
     addPaths.measureExecutionForTermination { params ->
+        logDebug { "addPaths request" }
+        logTrace { "path to userClasses - ${params.pathsToUserClasses}"}
+        logTrace { "path to dependencyClasses - ${params.pathsToDependencyClasses}"}
         pathsToUserClasses = params.pathsToUserClasses.split(File.pathSeparatorChar).toSet()
         pathsToDependencyClasses = params.pathsToDependencyClasses.split(File.pathSeparatorChar).toSet()
         HandlerClassesLoader.addUrls(pathsToUserClasses)
         HandlerClassesLoader.addUrls(pathsToDependencyClasses)
         kryoHelper.setKryoClassLoader(HandlerClassesLoader) // Now kryo will use our classloader when it encounters unregistered class.
-
-        logTrace { "User classes:" + pathsToUserClasses.joinToString() }
-
         UtContext.setUtContext(UtContext(HandlerClassesLoader))
     }
     stopProcess.measureExecutionForTermination {
+        logDebug { "stop request" }
         onStop()
     }
     collectCoverage.measureExecutionForTermination { params ->
+        logDebug { "collect coverage request" }
         val anyClass: Class<*> = kryoHelper.readObject(params.clazz)
+        logTrace { "class - ${anyClass.name}" }
         val result = (instrumentation as CoverageInstrumentation).collectCoverageInfo(anyClass)
         CollectCoverageResult(kryoHelper.writeObject(result))
     }
@@ -256,13 +279,12 @@ private suspend fun initiate(lifetime: Lifetime, port: Int, pid: Int) {
     val kryoHelper = KryoHelper(lifetime)
     logInfo { "kryo created" }
 
-    val scheduler = UtSingleThreadScheduler { logInfo(it) }
     val clientProtocol = Protocol(
         "ChildProcess",
         Serializers(),
         Identities(IdKind.Client),
-        scheduler,
-        SocketWire.Client(lifetime, scheduler, port),
+        UtRdCoroutineScope.scheduler,
+        SocketWire.Client(lifetime, UtRdCoroutineScope.scheduler, port),
         lifetime
     )
     val (sync, protocolModel) = obtainClientIO(lifetime, clientProtocol)
@@ -290,6 +312,7 @@ private suspend fun initiate(lifetime: Lifetime, port: Int, pid: Int) {
         logInfo { "starting instrumenting" }
         deferred.await()
     } catch (e: Throwable) {
-        logError { "Terminating process because exception occurred: ${e.stackTraceToString()}" }
+        logError { "Terminating process because exception occurred" }
+        logException(e)
     }
 }

utbot-rd/src/main/kotlin/org/utbot/rd/UtRdCoroutineScope.kt

@@ -3,50 +3,16 @@ package org.utbot.rd
 import com.jetbrains.rd.framework.util.RdCoroutineScope
 import com.jetbrains.rd.framework.util.asCoroutineDispatcher
 import com.jetbrains.rd.util.lifetime.Lifetime
-import kotlinx.coroutines.CancellationException
-import kotlinx.coroutines.Job
-import kotlinx.coroutines.cancelAndJoin
-import kotlinx.coroutines.runBlocking
-import mu.KotlinLogging
-
-private val logger = KotlinLogging.logger("UtRdCoroutineScope")
 
 class UtRdCoroutineScope(lifetime: Lifetime) : RdCoroutineScope(lifetime) {
     companion object {
-        private val dispatcher =
-            UtSingleThreadScheduler("UtRdCoroutineScope dispatcher") { logger.info(it) }.asCoroutineDispatcher
+        val scheduler = UtSingleThreadScheduler("UtRdCoroutineScope")
         val current = UtRdCoroutineScope(Lifetime.Eternal)
     }
 
     init {
-        lifetime.bracketIfAlive({
-            override(lifetime, this)
-            logger.info { "UtRdCoroutineScope overridden" }
-        }, {
-            logger.info { "UtRdCoroutineScope has been reset" }
-        })
-        lifetime.onTermination {
-            logger.info("UtRdCoroutineScope disposed")
-        }
+        override(lifetime, this)
     }
 
-    override val defaultDispatcher = dispatcher
-
-    override fun shutdown() {
-        try {
-            runBlocking {
-                coroutineContext[Job]!!.cancelAndJoin()
-            }
-        } catch (e: CancellationException) {
-            // nothing
-        } catch (e: Throwable) {
-            logger.error { "error during shutdown: $e" }
-        }
-    }
-
-    override fun onException(throwable: Throwable) {
-        if (throwable !is CancellationException) {
-            logger.error("Unhandled coroutine throwable: $throwable\n stacktrace: ${throwable.stackTraceToString()}")
-        }
-    }
+    override val defaultDispatcher = scheduler.asCoroutineDispatcher
 }

utbot-rd/src/main/kotlin/org/utbot/rd/UtRdLogger.kt renamed to utbot-rd/src/main/kotlin/org/utbot/rd/UtRdKLogger.kt

@@ -4,18 +4,16 @@ import com.jetbrains.rd.util.ILoggerFactory
 import com.jetbrains.rd.util.LogLevel
 import com.jetbrains.rd.util.Logger
 import com.jetbrains.rd.util.defaultLogFormat
+import mu.KLogger
 import mu.KotlinLogging
 
-private val logger = KotlinLogging.logger {}
-
-object UtRdLoggerFactory : ILoggerFactory {
+object UtRdKLoggerFactory : ILoggerFactory {
     override fun getLogger(category: String): Logger {
-        logger.trace { "getting logger for category: $category" }
-        return UtRdLogger(category)
+        return UtRdKLogger(KotlinLogging.logger(category), category)
     }
 }
 
-class UtRdLogger(private val category: String) : Logger {
+class UtRdKLogger(private val logger: KLogger, private val category: String) : Logger {
     override fun isEnabled(level: LogLevel): Boolean {
         return when (level) {
             LogLevel.Trace -> logger.isTraceEnabled

utbot-rd/src/main/kotlin/org/utbot/rd/UtRdUtil.kt

@@ -9,10 +9,6 @@ import com.jetbrains.rd.util.reactive.IScheduler
 import com.jetbrains.rd.util.reactive.ISource
 import kotlinx.coroutines.CompletableDeferred
 import kotlinx.coroutines.Deferred
-import mu.KotlinLogging
-
-private val logger = KotlinLogging.logger {}
-private val serverScheduler = UtSingleThreadScheduler { logger.info(it) }
 
 inline fun <T> LifetimeDefinition.terminateOnException(block: (Lifetime) -> T): T {
     try {
@@ -54,7 +50,7 @@ suspend fun <T> ISource<T>.adviseForConditionAsync(lifetime: Lifetime, condition
 }
 
 suspend fun ISource<Boolean>.adviseForConditionAsync(lifetime: Lifetime): Deferred<Unit> {
-    return this.adviseForConditionAsync(lifetime) {it}
+    return this.adviseForConditionAsync(lifetime) { it }
 }
 
 /**
@@ -73,8 +69,8 @@ suspend fun startUtProcessWithRdServer(
             "Server",
             Serializers(),
             Identities(IdKind.Server),
-            serverScheduler,
-            SocketWire.Server(it, serverScheduler, port, "ServerSocket"),
+            UtRdCoroutineScope.scheduler,
+            SocketWire.Server(it, UtRdCoroutineScope.scheduler, port, "ServerSocket"),
             it
         )
     }

utbot-rd/src/main/kotlin/org/utbot/rd/UtSingleThreadScheduler.kt

@@ -1,10 +1,13 @@
 package org.utbot.rd
 
+import com.jetbrains.rd.util.error
+import com.jetbrains.rd.util.getLogger
 import com.jetbrains.rd.util.threading.SingleThreadSchedulerBase
 
-class UtSingleThreadScheduler(name: String = "UtRdScheduler", private val log: (() -> String) -> Unit) :
-    SingleThreadSchedulerBase(name) {
+private val logger = getLogger<UtSingleThreadScheduler>()
+
+class UtSingleThreadScheduler(name: String) : SingleThreadSchedulerBase(name) {
     override fun onException(ex: Throwable) {
-        log { ex.toString() }
+        logger.error { "exception on scheduler $name: $ex |> ${ex.stackTraceToString()}" }
     }
 }