Skip to content

Commit 7f97aa5

Browse files
DomonionDomonion
committed
[utbot-logs]
1. Added Logger model to rd 2. InstrumentedProcess is now sending all logs to EngineProcess, which then writes to its own file 3. Removed instrumentedProcessLogLevel 4. auxiliary log functions 5. stop process rdcall 6. UtRd Loggers redesigned to have the same logging parttern
1 parent 1883cc7 commit 7f97aa5

35 files changed

+601
-245
lines changed

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

Lines changed: 17 additions & 9 deletions
Original file line numberDiff line numberDiff line change
@@ -6,11 +6,11 @@ import java.time.format.DateTimeFormatter
66
val timeFormatter: DateTimeFormatter = DateTimeFormatter.ofPattern("HH:mm:ss.SSS")
77
val dateTimeFormatter = DateTimeFormatter.ofPattern("dd-MM-yyyy_HH-mm-ss")
88

9-
class LoggerWithLogMethod(val logger: KLogger, val logMethod: (() -> Any?) -> Unit)
9+
class LoggerWithLogMethod(val logMethod: (() -> Any?) -> Unit)
1010

11-
fun KLogger.info(): LoggerWithLogMethod = LoggerWithLogMethod(this, this::info)
12-
fun KLogger.debug(): LoggerWithLogMethod = LoggerWithLogMethod(this, this::debug)
13-
fun KLogger.trace(): LoggerWithLogMethod = LoggerWithLogMethod(this, this::trace)
11+
fun KLogger.info(): LoggerWithLogMethod = LoggerWithLogMethod(this::info)
12+
fun KLogger.debug(): LoggerWithLogMethod = LoggerWithLogMethod(this::debug)
13+
fun KLogger.trace(): LoggerWithLogMethod = LoggerWithLogMethod(this::trace)
1414

1515
fun elapsedSecFrom(startNano: Long): String {
1616
val elapsedNano = System.nanoTime() - startNano
@@ -44,7 +44,7 @@ inline fun <T> LoggerWithLogMethod.bracket(
4444
val startNano = System.nanoTime()
4545
var alreadyLogged = false
4646

47-
var res : Maybe<T> = Maybe.empty()
47+
var res: Maybe<T> = Maybe.empty()
4848
try {
4949
// Note: don't replace this one with runCatching, otherwise return from lambda breaks "finished" logging.
5050
res = Maybe(block())
@@ -63,20 +63,28 @@ inline fun <T> LoggerWithLogMethod.bracket(
6363
}
6464
}
6565

66-
inline fun <T> KLogger.catchException(block: () -> T): T? {
66+
inline fun <T> KLogger.catchException(message: String = "Isolated", block: () -> T): T? {
6767
return try {
6868
block()
6969
} catch (e: Throwable) {
70-
this.error(e) { "Isolated" }
70+
this.error(message, e)
7171
null
7272
}
7373
}
7474

75-
inline fun <T> KLogger.logException(block: () -> T): T {
75+
inline fun <T> KLogger.logException(message: String ="Exception occurred", block: () -> T): T {
7676
return try {
7777
block()
7878
} catch (e: Throwable) {
79-
this.error("Exception occurred", e)
79+
this.error(message, e)
8080
throw e
8181
}
82+
}
83+
84+
inline fun <T> silent(block: () -> T): T? {
85+
return try {
86+
block()
87+
} catch (_: Throwable) {
88+
null
89+
}
8290
}

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

Lines changed: 0 additions & 6 deletions
Original file line numberDiff line numberDiff line change
@@ -1,6 +1,5 @@
11
package org.utbot.framework
22

3-
import com.jetbrains.rd.util.LogLevel
43
import java.io.File
54
import mu.KotlinLogging
65
import org.utbot.common.AbstractSettings
@@ -338,11 +337,6 @@ object UtSettings : AbstractSettings(logger, defaultKeyForSettingsPath, defaultS
338337
* @see [org.utbot.instrumentation.process.InstrumentedProcessRunner.cmds]
339338
*/
340339
var runInstrumentedProcessWithDebug by getBooleanProperty(false)
341-
342-
/**
343-
* Log level for instrumented process.
344-
*/
345-
var instrumentedProcessLogLevel by getEnumProperty(LogLevel.Info)
346340
// endregion
347341

348342
/**

‎utbot-framework/src/main/kotlin/org/utbot/framework/process/EngineProcessMain.kt‎

Lines changed: 49 additions & 46 deletions
Original file line numberDiff line numberDiff line change
@@ -6,10 +6,7 @@ import com.jetbrains.rd.util.lifetime.Lifetime
66
import kotlinx.coroutines.runBlocking
77
import mu.KotlinLogging
88
import org.utbot.analytics.AnalyticsConfigureUtil
9-
import org.utbot.common.AbstractSettings
10-
import org.utbot.common.allNestedClasses
11-
import org.utbot.common.appendHtmlLine
12-
import org.utbot.common.nameOfPackage
9+
import org.utbot.common.*
1310
import org.utbot.engine.util.mockListeners.ForceMockListener
1411
import org.utbot.engine.util.mockListeners.ForceStaticMockListener
1512
import org.utbot.framework.codegen.*
@@ -48,10 +45,16 @@ import kotlin.reflect.jvm.kotlinFunction
4845
import kotlin.time.Duration.Companion.seconds
4946

5047
private val messageFromMainTimeoutMillis = 120.seconds
51-
private val logger = KotlinLogging.logger {}
48+
private val logger = KotlinLogging.logger{}
49+
50+
@Suppress("unused")
51+
object EngineProcessMain
5252

5353
// use log4j2.configurationFile property to set log4j configuration
5454
suspend fun main(args: Array<String>) = runBlocking {
55+
logger.info("-----------------------------------------------------------------------")
56+
logger.info("-------------------NEW ENGINE PROCESS STARTED--------------------------")
57+
logger.info("-----------------------------------------------------------------------")
5558
// 0 - auto port for server, should not be used here
5659
val port = findRdPort(args)
5760

@@ -62,9 +65,6 @@ suspend fun main(args: Array<String>) = runBlocking {
6265
val kryoHelper = KryoHelper(lifetime)
6366
engineProcessModel.setup(kryoHelper, it, protocol)
6467
}
65-
logger.info { "runBlocking ending" }
66-
}.also {
67-
logger.info { "runBlocking ended" }
6868
}
6969

7070
private lateinit var testGenerator: TestCaseGenerator
@@ -74,12 +74,12 @@ private var idCounter: Long = 0
7474

7575
private fun EngineProcessModel.setup(kryoHelper: KryoHelper, watchdog: IdleWatchdog, realProtocol: IProtocol) {
7676
val model = this
77-
watchdog.wrapActiveCall(setupUtContext) { params ->
77+
watchdog.bracketActiveCall(setupUtContext, "UtContext setup") { params ->
7878
UtContext.setUtContext(UtContext(URLClassLoader(params.classpathForUrlsClassloader.map {
7979
File(it).toURI().toURL()
8080
}.toTypedArray())))
8181
}
82-
watchdog.wrapActiveCall(createTestGenerator) { params ->
82+
watchdog.bracketActiveCall(createTestGenerator, "Creating Test Generator") { params ->
8383
AnalyticsConfigureUtil.configureML()
8484
Instrumenter.adapter = RdInstrumenter(realProtocol.rdInstrumenterAdapter)
8585
testGenerator = TestCaseGenerator(buildDirs = params.buildDir.map { Paths.get(it) },
@@ -90,39 +90,43 @@ private fun EngineProcessModel.setup(kryoHelper: KryoHelper, watchdog: IdleWatch
9090
runBlocking {
9191
model.isCancelled.startSuspending(Unit)
9292
}
93-
})
93+
}
94+
)
9495
}
95-
watchdog.wrapActiveCall(generate) { params ->
96-
val mockFrameworkInstalled = params.mockInstalled
97-
val conflictTriggers = ConflictTriggers(kryoHelper.readObject(params.conflictTriggers))
98-
if (!mockFrameworkInstalled) {
99-
ForceMockListener.create(testGenerator, conflictTriggers, cancelJob = true)
100-
}
101-
val staticsMockingConfigured = params.staticsMockingIsConfigureda
102-
if (!staticsMockingConfigured) {
103-
ForceStaticMockListener.create(testGenerator, conflictTriggers, cancelJob = true)
104-
}
105-
val result = testGenerator.generate(kryoHelper.readObject(params.methods),
106-
MockStrategyApi.valueOf(params.mockStrategy),
107-
kryoHelper.readObject(params.chosenClassesToMockAlways),
108-
params.timeout,
109-
generate = testFlow {
110-
generationTimeout = params.generationTimeout
111-
isSymbolicEngineEnabled = params.isSymbolicEngineEnabled
112-
isFuzzingEnabled = params.isFuzzingEnabled
113-
fuzzingValue = params.fuzzingValue
114-
})
115-
.apply { logger.info("generation ended, starting summarization, result size: ${this.size}") }
116-
.map { it.summarize(Paths.get(params.searchDirectory)) }
117-
.apply { logger.info("summarization ended") }
118-
.filterNot { it.executions.isEmpty() && it.errors.isEmpty() }
96+
watchdog.bracketActiveCall(generate, "Generating tests") { params ->
97+
val methods: List<ExecutableId> = kryoHelper.readObject(params.methods)
98+
logger.debug().bracket("starting generation for ${methods.size} methods, starting with ${methods.first()}") {
99+
val mockFrameworkInstalled = params.mockInstalled
100+
val conflictTriggers = ConflictTriggers(kryoHelper.readObject(params.conflictTriggers))
101+
if (!mockFrameworkInstalled) {
102+
ForceMockListener.create(testGenerator, conflictTriggers, cancelJob = true)
103+
}
104+
val staticsMockingConfigured = params.staticsMockingIsConfigureda
105+
if (!staticsMockingConfigured) {
106+
ForceStaticMockListener.create(testGenerator, conflictTriggers, cancelJob = true)
107+
}
108+
val result = testGenerator.generate(methods,
109+
MockStrategyApi.valueOf(params.mockStrategy),
110+
kryoHelper.readObject(params.chosenClassesToMockAlways),
111+
params.timeout,
112+
generate = testFlow {
113+
generationTimeout = params.generationTimeout
114+
isSymbolicEngineEnabled = params.isSymbolicEngineEnabled
115+
isFuzzingEnabled = params.isFuzzingEnabled
116+
fuzzingValue = params.fuzzingValue
117+
})
118+
.apply { logger.info("generation ended, starting summarization, result size: ${this.size}") }
119+
.map { it.summarize(Paths.get(params.searchDirectory)) }
120+
.apply { logger.info("summarization ended") }
121+
.filterNot { it.executions.isEmpty() && it.errors.isEmpty() }
119122

120-
val id = ++idCounter
123+
val id = ++idCounter
121124

122-
testSets[id] = result
123-
GenerateResult(result.size, id)
125+
testSets[id] = result
126+
GenerateResult(result.size, id)
127+
}
124128
}
125-
watchdog.wrapActiveCall(render) { params ->
129+
watchdog.bracketActiveCall(render, "Rendering tests") { params ->
126130
val testFramework = testFrameworkByName(params.testFramework)
127131
val staticMocking = if (params.staticsMocking.startsWith("No")) {
128132
NoStaticMocking
@@ -153,11 +157,10 @@ private fun EngineProcessModel.setup(kryoHelper: KryoHelper, watchdog: IdleWatch
153157
RenderResult(it.generatedCode, it.utilClassKind?.javaClass?.simpleName)
154158
}
155159
}
156-
watchdog.wrapActiveCall(stopProcess) { watchdog.stopProtocol() }
157-
watchdog.wrapActiveCall(obtainClassId) { canonicalName ->
160+
watchdog.bracketActiveCall(obtainClassId, "Obtain class id in UtContext") { canonicalName ->
158161
kryoHelper.writeObject(UtContext.currentContext()!!.classLoader.loadClass(canonicalName).id)
159162
}
160-
watchdog.wrapActiveCall(findMethodsInClassMatchingSelected) { params ->
163+
watchdog.bracketActiveCall(findMethodsInClassMatchingSelected, "Find methods in Class") { params ->
161164
val classId = kryoHelper.readObject<ClassId>(params.classId)
162165
val selectedMethodDescriptions =
163166
params.methodDescriptions.map { MethodDescription(it.name, it.containingClass, it.parametersTypes) }
@@ -168,7 +171,7 @@ private fun EngineProcessModel.setup(kryoHelper: KryoHelper, watchdog: IdleWatch
168171
.map { it.executableId }
169172
}))
170173
}
171-
watchdog.wrapActiveCall(findMethodParamNames) { params ->
174+
watchdog.bracketActiveCall(findMethodParamNames, "Find method parameters names") { params ->
172175
val classId = kryoHelper.readObject<ClassId>(params.classId)
173176
val byMethodDescription = kryoHelper.readObject<Map<MethodDescription, List<String>>>(params.bySignature)
174177
FindMethodParamNamesResult(kryoHelper.writeObject(
@@ -177,7 +180,7 @@ private fun EngineProcessModel.setup(kryoHelper: KryoHelper, watchdog: IdleWatch
177180
.toMap()
178181
))
179182
}
180-
watchdog.wrapActiveCall(writeSarifReport) { params ->
183+
watchdog.bracketActiveCall(writeSarifReport, "Writing Sarif report") { params ->
181184
val reportFilePath = Paths.get(params.reportFilePath)
182185
reportFilePath.parent.toFile().mkdirs()
183186
val sarifReport = SarifReport(
@@ -188,12 +191,12 @@ private fun EngineProcessModel.setup(kryoHelper: KryoHelper, watchdog: IdleWatch
188191
reportFilePath.toFile().writeText(sarifReport)
189192
sarifReport
190193
}
191-
watchdog.wrapActiveCall(generateTestReport) { params ->
194+
watchdog.bracketActiveCall(generateTestReport, "Generating test report") { params ->
192195
val eventLogMessage = params.eventLogMessage
193196
val testPackageName: String? = params.testPackageName
194197
var hasWarnings = false
195198
val reports = testGenerationReports
196-
if (reports.isEmpty()) return@wrapActiveCall GenerateTestReportResult("No tests were generated", null, true)
199+
if (reports.isEmpty()) return@bracketActiveCall GenerateTestReportResult("No tests were generated", null, true)
197200
val isMultiPackage = params.isMultiPackage
198201
val (notifyMessage, statistics) = if (reports.size == 1) {
199202
val report = reports.first()

0 commit comments

Comments
 (0)