Concrete executor logs (#921)

[concrete-executor-logs]
fixes #870
Moved logs in RuntimeTraceStorage and DynamicClassTransformer to
ChildProcess.kt logging system

Author: Domonion

utbot-instrumentation/src/main/kotlin/org/utbot/instrumentation/agent/DynamicClassTransformer.kt

@@ -2,6 +2,8 @@ package org.utbot.instrumentation.agent
 
 import org.utbot.common.asPathToFile
 import org.utbot.framework.plugin.api.util.UtContext
+import org.utbot.instrumentation.process.logError
+import org.utbot.instrumentation.process.logInfo
 import java.lang.instrument.ClassFileTransformer
 import java.security.ProtectionDomain
 
@@ -30,13 +32,13 @@ class DynamicClassTransformer : ClassFileTransformer {
             return if (pathToClassfile in pathsToUserClasses ||
                 packsToAlwaysTransform.any(className::startsWith)
             ) {
-                System.err.println("Transforming: $className")
+                logInfo { "Transforming: $className" }
                 transformer.transform(loader, className, classBeingRedefined, protectionDomain, classfileBuffer)
             } else {
                 null
             }
         } catch (e: Throwable) {
-            System.err.println("Error while transforming: ${e.stackTraceToString()}")
+            logError { "Error while transforming: ${e.stackTraceToString()}" }
             throw e
         } finally {
             UtContext.currentContext()?.stopWatch?.start()

utbot-instrumentation/src/main/kotlin/org/utbot/instrumentation/instrumentation/et/TraceHandler.kt

@@ -9,6 +9,7 @@ import org.objectweb.asm.MethodVisitor
 import org.objectweb.asm.Opcodes
 import org.objectweb.asm.Type
 import org.objectweb.asm.commons.LocalVariablesSorter
+import org.utbot.instrumentation.process.logError
 
 sealed class InstructionData {
     abstract val line: Int
@@ -111,6 +112,8 @@ class ProcessingStorage {
  * Storage to which instrumented classes will write execution data.
  */
 object RuntimeTraceStorage {
+    internal var alreadyLoggedIncreaseStackSizeTip = false
+
     /**
      * Contains ids of instructions in the order of execution.
      */
@@ -151,7 +154,11 @@ object RuntimeTraceStorage {
             this.`$__trace__`[current] = id
             this.`$__counter__` = current + 1
         } else {
-            System.err.println("Stack overflow (increase stack size Settings.TRACE_ARRAY_SIZE)")
+            val loggedTip = alreadyLoggedIncreaseStackSizeTip
+            if (!loggedTip) {
+                alreadyLoggedIncreaseStackSizeTip = true
+                logError { "Stack overflow (increase stack size Settings.TRACE_ARRAY_SIZE)" }
+            }
         }
     }
 }
@@ -289,5 +296,6 @@ class TraceHandler {
     fun resetTrace() {
         instructionsList = null
         RuntimeTraceStorage.`$__counter__` = 0
+        RuntimeTraceStorage.alreadyLoggedIncreaseStackSizeTip = false
     }
 }

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

@@ -69,36 +69,32 @@ private val logLevel = ChildProcessLogLevel.Info
 
 // Logging
 private val dateFormatter: DateTimeFormatter = DateTimeFormatter.ofPattern("HH:mm:ss.SSS")
-private fun log(level: ChildProcessLogLevel, any: () -> Any?) {
+private inline fun log(level: ChildProcessLogLevel, any: () -> Any?) {
     if (level < logLevel)
         return
 
-    System.err.println(LocalDateTime.now().format(dateFormatter) + " | ${any()}")
+    System.err.println(LocalDateTime.now().format(dateFormatter) + " ${level.name.uppercase()}| ${any()}")
 }
 
 // errors that must be address
-private fun logError(any: () -> Any?) {
+internal inline 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?) {
+internal inline fun logInfo(any: () -> Any?) {
     log(ChildProcessLogLevel.Info, any)
 }
 
 // log level for frequent messages useful for debugging
-private fun logDebug(any: () -> Any?) {
+internal inline 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?) {
+internal fun logTrace(any: () -> Any?) {
     log(ChildProcessLogLevel.Trace, any)
 }
 
@@ -193,7 +189,7 @@ private fun <T, R> RdCall<T, R>.measureExecutionForTermination(block: (T) -> R)
                 try {
                     block(it)
                 } catch (e: Throwable) {
-                    logException(e)
+                    logError { e.stackTraceToString() }
                     throw e
                 }
             }
@@ -319,7 +315,6 @@ private suspend fun initiate(lifetime: Lifetime, port: Int, pid: Int) {
         logInfo { "starting instrumenting" }
         deferred.await()
     } catch (e: Throwable) {
-        logError { "Terminating process because exception occurred" }
-        logException(e)
+        logError { "Terminating process because exception occurred: ${e.stackTraceToString()}" }
     }
 }