[rd-refactoring]

Multiple refactorings and enhacements for process starting.
Removed UtSettings.logConcreteExecutionErrors and UtSettings.engineProcessLogLevel switches.
Logs for engine and concrete executor processes are always enabled.
Switched log configuration to utbot-intellij/log4j2.xml.
Use UtSettings#getIdeaProcessLogConfigFile from ~/.utbot/settings.properties to configure logs for engine and concrete executor processes without rebuilding plugin.

Author: Domonion

utbot-analytics/src/main/kotlin/org/utbot/visual/AbstractHtmlReport.kt

@@ -1,14 +1,13 @@
 package org.utbot.visual
 
+import org.utbot.common.dateTimeFormatter
 import java.time.LocalDateTime
 import java.time.format.DateTimeFormatter
 
 
 abstract class AbstractHtmlReport(bodyWidth: Int = 600) {
     val builder = HtmlBuilder(bodyMaxWidth = bodyWidth)
 
-    private val dateTimeFormatter = DateTimeFormatter.ofPattern("dd-MM-yyyy_HH-mm-ss")
-
     private fun nameWithDate() =
         "logs/Report_" + dateTimeFormatter.format(LocalDateTime.now()) + ".html"
 

utbot-core/src/main/kotlin/org/utbot/common/JvmUtil.kt

@@ -4,4 +4,7 @@ private val javaSpecificationVersion = System.getProperty("java.specification.ve
 val isJvm8 = javaSpecificationVersion.equals("1.8")
 val isJvm9Plus = !javaSpecificationVersion.contains(".") && javaSpecificationVersion.toInt() >= 9
 
-fun osSpecificJavaExecutable() = if (isWindows) "javaw" else "java"
+fun osSpecificJavaExecutable() = if (isWindows) "javaw" else "java"
+
+const val engineProcessDebugPort = 5005
+const val childProcessDebugPort = 5006

utbot-core/src/main/kotlin/org/utbot/common/Logging.kt

@@ -3,26 +3,21 @@ package org.utbot.common
 import mu.KLogger
 import java.time.format.DateTimeFormatter
 
-val dateFormatter: DateTimeFormatter = DateTimeFormatter.ofPattern("HH:mm:ss.SSS")
+val timeFormatter: DateTimeFormatter = DateTimeFormatter.ofPattern("HH:mm:ss.SSS")
+val dateTimeFormatter = DateTimeFormatter.ofPattern("dd-MM-yyyy_HH-mm-ss")
 
 class LoggerWithLogMethod(val logger: KLogger, val logMethod: (() -> Any?) -> Unit)
 
 fun KLogger.info(): LoggerWithLogMethod = LoggerWithLogMethod(this, this::info)
 fun KLogger.debug(): LoggerWithLogMethod = LoggerWithLogMethod(this, this::debug)
 fun KLogger.trace(): LoggerWithLogMethod = LoggerWithLogMethod(this, this::trace)
 
-
-/**
- *
- */
 fun elapsedSecFrom(startNano: Long): String {
     val elapsedNano = System.nanoTime() - startNano
     val elapsedS = elapsedNano.toDouble() / 1_000_000_000
     return String.format("%.3f", elapsedS) + " sec"
 }
 
-
-
 /**
  * Structured logging.
  *

utbot-core/src/main/kotlin/org/utbot/common/PathUtil.kt

@@ -10,6 +10,12 @@ import java.util.*
 
 object PathUtil {
 
+    fun String.toPathOrNull(): Path? = try {
+        Paths.get(this)
+    } catch (e: Throwable) {
+        null
+    }
+
     /**
      * Creates a Path from the String.
      */

utbot-framework-api/src/main/kotlin/org/utbot/framework/UtSettings.kt

@@ -264,24 +264,17 @@ object UtSettings : AbstractSettings(
         DEFAULT_CONCRETE_EXECUTION_TIMEOUT_IN_CHILD_PROCESS_MS
     )
 
-    /**
-     * Log level for engine process, which started in idea on generate tests action.
-     */
-    var engineProcessLogLevel by getEnumProperty(LogLevel.Info)
-
     /**
      * Log level for concrete executor process.
      */
     var childProcessLogLevel by getEnumProperty(LogLevel.Info)
 
     /**
-     * Determines whether should errors from a child process be written to a log file or suppressed.
-     * Note: being enabled, this option can highly increase disk usage when using ContestEstimator.
-     *
-     * False by default (for saving disk space).
+     * Path to custom log4j2 configuration file for EngineProcess.
+     * By default utbot-intellij/src/main/resources/log4j2.xml is used.
+     * Also default value is used if provided value is not a file.
      */
-    var logConcreteExecutionErrors by getBooleanProperty(false)
-
+    var ideaProcessLogConfigFile by getStringProperty("")
 
     /**
      * Property useful only for idea

utbot-framework-api/src/main/kotlin/org/utbot/framework/process/OpenModulesContainer.kt

@@ -4,10 +4,9 @@ import org.utbot.framework.plugin.services.JdkInfoService
 
 object OpenModulesContainer {
     private val modulesContainer: List<String>
-    val javaVersionSpecificArguments: List<String>
+    val javaVersionSpecificArguments: List<String>?
         get() = modulesContainer
             .takeIf { JdkInfoService.provide().version > 8 }
-            ?: emptyList()
 
     init {
         modulesContainer = buildList {

utbot-framework-test/src/test/resources/log4j2.xml

@@ -7,12 +7,12 @@
                      filePattern="logs/framework-%d{MM-dd-yyyy}.log.gz"
                      ignoreExceptions="false">
 
-            <PatternLayout pattern=" | %-5level | %c{1} | %msg%n"/>
+            <PatternLayout pattern="%d{HH:mm:ss.SSS} | %-5level | %-25c{1} | %msg%n"/>
         </File>
 
         <Console name="Console" target="SYSTEM_OUT">
             <ThresholdFilter level="DEBUG"  onMatch="NEUTRAL"   onMismatch="DENY"/>
-            <PatternLayout pattern="%d{HH:mm:ss.SSS} | %-5level | %c{1} | %msg%n"/>
+            <PatternLayout pattern="%d{HH:mm:ss.SSS} | %-5level | %-25c{1} | %msg%n"/>
         </Console>
     </Appenders>
     <Loggers>

utbot-framework/src/main/kotlin/org/utbot/framework/plugin/api/TestCaseGenerator.kt

@@ -204,7 +204,7 @@ open class TestCaseGenerator(
                             method2controller.values.forEach { it.paused = true }
                             controller.paused = false
 
-                            logger.info { "|> Resuming method $method" }
+                            logger.info { "Resuming method $method" }
                             val startTime = System.currentTimeMillis()
                             while (controller.job!!.isActive &&
                                 (System.currentTimeMillis() - startTime) < executionTimeEstimator.timeslotForOneToplevelMethodTraversalInMillis

utbot-framework/src/main/kotlin/org/utbot/framework/process/EngineMain.kt

@@ -32,7 +32,7 @@ import org.utbot.framework.process.generated.*
 import org.utbot.framework.util.ConflictTriggers
 import org.utbot.instrumentation.instrumentation.instrumenter.Instrumenter
 import org.utbot.instrumentation.util.KryoHelper
-import org.utbot.rd.CallsSynchronizer
+import org.utbot.rd.IdleWatchdog
 import org.utbot.rd.ClientProtocolBuilder
 import org.utbot.rd.findRdPort
 import org.utbot.rd.loggers.UtRdKLoggerFactory
@@ -56,11 +56,7 @@ suspend fun main(args: Array<String>) = runBlocking {
     Logger.set(Lifetime.Eternal, UtRdKLoggerFactory(logger))
 
     ClientProtocolBuilder().withProtocolTimeout(messageFromMainTimeoutMillis).start(port) {
-        settingsModel
-        rdSourceFindingStrategy
-        rdInstrumenterAdapter
-
-        AbstractSettings.setupFactory(RdSettingsContainerFactory(protocol))
+        AbstractSettings.setupFactory(RdSettingsContainerFactory(protocol.settingsModel))
         val kryoHelper = KryoHelper(lifetime)
         engineProcessModel.setup(kryoHelper, it, protocol)
     }
@@ -74,18 +70,16 @@ private val testSets: MutableMap<Long, List<UtMethodTestSet>> = mutableMapOf()
 private val testGenerationReports: MutableList<TestsGenerationReport> = mutableListOf()
 private var idCounter: Long = 0
 
-private fun EngineProcessModel.setup(
-    kryoHelper: KryoHelper, synchronizer: CallsSynchronizer, realProtocol: IProtocol
-) {
+private fun EngineProcessModel.setup(kryoHelper: KryoHelper, watchdog: IdleWatchdog, realProtocol: IProtocol) {
     val model = this
-    synchronizer.measureExecutionForTermination(setupUtContext) { params ->
+    watchdog.wrapActiveCall(setupUtContext) { params ->
         UtContext.setUtContext(UtContext(URLClassLoader(params.classpathForUrlsClassloader.map {
             File(it).toURI().toURL()
         }.toTypedArray())))
     }
-    synchronizer.measureExecutionForTermination(createTestGenerator) { params ->
+    watchdog.wrapActiveCall(createTestGenerator) { params ->
         AnalyticsConfigureUtil.configureML()
-        Instrumenter.adapter = RdInstrumenter(realProtocol)
+        Instrumenter.adapter = RdInstrumenter(realProtocol.rdInstrumenterAdapter)
         testGenerator = TestCaseGenerator(buildDirs = params.buildDir.map { Paths.get(it) },
             classpath = params.classpath,
             dependencyPaths = params.dependencyPaths,
@@ -96,7 +90,7 @@ private fun EngineProcessModel.setup(
                 }
             })
     }
-    synchronizer.measureExecutionForTermination(generate) { params ->
+    watchdog.wrapActiveCall(generate) { params ->
         val mockFrameworkInstalled = params.mockInstalled
         val conflictTriggers = ConflictTriggers(kryoHelper.readObject(params.conflictTriggers))
         if (!mockFrameworkInstalled) {
@@ -126,7 +120,7 @@ private fun EngineProcessModel.setup(
         testSets[id] = result
         GenerateResult(result.size, id)
     }
-    synchronizer.measureExecutionForTermination(render) { params ->
+    watchdog.wrapActiveCall(render) { params ->
         val testFramework = testFrameworkByName(params.testFramework)
         val staticMocking = if (params.staticsMocking.startsWith("No")) {
             NoStaticMocking
@@ -157,11 +151,11 @@ private fun EngineProcessModel.setup(
                 RenderResult(it.generatedCode, it.utilClassKind?.javaClass?.simpleName)
             }
     }
-    synchronizer.measureExecutionForTermination(stopProcess) { synchronizer.stopProtocol() }
-    synchronizer.measureExecutionForTermination(obtainClassId) { canonicalName ->
+    watchdog.wrapActiveCall(stopProcess) { watchdog.stopProtocol() }
+    watchdog.wrapActiveCall(obtainClassId) { canonicalName ->
         kryoHelper.writeObject(UtContext.currentContext()!!.classLoader.loadClass(canonicalName).id)
     }
-    synchronizer.measureExecutionForTermination(findMethodsInClassMatchingSelected) { params ->
+    watchdog.wrapActiveCall(findMethodsInClassMatchingSelected) { params ->
         val classId = kryoHelper.readObject<ClassId>(params.classId)
         val selectedSignatures = params.signatures.map { Signature(it.name, it.parametersTypes) }
         FindMethodsInClassMatchingSelectedResult(kryoHelper.writeObject(classId.jClass.allNestedClasses.flatMap { clazz ->
@@ -170,7 +164,7 @@ private fun EngineProcessModel.setup(
                 .map { it.executableId }
         }))
     }
-    synchronizer.measureExecutionForTermination(findMethodParamNames) { params ->
+    watchdog.wrapActiveCall(findMethodParamNames) { params ->
         val classId = kryoHelper.readObject<ClassId>(params.classId)
         val bySignature = kryoHelper.readObject<Map<Signature, List<String>>>(params.bySignature)
         FindMethodParamNamesResult(kryoHelper.writeObject(
@@ -179,7 +173,7 @@ private fun EngineProcessModel.setup(
                 .toMap()
         ))
     }
-    synchronizer.measureExecutionForTermination(writeSarifReport) { params ->
+    watchdog.wrapActiveCall(writeSarifReport) { params ->
         val reportFilePath = Paths.get(params.reportFilePath)
         reportFilePath.parent.toFile().mkdirs()
         val sarifReport = SarifReport(
@@ -190,12 +184,12 @@ private fun EngineProcessModel.setup(
         reportFilePath.toFile().writeText(sarifReport)
         sarifReport
     }
-    synchronizer.measureExecutionForTermination(generateTestReport) { params ->
+    watchdog.wrapActiveCall(generateTestReport) { params ->
         val eventLogMessage = params.eventLogMessage
         val testPackageName: String? = params.testPackageName
         var hasWarnings = false
         val reports = testGenerationReports
-        if (reports.isEmpty()) return@measureExecutionForTermination GenerateTestReportResult("No tests were generated", null, true)
+        if (reports.isEmpty()) return@wrapActiveCall GenerateTestReportResult("No tests were generated", null, true)
         val isMultiPackage = params.isMultiPackage
         val (notifyMessage, statistics) = if (reports.size == 1) {
             val report = reports.first()

utbot-framework/src/main/kotlin/org/utbot/framework/process/RdInstrumenter.kt

@@ -1,36 +1,30 @@
 package org.utbot.framework.process
 
-import com.jetbrains.rd.framework.IProtocol
 import kotlinx.coroutines.runBlocking
 import mu.KotlinLogging
+import org.utbot.common.logException
 import org.utbot.framework.process.generated.ComputeSourceFileByClassArguments
-import org.utbot.framework.process.generated.rdInstrumenterAdapter
+import org.utbot.framework.process.generated.RdInstrumenterAdapter
 import org.utbot.instrumentation.instrumentation.instrumenter.InstrumenterAdapter
+import org.utbot.rd.startBlocking
 import java.io.File
 import java.nio.file.Path
 
 private val logger = KotlinLogging.logger { }
 
-class RdInstrumenter(private val protocol: IProtocol): InstrumenterAdapter() {
+class RdInstrumenter(private val rdInstrumenterAdapter: RdInstrumenterAdapter) : InstrumenterAdapter() {
     override fun computeSourceFileByClass(
         className: String,
         packageName: String?,
         directoryToSearchRecursively: Path
-    ): File? = runBlocking {
+    ): File? {
         logger.debug { "starting computeSourceFileByClass with classname - $className" }
-        val result = try {
-             protocol.rdInstrumenterAdapter.computeSourceFileByClass.startSuspending(
-                ComputeSourceFileByClassArguments(
-                    className,
-                    packageName
-                )
-            )
-        }
-        catch(e: Exception) {
-            logger.error(e) { "error during computeSourceFileByClass" }
-            throw e
+        val result = logger.logException {
+            val arguments = ComputeSourceFileByClassArguments(className, packageName)
+
+            rdInstrumenterAdapter.computeSourceFileByClass.startBlocking(arguments)
         }
-        logger.debug { "computeSourceFileByClass result for $className from idea: $result"}
-        return@runBlocking result?.let { File(it) }
+        logger.debug { "computeSourceFileByClass result for $className from idea: $result" }
+        return result?.let { File(it) }
     }
 }

utbot-framework/src/main/kotlin/org/utbot/framework/process/RdSettingsContainer.kt

@@ -1,42 +1,43 @@
 package org.utbot.framework.process
 
-import com.jetbrains.rd.framework.IProtocol
 import kotlinx.coroutines.runBlocking
 import mu.KLogger
 import org.utbot.common.SettingsContainer
 import org.utbot.common.SettingsContainerFactory
 import org.utbot.framework.process.generated.SettingForArgument
-import org.utbot.framework.process.generated.settingsModel
+import org.utbot.framework.process.generated.SettingsModel
+import org.utbot.rd.startBlocking
 import kotlin.properties.PropertyDelegateProvider
 import kotlin.properties.ReadWriteProperty
 import kotlin.reflect.KProperty
 
-class RdSettingsContainerFactory(private val protocol: IProtocol) : SettingsContainerFactory {
+class RdSettingsContainerFactory(private val settingsModel: SettingsModel) : SettingsContainerFactory {
     override fun createSettingsContainer(
         logger: KLogger,
         defaultKeyForSettingsPath: String,
         defaultSettingsPath: String?
     ): SettingsContainer {
-        return RdSettingsContainer(logger, defaultKeyForSettingsPath, protocol)
+        return RdSettingsContainer(logger, defaultKeyForSettingsPath, settingsModel)
     }
 }
 
-class RdSettingsContainer(val logger: KLogger, val key: String, val protocol: IProtocol): SettingsContainer {
+class RdSettingsContainer(val logger: KLogger, val key: String, val settingsModel: SettingsModel) : SettingsContainer {
 
     override fun <T> settingFor(
         defaultValue: T,
         converter: (String) -> T
     ): PropertyDelegateProvider<Any?, ReadWriteProperty<Any?, T>> {
-        return PropertyDelegateProvider { _, prop ->
-            object: ReadWriteProperty<Any?, T> {
-                override fun getValue(thisRef: Any?, property: KProperty<*>): T = runBlocking {
-                    return@runBlocking protocol.settingsModel.settingFor.startSuspending(SettingForArgument(key, property.name)).value?.let {
+        return PropertyDelegateProvider { _, _ ->
+            object : ReadWriteProperty<Any?, T> {
+                override fun getValue(thisRef: Any?, property: KProperty<*>): T {
+                    val params = SettingForArgument(key, property.name)
+                    return settingsModel.settingFor.startBlocking(params).value?.let {
                         converter(it)
                     } ?: defaultValue
                 }
 
                 override fun setValue(thisRef: Any?, property: KProperty<*>, value: T) {
-                    throw NotImplementedError("Setting properties from child process not supported")
+                    throw NotImplementedError("Setting properties allowed only from plugin process")
                 }
             }
         }

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

@@ -244,7 +244,7 @@ class ConcreteExecutor<TIResult, TInstrumentation : Instrumentation<TIResult>> p
             val parametersByteArray = kryoHelper.writeObject(parameters)
             val params = InvokeMethodCommandParams(className, signature, argumentsByteArray, parametersByteArray)
 
-            val ba = protocolModel.invokeMethodCommand.startSuspending(lifetime, params).result
+            val ba = chidlProcessModel.invokeMethodCommand.startSuspending(lifetime, params).result
             kryoHelper.readObject(ba)
         }
     } catch (e: Throwable) {
@@ -284,7 +284,7 @@ class ConcreteExecutor<TIResult, TInstrumentation : Instrumentation<TIResult>> p
                 if (alive) {
                     try {
                         processInstance?.run {
-                            protocolModel.stopProcess.start(lifetime, Unit)
+                            chidlProcessModel.stopProcess.start(lifetime, Unit)
                         }
                     } catch (_: Exception) {}
                     processInstance = null
@@ -298,7 +298,7 @@ class ConcreteExecutor<TIResult, TInstrumentation : Instrumentation<TIResult>> p
 
 fun ConcreteExecutor<*,*>.warmup() = runBlocking {
     withProcess {
-        protocolModel.warmup.start(lifetime, Unit)
+        chidlProcessModel.warmup.start(lifetime, Unit)
     }
 }
 
@@ -310,7 +310,7 @@ fun <T> ConcreteExecutor<*, *>.computeStaticField(fieldId: FieldId): Result<T> =
         val fieldIdSerialized = kryoHelper.writeObject(fieldId)
         val params = ComputeStaticFieldParams(fieldIdSerialized)
 
-        val result = protocolModel.computeStaticField.startSuspending(lifetime, params)
+        val result = chidlProcessModel.computeStaticField.startSuspending(lifetime, params)
 
         kryoHelper.readObject(result.result)
     }