build scripts: Jps file logger moved and renamed according to its purpose

GitOrigin-RevId: d434dce677c88dfda922702eb69a2faa362dd163

platform/build-scripts/src/org/jetbrains/intellij/build/impl/JpsCompilationRunner.kt

@@ -1,48 +1,34 @@
 // Copyright 2000-2023 JetBrains s.r.o. and contributors. Use of this source code is governed by the Apache 2.0 license.
-@file:Suppress("ReplacePutWithAssignment", "ReplaceGetOrSet", "HardCodedStringLiteral")
-
 package org.jetbrains.intellij.build.impl
 
 import com.intellij.devkit.runtimeModuleRepository.jps.build.RuntimeModuleRepositoryBuildConstants
-import com.intellij.openapi.diagnostic.DefaultLogger
-import com.intellij.openapi.diagnostic.Logger
 import com.intellij.platform.diagnostic.telemetry.helpers.use
 import com.intellij.platform.diagnostic.telemetry.helpers.useWithScope
-import com.intellij.util.containers.MultiMap
-import com.jetbrains.plugin.structure.base.utils.createParentDirs
 import io.opentelemetry.api.common.AttributeKey
 import io.opentelemetry.api.common.Attributes
 import io.opentelemetry.api.trace.Span
-import org.jetbrains.annotations.Nls
 import org.jetbrains.groovy.compiler.rt.GroovyRtConstants
 import org.jetbrains.intellij.build.CompilationContext
 import org.jetbrains.intellij.build.TraceManager.spanBuilder
+import org.jetbrains.intellij.build.impl.logging.jps.withJpsLogging
 import org.jetbrains.jps.api.CmdlineRemoteProto.Message.ControllerMessage.ParametersMessage.TargetTypeBuildScope
 import org.jetbrains.jps.api.GlobalOptions
 import org.jetbrains.jps.backwardRefs.JavaBackwardReferenceIndexWriter
 import org.jetbrains.jps.build.Standalone
-import org.jetbrains.jps.builders.BuildTarget
 import org.jetbrains.jps.builders.java.JavaModuleBuildTargetType
-import org.jetbrains.jps.gant.Log4jFileLoggerFactory
-import org.jetbrains.jps.incremental.MessageHandler
 import org.jetbrains.jps.incremental.artifacts.ArtifactBuildTargetType
 import org.jetbrains.jps.incremental.artifacts.impl.ArtifactSorter
 import org.jetbrains.jps.incremental.artifacts.impl.JpsArtifactUtil
 import org.jetbrains.jps.incremental.dependencies.DependencyResolvingBuilder
 import org.jetbrains.jps.incremental.groovy.JpsGroovycRunner
-import org.jetbrains.jps.incremental.messages.*
 import org.jetbrains.jps.model.artifact.JpsArtifact
 import org.jetbrains.jps.model.artifact.JpsArtifactService
 import org.jetbrains.jps.model.artifact.elements.JpsModuleOutputPackagingElement
 import org.jetbrains.jps.model.java.JpsJavaExtensionService
 import org.jetbrains.jps.model.module.JpsModule
-import java.beans.Introspector
 import java.nio.file.Files
 import java.nio.file.Path
-import java.util.*
-import java.util.concurrent.ConcurrentHashMap
 import java.util.concurrent.TimeUnit
-import java.util.function.BiConsumer
 import kotlin.io.path.exists
 import kotlin.io.path.isDirectory
 import kotlin.io.path.listDirectoryEntries
@@ -263,21 +249,6 @@ internal class JpsCompilationRunner(private val context: CompilationContext) {
     return ArtifactSorter.addIncludedArtifacts(artifacts)
   }
 
-  private fun setupAdditionalBuildLogging(compilationData: JpsCompilationData) {
-    val categoriesWithDebugLevel = compilationData.categoriesWithDebugLevel
-    val buildLogFile = compilationData.buildLogFile
-    try {
-      val factory = Log4jFileLoggerFactory(buildLogFile.toFile(), categoriesWithDebugLevel)
-      JpsLoggerFactory.fileLoggerFactory = factory
-      context.messages.info(
-        "Build log (${if (categoriesWithDebugLevel.isEmpty()) "info" else "debug level for $categoriesWithDebugLevel"}) " +
-        "will be written to $buildLogFile")
-    }
-    catch (t: Throwable) {
-      context.messages.warning("Cannot setup additional logging to $buildLogFile: ${t.message}")
-    }
-  }
-
   private fun runBuild(moduleSet: Collection<String>,
                        allModules: Boolean,
                        artifactNames: Collection<String>,
@@ -285,14 +256,7 @@ internal class JpsCompilationRunner(private val context: CompilationContext) {
                        resolveProjectDependencies: Boolean,
                        generateRuntimeModuleRepository: Boolean = false) {
     synchronized(context.paths.projectHome.toString().intern()) {
-      messageHandler = JpsMessageHandler(context)
-      if (context.options.compilationLogEnabled) {
-        setupAdditionalBuildLogging(compilationData)
-      }
-
-      val oldLoggerFactory = Logger.getFactory()
-      Logger.setFactory(JpsLoggerFactory::class.java)
-      try {
+      withJpsLogging(context) { messageHandler ->
         val forceBuild = !context.options.incrementalCompilation ||
                          !context.compilationData.dataStorageRoot.exists() ||
                          !context.compilationData.dataStorageRoot.isDirectory() ||
@@ -376,167 +340,10 @@ internal class JpsCompilationRunner(private val context: CompilationContext) {
           compilationData.runtimeModuleRepositoryGenerated = true
         }
       }
-      finally {
-        Logger.setFactory(oldLoggerFactory)
-      }
     }
   }
 }
 
-private class JpsLoggerFactory : Logger.Factory {
-  companion object {
-    var fileLoggerFactory: Logger.Factory? = null
-  }
-
-  override fun getLoggerInstance(category: String): Logger = BackedLogger(category, fileLoggerFactory?.getLoggerInstance(category))
-}
-
-private class JpsMessageHandler(private val context: CompilationContext) : MessageHandler {
-  val errorMessagesByCompiler = MultiMap.createConcurrent<String, String>()
-  val compilationStartTimeForTarget = ConcurrentHashMap<String, Long>()
-  val compilationFinishTimeForTarget = ConcurrentHashMap<String, Long>()
-  var progress = (-1.0).toFloat()
-  override fun processMessage(message: BuildMessage) {
-    val text = message.messageText
-    when (message.kind) {
-      BuildMessage.Kind.ERROR, BuildMessage.Kind.INTERNAL_BUILDER_ERROR -> {
-        val compilerName: String
-        val messageText: String
-        if (message is CompilerMessage) {
-          compilerName = message.compilerName
-          val sourcePath = message.sourcePath
-          messageText = if (sourcePath != null) {
-            """
- $sourcePath${if (message.line != -1L) ":" + message.line else ""}:
- $text
- """.trimIndent()
-          }
-          else {
-            text
-          }
-        }
-        else {
-          compilerName = ""
-          messageText = text
-        }
-        errorMessagesByCompiler.putValue(compilerName, messageText)
-      }
-      BuildMessage.Kind.WARNING -> context.messages.warning(text)
-      BuildMessage.Kind.INFO, BuildMessage.Kind.JPS_INFO -> if (message is BuilderStatisticsMessage) {
-        val buildKind = if (context.options.incrementalCompilation) " (incremental)" else ""
-        context.messages.reportStatisticValue("Compilation time '${message.builderName}'$buildKind, ms", message.elapsedTimeMs.toString())
-        val sources = message.numberOfProcessedSources
-        context.messages.reportStatisticValue("Processed files by '${message.builderName}'$buildKind", sources.toString())
-        if (!context.options.incrementalCompilation && sources > 0) {
-          context.messages.reportStatisticValue("Compilation time per file for '${message.builderName}', ms",
-                                                String.format(Locale.US, "%.2f", message.elapsedTimeMs.toDouble() / sources))
-        }
-      }
-      else if (!text.isEmpty()) {
-        context.messages.info(text)
-      }
-      BuildMessage.Kind.PROGRESS -> if (message is ProgressMessage) {
-        progress = message.done
-        message.currentTargets?.let {
-          reportProgress(it.targets, message.messageText)
-        }
-      }
-      else if (message is BuildingTargetProgressMessage) {
-        val targets = message.targets
-        val target = targets.first()
-        val targetId = "${target.id}${if (targets.size > 1) " and ${targets.size} more" else ""} (${target.targetType.typeId})"
-        if (message.eventType == BuildingTargetProgressMessage.Event.STARTED) {
-          reportProgress(targets, "")
-          compilationStartTimeForTarget.put(targetId, System.nanoTime())
-        }
-        else {
-          compilationFinishTimeForTarget.put(targetId, System.nanoTime())
-        }
-      }
-      BuildMessage.Kind.OTHER, null -> context.messages.warning(text)
-    }
-  }
-
-  fun printPerModuleCompilationStatistics(compilationStart: Long) {
-    if (compilationStartTimeForTarget.isEmpty()) {
-      return
-    }
-
-    val csvPath = context.paths.logDir.resolve("compilation-time.csv").also { it.createParentDirs() }
-    Files.newBufferedWriter(csvPath).use { out ->
-      compilationFinishTimeForTarget.forEach(BiConsumer { k, v ->
-        val startTime = compilationStartTimeForTarget.getValue(k) - compilationStart
-        val finishTime = v - compilationStart
-        out.write("$k,$startTime,$finishTime\n")
-      })
-    }
-    val buildMessages = context.messages
-    buildMessages.info("Compilation time per target:")
-    val compilationTimeForTarget = compilationFinishTimeForTarget.entries.map {
-      it.key to (it.value - compilationStartTimeForTarget.getValue(it.key))
-    }
-
-    buildMessages.info(" average: ${
-      String.format("%.2f", ((compilationTimeForTarget.sumOf { it.second }.toDouble()) / compilationTimeForTarget.size) / 1000000)
-    }ms")
-    val topTargets = compilationTimeForTarget.sortedBy { it.second }.asReversed().take(10)
-    buildMessages.info(" top ${topTargets.size} targets by compilation time:")
-    for (entry in topTargets) {
-      buildMessages.info("  ${entry.first}: ${TimeUnit.NANOSECONDS.toMillis(entry.second)}ms")
-    }
-  }
-
-  fun reportProgress(targets: Collection<BuildTarget<*>>, targetSpecificMessage: String) {
-    val targetsString = targets.joinToString(separator = ", ") { Introspector.decapitalize(it.presentableName) }
-    val progressText = if (progress >= 0) " (${(100 * progress).toInt()}%)" else ""
-    val targetSpecificText = if (targetSpecificMessage.isEmpty()) "" else ", $targetSpecificMessage"
-    context.messages.progress("Compiling$progressText: $targetsString$targetSpecificText")
-  }
-}
-
-private class BackedLogger(category: String?, private val fileLogger: Logger?) : DefaultLogger(category) {
-  override fun error(@Nls message: String?, t: Throwable?, vararg details: String) {
-    if (t == null) {
-      messageHandler.processMessage(CompilerMessage(COMPILER_NAME, BuildMessage.Kind.ERROR, message))
-    }
-    else {
-      messageHandler.processMessage(CompilerMessage.createInternalBuilderError(COMPILER_NAME, t))
-    }
-    fileLogger?.error(message, t, *details)
-  }
-
-  override fun warn(message: String?, t: Throwable?) {
-    messageHandler.processMessage(CompilerMessage(COMPILER_NAME, BuildMessage.Kind.WARNING, message))
-    fileLogger?.warn(message, t)
-  }
-
-  override fun info(message: String?, t: Throwable?) {
-    messageHandler.processMessage(CompilerMessage(COMPILER_NAME, BuildMessage.Kind.INFO, message + (t?.message?.let { ": $it" } ?: "")))
-    fileLogger?.info(message, t)
-  }
-
-  override fun isDebugEnabled(): Boolean = fileLogger != null && fileLogger.isDebugEnabled
-
-  override fun debug(message: String?, t: Throwable?) {
-    fileLogger?.debug(message, t)
-  }
-
-  override fun isTraceEnabled(): Boolean = fileLogger != null && fileLogger.isTraceEnabled
-
-  override fun trace(message: String?) {
-    fileLogger?.trace(message)
-  }
-
-  override fun trace(t: Throwable?) {
-    fileLogger?.trace(t)
-  }
-}
-
-private lateinit var messageHandler: JpsMessageHandler
-
-@Nls
-private const val COMPILER_NAME = "build runner"
-
 private fun setSystemPropertyIfUndefined(name: String, value: String) {
   if (System.getProperty(name) == null) {
     System.setProperty(name, value)

platform/build-scripts/src/org/jetbrains/intellij/build/impl/logging/jps/JpsFileLoggerFactory.java

@@ -1,32 +1,35 @@
-// Copyright 2000-2022 JetBrains s.r.o. and contributors. Use of this source code is governed by the Apache 2.0 license.
-package org.jetbrains.jps.gant;
+// Copyright 2000-2023 JetBrains s.r.o. and contributors. Use of this source code is governed by the Apache 2.0 license.
+package org.jetbrains.intellij.build.impl.logging.jps;
 
 import com.intellij.openapi.diagnostic.IdeaLogRecordFormatter;
 import com.intellij.openapi.diagnostic.JulLogger;
+import com.intellij.openapi.diagnostic.Logger;
+import com.intellij.openapi.diagnostic.Logger.Factory;
 import com.intellij.openapi.diagnostic.RollingFileHandler;
+import org.jetbrains.annotations.ApiStatus;
 import org.jetbrains.annotations.NotNull;
 
-import java.io.File;
+import java.nio.file.Path;
 import java.util.Arrays;
 import java.util.Collections;
 import java.util.List;
 import java.util.logging.Level;
-import java.util.logging.Logger;
 
-public class Log4jFileLoggerFactory implements com.intellij.openapi.diagnostic.Logger.Factory {
+@ApiStatus.Internal
+public class JpsFileLoggerFactory implements Factory {
   private final RollingFileHandler myAppender;
   private final List<String> myCategoriesWithDebugLevel;
 
-  public Log4jFileLoggerFactory(File logFile, String categoriesWithDebugLevel) {
+  public JpsFileLoggerFactory(Path logFile, String categoriesWithDebugLevel) {
     myCategoriesWithDebugLevel = categoriesWithDebugLevel.isEmpty() ? Collections.emptyList() : Arrays.asList(categoriesWithDebugLevel.split(","));
-    myAppender = new RollingFileHandler(logFile.toPath(), 20_000_000L, 10, true);
+    myAppender = new RollingFileHandler(logFile, 20_000_000L, 10, true);
     myAppender.setFormatter(new IdeaLogRecordFormatter());
   }
 
   @NotNull
   @Override
-  public com.intellij.openapi.diagnostic.Logger getLoggerInstance(@NotNull String category) {
-    final Logger logger = Logger.getLogger(category);
+  public Logger getLoggerInstance(@NotNull String category) {
+    var logger = java.util.logging.Logger.getLogger(category);
     JulLogger.clearHandlers(logger);
     logger.addHandler(myAppender);
     logger.setUseParentHandlers(false);

platform/build-scripts/src/org/jetbrains/intellij/build/impl/logging/jps/JpsLoggerFactory.kt

@@ -0,0 +1,209 @@
+// Copyright 2000-2023 JetBrains s.r.o. and contributors. Use of this source code is governed by the Apache 2.0 license.
+@file:Suppress("ReplacePutWithAssignment", "ReplaceGetOrSet", "HardCodedStringLiteral")
+
+package org.jetbrains.intellij.build.impl.logging.jps
+
+import com.intellij.openapi.diagnostic.DefaultLogger
+import com.intellij.openapi.diagnostic.Logger
+import com.intellij.util.containers.MultiMap
+import com.jetbrains.plugin.structure.base.utils.createParentDirs
+import org.jetbrains.annotations.ApiStatus.Internal
+import org.jetbrains.annotations.Nls
+import org.jetbrains.intellij.build.CompilationContext
+import org.jetbrains.jps.builders.BuildTarget
+import org.jetbrains.jps.incremental.MessageHandler
+import org.jetbrains.jps.incremental.messages.*
+import java.beans.Introspector
+import java.nio.file.Files
+import java.util.*
+import java.util.concurrent.ConcurrentHashMap
+import java.util.concurrent.TimeUnit
+import java.util.function.BiConsumer
+
+@Internal
+fun withJpsLogging(context: CompilationContext, action: (JpsMessageHandler) -> Unit) {
+  val messageHandler = JpsMessageHandler(context)
+  JpsLoggerFactory.messageHandler = messageHandler
+  if (context.options.compilationLogEnabled) {
+    val categoriesWithDebugLevel = context.compilationData.categoriesWithDebugLevel
+    val buildLogFile = context.compilationData.buildLogFile
+    try {
+      JpsLoggerFactory.fileLoggerFactory = JpsFileLoggerFactory(buildLogFile, categoriesWithDebugLevel)
+      context.messages.info(
+        "Build log (${if (categoriesWithDebugLevel.isEmpty()) "info" else "debug level for $categoriesWithDebugLevel"}) " +
+        "will be written to $buildLogFile"
+      )
+    }
+    catch (t: Throwable) {
+      context.messages.warning("Cannot setup additional logging to $buildLogFile: ${t.message}")
+    }
+  }
+  val defaultLoggerFactory = Logger.getFactory()
+  Logger.setFactory(JpsLoggerFactory::class.java)
+  try {
+    action(messageHandler)
+  }
+  finally {
+    Logger.setFactory(defaultLoggerFactory)
+  }
+}
+
+private class JpsLoggerFactory : Logger.Factory {
+  companion object {
+    lateinit var messageHandler: JpsMessageHandler
+    var fileLoggerFactory: JpsFileLoggerFactory? = null
+  }
+
+  override fun getLoggerInstance(category: String): Logger {
+    return JpsLogger(category, fileLoggerFactory?.getLoggerInstance(category))
+  }
+}
+
+@Internal
+class JpsMessageHandler(private val context: CompilationContext) : MessageHandler {
+  val errorMessagesByCompiler = MultiMap.createConcurrent<String, String>()
+  private val compilationStartTimeForTarget = ConcurrentHashMap<String, Long>()
+  private val compilationFinishTimeForTarget = ConcurrentHashMap<String, Long>()
+  private var progress = (-1.0).toFloat()
+  override fun processMessage(message: BuildMessage) {
+    val text = message.messageText
+    when (message.kind) {
+      BuildMessage.Kind.ERROR, BuildMessage.Kind.INTERNAL_BUILDER_ERROR -> {
+        val compilerName: String
+        val messageText: String
+        if (message is CompilerMessage) {
+          compilerName = message.compilerName
+          val sourcePath = message.sourcePath
+          messageText = if (sourcePath != null) {
+            """
+ $sourcePath${if (message.line != -1L) ":" + message.line else ""}:
+ $text
+ """.trimIndent()
+          }
+          else {
+            text
+          }
+        }
+        else {
+          compilerName = ""
+          messageText = text
+        }
+        errorMessagesByCompiler.putValue(compilerName, messageText)
+      }
+      BuildMessage.Kind.WARNING -> context.messages.warning(text)
+      BuildMessage.Kind.INFO, BuildMessage.Kind.JPS_INFO -> if (message is BuilderStatisticsMessage) {
+        val buildKind = if (context.options.incrementalCompilation) " (incremental)" else ""
+        context.messages.reportStatisticValue("Compilation time '${message.builderName}'$buildKind, ms", message.elapsedTimeMs.toString())
+        val sources = message.numberOfProcessedSources
+        context.messages.reportStatisticValue("Processed files by '${message.builderName}'$buildKind", sources.toString())
+        if (!context.options.incrementalCompilation && sources > 0) {
+          context.messages.reportStatisticValue("Compilation time per file for '${message.builderName}', ms",
+                                                String.format(Locale.US, "%.2f", message.elapsedTimeMs.toDouble() / sources))
+        }
+      }
+      else if (!text.isEmpty()) {
+        context.messages.info(text)
+      }
+      BuildMessage.Kind.PROGRESS -> if (message is ProgressMessage) {
+        progress = message.done
+        message.currentTargets?.let {
+          reportProgress(it.targets, message.messageText)
+        }
+      }
+      else if (message is BuildingTargetProgressMessage) {
+        val targets = message.targets
+        val target = targets.first()
+        val targetId = "${target.id}${if (targets.size > 1) " and ${targets.size} more" else ""} (${target.targetType.typeId})"
+        if (message.eventType == BuildingTargetProgressMessage.Event.STARTED) {
+          reportProgress(targets, "")
+          compilationStartTimeForTarget.put(targetId, System.nanoTime())
+        }
+        else {
+          compilationFinishTimeForTarget.put(targetId, System.nanoTime())
+        }
+      }
+      BuildMessage.Kind.OTHER, null -> context.messages.warning(text)
+    }
+  }
+
+  fun printPerModuleCompilationStatistics(compilationStart: Long) {
+    if (compilationStartTimeForTarget.isEmpty()) {
+      return
+    }
+
+    val csvPath = context.paths.logDir.resolve("compilation-time.csv").also { it.createParentDirs() }
+    Files.newBufferedWriter(csvPath).use { out ->
+      compilationFinishTimeForTarget.forEach(BiConsumer { k, v ->
+        val startTime = compilationStartTimeForTarget.getValue(k) - compilationStart
+        val finishTime = v - compilationStart
+        out.write("$k,$startTime,$finishTime\n")
+      })
+    }
+    val buildMessages = context.messages
+    buildMessages.info("Compilation time per target:")
+    val compilationTimeForTarget = compilationFinishTimeForTarget.entries.map {
+      it.key to (it.value - compilationStartTimeForTarget.getValue(it.key))
+    }
+
+    buildMessages.info(" average: ${
+      String.format("%.2f", ((compilationTimeForTarget.sumOf { it.second }.toDouble()) / compilationTimeForTarget.size) / 1000000)
+    }ms")
+    val topTargets = compilationTimeForTarget.sortedBy { it.second }.asReversed().take(10)
+    buildMessages.info(" top ${topTargets.size} targets by compilation time:")
+    for (entry in topTargets) {
+      buildMessages.info("  ${entry.first}: ${TimeUnit.NANOSECONDS.toMillis(entry.second)}ms")
+    }
+  }
+
+  private fun reportProgress(targets: Collection<BuildTarget<*>>, targetSpecificMessage: String) {
+    val targetsString = targets.joinToString(separator = ", ") { Introspector.decapitalize(it.presentableName) }
+    val progressText = if (progress >= 0) " (${(100 * progress).toInt()}%)" else ""
+    val targetSpecificText = if (targetSpecificMessage.isEmpty()) "" else ", $targetSpecificMessage"
+    context.messages.progress("Compiling$progressText: $targetsString$targetSpecificText")
+  }
+}
+
+private class JpsLogger(category: String?, val fileLogger: Logger?) : DefaultLogger(category) {
+  companion object {
+    @Nls
+    const val COMPILER_NAME = "build runner"
+  }
+
+  val messageHandler get() = JpsLoggerFactory.messageHandler
+
+  override fun error(@Nls message: String?, t: Throwable?, vararg details: String) {
+    if (t == null) {
+      messageHandler.processMessage(CompilerMessage(COMPILER_NAME, BuildMessage.Kind.ERROR, message))
+    }
+    else {
+      messageHandler.processMessage(CompilerMessage.createInternalBuilderError(COMPILER_NAME, t))
+    }
+    fileLogger?.error(message, t, *details)
+  }
+
+  override fun warn(message: String?, t: Throwable?) {
+    messageHandler.processMessage(CompilerMessage(COMPILER_NAME, BuildMessage.Kind.WARNING, message))
+    fileLogger?.warn(message, t)
+  }
+
+  override fun info(message: String?, t: Throwable?) {
+    messageHandler.processMessage(CompilerMessage(COMPILER_NAME, BuildMessage.Kind.INFO, message + (t?.message?.let { ": $it" } ?: "")))
+    fileLogger?.info(message, t)
+  }
+
+  override fun isDebugEnabled(): Boolean = fileLogger != null && fileLogger.isDebugEnabled
+
+  override fun debug(message: String?, t: Throwable?) {
+    fileLogger?.debug(message, t)
+  }
+
+  override fun isTraceEnabled(): Boolean = fileLogger != null && fileLogger.isTraceEnabled
+
+  override fun trace(message: String?) {
+    fileLogger?.trace(message)
+  }
+
+  override fun trace(t: Throwable?) {
+    fileLogger?.trace(t)
+  }
+}