Skip to content

Commit c54dc3b

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 332c215 commit c54dc3b

File tree

35 files changed

+656
-326
lines changed

35 files changed

+656
-326
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: 5 additions & 16 deletions
Original file line numberDiff line numberDiff line change
@@ -1,8 +1,6 @@
11
package org.utbot.framework.plugin.api
22

33
import org.utbot.framework.plugin.api.visible.UtStreamConsumingException
4-
import java.io.File
5-
import java.util.LinkedList
64

75
sealed class UtExecutionResult
86

@@ -38,8 +36,11 @@ data class UtStreamConsumingFailure(
3836

3937
/**
4038
* unexpectedFail (when exceptions such as NPE, IOBE, etc. appear, but not thrown by a user, applies both for function under test and nested calls )
39+
*
4140
* expectedCheckedThrow (when function under test or nested call explicitly says that checked exception could be thrown and throws it)
41+
*
4242
* expectedUncheckedThrow (when there is a throw statement for unchecked exception inside of function under test)
43+
*
4344
* unexpectedUncheckedThrow (in case when there is unchecked exception thrown from nested call)
4445
*/
4546
data class UtExplicitlyThrownException(
@@ -60,25 +61,13 @@ data class UtTimeoutException(override val exception: TimeoutException) : UtExec
6061
* Indicates failure in concrete execution.
6162
* For now it is explicitly throwing by ConcreteExecutor in case instrumented process death.
6263
*/
63-
class InstrumentedProcessDeathException(cause: Throwable, errorFile: File, val processStdout: List<String>) :
64+
class InstrumentedProcessDeathException(cause: Throwable) :
6465
Exception(
6566
buildString {
6667
appendLine()
6768
appendLine("----------------------------------------")
6869
appendLine("The instrumented process is dead")
6970
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-
}
8271
appendLine("----------------------------------------")
8372
},
8473
cause
@@ -105,4 +94,4 @@ inline fun UtExecutionResult.onFailure(action: (exception: Throwable) -> Unit):
10594
fun UtExecutionResult.exceptionOrNull(): Throwable? = when (this) {
10695
is UtExecutionFailure -> rootCauseException
10796
is UtExecutionSuccess -> null
108-
}
97+
}

‎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
@@ -1899,22 +1899,6 @@ open class CgMethodConstructor(val context: CgContext) : CgContextOwner by conte
18991899
methodType = this@CgMethodConstructor.methodType
19001900
val docComment = currentExecution?.summary?.map { convertDocToCg(it) }?.toMutableList() ?: mutableListOf()
19011901

1902-
// add JVM crash report path if exists
1903-
if (result is UtConcreteExecutionFailure) {
1904-
result.extractJvmReportPathOrNull()?.let {
1905-
val jvmReportDocumentation = CgDocRegularStmt(getJvmReportDocumentation(it))
1906-
val lastTag = docComment.lastOrNull()
1907-
// if the last statement is a <pre> tag, put the path inside it
1908-
if (lastTag == null || lastTag !is CgDocPreTagStatement) {
1909-
docComment += jvmReportDocumentation
1910-
} else {
1911-
val tagContent = lastTag.content
1912-
docComment.removeLast()
1913-
docComment += CgDocPreTagStatement(tagContent + jvmReportDocumentation)
1914-
}
1915-
}
1916-
}
1917-
19181902
documentation = CgDocumentationComment(docComment)
19191903
documentation = if (parameterized) {
19201904
CgDocumentationComment(text = null)
@@ -1970,18 +1954,6 @@ open class CgMethodConstructor(val context: CgContext) : CgContextOwner by conte
19701954
return CgSimpleRegion("Errors report for ${executable.name}", listOf(errorTestMethod))
19711955
}
19721956

1973-
private fun getJvmReportDocumentation(jvmReportPath: String): String {
1974-
val pureJvmReportPath = jvmReportPath.substringAfter("# ")
1975-
1976-
// \n is here because IntellijIdea cannot process other separators
1977-
return PathUtil.toHtmlLinkTag(PathUtil.replaceSeparator(pureJvmReportPath), fileName = "JVM crash report") + "\n"
1978-
}
1979-
1980-
private fun UtConcreteExecutionFailure.extractJvmReportPathOrNull(): String? =
1981-
exception.processStdout.singleOrNull {
1982-
"hs_err_pid" in it
1983-
}
1984-
19851957
private fun CgExecutableCall.wrapReflectiveCall() {
19861958
+tryBlock {
19871959
+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)