Skip to content

Commit ae0546c

Browse files
DomonionDomonion
committed
temp commit for ultra logs
1 parent 22badb4 commit ae0546c

File tree

33 files changed

+624
-285
lines changed

33 files changed

+624
-285
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: 19 additions & 19 deletions
Original file line numberDiff line numberDiff line change
@@ -1904,21 +1904,21 @@ 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-
}
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+
// }
19221922

19231923
documentation = CgDocumentationComment(docComment)
19241924
documentation = if (parameterized) {
@@ -1982,10 +1982,10 @@ open class CgMethodConstructor(val context: CgContext) : CgContextOwner by conte
19821982
return PathUtil.toHtmlLinkTag(PathUtil.replaceSeparator(pureJvmReportPath), fileName = "JVM crash report") + "\n"
19831983
}
19841984

1985-
private fun UtConcreteExecutionFailure.extractJvmReportPathOrNull(): String? =
1986-
exception.processStdout.singleOrNull {
1987-
"hs_err_pid" in it
1988-
}
1985+
// private fun UtConcreteExecutionFailure.extractJvmReportPathOrNull(): String? =
1986+
// exception.processStdout.singleOrNull {
1987+
// "hs_err_pid" in it
1988+
// }
19891989

19901990
private fun CgExecutableCall.wrapReflectiveCall() {
19911991
+tryBlock {

‎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)