IC: improve logging in tests and fix DataContainerVersionChangedTestGenerated#testWithError

Test logging improvements:
  * print which chunk building in the round for multimodule projects
  * print actions after cache changed

jps-plugin/jps-tests/test/org/jetbrains/kotlin/jps/build/AbstractIncrementalJpsTest.kt

@@ -25,6 +25,7 @@ import org.apache.log4j.ConsoleAppender
 import org.apache.log4j.Level
 import org.apache.log4j.Logger
 import org.apache.log4j.PatternLayout
+import org.jetbrains.jps.ModuleChunk
 import org.jetbrains.jps.api.CanceledStatus
 import org.jetbrains.jps.builders.BuildResult
 import org.jetbrains.jps.builders.CompileScopeTestBuilder
@@ -34,16 +35,14 @@ import org.jetbrains.jps.builders.impl.logging.ProjectBuilderLoggerBase
 import org.jetbrains.jps.builders.java.dependencyView.Callbacks
 import org.jetbrains.jps.builders.logging.BuildLoggingManager
 import org.jetbrains.jps.cmdline.ProjectDescriptor
-import org.jetbrains.jps.incremental.BuilderRegistry
+import org.jetbrains.jps.incremental.*
-import org.jetbrains.jps.incremental.IncProjectBuilder
-import org.jetbrains.jps.incremental.ModuleBuildTarget
-import org.jetbrains.jps.incremental.ModuleLevelBuilder
 import org.jetbrains.jps.incremental.messages.BuildMessage
 import org.jetbrains.jps.model.JpsModuleRootModificationUtil
 import org.jetbrains.jps.model.java.JpsJavaDependencyScope
 import org.jetbrains.jps.model.java.JpsJavaExtensionService
 import org.jetbrains.jps.util.JpsPathUtil
 import org.jetbrains.kotlin.config.IncrementalCompilation
+import org.jetbrains.kotlin.incremental.CacheVersion
 import org.jetbrains.kotlin.incremental.LookupSymbol
 import org.jetbrains.kotlin.incremental.components.LookupTracker
 import org.jetbrains.kotlin.incremental.testingUtils.*
@@ -390,13 +389,13 @@ abstract class AbstractIncrementalJpsTest(
             preProcessSources(sourceDestinationDir)
         }
 
-        var moduleNames: Set<String>?
         JpsJavaExtensionService.getInstance().getOrCreateProjectExtension(myProject).outputUrl = JpsPathUtil.pathToUrl(getAbsolutePath("out"))
 
         val jdk = addJdk("my jdk")
         val moduleDependencies = readModuleDependencies()
         mapWorkingToOriginalFile = hashMapOf()
 
+        val moduleNames: Set<String>?
         if (moduleDependencies == null) {
             addModule("module", arrayOf(getAbsolutePath("src")), null, null, jdk)
             prepareModuleSources(moduleName = null)
@@ -436,10 +435,22 @@ abstract class AbstractIncrementalJpsTest(
 
         private val dirtyFiles = ArrayList<File>()
 
+        override fun actionsOnCacheVersionChanged(actions: List<CacheVersion.Action>) {
+            if (actions.size > 1 && actions.any { it != CacheVersion.Action.DO_NOTHING }) {
+                logLine("Actions after cache changed: $actions")
+            }
+        }
+
         override fun markedAsDirty(files: Iterable<File>) {
             dirtyFiles.addAll(files)
         }
 
+        override fun buildStarted(context: CompileContext, chunk: ModuleChunk) {
+            if (context.projectDescriptor.project.modules.size > 1) {
+                logLine("Building ${chunk.modules.sortedBy { it.name }.joinToString { it.name }}")
+            }
+        }
+
         override fun buildFinished(exitCode: ModuleLevelBuilder.ExitCode) {
 
             if (dirtyFiles.isNotEmpty()) {

jps-plugin/src/org/jetbrains/kotlin/jps/build/BuildLogger.kt

@@ -16,20 +16,15 @@
 
 package org.jetbrains.kotlin.jps.build
 
+import org.jetbrains.jps.ModuleChunk
+import org.jetbrains.jps.incremental.CompileContext
 import org.jetbrains.jps.incremental.ModuleLevelBuilder
+import org.jetbrains.kotlin.incremental.CacheVersion
 import java.io.File
 
 interface BuildLogger {
+    fun actionsOnCacheVersionChanged(actions: List<CacheVersion.Action>)
+    fun buildStarted(context: CompileContext, chunk: ModuleChunk)
     fun buildFinished(exitCode: ModuleLevelBuilder.ExitCode)
     fun markedAsDirty(files: Iterable<File>)
-
-    companion object {
-        val DO_NOTHING = object : BuildLogger {
-            override fun buildFinished(exitCode: ModuleLevelBuilder.ExitCode) {
-            }
-
-            override fun markedAsDirty(files: Iterable<File>) {
-            }
-        }
-    }
 }

jps-plugin/src/org/jetbrains/kotlin/jps/build/FSOperationsHelper.kt

@@ -31,7 +31,7 @@ class FSOperationsHelper(
     internal var hasMarkedDirty = false
         private set
 
-    private val buildLogger = compileContext.testingContext?.buildLogger ?: BuildLogger.DO_NOTHING
+    private val buildLogger = compileContext.testingContext?.buildLogger
 
     fun markChunk(recursively: Boolean, kotlinOnly: Boolean, excludeFiles: Set<File> = setOf()) {
         fun shouldMark(file: File): Boolean {
@@ -56,7 +56,7 @@ class FSOperationsHelper(
         filesToMark.removeAll(excludeFiles)
 
         log.debug("Mark dirty: $filesToMark")
-        buildLogger.markedAsDirty(filesToMark)
+        buildLogger?.markedAsDirty(filesToMark)
 
         for (file in filesToMark) {
             if (!file.exists()) continue

jps-plugin/src/org/jetbrains/kotlin/jps/build/KotlinBuilder.kt

@@ -103,6 +103,8 @@ class KotlinBuilder : ModuleLevelBuilder(BuilderCategory.SOURCE_PROCESSOR) {
     override fun chunkBuildStarted(context: CompileContext, chunk: ModuleChunk) {
         super.chunkBuildStarted(context, chunk)
 
+        context.testingContext?.buildLogger?.buildStarted(context, chunk)
+
         if (JavaBuilderUtil.isForcedRecompilationAllJavaModules(context)) return
 
         val targets = chunk.targets
@@ -142,9 +144,7 @@ class KotlinBuilder : ModuleLevelBuilder(BuilderCategory.SOURCE_PROCESSOR) {
 
             LOG.info("Build result: " + actualExitCode)
 
-            context.testingContext?.run {
+            context.testingContext?.buildLogger?.buildFinished(actualExitCode)
-                buildLogger.buildFinished(actualExitCode)
-            }
 
             return actualExitCode
         }
@@ -294,7 +294,11 @@ class KotlinBuilder : ModuleLevelBuilder(BuilderCategory.SOURCE_PROCESSOR) {
         val hasKotlin = HasKotlinMarker(dataManager)
         val rebuildAfterCacheVersionChanged = RebuildAfterCacheVersionChangeMarker(dataManager)
 
-        for (status in actions.sorted()) {
+        val sortedActions = actions.sorted()
+
+        context.testingContext?.buildLogger?.actionsOnCacheVersionChanged(sortedActions)
+
+        for (status in sortedActions) {
             when (status) {
                 CacheVersion.Action.REBUILD_ALL_KOTLIN -> {
                     LOG.info("Kotlin global lookup map format changed, so rebuild all kotlin")
@@ -879,8 +883,3 @@ private fun hasKotlinDirtyOrRemovedFiles(
     return chunk.targets.any { KotlinSourceFileCollector.getRemovedKotlinFiles(dirtyFilesHolder, it).isNotEmpty() }
 }
 
-private inline fun Logger.debug(message: ()->String) {
-    if (isDebugEnabled) {
-        debug(message())
-    }
-}

jps-plugin/testData/incremental/cacheVersionChanged/withError/build.log

@@ -1,5 +1,7 @@
 ================ Step #1 =================
 
+Building module1
+Actions after cache changed: [REBUILD_CHUNK, DO_NOTHING]
 Cleaning output files:
   out/production/module1/META-INF/module1.kotlin_module
   out/production/module1/module1/A.class
@@ -17,12 +19,15 @@ Name expected
 
 ================ Step #2 =================
 
+Building module1
 Compiling files:
   module1/src/a.kt
   module1/src/f.kt
 End of files
 Exit code: OK
 ------------------------------------------
+Building module2
+Actions after cache changed: [REBUILD_CHUNK, DO_NOTHING]
 Cleaning output files:
   out/production/module2/META-INF/module2.kotlin_module
   out/production/module2/module2/BKt.class
@@ -32,6 +37,8 @@ Compiling files:
 End of files
 Exit code: OK
 ------------------------------------------
+Building module3
+Actions after cache changed: [REBUILD_CHUNK, DO_NOTHING]
 Cleaning output files:
   out/production/module3/META-INF/module3.kotlin_module
   out/production/module3/module3/CKt.class
@@ -41,6 +48,8 @@ Compiling files:
 End of files
 Exit code: OK
 ------------------------------------------
+Building module4
+Actions after cache changed: [REBUILD_CHUNK, DO_NOTHING]
 Cleaning output files:
   out/production/module4/module4/D.class
 End of files
@@ -49,5 +58,6 @@ Compiling files:
 End of files
 Exit code: OK
 ------------------------------------------
+Building module5
 Exit code: NOTHING_DONE
-------------------------------------------
+------------------------------------------

jps-plugin/testData/incremental/cacheVersionChanged/withError/data-container-version-build.log

@@ -1,21 +1,7 @@
 ================ Step #1 =================
 
-Exit code: NOTHING_DONE
+Building module1
-------------------------------------------
+Actions after cache changed: [REBUILD_ALL_KOTLIN, DO_NOTHING]
-Cleaning output files:
-  out/production/module4/module4/D.class
-End of files
-Compiling files:
-  module4/src/d.kt
-End of files
-Marked as dirty by Kotlin:
-  module1/src/a.kt
-  module1/src/f.kt
-  module2/src/b.kt
-  module3/src/c.kt
-  module4/src/d.kt
-Exit code: OK
-------------------------------------------
 Cleaning output files:
   out/production/module1/META-INF/module1.kotlin_module
   out/production/module1/module1/A.class
@@ -26,6 +12,12 @@ Compiling files:
   module1/src/a.kt
   module1/src/f.kt
 End of files
+Marked as dirty by Kotlin:
+  module1/src/a.kt
+  module1/src/f.kt
+  module2/src/b.kt
+  module3/src/c.kt
+  module4/src/d.kt
 Exit code: ABORT
 ------------------------------------------
 COMPILATION FAILED
@@ -33,16 +25,22 @@ Name expected
 
 ================ Step #2 =================
 
-Exit code: NOTHING_DONE
+Building module1
-------------------------------------------
+Actions after cache changed: [REBUILD_ALL_KOTLIN, REBUILD_CHUNK]
-Exit code: NOTHING_DONE
-------------------------------------------
 Compiling files:
   module1/src/a.kt
   module1/src/f.kt
 End of files
+Marked as dirty by Kotlin:
+  module1/src/a.kt
+  module1/src/f.kt
+  module2/src/b.kt
+  module3/src/c.kt
+  module4/src/d.kt
 Exit code: OK
 ------------------------------------------
+Building module2
+Actions after cache changed: [REBUILD_CHUNK, DO_NOTHING]
 Cleaning output files:
   out/production/module2/META-INF/module2.kotlin_module
   out/production/module2/module2/BKt.class
@@ -52,6 +50,8 @@ Compiling files:
 End of files
 Exit code: OK
 ------------------------------------------
+Building module3
+Actions after cache changed: [REBUILD_CHUNK, DO_NOTHING]
 Cleaning output files:
   out/production/module3/META-INF/module3.kotlin_module
   out/production/module3/module3/CKt.class
@@ -61,3 +61,16 @@ Compiling files:
 End of files
 Exit code: OK
 ------------------------------------------
+Building module4
+Actions after cache changed: [REBUILD_CHUNK, DO_NOTHING]
+Cleaning output files:
+  out/production/module4/module4/D.class
+End of files
+Compiling files:
+  module4/src/d.kt
+End of files
+Exit code: OK
+------------------------------------------
+Building module5
+Exit code: NOTHING_DONE
+------------------------------------------