From 2a589065d8c855b512afcf90f1df14317891261e Mon Sep 17 00:00:00 2001 From: "Artemii.Kononov" Date: Fri, 9 Sep 2022 18:21:14 +0300 Subject: [PATCH] [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. --- .../concrete/UtExecutionInstrumentation.kt | 7 +++ .../utbot/instrumentation/ConcreteExecutor.kt | 4 +- .../instrumentation/process/ChildProcess.kt | 61 +++++++++++++------ .../kotlin/org/utbot/rd/UtRdCoroutineScope.kt | 40 +----------- .../rd/{UtRdLogger.kt => UtRdKLogger.kt} | 10 ++- .../src/main/kotlin/org/utbot/rd/UtRdUtil.kt | 10 +-- .../org/utbot/rd/UtSingleThreadScheduler.kt | 9 ++- 7 files changed, 67 insertions(+), 74 deletions(-) rename utbot-rd/src/main/kotlin/org/utbot/rd/{UtRdLogger.kt => UtRdKLogger.kt} (82%) diff --git a/utbot-framework/src/main/kotlin/org/utbot/framework/concrete/UtExecutionInstrumentation.kt b/utbot-framework/src/main/kotlin/org/utbot/framework/concrete/UtExecutionInstrumentation.kt index 51115897c4..d57f6c2da8 100644 --- a/utbot-framework/src/main/kotlin/org/utbot/framework/concrete/UtExecutionInstrumentation.kt +++ b/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 { diff --git a/utbot-instrumentation/src/main/kotlin/org/utbot/instrumentation/ConcreteExecutor.kt b/utbot-instrumentation/src/main/kotlin/org/utbot/instrumentation/ConcreteExecutor.kt index ba71fcdb11..41cb7fdc02 100644 --- a/utbot-instrumentation/src/main/kotlin/org/utbot/instrumentation/ConcreteExecutor.kt +++ b/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> p var defaultPathsToDependencyClasses = "" init { - Logger.set(Lifetime.Eternal, UtRdLoggerFactory) + Logger.set(Lifetime.Eternal, UtRdKLoggerFactory) Runtime.getRuntime().addShutdownHook(thread(start = false) { defaultPool.close() }) } diff --git a/utbot-instrumentation/src/main/kotlin/org/utbot/instrumentation/process/ChildProcess.kt b/utbot-instrumentation/src/main/kotlin/org/utbot/instrumentation/process/ChildProcess.kt index 679609d8cd..70fb867205 100644 --- a/utbot-instrumentation/src/main/kotlin/org/utbot/instrumentation/process/ChildProcess.kt +++ b/utbot-instrumentation/src/main/kotlin/org/utbot/instrumentation/process/ChildProcess.kt @@ -2,7 +2,6 @@ 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 @@ -10,9 +9,11 @@ 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) = 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,7 +188,12 @@ private fun RdCall.measureExecutionForTermination(block: (T) -> R) this.set { it -> runBlocking { measureExecutionForTermination { - block(it) + try { + block(it) + } catch (e: Throwable) { + logException(e) + throw e + } } } } @@ -185,12 +201,14 @@ private fun RdCall.measureExecutionForTermination(block: (T) -> R) 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) } } \ No newline at end of file diff --git a/utbot-rd/src/main/kotlin/org/utbot/rd/UtRdCoroutineScope.kt b/utbot-rd/src/main/kotlin/org/utbot/rd/UtRdCoroutineScope.kt index 75216461ed..eea2b0d1d8 100644 --- a/utbot-rd/src/main/kotlin/org/utbot/rd/UtRdCoroutineScope.kt +++ b/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 } \ No newline at end of file diff --git a/utbot-rd/src/main/kotlin/org/utbot/rd/UtRdLogger.kt b/utbot-rd/src/main/kotlin/org/utbot/rd/UtRdKLogger.kt similarity index 82% rename from utbot-rd/src/main/kotlin/org/utbot/rd/UtRdLogger.kt rename to utbot-rd/src/main/kotlin/org/utbot/rd/UtRdKLogger.kt index 83acefc785..b0dcb70616 100644 --- a/utbot-rd/src/main/kotlin/org/utbot/rd/UtRdLogger.kt +++ b/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 diff --git a/utbot-rd/src/main/kotlin/org/utbot/rd/UtRdUtil.kt b/utbot-rd/src/main/kotlin/org/utbot/rd/UtRdUtil.kt index cd3fd6ca0a..87086fb0b0 100644 --- a/utbot-rd/src/main/kotlin/org/utbot/rd/UtRdUtil.kt +++ b/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 LifetimeDefinition.terminateOnException(block: (Lifetime) -> T): T { try { @@ -54,7 +50,7 @@ suspend fun ISource.adviseForConditionAsync(lifetime: Lifetime, condition } suspend fun ISource.adviseForConditionAsync(lifetime: Lifetime): Deferred { - 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 ) } diff --git a/utbot-rd/src/main/kotlin/org/utbot/rd/UtSingleThreadScheduler.kt b/utbot-rd/src/main/kotlin/org/utbot/rd/UtSingleThreadScheduler.kt index 4b63b8bdaf..f01e2ba29f 100644 --- a/utbot-rd/src/main/kotlin/org/utbot/rd/UtSingleThreadScheduler.kt +++ b/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() + +class UtSingleThreadScheduler(name: String) : SingleThreadSchedulerBase(name) { override fun onException(ex: Throwable) { - log { ex.toString() } + logger.error { "exception on scheduler $name: $ex |> ${ex.stackTraceToString()}" } } } \ No newline at end of file