diff --git a/docs/InterProcessLogging.md b/docs/InterProcessLogging.md index dd5207fa1d..e54c27c864 100644 --- a/docs/InterProcessLogging.md +++ b/docs/InterProcessLogging.md @@ -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 ``` - 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 ... @@ -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 ... @@ -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 ``` -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 { @@ -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. \ No newline at end of file +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. \ No newline at end of file