Add test debug logging for PerModulePackageCacheService

idea/idea-analysis/src/org/jetbrains/kotlin/idea/caches/PerModulePackageCacheService.kt

@@ -7,6 +7,7 @@ package org.jetbrains.kotlin.idea.caches
 
 import com.intellij.ProjectTopics
 import com.intellij.openapi.Disposable
+import com.intellij.openapi.application.ApplicationManager
 import com.intellij.openapi.components.ServiceManager
 import com.intellij.openapi.diagnostic.Logger
 import com.intellij.openapi.fileTypes.FileTypeRegistry
@@ -82,19 +83,27 @@ class KotlinPackageContentModificationListener(private val project: Project) {
 
 class KotlinPackageStatementPsiTreeChangePreprocessor(private val project: Project) : PsiTreeChangePreprocessor {
     override fun treeChanged(event: PsiTreeChangeEventImpl) {
-        val file = event.file as? KtFile ?: return
+        val eFile = event.file
+        if (eFile == null) LOG.debugInTests("Got PsiEvent: $event without file", true)
+        val file = eFile as? KtFile ?: return
 
         when (event.code) {
             PsiTreeChangeEventImpl.PsiEventType.CHILD_ADDED,
             PsiTreeChangeEventImpl.PsiEventType.CHILD_MOVED,
             PsiTreeChangeEventImpl.PsiEventType.CHILD_REPLACED,
             PsiTreeChangeEventImpl.PsiEventType.CHILD_REMOVED -> {
-                val child = event.child ?: return
+                val child = event.child ?: run {
+                    LOG.debugInTests("Got PsiEvent: $event without child", true)
+                    return
+                }
                 if (child.getParentOfType<KtPackageDirective>(false) != null)
                     ServiceManager.getService(project, PerModulePackageCacheService::class.java).notifyPackageChange(file)
             }
             PsiTreeChangeEventImpl.PsiEventType.CHILDREN_CHANGED -> {
-                val parent = event.parent ?: return
+                val parent = event.parent ?: run {
+                    LOG.debugInTests("Got PsiEvent: $event without parent", true)
+                    return
+                }
                 if (parent.getChildrenOfType<KtPackageDirective>().any())
                     ServiceManager.getService(project, PerModulePackageCacheService::class.java).notifyPackageChange(file)
             }
@@ -102,6 +111,10 @@ class KotlinPackageStatementPsiTreeChangePreprocessor(private val project: Proje
             }
         }
     }
+
+    companion object {
+        val LOG = Logger.getInstance(this::class.java)
+    }
 }
 
 private typealias ImplicitPackageData = MutableMap<FqName, MutableList<VirtualFile>>
@@ -229,6 +242,7 @@ class PerModulePackageCacheService(private val project: Project) {
     }
 
     private fun invalidateCacheForModuleSourceInfo(moduleSourceInfo: ModuleSourceInfo) {
+        LOG.debugInTests("Invalidated cache for $moduleSourceInfo", false)
         val perSourceInfoData = cache[moduleSourceInfo.module] ?: return
         val dataForSourceInfo = perSourceInfoData[moduleSourceInfo] ?: return
         dataForSourceInfo.clear()
@@ -248,11 +262,16 @@ class PerModulePackageCacheService(private val project: Project) {
                         if (sourceRootUrls.any { url ->
                                 vfile.containedInOrContains(url)
                             }) {
+                            LOG.debugInTests("Invalidated cache for $module")
                             data.clear()
                         }
                     }
                 } else {
-                    (getModuleInfoByVirtualFile(project, vfile) as? ModuleSourceInfo)?.let {
+                    val infoByVirtualFile = getModuleInfoByVirtualFile(project, vfile)
+                    if (infoByVirtualFile == null || infoByVirtualFile !is ModuleSourceInfo) {
+                        LOG.debugInTests("Skip $vfile as it has mismatched ModuleInfo=$infoByVirtualFile")
+                    }
+                    (infoByVirtualFile as? ModuleSourceInfo)?.let {
                         invalidateCacheForModuleSourceInfo(it)
                     }
                 }
@@ -262,9 +281,14 @@ class PerModulePackageCacheService(private val project: Project) {
 
             pendingKtFileChanges.processPending { file ->
                 if (file.virtualFile != null && file.virtualFile !in projectScope) {
+                    LOG.debugInTests("Skip $file without vFile, or not in scope: ${file.virtualFile?.let { it !in projectScope }}")
                     return@processPending
                 }
-                (file.getNullableModuleInfo() as? ModuleSourceInfo)?.let { invalidateCacheForModuleSourceInfo(it) }
+                val nullableModuleInfo = file.getNullableModuleInfo()
+                (nullableModuleInfo as? ModuleSourceInfo)?.let { invalidateCacheForModuleSourceInfo(it) }
+                if (nullableModuleInfo == null || nullableModuleInfo !is ModuleSourceInfo) {
+                    LOG.debugInTests("Skip $file as it has mismatched ModuleInfo=$nullableModuleInfo")
+                }
                 implicitPackagePrefixCache.update(file)
             }
         }
@@ -301,8 +325,11 @@ class PerModulePackageCacheService(private val project: Project) {
         val cacheForCurrentModuleInfo = perSourceInfoCache.getOrPut(moduleInfo) {
             ContainerUtil.createConcurrentSoftMap()
         }
+
         return cacheForCurrentModuleInfo.getOrPut(packageFqName) {
-            PackageIndexUtil.packageExists(packageFqName, moduleInfo.contentScope(), project)
+            val packageExists = PackageIndexUtil.packageExists(packageFqName, moduleInfo.contentScope(), project)
+            LOG.debugInTests("Computed cache value for $packageFqName in $moduleInfo is $packageExists")
+            packageExists
         }
     }
 
@@ -318,4 +345,16 @@ class PerModulePackageCacheService(private val project: Project) {
         fun getInstance(project: Project): PerModulePackageCacheService =
             ServiceManager.getService(project, PerModulePackageCacheService::class.java)
     }
+}
+
+
+private fun Logger.debugInTests(message: String, withCurrentTrace: Boolean = false) {
+    if (ApplicationManager.getApplication().isUnitTestMode) {
+        if (withCurrentTrace) {
+            val e = Exception().apply { fillInStackTrace() }
+            this.debug(message, e)
+        } else {
+            this.debug(message)
+        }
+    }
 }