Skip to content

Review InterProcessLogging.md for linguistic and formatting bugs #1786

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged
merged 3 commits into from
Feb 22, 2023
Merged

Review InterProcessLogging.md for linguistic and formatting bugs #1786

Changes from all commits
Commits
Show all changes
3 commits
Select commit Hold shift + click to select a range
d61c8fc
InterProcessLogging.md reviewed for linguistic and formatting bugs
olganaumenko Feb 13, 2023
6a4cb2b
Fixed info about directories and minor wordings
olganaumenko Feb 22, 2023
2c696da
Merge branch 'main' into olganaumenko/InterProcessLogging_doc_review
olganaumenko Feb 22, 2023
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
223 changes: 121 additions & 102 deletions docs/InterProcessLogging.md
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -1,119 +1,131 @@
# Interprocess logging

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

## Architecture

All logging relies on log4j2.
When UtBot is used as IDEA plugin - [`utbot-intellij/log4j2.xml`](../utbot-intellij/src/main/resources/log4j2.xml)
is used as configuration file.
In other cases(`ContestEstimator`, `Gradle/Maven` tasks, `CLI`, tests) it searches for the first `log4j2.xml` in resources in classpath.
The UnitTestBot Java logging system relies on `log4j2` library.

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

When used as Contest estimator or the Gradle/Maven plugins, via CLI or during the CI test runs,
UnitTestBot Java engine searches classpath for the first `log4j2.xml` in the `resources` directory.

### IDE process
IDEA part of UtBot write logs to `idea.log`.
Log configuration file is used as is, so if you want to configure logs in IDEA part - use it straight.
If you want to change log configuration in already built plugin -
use `Help > Diagnostic Tools > Debug Log Settings...` to change `log4j2.xml` configuration for plugin.

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

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

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

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

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

#### Engine process started from IDEA
The Engine process can be started either from IntelliJ IDEA or separately — as a standalone engine.

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

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

[`utbot-intellij/log4j2.xml`](../utbot-intellij/src/main/resources/log4j2.xml) is copied in
UtBot temporary directory - `org.utbot.intellij.plugin.process.EngineProcessKt.engineProcessLogConfigurationsDirectory`,
and then provided to Engine process via following CLI switch:
The default log file directory is `%user_temp%/UtBot/rdEngineProcessLogs`.

The [`utbot-intellij/log4j2.xml`](../utbot-intellij/src/main/resources/log4j2.xml) file is copied to the
UnitTestBot Java temporary directory:
`org.utbot.intellij.plugin.process.EngineProcessKt.engineProcessLogConfigurationsDirectory`.
Then this file is provided to the Engine process via the following CLI switch:
```
-Dlog4j2.configurationFile=%configuration_file%
```

where `%configuration_file%` will be either:
1. Modified copy of [`utbot-intellij/log4j2.xml`](../utbot-intellij/src/main/resources/log4j2.xml) at UtBot temp directory.
Here, `%configuration_file%` can take one of two values:
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.

More precisely, there are 2 appenders in configuration file:
More precisely, there are 2 appenders in the configuration file:
```xml
<Appenders>
<Console name="IdeaAppender" .../>
<RollingFile name="EngineProcessAppender" .../>
</Appenders>
```
By default `IdeaAppender` is used everywhere in file, which is used in IDEA plugin.
By default, `IdeaAppender` is used everywhere in a file for the IDE plugin.

When working as Engine process - temporary `log4j2.`xml would be created, in which
substring `ref="IdeaAppender"` will be replaced with `ref="EngineProcessAppender"`,
thus changing all appenders and log pattern, but preserving same categories and log levels for loggers.
For the Engine process, a temporary `log4j2.xml` is created,
where the `ref="IdeaAppender"` substring is replaced with `ref="EngineProcessAppender"`:
this replacement changes all the appenders and the log pattern
but keeps categories and log levels for the loggers the same.

After that, logs will be written by `RollingFileAppender` in `utbot-engine-current.log` file with rolling over
after file reaches 20MB size. Previous log files are named `utbot-engine-%i.log`. Log file with
maximal index is the last one rolled. For example, `utbot-engine-1.log` is created earlier than `utbot-engine-10.log`.
As soon as the file reaches 20 MB size, `RollingFileAppender` writes the logs to the `utbot-engine-current.log` file.
The created log files are named `utbot-engine-%i.log`.
A log file with the largest index is the latest one: `utbot-engine-1.log` has been created earlier than `utbot-engine-10.log`.

In IDEA log following lines are printed each time Engine process started:
Each time the Engine process starts, the following lines are printed into the IntelliJ IDEA log:
```
| UtBot - EngineProcess | Engine process started with PID = 4172
| UtBot - EngineProcess | Engine process log directory - C:\Users\user_name\AppData\Local\Temp\UTBot\rdEngineProcessLogs
| UtBot - EngineProcess | Engine process log file - C:\Users\user_name\AppData\Local\Temp\UTBot\rdEngineProcessLogs\utbot-engine-current.log
```

2. Path from `UtSettings.engineProcessLogConfigFile`.
2. A path from `UtSettings.engineProcessLogConfigFile`.

This option allows to provide path to external Log4j2 configuration file instead of [`utbot-intellij/log4j2.xml`](../utbot-intellij/src/main/resources/log4j2.xml).
At `~/.utbot/settings.properties` you can set path to custom configuration file,
which would apply for engine process, for example:
The option provides the external `log4j2` configuration file with the path instead of [`utbot-intellij/log4j2.xml`](../utbot-intellij/src/main/resources/log4j2.xml).
In the `~/.utbot/settings.properties` file, one can set this path to a custom configuration file applicable to the Engine process, for example:
```
engineProcessLogConfigFile=C:\wrk\UTBotJava\engineProcessLog4j2.xml
```
This allows you to configure logs for Engine process even for already built plugin,
you need only to restart IDE.
This allows you to configure logs for the Engine process even for the prebuilt plugin (you need to restart an IDE).

#### Engine process started separately

This is the case for `ContestEstimator`, `Gradle/Maven` tasks, `CLI`, tests, etc.
Configuration is taken from `log4j2.xml` in resources from the first `log4j2.xml` in resources in classpath.
When used as Contest estimator or the Gradle/Maven plugins, via CLI or during the CI test runs,
UnitTestBot Java engine searches classpath for the first `log4j2.xml` in the `resources` directory
to get configuration information.

### Instrumented process

Instrumented process sends its logs to the parent Engine process.
Logs are sent via corresponding RD model: `org.utbot.rd.models.LoggerModel`.
See `org.utbot.instrumentation.rd.InstrumentedProcess.Companion.invoke` and
The Instrumented process sends the logs to its parent — to the Engine process.
Logs are sent via the corresponding Rd model: `org.utbot.rd.models.LoggerModel`.

See also `org.utbot.instrumentation.rd.InstrumentedProcess.Companion.invoke` and
`org.utbot.instrumentation.process.InstrumentedProcessMainKt.main`.

## RD logs
Rd has its own logging system, based on `com.jetbrains.rd.util.Logger` interface. It is convenient to use
RD logging as default logging system in instrumented process because log4j2 classes in utbot would be confused
at concrete execution with log4j2 classes in tested project - we will have duplicated versions of log4j2 libs,
this would break instrumentation and coverage statistics.
## Rd logging system

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
`com.jetbrains.rd.util.ILoggerFactory`. Already created loggers will be automatically reinstantiated to obtain
new logger from provided factory. You can obtain logger via `com.jetbrains.rd.util.getLogger` function.
Check `EngineProcessMain` for RD logging example.
Rd has the custom logging system based on `com.jetbrains.rd.util.Logger` interface.
It is convenient to set the Rd logging system as default for the Instrumented process:
during concrete execution,
the `log4j2` classes in UnitTestBot Java could be confused with the `log4j2` classes from the project under test.
Duplicated `log4j2` libraries can break instrumentation and coverage statistics.

For available RD factories see `org.utbot.rd.loggers` package - it contains useful implemented factories,
which log message in the same format as described in `utbot-intellij/src/main/resources/log4j2.xml`.
You should always override the default Rd logging strategy, which writes log data to `stdout/stderr`.
Use `com.jetbrains.rd.util.Logger.Companion.set` method to provide custom
`com.jetbrains.rd.util.ILoggerFactory`.
The created loggers will be automatically re-instantiated to obtain a new logger from the provided factory.
You can obtain a logger via the `com.jetbrains.rd.util.getLogger` function.
Check `EngineProcessMain` for Rd logging example.

For available Rd factories, see the `org.utbot.rd.loggers` package: it contains the implemented factories.
The format of the log messages is the same as described in `utbot-intellij/src/main/resources/log4j2.xml`.

## Implementation details

### Additivity

Sometimes same log entry might be written to log multiple times. At log you will see something like:
An entry may appear in a log many times due to _additivity_. The resulting log may look like this:
```
13:55:41.204 | INFO | AnalyticsConfigureUtil | PathSelectorType: INHERITORS_SELECTOR
13:55:41.204 | INFO | AnalyticsConfigureUtil | PathSelectorType: INHERITORS_SELECTOR
```

This is because of loggers *additivity* - their full names defines tree structure, and events from children
are visible for parents. For example, following `log4j2.xml` configuration in IDEA will produce such problem:
The logger's full name constitutes a tree structure so that the logged events from a child are visible to a parent.

For example, the following `log4j2.xml` configuration in IntelliJ IDEA will produce such a problem:
```xml
...
<Loggers>
Expand All @@ -127,10 +139,10 @@ are visible for parents. For example, following `log4j2.xml` configuration in ID
...
```

This happens because `org.utbot` logger is parent for `org.utbot.intellij`, and all events from
`org.utbot.intellij` are also transferred to parent. This is called `additivity`.
This happens because the `org.utbot` logger is a parent to `org.utbot.intellij`, and all the events from
`org.utbot.intellij` are also transferred to `org.utbot`.

The solution is to manually add ```additivity="false"``` tag to all loggers:
To modify this behavior, add the `additivity="false"` tag to all loggers manually:
```xml
...
<Loggers>
Expand All @@ -144,64 +156,68 @@ The solution is to manually add ```additivity="false"``` tag to all loggers:
...
```

Consider this problem when you manually configure log level and appender for logger.
Consider this problem when you manually configure log level and appender for a logger.

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

### Useful
See auxiliary methods to work with logs at `UtRdLogUtil.kt` and `Logging.kt`.
If you want to trace how long execution took - use `org.utbot.common.LoggingKt.logMeasure`
method with corresponding log level scope.
### Logging: auxiliary methods

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

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

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

## Miscellaneous
## Log levels and performance

### Performance considerations
For development, the `Debug` level is preferred in most cases.

`Debug` level is preferred in the most cases for developing. `Info` is sufficient for release.
The `Info` log level is sufficient for release.

`Trace` log level for RD loggers(for ex. if you specify `Trace` for all loggers, or as default level for root logger)
will enable logging all technical send/receive event from protocol,
causing ~50mb additional logs per generation and ***heavily*** polluting log. This might be useful
when troubleshooting inter-process communication, but in all other cases prefer `Debug` level or
specify `Trace` level per logger explicitly.
In Rd, if you choose the `Trace` level for all loggers or set it as default for the root logger,
this enables logging for all technical _send/receive_ events from protocol.
It may cause ~50 MB of additional entries per generation to appear and _heavily_ pollutes the log. This might be useful
for troubleshooting interprocess communication but in all other cases prefer the `Debug` level or
specify the `Trace` level per logger explicitly.

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

logger.debug("data structure representation - $someVeryBigDataStructure") // <---- interpolation
```
In that code even though message uses `Debug` level, interpolation will always occur because
message is passed as a parameter, which are evaluated at call site.
In case logger is configured to `Info` level or higher - this means message will be built, but not logged,
resulting in unnecessary work, possibly causing performance issue.
Here, even for a message with the `Debug` level, interpolation will always occur because
the message is passed as a parameter, which is evaluated at call site.
If the `Info` level (or higher) is set for a logger,
the message is built, but not logged,
resulting in unnecessary work, possibly causing performance issues.

Consider using lambdas:
```kotlin
// message will be created only if debug log level is available
logger.debug { "data structure representation - $someVeryBigDataStructure"}
```

Although now logs are sent from one process to another - performance penalties were not noticed.
Additional performance can be achieved playing with `bufferedIO` and `immediateFlush` properties in `log4j2.xml`.
For example, you can make following changes in `utbot-intellij`:
Here, although the logs are sent from one process to another, no performance penalties have been noticed.

To reach higher performance, try to use `bufferedIO` and `immediateFlush` properties in `log4j2.xml`.
For example, you can make the following changes to the `log4j2.xml` file in `utbot-intellij`:
```xml
<RollingFile ... bufferedIO="true" immediateFlush="false" ... >
```

This will reduce number of IO operations and use log4j2 buffer more efficiently. The cost it that
when process terminates - log4j2 terminates logging service before buffer is flushed, and
you will lose last portion of logs. This might be undesired behaviour in tests and debugging,
but probably acceptable in release.
This will reduce a number of I/O operations and help to use `log4j2` buffer more efficiently.
This may also have a flip side:
when the process terminates, `log4j2` terminates the logging service before the buffer is flushed, and
you will lose the last portion of logs.
This behavior is undesirable for testing and debugging,
but probably acceptable for release.

### Docker and Gradle
## Docker and Gradle

To see logs in Gradle from console, Docker and CI - add following `build.gradle.kts`:
To see the logs in Gradle from console, Docker and CI, add the following `build.gradle.kts` file:
```kotlin
allprojects {
tasks {
Expand All @@ -213,17 +229,20 @@ allprojects {
}
```

## Links
## Useful links

Related topics:
UnitTestBot Java documentation:
1. [Multiprocess architecture](RD%20for%20UnitTestBot.md)
2. [Inter process debugging](./contributing/InterProcessDebugging.md)

Log4j2:
2. [Architecture](https://logging.apache.org/log4j/2.x/manual/architecture.html) - overall log4j2 description.
2. [Layouts](https://logging.apache.org/log4j/2.x/manual/layouts.html) - how to format log messages.
UtBot uses `Pattern layout` everywhere.
3. [Appenders](https://logging.apache.org/log4j/2.x/manual/appenders.html) - about different ways to store log entries,
different storages for log entries and how to configure them. UtBot uses `Console`, `File` and `RollingFile` appenders.
4. [Configuration](https://logging.apache.org/log4j/2.x/manual/configuration.html) - what you can write in configuration file,
precise algorithm which file is used and many other useful info. It is **highly advised** to read `Additivity` part.
2. [Interprocess debugging](./contributing/InterProcessDebugging.md)
3. [How to use loggers](../HowToUseLoggers.md)

`log4j2` documentation:
1. [Architecture](https://logging.apache.org/log4j/2.x/manual/architecture.html) — an overall `log4j2` description.
2. [Layouts](https://logging.apache.org/log4j/2.x/manual/layouts.html) — how to format log messages.
(UnitTestBot Java uses `Pattern layout` everywhere.)
3. [Appenders](https://logging.apache.org/log4j/2.x/manual/appenders.html) —
a description of various ways to store log entries (and how to configure the storages).
UnitTestBot Java uses the `Console`, `File` and `RollingFile` appenders.
4. [Configuration](https://logging.apache.org/log4j/2.x/manual/configuration.html) —
how to use a configuration file, how to check the file, and other useful information.
It is **highly advised** to read the `Additivity` part.