SbtStructureDump: pass coursier paths env variables to sbt process in…

… unit tests on windows to avoid hanging ProjectImportTest

This is required to workaround sbt/sbt#5128;
The bug is reproduced on Teamcity, on Windows agents.
ProjectImportingTest is stuck indefinitely when the test is run from sbt.
It's also reproduces locally when running the test from sbt.
But for some reason is not reproduced when running from IDEA test runners.

Environment variables which have to be mocked are inferred from
  - lmcoursier.internal.shaded.coursier.paths.CoursierPaths.computeCacheDirectory
  - lmcoursier.internal.shaded.coursier.paths.CoursierPaths.computeJvmCacheDirectory

see also dirs-dev/directories-jvm#49
see also https://github.com/ScoopInstaller/Main/pull/878/files

scala/scala-impl/src/org/jetbrains/sbt/project/SbtProjectResolver.scala

@@ -1,9 +1,6 @@
 package org.jetbrains.sbt
 package project
 
-import java.io.{File, FileNotFoundException}
-import java.util.{Locale, UUID}
-
 import com.intellij.notification.NotificationType
 import com.intellij.openapi.diagnostic.Logger
 import com.intellij.openapi.externalSystem.model.project.{ProjectData => ESProjectData, _}
@@ -33,9 +30,11 @@ import org.jetbrains.sbt.structure.XmlSerializer._
 import org.jetbrains.sbt.structure.{BuildData, ConfigurationData, DependencyData, DirectoryData, JavaData, ProjectData}
 import org.jetbrains.sbt.{structure => sbtStructure}
 
-import scala.jdk.CollectionConverters._
+import java.io.{File, FileNotFoundException}
+import java.util.{Locale, UUID}
 import scala.concurrent.Await
 import scala.concurrent.duration.Duration
+import scala.jdk.CollectionConverters._
 import scala.util.{Failure, Random, Success, Try}
 import scala.xml.{Elem, XML}
 
@@ -182,13 +181,22 @@ class SbtProjectResolver extends ExternalSystemProjectResolver[SbtExecutionSetti
       }
       activeProcessDumper = None
 
-      messageResult.flatMap { messages =>
-        val tried = if (messages.status != BuildMessages.OK || !structureFile.isFile || structureFile.length <= 0) {
-          val message = SbtBundle.message("sbt.import.extracting.structure.failed")
-          Failure(new Exception(message))
-        } else Try {
-          val elem = XML.load(structureFile.toURI.toURL)
-          (elem, messages)
+      val result: Try[(Elem, BuildMessages)] = messageResult.flatMap { messages =>
+        val tried = {
+          def failure(reason: String): Failure[(Elem, BuildMessages)] = {
+            val message = SbtBundle.message("sbt.import.extracting.structure.failed") + s", reason: ${reason}"
+            Failure(new Exception(message))
+          }
+          if (messages.status != BuildMessages.OK)
+            failure(s"not ok build status: ${messages.status} (${messages})")
+          else if (!structureFile.isFile)
+            failure(s"structure file is not a file")
+          else if (structureFile.length <= 0)
+            failure(s"structure file is empty")
+          else Try {
+            val elem = XML.load(structureFile.toURI.toURL)
+            (elem, messages)
+          }
         }
 
         tried.recoverWith { case error =>
@@ -200,6 +208,12 @@ class SbtProjectResolver extends ExternalSystemProjectResolver[SbtExecutionSetti
           Failure(new Exception(message, error.getCause))
         }
       }
+      if (result.isFailure) {
+        val processOutput = dumper.processOutput.mkString
+        // exception is logged in other places
+        log.debug(s"failed to dump sbt structure, sbt process output:\n$processOutput")
+      }
+      result
     }
   }
 

scala/scala-impl/src/org/jetbrains/sbt/project/structure/ListenerAdapter.scala

@@ -12,7 +12,8 @@ class ListenerAdapter(listener: (OutputType, String) => Unit) extends ProcessAda
     val textType = outputType match {
       case ProcessOutputTypes.STDOUT => Some(OutputType.StdOut)
       case ProcessOutputTypes.STDERR => Some(OutputType.StdErr)
-      case _ => None
+      case ProcessOutputTypes.SYSTEM => Some(OutputType.MySystem)
+      case other                     => Some(OutputType.Other(other))
     }
     textType.foreach(t => listener(t, event.getText))
   }

scala/scala-impl/src/org/jetbrains/sbt/project/structure/OutputType.scala

@@ -1,6 +1,8 @@
 package org.jetbrains.sbt
 package project.structure
 
+import com.intellij.openapi.util.Key
+
 /**
  * @author Pavel Fatin
  */
@@ -9,4 +11,6 @@ sealed abstract class OutputType
 object OutputType {
   object StdOut extends OutputType
   object StdErr extends OutputType
+  object MySystem extends OutputType
+  final case class Other(key: Key[_]) extends OutputType
 }

scala/scala-impl/src/org/jetbrains/sbt/project/structure/SbtStructureDump.scala

@@ -1,34 +1,47 @@
 package org.jetbrains.sbt.project.structure
 
-import java.io.{BufferedWriter, File, OutputStreamWriter, PrintWriter}
-import java.nio.charset.Charset
-import java.util.UUID
-import java.util.concurrent.atomic.AtomicBoolean
-
 import com.intellij.build.events.impl.{FailureResultImpl, SkippedResultImpl, SuccessResultImpl}
 import com.intellij.execution.process.OSProcessHandler
+import com.intellij.openapi.application.ApplicationManager
+import com.intellij.openapi.diagnostic.Logger
 import com.intellij.openapi.externalSystem.model.ExternalSystemException
 import com.intellij.openapi.project.Project
+import com.intellij.openapi.util.SystemInfo
 import org.jetbrains.annotations.{Nls, NonNls}
 import org.jetbrains.plugins.scala.build.BuildMessages.EventId
 import org.jetbrains.plugins.scala.build.{BuildMessages, BuildReporter, ExternalSystemNotificationReporter}
+import org.jetbrains.plugins.scala.extensions.LoggerExt
 import org.jetbrains.plugins.scala.findUsages.compilerReferences.compilation.SbtCompilationSupervisor
 import org.jetbrains.plugins.scala.findUsages.compilerReferences.settings.CompilerIndicesSettings
+import org.jetbrains.sbt.SbtBundle
 import org.jetbrains.sbt.SbtUtil._
 import org.jetbrains.sbt.project.SbtProjectResolver.ImportCancelledException
 import org.jetbrains.sbt.project.structure.SbtStructureDump._
 import org.jetbrains.sbt.shell.SbtShellCommunication
 import org.jetbrains.sbt.shell.SbtShellCommunication._
-import org.jetbrains.sbt.SbtBundle
 
-import scala.jdk.CollectionConverters._
+import java.io.{BufferedWriter, File, OutputStreamWriter, PrintWriter}
+import java.nio.charset.Charset
+import java.util.UUID
+import java.util.concurrent.TimeoutException
+import java.util.concurrent.atomic.AtomicBoolean
 import scala.concurrent.Future
+import scala.concurrent.duration.{DurationInt, FiniteDuration}
+import scala.jdk.CollectionConverters._
 import scala.util.{Failure, Success, Try, Using}
 
 class SbtStructureDump {
 
   private val cancellationFlag: AtomicBoolean = new AtomicBoolean(false)
 
+  // NOTE: if this is a first run of sbt with a particular version on current machine
+  // sbt import will take some time because it will have to download quite a lot of dependencies
+  private val MaxImportDurationInUnitTests: FiniteDuration = 10.minutes
+
+  // in failed tests we would like to see sbt process output
+  private val processOutputBuilder = new StringBuilder
+  def processOutput: String = processOutputBuilder.mkString
+
   def cancel(): Unit = cancellationFlag.set(true)
 
   def dumpFromShell(project: Project,
@@ -93,11 +106,41 @@ class SbtStructureDump {
     )
   }
 
+  /**
+   * This is a workaround for [[https://github.com/sbt/sbt/issues/5128]]
+   *
+   * The bug is reproduced on Teamcity, on Windows agents:
+   * ProjectImportingTest is stuck indefinitely when the test is run from sbt.<br>
+   * It's also reproduces locally when running the test from sbt.<br>
+   * But for some reason is not reproduced when running from IDEA test runners<br>
+   *
+   * Environment variables which have to be mocked are inferred from
+   *  - lmcoursier.internal.shaded.coursier.paths.CoursierPaths.computeCacheDirectory
+   *  - lmcoursier.internal.shaded.coursier.paths.CoursierPaths.computeJvmCacheDirectory
+   *
+   * @see [[https://github.com/sbt/sbt/issues/5128]]
+   * @see [[https://github.com/dirs-dev/directories-jvm/issues/49]]
+   * @see [[https://github.com/ScoopInstaller/Main/pull/878/files]]
+   */
+  private def defaultCoursierDirectoriesAsEnvVariables(): Seq[(String, String)] = {
+    val LocalAppData = System.getenv("LOCALAPPDATA")
+    val AppData = System.getenv("APPDATA")
+
+    val CoursierLocalAppDataHome = LocalAppData + "/Coursier"
+    val CoursierAppDataHome = AppData + "/Coursier"
+
+    Seq(
+      ("COURSIER_HOME", CoursierLocalAppDataHome),
+      ("COURSIER_CACHE", CoursierLocalAppDataHome + "/cache"),
+      ("COURSIER_CONFIG_DIR", CoursierAppDataHome + "/config"),
+    )
+  }
+
   /** Run sbt with some sbt commands. */
   def runSbt(directory: File,
              vmExecutable: File,
              vmOptions: Seq[String],
-             environment: Map[String, String],
+             environment0: Map[String, String],
              sbtLauncher: File,
              sbtCommandLineArgs: List[String],
              @NonNls sbtCommands: String,
@@ -106,6 +149,24 @@ class SbtStructureDump {
             (implicit reporter: BuildReporter)
   : Try[BuildMessages] = {
 
+    val environment = if (ApplicationManager.getApplication.isUnitTestMode && SystemInfo.isWindows) {
+      val extraEnvs = defaultCoursierDirectoriesAsEnvVariables()
+      environment0 ++ extraEnvs
+    }
+    else environment0
+
+    Log.debugSafe(
+      s"""runSbt
+         |  directory: $directory,
+         |  vmExecutable: $vmExecutable,
+         |  vmOptions: $vmOptions,
+         |  environment: $environment,
+         |  sbtLauncher: $sbtLauncher,
+         |  sbtCommandLineArgs: $sbtCommandLineArgs,
+         |  sbtCommands: $sbtCommands,
+         |  reportMessage: $reportMessage""".stripMargin
+    )
+
     val startTime = System.currentTimeMillis()
     // assuming here that this method might still be called without valid project
 
@@ -119,7 +180,7 @@ class SbtStructureDump {
         "-Dfile.encoding=UTF-8") ++
       jvmOptions ++
       List("-jar", normalizePath(sbtLauncher)) ++
-      sbtCommandLineArgs
+      sbtCommandLineArgs // :+ "--debug"
 
     val processCommands = processCommandsRaw.filterNot(_.isEmpty)
 
@@ -133,6 +194,10 @@ class SbtStructureDump {
       val procString = processBuilder.command().asScala.mkString(" ")
       reporter.log(procString)
 
+      Log.debugSafe(
+        s"""processBuilder.start()
+           |  command line: ${processBuilder.command().asScala.mkString(" ")}""".stripMargin
+      )
       processBuilder.start()
     }
       .flatMap { process =>
@@ -192,44 +257,74 @@ class SbtStructureDump {
       }
     }
 
-    val processListener: (OutputType, String) => Unit = {
-      case (typ@OutputType.StdOut, text) =>
-        if (text.contains("(q)uit")) {
-          val writer = new PrintWriter(process.getOutputStream)
-          writer.println("q")
-          writer.close()
-        } else {
-          update(typ, text)
+    val isUnitTest = ApplicationManager.getApplication.isUnitTestMode
+    processOutputBuilder.clear()
+
+    val processListener: (OutputType, String) => Unit = (typ, line) => {
+      if (isUnitTest) {
+        processOutputBuilder.append(s"[${typ.getClass.getSimpleName}] $line")
+        if (!line.endsWith("\n")) {
+          processOutputBuilder.append('\n')
         }
-      case (typ@OutputType.StdErr, text) =>
-        update(typ, text)
+      }
+      (typ, line) match {
+        case (typ@OutputType.StdOut, text) =>
+          if (text.contains("(q)uit")) {
+            val writer = new PrintWriter(process.getOutputStream)
+            writer.println("q")
+            writer.close()
+          } else {
+            update(typ, text)
+          }
+        case (typ@OutputType.StdErr, text) =>
+          update(typ, text)
+        case _ => // ignore
+      }
     }
 
-    Try {
-      val handler = new OSProcessHandler(process, "sbt import", Charset.forName("UTF-8"))
+    val handler = new OSProcessHandler(process, "sbt import", Charset.forName("UTF-8"))
+    // TODO: rewrite this code, do not use try, throw
+    val result = Try {
       handler.addProcessListener(new ListenerAdapter(processListener))
+      Log.debug("handler.startNotify()")
       handler.startNotify()
 
+      val start = System.currentTimeMillis()
+
       var processEnded = false
-      while (!processEnded && !cancellationFlag.get())
+      while (!processEnded && !cancellationFlag.get()) {
         processEnded = handler.waitFor(SBT_PROCESS_CHECK_TIMEOUT_MSEC)
 
-      if (!processEnded) {
-        // task was cancelled
-        handler.setShouldDestroyProcessRecursively(false)
-        handler.destroyProcess()
+        val importIsTooLong = isUnitTest && System.currentTimeMillis() - start > MaxImportDurationInUnitTests.toMillis
+        if (importIsTooLong) {
+          throw new TimeoutException(s"sbt process hasn't finished in $MaxImportDurationInUnitTests")
+        }
+      }
+
+      val exitCode = handler.getExitCode
+      Log.debug(s"processEnded: $processEnded, exitCode: $exitCode")
+      if (!processEnded)
         throw ImportCancelledException(new Exception(SbtBundle.message("sbt.task.canceled")))
-      } else if (handler.getExitCode != 0)
-          messages.status(BuildMessages.Error)
+      else if (exitCode != 0)
+        messages.status(BuildMessages.Error)
       else if (messages.status == BuildMessages.Indeterminate)
         messages.status(BuildMessages.OK)
-      else messages
+      else
+        messages
     }
+    if (!handler.isProcessTerminated) {
+      Log.debug(s"sbt process has not terminated, destroying the process...")
+      handler.setShouldDestroyProcessRecursively(false) // TODO: why not `true`?
+      handler.destroyProcess()
+    }
+    result
   }
 }
 
 object SbtStructureDump {
 
+  private val Log = Logger.getInstance(classOf[SbtStructureDump])
+
   private val SBT_PROCESS_CHECK_TIMEOUT_MSEC = 100
 
   private def reportEvent(messages: BuildMessages,