Skip to content

Commit c96c830

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 its 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 7. Added summarization start/end log notifications and instrumented process starting messages. 8. Design doc for logs, clarifying comments and refactoring. 9. Changed `bracket` to `logMeasure`. its signature from plain string message to lambda to remove extra interpolation when message log level is not supported/
1 parent 7ae6665 commit c96c830

File tree

55 files changed

+1405
-905
lines changed

Some content is hidden

Large Commits have some content hidden by default. Use the searchbox below for content that may be hidden.

55 files changed

+1405
-905
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: 229 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,229 @@
1+
# Interprocess logging
2+
3+
This document described how logging is performed across all 3 different processes: IDEA, Engine and Instrumented.
4+
5+
## Architecture
6+
7+
All logging relies on log4j2.
8+
When UtBot is used as IDEA plugin - [`utbot-intellij/log4j2.xml`](../utbot-intellij/src/main/resources/log4j2.xml)
9+
is used as configuration file.
10+
In other cases(`ContestEstimator`, `Gradle/Maven` tasks, `CLI`, tests) it searches for the first `log4j2.xml` in resources in classpath.
11+
12+
### IDE process
13+
IDEA part of UtBot write logs to `idea.log`.
14+
Log configuration file is used as is, so if you want to configure logs in IDEA part - use it straight.
15+
If you want to change log configuration in already built plugin -
16+
use `Help > Diagnostic Tools > Debug Log Settings...` to change `log4j2.xml` configuration for plugin.
17+
18+
19+
### UtBot plugin
20+
21+
22+
UtBot plugin creates log directory `org.utbot.intellij.plugin.process.EngineProcessKt.engineProcessLogDirectory`
23+
where places log files.
24+
25+
### Engine process
26+
Things are a bit more complicated here. There are cases - Engine process started from IDEA, and Engine process started separately.
27+
28+
#### Engine process started from IDEA
29+
30+
As plugin does not support multiple generation processes at a time - logs from any Engine process are written to the same file.
31+
32+
Default log file directory is `%user_temp%/UtBot/rdEngineProcessLogs`.
33+
34+
[`utbot-intellij/log4j2.xml`](../utbot-intellij/src/main/resources/log4j2.xml) is copied in
35+
UtBot temporary directory - `org.utbot.intellij.plugin.process.EngineProcessKt.engineProcessLogConfigurationsDirectory`,
36+
and then provided to Engine process via following CLI switch:
37+
```
38+
-Dlog4j2.configurationFile=%configuration_file%
39+
```
40+
41+
where `%configuration_file%` will be either:
42+
1. Modified copy of [`utbot-intellij/log4j2.xml`](../utbot-intellij/src/main/resources/log4j2.xml) at UtBot temp directory.
43+
44+
More precisely, there are 2 appenders in configuration file:
45+
```xml
46+
<Appenders>
47+
<Console name="IdeaAppender" .../>
48+
<RollingFile name="EngineProcessAppender" .../>
49+
</Appenders>
50+
```
51+
By default `IdeaAppender` is used everywhere in file, which is used in IDEA plugin.
52+
53+
When working as Engine process - temporary `log4j2.`xml would be created, in which
54+
substring `ref="IdeaAppender"` will be replaced with `ref="EngineProcessAppender"`,
55+
thus changing all appenders and log pattern, but preserving same categories and log levels for loggers.
56+
57+
After that, logs will be written by `RollingFileAppender` in `utbot-engine-current.log` file with rolling over
58+
after file reaches 20MB size. Previous log files are named `utbot-engine-%i.log`. Log file with
59+
maximal index is the last one rolled. For example, `utbot-engine-1.log` is created earlier than `utbot-engine-10.log`.
60+
61+
In IDEA log following lines are printed each time Engine process started:
62+
```
63+
| UtBot - EngineProcess | Engine process started with PID = 4172
64+
| UtBot - EngineProcess | Engine process log directory - C:\Users\user_name\AppData\Local\Temp\UTBot\rdEngineProcessLogs
65+
| UtBot - EngineProcess | Engine process log file - C:\Users\user_name\AppData\Local\Temp\UTBot\rdEngineProcessLogs\utbot-engine-current.log
66+
```
67+
68+
2. Path from `UtSettings.engineProcessLogConfigFile`.
69+
70+
This option allows to provide path to external Log4j2 configuration file instead of [`utbot-intellij/log4j2.xml`](../utbot-intellij/src/main/resources/log4j2.xml).
71+
At `~/.utbot/settings.properties` you can set path to custom configuration file,
72+
which would apply for engine process, for example:
73+
```
74+
engineProcessLogConfigFile=C:\wrk\UTBotJava\engineProcessLog4j2.xml
75+
```
76+
This allows you to configure logs for Engine process even for already built plugin,
77+
you need only to restart IDE.
78+
79+
#### Engine process started separately
80+
81+
This is the case for `ContestEstimator`, `Gradle/Maven` tasks, `CLI`, tests, etc.
82+
Configuration is taken from `log4j2.xml` in resources from the first `log4j2.xml` in resources in classpath.
83+
84+
### Instrumented process
85+
86+
Instrumented process sends its logs to the parent Engine process.
87+
Logs are sent via corresponding RD model: `org.utbot.rd.models.LoggerModel`.
88+
See `org.utbot.instrumentation.rd.InstrumentedProcess.Companion.invoke` and
89+
`org.utbot.instrumentation.process.InstrumentedProcessMainKt.main`.
90+
91+
## RD logs
92+
Rd has its own logging system, based on `com.jetbrains.rd.util.Logger` interface. It is convenient to use
93+
RD logging as default logging system in instrumented process because log4j2 classes in utbot would be confused
94+
at concrete execution with log4j2 classes in tested project - we will have duplicated versions of log4j2 libs,
95+
this would break instrumentation and coverage statistics.
96+
97+
You should always override default RD logging strategy as by default it writes to stdout/stderr - use `com.jetbrains.rd.util.Logger.Companion.set` method to provide custom
98+
`com.jetbrains.rd.util.ILoggerFactory`. Already created loggers will be automatically reinstantiated to obtain
99+
new logger from provided factory. You can obtain logger via `com.jetbrains.rd.util.getLogger` function.
100+
Check `EngineProcessMain` for RD logging example.
101+
102+
For available RD factories see `org.utbot.rd.loggers` package - it contains useful implemented factories,
103+
which log message in the same format as described in `utbot-intellij/src/main/resources/log4j2.xml`.
104+
105+
## Implementation details
106+
107+
### Additivity
108+
109+
Sometimes same log entry might be written to log multiple times. At log you will see something like:
110+
```
111+
13:55:41.204 | INFO | AnalyticsConfigureUtil | PathSelectorType: INHERITORS_SELECTOR
112+
13:55:41.204 | INFO | AnalyticsConfigureUtil | PathSelectorType: INHERITORS_SELECTOR
113+
```
114+
115+
This is because of loggers *additivity* - their full names defines tree structure, and events from children
116+
are visible for parents. For example, following `log4j2.xml` configuration in IDEA will produce such problem:
117+
```xml
118+
...
119+
<Loggers>
120+
<Logger name="org.utbot.intellij" level="info">
121+
<AppenderRef ref="IdeaAppender"/>
122+
</Logger>
123+
<Logger name="org.utbot" level="info">
124+
<AppenderRef ref="IdeaAppender"/>
125+
</Logger>
126+
</Loggers>
127+
...
128+
```
129+
130+
This happens because `org.utbot` logger is parent for `org.utbot.intellij`, and all events from
131+
`org.utbot.intellij` are also transferred to parent. This is called `additivity`.
132+
133+
The solution is to manually add ```additivity="false"``` tag to all loggers:
134+
```xml
135+
...
136+
<Loggers>
137+
<Logger name="org.utbot.intellij" level="info" additivity="false">
138+
<AppenderRef ref="IdeaAppender"/>
139+
</Logger>
140+
<Logger name="org.utbot" level="info" additivity="false">
141+
<AppenderRef ref="IdeaAppender"/>
142+
</Logger>
143+
</Loggers>
144+
...
145+
```
146+
147+
Consider this problem when you manually configure log level and appender for logger.
148+
149+
More information is available [here](https://logging.apache.org/log4j/2.x/manual/configuration.html#Additivity).
150+
151+
### Useful
152+
See auxiliary methods to work with logs at `UtRdLogUtil.kt` and `Logging.kt`.
153+
If you want to trace how long execution took - use `org.utbot.common.LoggingKt.logMeasure`
154+
method with corresponding log level scope.
155+
156+
In the Engine process log entries from Instrumented process are logged by `org.utbot.instrumentation.rd.InstrumentedProcessKt.rdLogger`.
157+
158+
## How to use log4j2 loggers
159+
160+
See related document - [How to use loggers](../HowToUseLoggers.md).
161+
162+
## Miscellaneous
163+
164+
### Performance considerations
165+
166+
`Debug` level is preferred in the most cases for developing. `Info` is sufficient for release.
167+
168+
`Trace` log level for RD loggers(for ex. if you specify `Trace` for all loggers, or as default level for root logger)
169+
will enable logging all technical send/receive event from protocol,
170+
causing ~50mb additional logs per generation and ***heavily*** polluting log. This might be useful
171+
when troubleshooting inter-process communication, but in all other cases prefer `Debug` level or
172+
specify `Trace` level per logger explicitly.
173+
174+
If your `Debug` level log message requires heavy string interpolation - wrap it in lambda, for example:
175+
```kotlin
176+
val someVeryBigDataStructure = VeryBigDataStructure()
177+
178+
logger.debug("data structure representation - $someVeryBigDataStructure") // <---- interpolation
179+
```
180+
In that code even though message uses `Debug` level, interpolation will always occur because
181+
message is passed as a parameter, which are evaluated at call site.
182+
In case logger is configured to `Info` level or higher - this means message will be built, but not logged,
183+
resulting in unnecessary work, possibly causing performance issue.
184+
Consider using lambdas:
185+
```kotlin
186+
// message will be created only if debug log level is available
187+
logger.debug { "data structure representation - $someVeryBigDataStructure"}
188+
```
189+
190+
Although now logs are sent from one process to another - performance penalties were not noticed.
191+
Additional performance can be achieved playing with `bufferedIO` and `immediateFlush` properties in `log4j2.xml`.
192+
For example, you can make following changes in `utbot-intellij`:
193+
```xml
194+
<RollingFile ... bufferedIO="true" immediateFlush="false" ... >
195+
```
196+
197+
This will reduce number of IO operations and use log4j2 buffer more efficiently. The cost it that
198+
when process terminates - log4j2 terminates logging service before buffer is flushed, and
199+
you will lose last portion of logs. This might be undesired behaviour in tests and debugging,
200+
but probably acceptable in release.
201+
202+
### Docker and Gradle
203+
204+
To see logs in Gradle from console, Docker and CI - add following `build.gradle.kts`:
205+
```kotlin
206+
allprojects {
207+
tasks {
208+
withType<Test> {
209+
testLogging.showStandardStreams = true
210+
testLogging.showStackTraces = true
211+
}
212+
}
213+
}
214+
```
215+
216+
## Links
217+
218+
Related topics:
219+
1. [Multiprocess architecture](RD%20for%20UnitTestBot.md)
220+
2. [Inter process debugging](./contributing/InterProcessDebugging.md)
221+
222+
Log4j2:
223+
2. [Architecture](https://logging.apache.org/log4j/2.x/manual/architecture.html) - overall log4j2 description.
224+
2. [Layouts](https://logging.apache.org/log4j/2.x/manual/layouts.html) - how to format log messages.
225+
UtBot uses `Pattern layout` everywhere.
226+
3. [Appenders](https://logging.apache.org/log4j/2.x/manual/appenders.html) - about different ways to store log entries,
227+
different storages for log entries and how to configure them. UtBot uses `Console`, `File` and `RollingFile` appenders.
228+
4. [Configuration](https://logging.apache.org/log4j/2.x/manual/configuration.html) - what you can write in configuration file,
229+
precise algorithm which file is used and many other useful info. It is **highly advised** to read `Additivity` part.

‎docs/RD for UnitTestBot.md

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -228,7 +228,7 @@ Sometimes the _Instrumented process_ may unexpectedly die due to concrete execut
228228
- **Important**: do not add [`Rdgen`](https://mvnrepository.com/artifact/com.jetbrains.rd/rd-gen) as
229229
an implementation dependency — it breaks some JAR files as it contains `kotlin-compiler-embeddable`.
230230
5. Logging & debugging:
231-
- [Interprocess logging](./contributing/InterProcessLogging.md)
231+
- [Interprocess logging](./InterProcessLogging.md)
232232
- [Interprocess debugging](./contributing/InterProcessDebugging.md)
233233
6. Custom protocol marshaling types: do not spend time on it until `UtModels` get simpler, e.g. compatible with
234234
`kotlinx.serialization`.

‎docs/contributing/InterProcessDebugging.md

Lines changed: 2 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -35,7 +35,7 @@ To debug the _Engine process_ and the _Instrumented process_, you need to enable
3535

3636
* **Discouraged**: you can change the options in the source file, but this will involve moderate project
3737
recompilation.
38-
4. You can set additional options for the Java Debug Wire Protocol (JDWP) agent if debugging is enabled:
38+
3. You can set additional options for the Java Debug Wire Protocol (JDWP) agent if debugging is enabled:
3939
* `engineProcessDebugPort` and `instrumentedProcessDebugPort` are the ports for debugging.
4040

4141
Default values:
@@ -62,7 +62,7 @@ To debug the _Engine process_ and the _Instrumented process_, you need to enable
6262
"-agentlib:jdwp=transport=dt_socket,server=n,suspend=n,quiet=y,address=12345"
6363
```
6464
See `org.utbot.intellij.plugin.process.EngineProcess.Companion.debugArgument` for switch implementation.
65-
5. For information about logs, refer to the [Interprocess logging](InterProcessLogging.md) guide.
65+
4. For information about logs, refer to the [Interprocess logging](../InterProcessLogging.md) guide.
6666

6767
### Run configurations for debugging the Engine process
6868

‎docs/contributing/InterProcessLogging.md

Lines changed: 0 additions & 129 deletions
This file was deleted.

0 commit comments

Comments
 (0)