Skip to content

Commit 2892c2e

Browse files
DomonionDomonion
committed
[utbot-logs]
Design doc for logs, clarifying comments and refactoring.
1 parent 5641169 commit 2892c2e

File tree

11 files changed

+204
-44
lines changed

11 files changed

+204
-44
lines changed

‎build.gradle.kts

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -57,6 +57,7 @@ allprojects {
5757
// this is useful if you debug in docker
5858
// testLogging.showStandardStreams = true
5959
// testLogging.showStackTraces = true
60+
6061
// set heap size for the test JVM(s)
6162
minHeapSize = "128m"
6263
maxHeapSize = "3072m"

‎docs/InterprocessLogging.md

Lines changed: 123 additions & 22 deletions
Original file line numberDiff line numberDiff line change
@@ -5,38 +5,139 @@ This document described how logging is performed across all 3 different processe
55
## Architecture
66

77
All logging relies on log4j2. Writing log entries should occur only in 1 process.
8-
Other processes should send their entries to writing process.
8+
Other processes should **must** send their entries to writing process.
99

1010
Current design:
11-
1. Instrumented process sends its logs to the parent process.
12-
2. IDEA
13-
3. asddddddddddddddddddddddddddddd
11+
1. Instrumented process sends its logs to the parent process.
12+
2. Parent engine process if started from IDEA receives separate instance of log4j2.xml configuration file.
13+
By default, it always writes to the same place for all generation queries as current design implies that there are no concurrent generation processes.
14+
3. In other cases(`ContestEstimator`, `Gradle/Maven` tasks, `CLI`) it searches for `log4j2.xml` in resources from `.jar` it started.
1415

15-
Logs sent via rd
16+
Logs from instrumented process are sent via corresponding RD model: `org.utbot.rd.models.LoggerModel`,
17+
which is instantiated in `org.utbot.instrumentation.rd.InstrumentedProcess.Companion.invoke` and
18+
`org.utbot.instrumentation.process.InstrumentedProcessMainKt.main`.
1619

17-
Folder is here
20+
Log4j2 configuration file path for Engine process is stored at `org.utbot.intellij.plugin.process.EngineProcess.log4j2ConfigFile`.
21+
It is generated from `utbot-intellij/src/main/resources/log4j2.xml`.
1822

19-
### Rd factories
23+
You can override which configuration file to use with `UtSettings.org.utbot.framework.UtSettings.getEngineProcessLogConfigFile`
24+
property from `~/.utbot/settings.properties`. This file will be used **as-is**.
2025

21-
## Log4j2 commons
26+
### Rd logging
2227

23-
File it takesz
24-
Treelike
25-
LogLevels
26-
Service which is killed before sth really ends
27-
# Appenders
28-
1. Console
29-
2. FileAppender
30-
3. RollingFileAppender
28+
Rd has its own logging system, based on `com.jetbrains.rd.util.Logger` interface. It is convenient to use
29+
RD logging as default logging system in instrumented process because log4j2 classes in utbot would be confused
30+
at concrete execution with log4j2 classes in tested project - we will have duplicated versions of log4j2 libs,
31+
this would break instrumentation and coverage statistics.
3132

32-
## Example of log4j2
33+
To override default RD strategy - use `com.jetbrains.rd.util.Logger.Companion.set` method to provide custom
34+
`com.jetbrains.rd.util.ILoggerFactory`. Already created loggers will be automatically reinstantiated to obtain
35+
new logger from provided factory. You can obtain logger via `com.jetbrains.rd.util.getLogger` function.
3336

34-
Just how to configure everything in mentioned in code and log file
37+
It is **highly advised** to override RD logs before first RD use as default system writes to standard
38+
output and error streams. Check `EngineProcessMain` for RD logging example.
3539

36-
## Useful info
40+
For available RD factories see `org.utbot.rd.loggers` package - it contains useful implemented factories,
41+
which log message in the same format as described in `utbot-intellij/src/main/resources/log4j2.xml`.
3742

38-
Performance - about buffered, flush and how it is not logging
43+
## Implementation details
3944

40-
Docker and gradle -
45+
### Additivity
4146

42-
## Links
47+
Sometimes same log entry might be written to log multiple times. At log you will see something like:
48+
```
49+
TODO
50+
```
51+
52+
This is because of loggers *additivity* - their full names defines tree structure, and events from children
53+
are visible for parents. For example, following `log4j2.xml` configuration in IDEA will produce such problem:
54+
```
55+
TODO
56+
```
57+
58+
The solution is to manually add ```additivity="false"``` tag to all loggers.
59+
See `utbot-intellij/src/main/resources/log4j2.xml` for example.
60+
61+
More information is available [here](https://logging.apache.org/log4j/2.x/manual/configuration.html#Additivity).
62+
63+
### UtBot plugin
64+
65+
As plugin does not support multiple generation processes at a time - all engine processes logs to the same file.
66+
67+
UtBot plugin creates log directory `org.utbot.intellij.plugin.process.EngineProcessKt.engineProcessLogDirectory`
68+
where places log files. Logs are written by `RollingFileAppender` in `utbot-engine-current.log` file with rolloing over
69+
after file reaches 20MB size. Previous log files are named `utbot-engine-%i.log`. Log file with
70+
maximal index is the last one rolled. For example, `utbot-engine-1.log` is created earlier than `utbot-engine-10.log`.
71+
72+
### Useful
73+
See auxiliary methods to work with logs at `UtRdLogUtil.kt` and `Logging.kt`.
74+
If you want to trace how long execution took - use `org.utbot.common.LoggingKt.bracket`
75+
method with corresponding log level scope.
76+
77+
Log entries from Instrumented process are logged by `org.utbot.instrumentation.rd.InstrumentedProcessKt.rdLogger`.
78+
79+
## How to use log4j2 loggers
80+
81+
See related document - [How to use loggers](../HowToUseLoggers.md).
82+
83+
## Miscellaneous
84+
85+
### Performance considerations
86+
87+
`Trace` log level for RD loggers(for ex. if you specify `Trace` for all loggers, or as default level for root logger)
88+
will enable logging all technical send/receive event from protocol,
89+
causing ~50mb additional logs per generation and ***heavily*** polluting log. This might be useful
90+
when troubleshooting inter-process communication, but in all other cases prefer `Debug` level or
91+
specify `Trace` level per logger explicitly.
92+
93+
94+
If your log message requires some string interpolation - you might cause unnecessary work, for example:
95+
96+
```kotlin
97+
val someVeryBigDataStructure = VeryBigDataStructure()
98+
99+
logger.debug("data structure representation - $someVeryBigDataStructure") // <---- interpolation
100+
```
101+
In that code even though message uses `Debug` level, interpolation will always occur because
102+
message is passed as a parameter, which are evaluated at call side. Consider using lambdas:
103+
```kotlin
104+
// message will be created only if debug log level is available
105+
logger.debug { "data structure representation - $someVeryBigDataStructure"}
106+
```
107+
108+
Although now logs are sent from one process to another - performance penalties were not noticed.
109+
Additional performance can be achieved playing with `bufferedIO` and `immediateFlush` properties in `log4j2.xml`.
110+
For example you can make following changes in `utbot-intellij`:
111+
```xml
112+
<RollingFile ... bufferedIO="true" immediateFlush="false" ... >
113+
```
114+
115+
This will reduce number of IO operations and use log4j2 buffer more efficiently. The cost it that
116+
when process terminates - log4j2 terminates logging service before buffer is flushed and
117+
you will lose last portion of logs. This might be undesired behaviour in tests and debugging,
118+
but probably acceptable in release.
119+
120+
### Docker and Gradle
121+
122+
To see logs in Gradle from console, Docker and CI - add following `build.gradle.kts`:
123+
```kotlin
124+
allprojects {
125+
tasks {
126+
withType<Test> {
127+
testLogging.showStandardStreams = true
128+
testLogging.showStackTraces = true
129+
}
130+
}
131+
}
132+
```
133+
134+
## Links
135+
136+
Log4j2:
137+
1. [Architecture](https://logging.apache.org/log4j/2.x/manual/architecture.html) - overall log4j2 description.
138+
2. [Layouts](https://logging.apache.org/log4j/2.x/manual/layouts.html) - how to format log messages.
139+
UtBot uses `Pattern layout` everywhere.
140+
3. [Appenders](https://logging.apache.org/log4j/2.x/manual/appenders.html) - about different ways to store log entries,
141+
different storages for log entries and how to configure them. UtBot uses `Console`, `File` and `RollingFile` appenders.
142+
4. [Configuration](https://logging.apache.org/log4j/2.x/manual/configuration.html) - what you can write in configuration file,
143+
precise algorithm which file is used and many other useful info. It is **highly advised** to read `Additivity` part.

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

Lines changed: 2 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -52,13 +52,14 @@ object EngineProcessMain
5252

5353
// use log4j2.configurationFile property to set log4j configuration
5454
suspend fun main(args: Array<String>) = runBlocking {
55+
Logger.set(Lifetime.Eternal, UtRdKLoggerFactory(logger))
56+
5557
logger.info("-----------------------------------------------------------------------")
5658
logger.info("-------------------NEW ENGINE PROCESS STARTED--------------------------")
5759
logger.info("-----------------------------------------------------------------------")
5860
// 0 - auto port for server, should not be used here
5961
val port = findRdPort(args)
6062

61-
Logger.set(Lifetime.Eternal, UtRdKLoggerFactory(logger))
6263

6364
ClientProtocolBuilder().withProtocolTimeout(messageFromMainTimeoutMillis).start(port) {
6465
AbstractSettings.setupFactory(RdSettingsContainerFactory(protocol.settingsModel))

‎utbot-instrumentation/src/main/kotlin/org/utbot/instrumentation/instrumentation/execution/phases/ExecutionPhase.kt

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -3,7 +3,7 @@ package org.utbot.instrumentation.instrumentation.execution.phases
33
import com.jetbrains.rd.util.getLogger
44
import org.utbot.common.bracket
55
import org.utbot.instrumentation.instrumentation.execution.UtConcreteExecutionResult
6-
import org.utbot.rd.debug
6+
import org.utbot.rd.loggers.debug
77

88
private val logger = getLogger<ExecutionPhase>()
99

‎utbot-intellij/src/main/kotlin/org/utbot/intellij/plugin/process/EngineProcess.kt

Lines changed: 11 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -53,10 +53,14 @@ import kotlin.io.path.pathString
5353
import kotlin.reflect.KProperty1
5454
import kotlin.reflect.full.memberProperties
5555

56-
private val engineProcessLogConfigurations = utBotTempDirectory.toFile().resolve("rdEngineProcessLogConfigurations")
56+
private val engineProcessLogConfigurationsDirectory = utBotTempDirectory.toFile().resolve("rdEngineProcessLogConfigurations")
5757
private val logger = KotlinLogging.logger {}
5858
private val engineProcessLogDirectory = utBotTempDirectory.toFile().resolve("rdEngineProcessLogs")
5959

60+
private const val configurationFileDeleteKey = "delete_this_comment_key"
61+
private const val deleteOpenComment = "<!--$configurationFileDeleteKey"
62+
private const val deleteCloseComment = "$configurationFileDeleteKey-->"
63+
6064
data class RdTestGenerationResult(val notEmptyCases: Int, val testSetsId: Long)
6165

6266
class EngineProcessInstantDeathException :
@@ -69,7 +73,7 @@ class EngineProcess private constructor(val project: Project, private val classN
6973

7074
init {
7175
engineProcessLogDirectory.mkdirs()
72-
engineProcessLogConfigurations.mkdirs()
76+
engineProcessLogConfigurationsDirectory.mkdirs()
7377
if (Statics<ILoggerFactory>().get() !is UtRdKLoggerFactory) {
7478
Logger.set(Lifetime.Eternal, UtRdKLoggerFactory(logger))
7579
}
@@ -79,10 +83,10 @@ class EngineProcess private constructor(val project: Project, private val classN
7983
if (customFile.exists()) {
8084
log4j2ConfigFile = customFile
8185
} else {
82-
log4j2ConfigFile = Files.createTempFile(engineProcessLogConfigurations.toPath(), null, ".xml").toFile()
83-
log4j2ConfigFile.deleteOnExit()
86+
log4j2ConfigFile = Files.createTempFile(engineProcessLogConfigurationsDirectory.toPath(), null, ".xml").toFile()
8487
this.javaClass.classLoader.getResourceAsStream("log4j2.xml")?.use { logConfig ->
8588
val resultConfig = logConfig.readBytes().toString(Charset.defaultCharset())
89+
.replace(Regex("$deleteOpenComment|$deleteCloseComment"), "")
8690
.replace("ref=\"IdeaAppender\"", "ref=\"EngineProcessAppender\"")
8791
.replace("\${env:UTBOT_LOG_DIR}", engineProcessLogDirectory.canonicalPath.trimEnd(File.separatorChar) + File.separatorChar)
8892
Files.copy(
@@ -140,6 +144,9 @@ class EngineProcess private constructor(val project: Project, private val classN
140144
val process = builder.start()
141145

142146
logger.info { "Engine process started with PID = ${process.getPid}" }
147+
logger.info { "Engine process log directory - ${engineProcessLogDirectory.canonicalPath}" }
148+
logger.info { "Engine process log file - ${engineProcessLogDirectory.resolve("utbot-engine-current.log")}" }
149+
logger.info { "Log4j2 configuration file path - ${log4j2ConfigFile.canonicalPath}" }
143150

144151
if (!process.isAlive) {
145152
throw EngineProcessInstantDeathException()

‎utbot-intellij/src/main/resources/log4j2.xml

Lines changed: 34 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -1 +1,34 @@
1-
<?xml version="1.0" encoding="UTF-8"?><Configuration> <Appenders><!-- Idea catches plugin stdout log and wraps it in its own format, so in IDE only message is logged--> <Console name="IdeaAppender" target="SYSTEM_OUT"> <PatternLayout pattern="| UtBot - %-25c{1} | %msg%n"/> </Console><!-- When working as separate process - temporary log4j2.xml would be created, in which --><!-- substring `ref="IdeaAppender"` will be replaced with `ref="EngineProcessAppender"`--><!-- You can set bufferIO=true and immediateFlush=false for better performance, but possibly lose some logs on process death - log4j2 service might die unflushed--> <RollingFile append="true" name="EngineProcessAppender" bufferedIO="false" immediateFlush="true" fileName="${env:UTBOT_LOG_DIR}utbot-engine-current.log" filePattern="${env:UTBOT_LOG_DIR}utbot-engine-%i.log" bufferSize="1048576"> <PatternLayout pattern="%d{HH:mm:ss.SSS} | %-5level | %-25c{1} | %msg%n"/> <Policies> <SizeBasedTriggeringPolicy size="20 MB"/> </Policies> <DefaultRolloverStrategy max="10"/> </RollingFile> </Appenders> <Loggers> <Logger name="org.utbot.intellij" level="info" additivity="false"> <AppenderRef ref="IdeaAppender"/> </Logger> <Logger name="org.utbot" level="info" additivity="false"> <AppenderRef ref="IdeaAppender"/> </Logger> <Root level="error"> <AppenderRef ref="IdeaAppender"/> </Root> </Loggers></Configuration>
1+
<?xml version="1.0" encoding="UTF-8"?>
2+
<Configuration>
3+
<Appenders>
4+
<!-- Idea catches plugin stdout log and wraps it in its own format, so in IDE only message is logged-->
5+
<Console name="IdeaAppender" target="SYSTEM_OUT">
6+
<PatternLayout pattern="| UtBot - %-25c{1} | %msg%n"/>
7+
</Console>
8+
<!-- When working as separate process - temporary log4j2.xml would be created, in which -->
9+
<!-- substring `ref="IdeaAppender"` will be replaced with `ref="EngineProcessAppender"` -->
10+
<!-- delete_this_comment_key identifies lines which will be deleted prior creating temp log4j2.xml -->
11+
<!-- You can set bufferIO=true and immediateFlush=false for better performance, -->
12+
<!-- but possibly lose some logs on process death - log4j2 service might die unflushed -->
13+
<!--delete_this_comment_key
14+
<RollingFile append="true" name="EngineProcessAppender" bufferedIO="false" immediateFlush="true" fileName="${env:UTBOT_LOG_DIR}utbot-engine-current.log" filePattern="${env:UTBOT_LOG_DIR}utbot-engine-%i.log" bufferSize="1048576">
15+
<PatternLayout pattern="%d{HH:mm:ss.SSS} | %-5level | %-25c{1} | %msg%n"/>
16+
<Policies>
17+
<SizeBasedTriggeringPolicy size="20 MB"/>
18+
</Policies>
19+
<DefaultRolloverStrategy max="10"/>
20+
</RollingFile>
21+
delete_this_comment_key-->
22+
</Appenders>
23+
<Loggers>
24+
<Logger name="org.utbot.intellij" level="info" additivity="false">
25+
<AppenderRef ref="IdeaAppender"/>
26+
</Logger>
27+
<Logger name="org.utbot" level="info" additivity="false">
28+
<AppenderRef ref="IdeaAppender"/>
29+
</Logger>
30+
<Root level="error">
31+
<AppenderRef ref="IdeaAppender"/>
32+
</Root>
33+
</Loggers>
34+
</Configuration>

‎utbot-rd/src/main/kotlin/org/utbot/rd/ClientProcessUtil.kt

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -19,6 +19,7 @@ import kotlinx.coroutines.channels.trySendBlocking
1919
import kotlinx.coroutines.withTimeoutOrNull
2020
import org.utbot.common.*
2121
import org.utbot.rd.generated.synchronizationModel
22+
import org.utbot.rd.loggers.withLevel
2223
import java.io.File
2324
import kotlin.time.Duration
2425

‎utbot-rd/src/main/kotlin/org/utbot/rd/UtRdUtil.kt

Lines changed: 0 additions & 14 deletions
Original file line numberDiff line numberDiff line change
@@ -124,18 +124,4 @@ suspend fun startUtProcessWithRdServer(
124124
it
125125
)
126126
}
127-
}
128-
129-
fun Logger.withLevel(logLevel: LogLevel): LoggerWithLogMethod = LoggerWithLogMethod {
130-
this.log(logLevel, it)
131-
}
132-
133-
fun Logger.info(): LoggerWithLogMethod = LoggerWithLogMethod {
134-
this.info(it)
135-
}
136-
fun Logger.debug(): LoggerWithLogMethod = LoggerWithLogMethod {
137-
this.debug(it)
138-
}
139-
fun Logger.trace(): LoggerWithLogMethod = LoggerWithLogMethod {
140-
this.trace(it)
141127
}

‎utbot-rd/src/main/kotlin/org/utbot/rd/loggers/UtRdLogUtil.kt

Lines changed: 19 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,19 @@
1+
package org.utbot.rd.loggers
2+
3+
import com.jetbrains.rd.util.*
4+
import org.utbot.common.LoggerWithLogMethod
5+
6+
7+
fun Logger.withLevel(logLevel: LogLevel): LoggerWithLogMethod = LoggerWithLogMethod {
8+
this.log(logLevel, it)
9+
}
10+
11+
fun Logger.info(): LoggerWithLogMethod = LoggerWithLogMethod {
12+
this.info(it)
13+
}
14+
fun Logger.debug(): LoggerWithLogMethod = LoggerWithLogMethod {
15+
this.debug(it)
16+
}
17+
fun Logger.trace(): LoggerWithLogMethod = LoggerWithLogMethod {
18+
this.trace(it)
19+
}

‎utbot-rd/src/main/kotlin/org/utbot/rd/loggers/UtRdRemoteLogger.kt

Lines changed: 7 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -25,6 +25,13 @@ class UtRdRemoteLogger(
2525
}
2626

2727
override fun isEnabled(level: LogLevel): Boolean {
28+
// On every protocol send/receive event RD to its own loggers.
29+
// They will be redirected here, and then sent via RD to another process,
30+
// producing new log event again thus causing infinite recursion.
31+
// The solution is to prohibit writing any logs from inside logger.
32+
// This is implemented via thread local counter per logger,
33+
// which will be incremented when this logger fires event to another process,
34+
// and deny all following log events until previous log event is delivered.
2835
if (threadLocalExecuting[this] > 0)
2936
return false
3037

0 commit comments

Comments
 (0)