Skip to content

Commit b74e10c

Browse files
olganaumenkosofurihafe
authored andcommitted
Review InterProcessLogging.md for linguistic and formatting bugs (#1786)
* InterProcessLogging.md reviewed for linguistic and formatting bugs * Fixed info about directories and minor wordings
1 parent 8daad71 commit b74e10c

File tree

1 file changed

+121
-102
lines changed

1 file changed

+121
-102
lines changed

docs/InterProcessLogging.md

Lines changed: 121 additions & 102 deletions
Original file line numberDiff line numberDiff line change
@@ -1,119 +1,131 @@
11
# Interprocess logging
22

3-
This document described how logging is performed across all 3 different processes: IDEA, Engine and Instrumented.
3+
This document describes
4+
how logging is implemented across the UnitTestBot Java [processes](https://github.com/UnitTestBot/UTBotJava/blob/main/docs/RD%20for%20UnitTestBot.md):
5+
the IDE process, the Engine process, and the Instrumented process.
46

57
## Architecture
68

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.
9+
The UnitTestBot Java logging system relies on `log4j2` library.
10+
11+
For UnitTestBot Java used as an IntelliJ IDEA plugin, the configuration file for logging is [`utbot-intellij/log4j2.xml`](../utbot-intellij/src/main/resources/log4j2.xml).
12+
13+
When used as Contest estimator or the Gradle/Maven plugins, via CLI or during the CI test runs,
14+
UnitTestBot Java engine searches classpath for the first `log4j2.xml` in the `resources` directory.
1115

1216
### 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.
1717

18+
The IDE process writes logging information to standard `idea.log` files and puts them into the default log directory.
1819

19-
### UtBot plugin
20+
To configure logs for the IDE process, use the log configuration file in a straightforward way.
2021

22+
To change the log configuration for the prebuilt plugin,
23+
go to **Help** > **Diagnostic Tools** > **Debug Log Settings...** and configure `log4j2.xml`.
2124

22-
UtBot plugin creates log directory `org.utbot.intellij.plugin.process.EngineProcessKt.engineProcessLogDirectory`
23-
where places log files.
25+
To store log data for the Engine process started from the IDE process, the UnitTestBot Java plugin creates a directory:
26+
`org.utbot.intellij.plugin.process.EngineProcessKt.engineProcessLogDirectory`.
2427

25-
### Engine process
26-
Things are a bit more complicated here. There are cases - Engine process started from IDEA, and Engine process started separately.
28+
### Engine process
2729

28-
#### Engine process started from IDEA
30+
The Engine process can be started either from IntelliJ IDEA or separately — as a standalone engine.
2931

30-
As plugin does not support multiple generation processes at a time - logs from any Engine process are written to the same file.
32+
#### Engine process started from IntelliJ IDEA
3133

32-
Default log file directory is `%user_temp%/UtBot/rdEngineProcessLogs`.
34+
As the plugin does not support multiple generation processes,
35+
the logs from the Engine process are written to the same file.
3336

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+
The default log file directory is `%user_temp%/UtBot/rdEngineProcessLogs`.
38+
39+
The [`utbot-intellij/log4j2.xml`](../utbot-intellij/src/main/resources/log4j2.xml) file is copied to the
40+
UnitTestBot Java temporary directory:
41+
`org.utbot.intellij.plugin.process.EngineProcessKt.engineProcessLogConfigurationsDirectory`.
42+
Then this file is provided to the Engine process via the following CLI switch:
3743
```
3844
-Dlog4j2.configurationFile=%configuration_file%
3945
```
4046

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.
47+
Here, `%configuration_file%` can take one of two values:
48+
1. A modified copy of [`utbot-intellij/log4j2.xml`](../utbot-intellij/src/main/resources/log4j2.xml) file, which is stored in UnitTestBot Java temporary directory.
4349

44-
More precisely, there are 2 appenders in configuration file:
50+
More precisely, there are 2 appenders in the configuration file:
4551
```xml
4652
<Appenders>
4753
<Console name="IdeaAppender" .../>
4854
<RollingFile name="EngineProcessAppender" .../>
4955
</Appenders>
5056
```
51-
By default `IdeaAppender` is used everywhere in file, which is used in IDEA plugin.
57+
By default, `IdeaAppender` is used everywhere in a file for the IDE plugin.
5258

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.
59+
For the Engine process, a temporary `log4j2.xml` is created,
60+
where the `ref="IdeaAppender"` substring is replaced with `ref="EngineProcessAppender"`:
61+
this replacement changes all the appenders and the log pattern
62+
but keeps categories and log levels for the loggers the same.
5663

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`.
64+
As soon as the file reaches 20 MB size, `RollingFileAppender` writes the logs to the `utbot-engine-current.log` file.
65+
The created log files are named `utbot-engine-%i.log`.
66+
A log file with the largest index is the latest one: `utbot-engine-1.log` has been created earlier than `utbot-engine-10.log`.
6067

61-
In IDEA log following lines are printed each time Engine process started:
68+
Each time the Engine process starts, the following lines are printed into the IntelliJ IDEA log:
6269
```
6370
| UtBot - EngineProcess | Engine process started with PID = 4172
6471
| UtBot - EngineProcess | Engine process log directory - C:\Users\user_name\AppData\Local\Temp\UTBot\rdEngineProcessLogs
6572
| UtBot - EngineProcess | Engine process log file - C:\Users\user_name\AppData\Local\Temp\UTBot\rdEngineProcessLogs\utbot-engine-current.log
6673
```
6774
68-
2. Path from `UtSettings.engineProcessLogConfigFile`.
75+
2. A path from `UtSettings.engineProcessLogConfigFile`.
6976
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:
77+
The option provides the external `log4j2` configuration file with the path instead of [`utbot-intellij/log4j2.xml`](../utbot-intellij/src/main/resources/log4j2.xml).
78+
In the `~/.utbot/settings.properties` file, one can set this path to a custom configuration file applicable to the Engine process, for example:
7379
```
7480
engineProcessLogConfigFile=C:\wrk\UTBotJava\engineProcessLog4j2.xml
7581
```
76-
This allows you to configure logs for Engine process even for already built plugin,
77-
you need only to restart IDE.
82+
This allows you to configure logs for the Engine process even for the prebuilt plugin (you need to restart an IDE).
7883
7984
#### Engine process started separately
8085
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.
86+
When used as Contest estimator or the Gradle/Maven plugins, via CLI or during the CI test runs,
87+
UnitTestBot Java engine searches classpath for the first `log4j2.xml` in the `resources` directory
88+
to get configuration information.
8389
8490
### Instrumented process
8591
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
92+
The Instrumented process sends the logs to its parent — to the Engine process.
93+
Logs are sent via the corresponding Rd model: `org.utbot.rd.models.LoggerModel`.
94+
95+
See also `org.utbot.instrumentation.rd.InstrumentedProcess.Companion.invoke` and
8996
`org.utbot.instrumentation.process.InstrumentedProcessMainKt.main`.
9097
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.
98+
## Rd logging system
9699
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.
100+
Rd has the custom logging system based on `com.jetbrains.rd.util.Logger` interface.
101+
It is convenient to set the Rd logging system as default for the Instrumented process:
102+
during concrete execution,
103+
the `log4j2` classes in UnitTestBot Java could be confused with the `log4j2` classes from the project under test.
104+
Duplicated `log4j2` libraries can break instrumentation and coverage statistics.
101105
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`.
106+
You should always override the default Rd logging strategy, which writes log data to `stdout/stderr`.
107+
Use `com.jetbrains.rd.util.Logger.Companion.set` method to provide custom
108+
`com.jetbrains.rd.util.ILoggerFactory`.
109+
The created loggers will be automatically re-instantiated to obtain a new logger from the provided factory.
110+
You can obtain a logger via the `com.jetbrains.rd.util.getLogger` function.
111+
Check `EngineProcessMain` for Rd logging example.
112+
113+
For available Rd factories, see the `org.utbot.rd.loggers` package: it contains the implemented factories.
114+
The format of the log messages is the same as described in `utbot-intellij/src/main/resources/log4j2.xml`.
104115
105116
## Implementation details
106117
107118
### Additivity
108119
109-
Sometimes same log entry might be written to log multiple times. At log you will see something like:
120+
An entry may appear in a log many times due to _additivity_. The resulting log may look like this:
110121
```
111122
13:55:41.204 | INFO | AnalyticsConfigureUtil | PathSelectorType: INHERITORS_SELECTOR
112123
13:55:41.204 | INFO | AnalyticsConfigureUtil | PathSelectorType: INHERITORS_SELECTOR
113124
```
114125
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:
126+
The logger's full name constitutes a tree structure so that the logged events from a child are visible to a parent.
127+
128+
For example, the following `log4j2.xml` configuration in IntelliJ IDEA will produce such a problem:
117129
```xml
118130
...
119131
<Loggers>
@@ -127,10 +139,10 @@ are visible for parents. For example, following `log4j2.xml` configuration in ID
127139
...
128140
```
129141

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`.
142+
This happens because the `org.utbot` logger is a parent to `org.utbot.intellij`, and all the events from
143+
`org.utbot.intellij` are also transferred to `org.utbot`.
132144

133-
The solution is to manually add ```additivity="false"``` tag to all loggers:
145+
To modify this behavior, add the `additivity="false"` tag to all loggers manually:
134146
```xml
135147
...
136148
<Loggers>
@@ -144,64 +156,68 @@ The solution is to manually add ```additivity="false"``` tag to all loggers:
144156
...
145157
```
146158

147-
Consider this problem when you manually configure log level and appender for logger.
159+
Consider this problem when you manually configure log level and appender for a logger.
148160

149-
More information is available [here](https://logging.apache.org/log4j/2.x/manual/configuration.html#Additivity).
161+
For more information,
162+
refer to the [`log4j2` additivity](https://logging.apache.org/log4j/2.x/manual/configuration.html#Additivity) document.
150163

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.
164+
### Logging: auxiliary methods
155165

156-
In the Engine process log entries from Instrumented process are logged by `org.utbot.instrumentation.rd.InstrumentedProcessKt.rdLogger`.
166+
Find more logging-related methods at `UtRdLogUtil.kt` and `Logging.kt`.
157167

158-
## How to use log4j2 loggers
168+
To trace the execution duration,
169+
use the `measureTime` method (see `Logging.kt`) with the corresponding log level scope.
159170

160-
See related document - [How to use loggers](../HowToUseLoggers.md).
171+
In the Engine process, the entries from the Instrumented process are logged by `org.utbot.instrumentation.rd.InstrumentedProcessKt.rdLogger`.
161172

162-
## Miscellaneous
173+
## Log levels and performance
163174

164-
### Performance considerations
175+
For development, the `Debug` level is preferred in most cases.
165176

166-
`Debug` level is preferred in the most cases for developing. `Info` is sufficient for release.
177+
The `Info` log level is sufficient for release.
167178

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.
179+
In Rd, if you choose the `Trace` level for all loggers or set it as default for the root logger,
180+
this enables logging for all technical _send/receive_ events from protocol.
181+
It may cause ~50 MB of additional entries per generation to appear and _heavily_ pollutes the log. This might be useful
182+
for troubleshooting interprocess communication but in all other cases prefer the `Debug` level or
183+
specify the `Trace` level per logger explicitly.
173184

174-
If your `Debug` level log message requires heavy string interpolation - wrap it in lambda, for example:
185+
For the `Debug` level, if a log message requires heavy string interpolation, wrap it in lambda, for example:
175186
```kotlin
176187
val someVeryBigDataStructure = VeryBigDataStructure()
177188

178189
logger.debug("data structure representation - $someVeryBigDataStructure") // <---- interpolation
179190
```
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.
191+
Here, even for a message with the `Debug` level, interpolation will always occur because
192+
the message is passed as a parameter, which is evaluated at call site.
193+
If the `Info` level (or higher) is set for a logger,
194+
the message is built, but not logged,
195+
resulting in unnecessary work, possibly causing performance issues.
196+
184197
Consider using lambdas:
185198
```kotlin
186199
// message will be created only if debug log level is available
187200
logger.debug { "data structure representation - $someVeryBigDataStructure"}
188201
```
189202

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`:
203+
Here, although the logs are sent from one process to another, no performance penalties have been noticed.
204+
205+
To reach higher performance, try to use `bufferedIO` and `immediateFlush` properties in `log4j2.xml`.
206+
For example, you can make the following changes to the `log4j2.xml` file in `utbot-intellij`:
193207
```xml
194208
<RollingFile ... bufferedIO="true" immediateFlush="false" ... >
195209
```
196210

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.
211+
This will reduce a number of I/O operations and help to use `log4j2` buffer more efficiently.
212+
This may also have a flip side:
213+
when the process terminates, `log4j2` terminates the logging service before the buffer is flushed, and
214+
you will lose the last portion of logs.
215+
This behavior is undesirable for testing and debugging,
216+
but probably acceptable for release.
201217

202-
### Docker and Gradle
218+
## Docker and Gradle
203219

204-
To see logs in Gradle from console, Docker and CI - add following `build.gradle.kts`:
220+
To see the logs in Gradle from console, Docker and CI, add the following `build.gradle.kts` file:
205221
```kotlin
206222
allprojects {
207223
tasks {
@@ -213,17 +229,20 @@ allprojects {
213229
}
214230
```
215231

216-
## Links
232+
## Useful links
217233

218-
Related topics:
234+
UnitTestBot Java documentation:
219235
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.
236+
2. [Interprocess debugging](./contributing/InterProcessDebugging.md)
237+
3. [How to use loggers](../HowToUseLoggers.md)
238+
239+
`log4j2` documentation:
240+
1. [Architecture](https://logging.apache.org/log4j/2.x/manual/architecture.html) — an overall `log4j2` description.
241+
2. [Layouts](https://logging.apache.org/log4j/2.x/manual/layouts.html) — how to format log messages.
242+
(UnitTestBot Java uses `Pattern layout` everywhere.)
243+
3. [Appenders](https://logging.apache.org/log4j/2.x/manual/appenders.html)
244+
a description of various ways to store log entries (and how to configure the storages).
245+
UnitTestBot Java uses the `Console`, `File` and `RollingFile` appenders.
246+
4. [Configuration](https://logging.apache.org/log4j/2.x/manual/configuration.html)
247+
how to use a configuration file, how to check the file, and other useful information.
248+
It is **highly advised** to read the `Additivity` part.

0 commit comments

Comments
 (0)