Skip to content

Commit 9eb68e0

Browse files
DomonionDomonion
committed
[utbot-logs]
Complete logs redesign 1. Added Logger model to rd 2. InstrumentedProcess is now sending all logs to EngineProcess, which then writes to itws own file 3. Removed UtSettings.instrumentedProcessLogLevel 4. Auxiliary log functions 5. UtRdLoggers redesigned to have the same logging pattern 6. From now log4j2.xml is responsible for instrumentation process log configuration
1 parent 5eac028 commit 9eb68e0

33 files changed

+594
-317
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
@@ -339,11 +338,6 @@ object UtSettings : AbstractSettings(logger, defaultKeyForSettingsPath, defaultS
339338
* @see [org.utbot.instrumentation.process.InstrumentedProcessRunner.cmds]
340339
*/
341340
var runInstrumentedProcessWithDebug by getBooleanProperty(false)
342-
343-
/**
344-
* Log level for instrumented process.
345-
*/
346-
var instrumentedProcessLogLevel by getEnumProperty(LogLevel.Info)
347341
// endregion
348342

349343
/**

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

Lines changed: 1 addition & 13 deletions
Original file line numberDiff line numberDiff line change
@@ -60,25 +60,13 @@ data class UtTimeoutException(override val exception: TimeoutException) : UtExec
6060
* Indicates failure in concrete execution.
6161
* For now it is explicitly throwing by ConcreteExecutor in case instrumented process death.
6262
*/
63-
class ConcreteExecutionFailureException(cause: Throwable, errorFile: File, val processStdout: List<String>) :
63+
class ConcreteExecutionFailureException(cause: Throwable) :
6464
Exception(
6565
buildString {
6666
appendLine()
6767
appendLine("----------------------------------------")
6868
appendLine("The instrumented process is dead")
6969
appendLine("Cause:\n${cause.message}")
70-
appendLine("Last 1000 lines of the error log ${errorFile.absolutePath}:")
71-
appendLine("----------------------------------------")
72-
errorFile.useLines { lines ->
73-
val lastLines = LinkedList<String>()
74-
for (line in lines) {
75-
lastLines.add(line)
76-
if (lastLines.size > 1000) {
77-
lastLines.removeFirst()
78-
}
79-
}
80-
lastLines.forEach { appendLine(it) }
81-
}
8270
appendLine("----------------------------------------")
8371
},
8472
cause

‎utbot-framework/src/main/kotlin/org/utbot/framework/codegen/tree/CgMethodConstructor.kt

Lines changed: 0 additions & 28 deletions
Original file line numberDiff line numberDiff line change
@@ -1904,22 +1904,6 @@ open class CgMethodConstructor(val context: CgContext) : CgContextOwner by conte
19041904
methodType = this@CgMethodConstructor.methodType
19051905
val docComment = currentExecution?.summary?.map { convertDocToCg(it) }?.toMutableList() ?: mutableListOf()
19061906

1907-
// add JVM crash report path if exists
1908-
if (result is UtConcreteExecutionFailure) {
1909-
result.extractJvmReportPathOrNull()?.let {
1910-
val jvmReportDocumentation = CgDocRegularStmt(getJvmReportDocumentation(it))
1911-
val lastTag = docComment.lastOrNull()
1912-
// if the last statement is a <pre> tag, put the path inside it
1913-
if (lastTag == null || lastTag !is CgDocPreTagStatement) {
1914-
docComment += jvmReportDocumentation
1915-
} else {
1916-
val tagContent = lastTag.content
1917-
docComment.removeLast()
1918-
docComment += CgDocPreTagStatement(tagContent + jvmReportDocumentation)
1919-
}
1920-
}
1921-
}
1922-
19231907
documentation = CgDocumentationComment(docComment)
19241908
documentation = if (parameterized) {
19251909
CgDocumentationComment(text = null)
@@ -1975,18 +1959,6 @@ open class CgMethodConstructor(val context: CgContext) : CgContextOwner by conte
19751959
return CgSimpleRegion("Errors report for ${executable.name}", listOf(errorTestMethod))
19761960
}
19771961

1978-
private fun getJvmReportDocumentation(jvmReportPath: String): String {
1979-
val pureJvmReportPath = jvmReportPath.substringAfter("# ")
1980-
1981-
// \n is here because IntellijIdea cannot process other separators
1982-
return PathUtil.toHtmlLinkTag(PathUtil.replaceSeparator(pureJvmReportPath), fileName = "JVM crash report") + "\n"
1983-
}
1984-
1985-
private fun UtConcreteExecutionFailure.extractJvmReportPathOrNull(): String? =
1986-
exception.processStdout.singleOrNull {
1987-
"hs_err_pid" in it
1988-
}
1989-
19901962
private fun CgExecutableCall.wrapReflectiveCall() {
19911963
+tryBlock {
19921964
+this@wrapReflectiveCall

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

Lines changed: 61 additions & 68 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.*
@@ -50,8 +47,14 @@ import kotlin.time.Duration.Companion.seconds
5047
private val messageFromMainTimeoutMillis = 120.seconds
5148
private val logger = KotlinLogging.logger {}
5249

50+
@Suppress("unused")
51+
object EngineProcessMain
52+
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) },
@@ -92,37 +92,39 @@ private fun EngineProcessModel.setup(kryoHelper: KryoHelper, watchdog: IdleWatch
9292
}
9393
})
9494
}
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), sourceFile = null) }
117-
.apply { logger.info("summarization ended") }
118-
.filterNot { it.executions.isEmpty() && it.errors.isEmpty() }
95+
watchdog.bracketActiveCall(generate, "Generating tests") { params ->
96+
val methods: List<ExecutableId> = kryoHelper.readObject(params.methods)
97+
logger.debug().bracket("starting generation for ${methods.size} methods, starting with ${methods.first()}") {
98+
val mockFrameworkInstalled = params.mockInstalled
99+
val conflictTriggers = ConflictTriggers(kryoHelper.readObject(params.conflictTriggers))
100+
if (!mockFrameworkInstalled) {
101+
ForceMockListener.create(testGenerator, conflictTriggers, cancelJob = true)
102+
}
103+
val staticsMockingConfigured = params.staticsMockingIsConfigureda
104+
if (!staticsMockingConfigured) {
105+
ForceStaticMockListener.create(testGenerator, conflictTriggers, cancelJob = true)
106+
}
107+
val result = testGenerator.generate(methods,
108+
MockStrategyApi.valueOf(params.mockStrategy),
109+
kryoHelper.readObject(params.chosenClassesToMockAlways),
110+
params.timeout,
111+
generate = testFlow {
112+
generationTimeout = params.generationTimeout
113+
isSymbolicEngineEnabled = params.isSymbolicEngineEnabled
114+
isFuzzingEnabled = params.isFuzzingEnabled
115+
fuzzingValue = params.fuzzingValue
116+
}).apply { logger.info("generation ended, starting summarization, result size: ${this.size}") }
117+
.map { it.summarize(Paths.get(params.searchDirectory), null) }
118+
.apply { logger.info("summarization ended") }
119+
.filterNot { it.executions.isEmpty() && it.errors.isEmpty() }
119120

120-
val id = ++idCounter
121+
val id = ++idCounter
121122

122-
testSets[id] = result
123-
GenerateResult(result.size, id)
123+
testSets[id] = result
124+
GenerateResult(result.size, id)
125+
}
124126
}
125-
watchdog.wrapActiveCall(render) { params ->
127+
watchdog.bracketActiveCall(render, "Rendering tests") { params ->
126128
val testFramework = testFrameworkByName(params.testFramework)
127129
val staticMocking = if (params.staticsMocking.startsWith("No")) {
128130
NoStaticMocking
@@ -147,37 +149,32 @@ private fun EngineProcessModel.setup(kryoHelper: KryoHelper, watchdog: IdleWatch
147149
enableTestsTimeout = params.enableTestsTimeout,
148150
testClassPackageName = params.testClassPackageName
149151
)
150-
codeGenerator.generateAsStringWithTestReport(testSets[testSetsId]!!)
151-
.let {
152-
testGenerationReports.add(it.testsGenerationReport)
153-
RenderResult(it.generatedCode, it.utilClassKind?.javaClass?.simpleName)
154-
}
152+
codeGenerator.generateAsStringWithTestReport(testSets[testSetsId]!!).let {
153+
testGenerationReports.add(it.testsGenerationReport)
154+
RenderResult(it.generatedCode, it.utilClassKind?.javaClass?.simpleName)
155+
}
155156
}
156-
watchdog.wrapActiveCall(stopProcess) { watchdog.stopProtocol() }
157-
watchdog.wrapActiveCall(obtainClassId) { canonicalName ->
157+
watchdog.bracketActiveCall(obtainClassId, "Obtain class id in UtContext") { canonicalName ->
158158
kryoHelper.writeObject(UtContext.currentContext()!!.classLoader.loadClass(canonicalName).id)
159159
}
160-
watchdog.wrapActiveCall(findMethodsInClassMatchingSelected) { params ->
160+
watchdog.bracketActiveCall(findMethodsInClassMatchingSelected, "Find methods in Class") { params ->
161161
val classId = kryoHelper.readObject<ClassId>(params.classId)
162162
val selectedMethodDescriptions =
163163
params.methodDescriptions.map { MethodDescription(it.name, it.containingClass, it.parametersTypes) }
164164
FindMethodsInClassMatchingSelectedResult(kryoHelper.writeObject(classId.jClass.allNestedClasses.flatMap { clazz ->
165165
clazz.id.allMethods.mapNotNull { it.method.kotlinFunction }
166166
.sortedWith(compareBy { selectedMethodDescriptions.indexOf(it.methodDescription()) })
167-
.filter { it.methodDescription().normalized() in selectedMethodDescriptions }
168-
.map { it.executableId }
167+
.filter { it.methodDescription().normalized() in selectedMethodDescriptions }.map { it.executableId }
169168
}))
170169
}
171-
watchdog.wrapActiveCall(findMethodParamNames) { params ->
170+
watchdog.bracketActiveCall(findMethodParamNames, "Find method parameters names") { params ->
172171
val classId = kryoHelper.readObject<ClassId>(params.classId)
173172
val byMethodDescription = kryoHelper.readObject<Map<MethodDescription, List<String>>>(params.bySignature)
174-
FindMethodParamNamesResult(kryoHelper.writeObject(
175-
classId.jClass.allNestedClasses.flatMap { clazz -> clazz.id.allMethods.mapNotNull { it.method.kotlinFunction } }
176-
.mapNotNull { method -> byMethodDescription[method.methodDescription()]?.let { params -> method.executableId to params } }
177-
.toMap()
178-
))
173+
FindMethodParamNamesResult(kryoHelper.writeObject(classId.jClass.allNestedClasses.flatMap { clazz -> clazz.id.allMethods.mapNotNull { it.method.kotlinFunction } }
174+
.mapNotNull { method -> byMethodDescription[method.methodDescription()]?.let { params -> method.executableId to params } }
175+
.toMap()))
179176
}
180-
watchdog.wrapActiveCall(writeSarifReport) { params ->
177+
watchdog.bracketActiveCall(writeSarifReport, "Writing Sarif report") { params ->
181178
val reportFilePath = Paths.get(params.reportFilePath)
182179
reportFilePath.parent.toFile().mkdirs()
183180
val sarifReport = SarifReport(
@@ -188,12 +185,12 @@ private fun EngineProcessModel.setup(kryoHelper: KryoHelper, watchdog: IdleWatch
188185
reportFilePath.toFile().writeText(sarifReport)
189186
sarifReport
190187
}
191-
watchdog.wrapActiveCall(generateTestReport) { params ->
188+
watchdog.bracketActiveCall(generateTestReport, "Generating test report") { params ->
192189
val eventLogMessage = params.eventLogMessage
193190
val testPackageName: String? = params.testPackageName
194191
var hasWarnings = false
195192
val reports = testGenerationReports
196-
if (reports.isEmpty()) return@wrapActiveCall GenerateTestReportResult("No tests were generated", null, true)
193+
if (reports.isEmpty()) return@bracketActiveCall GenerateTestReportResult("No tests were generated", null, true)
197194
val isMultiPackage = params.isMultiPackage
198195
val (notifyMessage, statistics) = if (reports.size == 1) {
199196
val report = reports.first()
@@ -202,15 +199,13 @@ private fun EngineProcessModel.setup(kryoHelper: KryoHelper, watchdog: IdleWatch
202199
val message = buildString {
203200
appendHtmlLine(report.toString(isShort = true))
204201

205-
val classUnderTestPackageName =
206-
report.classUnderTest.java.nameOfPackage
202+
val classUnderTestPackageName = report.classUnderTest.java.nameOfPackage
207203

208-
destinationWarningMessage(testPackageName, classUnderTestPackageName)
209-
?.let {
210-
hasWarnings = true
211-
appendHtmlLine(it)
212-
appendHtmlLine()
213-
}
204+
destinationWarningMessage(testPackageName, classUnderTestPackageName)?.let {
205+
hasWarnings = true
206+
appendHtmlLine(it)
207+
appendHtmlLine()
208+
}
214209
eventLogMessage?.let {
215210
appendHtmlLine(it)
216211
}
@@ -232,13 +227,11 @@ private fun EngineProcessModel.setup(kryoHelper: KryoHelper, watchdog: IdleWatch
232227
// TODO maybe add statistics info here
233228

234229
for (report in reports) {
235-
val classUnderTestPackageName =
236-
report.classUnderTest.java.nameOfPackage
230+
val classUnderTestPackageName = report.classUnderTest.java.nameOfPackage
237231

238232
hasWarnings = hasWarnings || report.hasWarnings
239233
if (!isMultiPackage) {
240-
val destinationWarning =
241-
destinationWarningMessage(testPackageName, classUnderTestPackageName)
234+
val destinationWarning = destinationWarningMessage(testPackageName, classUnderTestPackageName)
242235
if (destinationWarning != null) {
243236
hasWarnings = true
244237
appendHtmlLine(destinationWarning)

0 commit comments

Comments
 (0)