Prefix logging for BSP (#5180)

Same as #5154, with a cleaner
git history to ease review

---

When Mill runs as a BSP server, this makes it log in a similar way as
when running Mill from the command-line, with `[…] ` prefixes.

For example, the small BSP session run in the test added in this PR logs
the following to stderr:
```text
[bsp] Trying to load BSP server...
[bsp] BSP server started
[1-buildInitialize] Entered buildInitialize
[1-buildInitialize] buildInitialize took 2 msec
[2-workspaceBuildTargets] Entered workspaceBuildTargets
[bsp-init-build.mill-61] [info] compiling 3 Scala sources to /Users/alexandre/projects/mill/mill-class-loading/out/integration/ide/bsp-server/local/daemon/testForked.dest/sandbox/run-1/out/mill-build/compile.dest/classes ...
[bsp-init-build.mill-61] [warn] package scala contains object and package with same name: caps.
[bsp-init-build.mill-61] [warn] This indicates that there are several versions of the Scala standard library on the classpath.
[bsp-init-build.mill-61] [warn] The build should be reconfigured so that only one version of the standard library is on the classpath.
[bsp-init-build.mill-61] [warn] one warning found
[bsp-init-build.mill-61] [info] done compiling
[bsp-init] SNAPSHOT
[2-workspaceBuildTargets] Evaluating 5 tasks
[2-workspaceBuildTargets] Done
[2-workspaceBuildTargets] Evaluating 1 task
[2-workspaceBuildTargets] Done
[2-workspaceBuildTargets] workspaceBuildTargets took 4197 msec
[3-loggingTest] Entered loggingTest
[3-loggingTest] Evaluating 1 task
[3-loggingTest-1] bspLoggingTest from System.out
[3-loggingTest-1] bspLoggingTest from System.err
[3-loggingTest-1] bspLoggingTest from Console.out
[3-loggingTest-1] bspLoggingTest from Console.err
[3-loggingTest-1] bspLoggingTest from Task.log.info
[3-loggingTest] Done
[3-loggingTest] loggingTest took 11 msec
[4-buildShutdown] Entered buildShutdown
[5-onBuildExit] Entered onBuildExit
Reload finished, result: mill.api.internal.BspServerResult$Shutdown$@6726cc69
Shutting down executor
[bsp] BSP session returned with mill.api.internal.BspServerResult$Shutdown$@6726cc69
Stopping server via handle...
[bsp] Exiting BSP runner loop. Stopping BSP server. Last result: Success(mill.api.internal.BspServerResult$Shutdown$@6726cc69)
```

This helps make sense of what's going on when working on BSP-releated
features, but could also help Mill BSP users in case anything goes
wrong.

Author: alexarchambault

core/api/src/mill/api/SystemStreams.scala

@@ -3,6 +3,8 @@ package mill.api
 import java.io.InputStream
 import java.io.PrintStream
 
+import scala.util.DynamicVariable
+
 /**
  * Represents a set of streams that look similar to those provided by the
  * operating system. These may internally be proxied/redirected/processed, but
@@ -14,3 +16,8 @@ class SystemStreams(
     val err: PrintStream,
     val in: InputStream
 )
+
+object SystemStreams {
+  val original = new SystemStreams(System.out, System.err, System.in)
+  val current = new DynamicVariable(original)
+}

core/api/src/mill/api/internal/api.scala

@@ -32,6 +32,8 @@ trait JavaModuleApi extends ModuleApi {
 
   private[mill] def bspBuildTargetCompile: TaskApi[java.nio.file.Path]
 
+  private[mill] def bspLoggingTest: TaskApi[Unit]
+
   private[mill] def bspBuildTargetJavacOptions(clientWantsSemanticDb: Boolean)
       : TaskApi[EvaluatorApi => (java.nio.file.Path, Seq[String], Seq[String])]
 

core/define/src/mill/define/SystemStreams.scala

@@ -4,7 +4,6 @@ import mill.api.DummyInputStream
 import mill.constants.InputPumper
 
 import java.io.{InputStream, OutputStream, PrintStream}
-import scala.util.DynamicVariable
 
 object SystemStreams {
 
@@ -16,7 +15,7 @@ object SystemStreams {
    * That means that the logs may appear out of order, jumbling your logs and screwing up
    * your terminal
    */
-  val original = new mill.api.SystemStreams(System.out, System.err, System.in)
+  def original = mill.api.SystemStreams.original
 
   /**
    * Used to check whether the system streams are all "original", i,e. they
@@ -116,6 +115,7 @@ object SystemStreams {
     }
   }
   def setTopLevelSystemStreamProxy(): Unit = {
+    val _ = mill.api.SystemStreams.current
     // Make sure to initialize `Console` to cache references to the original
     // `System.{in,out,err}` streams before we redirect them
     val _ = Console.out
@@ -126,8 +126,11 @@ object SystemStreams {
     System.setErr(ThreadLocalStreams.Err)
   }
 
+  def current(): mill.api.SystemStreams =
+    ThreadLocalStreams.current.value
+
   private[mill] object ThreadLocalStreams {
-    val current = new DynamicVariable(original)
+    def current = mill.api.SystemStreams.current
 
     object Out extends PrintStream(new ProxyOutputStream { def delegate() = current.value.out })
     object Err extends PrintStream(new ProxyOutputStream { def delegate() = current.value.err })

core/internal/src/mill/internal/PrefixLogger.scala

@@ -56,25 +56,30 @@ private[mill] class PrefixLogger(
     logger0.unprefixedStreams.in
   )
 
+  private def addPrefix(prefix: String, s: String): String =
+    s.linesWithSeparators.map(prefix + _).mkString
+
   override def info(s: String): Unit = {
     prompt.reportKey(logKey)
-    logger0.info("" + prompt.infoColor(linePrefix) + s)
+    unprefixedStreams.err.println(addPrefix(prompt.infoColor(linePrefix), s))
   }
   override def warn(s: String): Unit = {
     prompt.reportKey(logKey)
-    logger0.warn("" + prompt.warnColor(linePrefix) + s)
+    unprefixedStreams.err.println(addPrefix(prompt.warnColor(linePrefix), s))
   }
   override def error(s: String): Unit = {
     prompt.reportKey(logKey)
-    logger0.error("" + prompt.infoColor(linePrefix) + s)
+    unprefixedStreams.err.println(addPrefix(prompt.errorColor(linePrefix), s))
   }
   override def ticker(s: String): Unit = prompt.setPromptDetail(logKey, s)
 
   def prompt = logger0.prompt
 
   override def debug(s: String): Unit = {
-    if (prompt.debugEnabled) prompt.reportKey(logKey)
-    logger0.debug("" + prompt.infoColor(linePrefix) + s)
+    if (debugEnabled) {
+      if (prompt.debugEnabled) prompt.reportKey(logKey)
+      unprefixedStreams.err.println(addPrefix(prompt.infoColor(linePrefix), s))
+    }
   }
   override def withOutStream(outStream: PrintStream): Logger = new ProxyLogger(this) with Logger {
     override lazy val unprefixedStreams = new SystemStreams(

core/internal/src/mill/internal/SimpleLogger.scala

@@ -0,0 +1,50 @@
+package mill.internal
+
+import mill.api.{SystemStreams, Logger}
+
+import java.io.PrintStream
+
+private[mill] class SimpleLogger(
+    override val unprefixedStreams: SystemStreams,
+    override val logKey: Seq[String],
+    debugEnabled: Boolean
+) extends Logger {
+  override def toString: String = s"SimpleLogger($unprefixedStreams, $debugEnabled)"
+
+  private val linePrefix: String =
+    if (logKey.isEmpty) ""
+    else s"[${logKey.mkString("-")}] "
+  private def prefixPrintStream(stream: java.io.OutputStream) = {
+    new PrintStream(new LinePrefixOutputStream(
+      linePrefix,
+      stream,
+      () => ()
+    ))
+  }
+
+  val streams = new SystemStreams(
+    out = prefixPrintStream(unprefixedStreams.out),
+    err = prefixPrintStream(unprefixedStreams.err),
+    unprefixedStreams.in
+  )
+
+  def isInteractive() = false
+
+  def info(s: String): Unit =
+    unprefixedStreams.err.println(s)
+
+  def warn(s: String): Unit =
+    unprefixedStreams.err.println(s)
+
+  def error(s: String): Unit =
+    unprefixedStreams.err.println(s)
+
+  val prompt = new Logger.Prompt.NoOp {
+    override def enableTicker = true
+  }
+  def ticker(s: String): Unit = ()
+
+  def debug(s: String): Unit =
+    if (debugEnabled)
+      unprefixedStreams.err.println(s)
+}

integration/ide/bsp-server/resources/project/build.mill

@@ -37,3 +37,13 @@ object app extends scalalib.JavaModule {
     mvn"com.mysql:mysql-connector-j:9.1.0"
   )
 }
+
+object errored extends scalalib.ScalaModule {
+  def scalaVersion = Option(System.getenv("TEST_SCALA_2_13_VERSION")).getOrElse(???)
+
+  def compile = Task {
+    val res = super.compile()
+    sys.error("nope")
+    res
+  }
+}

integration/ide/bsp-server/resources/snapshots/logging

@@ -0,0 +1,37 @@
+[bsp] Trying to load BSP server...
+[bsp] BSP server started
+[1-buildInitialize] Entered buildInitialize
+[1-buildInitialize] buildInitialize took * msec
+[2-workspaceBuildTargets] Entered workspaceBuildTargets
+[bsp-init-build.mill-61] [info] compiling * Scala sources to * ...
+[bsp-init-build.mill-61] [info] done compiling
+[bsp-init] SNAPSHOT
+[2-workspaceBuildTargets] Evaluating * tasks
+[2-workspaceBuildTargets] Done
+[2-workspaceBuildTargets] Evaluating 1 task
+[2-workspaceBuildTargets] Done
+[2-workspaceBuildTargets] workspaceBuildTargets took * msec
+[3-loggingTest] Entered loggingTest
+[3-loggingTest] Evaluating 1 task
+[3-loggingTest-1] bspLoggingTest from System.out
+[3-loggingTest-1] bspLoggingTest from System.err
+[3-loggingTest-1] bspLoggingTest from Console.out
+[3-loggingTest-1] bspLoggingTest from Console.err
+[3-loggingTest-1] bspLoggingTest from Task.log.info
+[3-loggingTest] Done
+[3-loggingTest] loggingTest took * msec
+[4-compile] Entered buildTargetCompile
+[4-compile] Evaluating 1 task
+[4-compile] * tasks failed
+[4-compile] errored.compile java.lang.RuntimeException: nope
+[4-compile]     scala.sys.package$.error(package.scala:*)
+[4-compile]     build_.package_.build_$package_$errored$$$_$compile$$anonfun$1$$anonfun$1(build.mill:*)
+[4-compile]     mill.define.Task$Named.evaluate(Task.scala:*)
+[4-compile]     mill.define.Task$Named.evaluate$(Task.scala:*)
+[4-compile]     mill.define.Task$Computed.evaluate(Task.scala:*)
+[4-compile] Failed
+[4-compile] buildTargetCompile took * msec
+[5-buildShutdown] Entered buildShutdown
+[6-onBuildExit] Entered onBuildExit
+[bsp] BSP session returned with mill.api.internal.BspServerResult$Shutdown$@*
+[bsp] Exiting BSP runner loop. Stopping BSP server. Last result: Success(mill.api.internal.BspServerResult$Shutdown$@*)

integration/ide/bsp-server/resources/snapshots/workspace-build-targets.json

@@ -30,6 +30,46 @@
         "javaVersion": "<java-version>"
       }
     },
+    {
+      "id": {
+        "uri": "file:///workspace/errored"
+      },
+      "displayName": "errored",
+      "baseDirectory": "file:///workspace/errored",
+      "tags": [
+        "library",
+        "application"
+      ],
+      "languageIds": [
+        "java",
+        "scala"
+      ],
+      "dependencies": [],
+      "capabilities": {
+        "canCompile": true,
+        "canTest": false,
+        "canRun": true,
+        "canDebug": false
+      },
+      "dataKind": "scala",
+      "data": {
+        "scalaOrganization": "org.scala-lang",
+        "scalaVersion": "<scala-version>",
+        "scalaBinaryVersion": "2.13",
+        "platform": 1,
+        "jars": [
+          "file:///coursier-cache/https/repo1.maven.org/maven2/org/scala-lang/scala-compiler/<scala-version>/scala-compiler-<scala-version>.jar",
+          "file:///coursier-cache/https/repo1.maven.org/maven2/org/scala-lang/scala-reflect/<scala-version>/scala-reflect-<scala-version>.jar",
+          "file:///coursier-cache/https/repo1.maven.org/maven2/org/scala-lang/scala-library/<scala-version>/scala-library-<scala-version>.jar",
+          "file:///coursier-cache/https/repo1.maven.org/maven2/io/github/java-diff-utils/java-diff-utils/<java-diff-utils-version>/java-diff-utils-<java-diff-utils-version>.jar",
+          "file:///coursier-cache/https/repo1.maven.org/maven2/org/jline/jline/<jline-version>/jline-<jline-version>-jdk8.jar"
+        ],
+        "jvmBuildTarget": {
+          "javaHome": "java-home",
+          "javaVersion": "<java-version>"
+        }
+      }
+    },
     {
       "id": {
         "uri": "file:///workspace/hello-java"

integration/ide/bsp-server/src/BspServerTestUtil.scala

@@ -5,11 +5,13 @@ import com.google.gson.{Gson, GsonBuilder}
 import coursier.cache.CacheDefaults
 import mill.api.BuildInfo
 import mill.bsp.Constants
+import mill.testrunner.TestRunnerUtils
 import org.eclipse.{lsp4j => l}
+import org.eclipse.lsp4j.jsonrpc.services.JsonRequest
 
 import java.io.ByteArrayOutputStream
 import java.util.concurrent.atomic.AtomicInteger
-import java.util.concurrent.{ExecutorService, Executors, ThreadFactory}
+import java.util.concurrent.{CompletableFuture, ExecutorService, Executors, ThreadFactory}
 
 import scala.jdk.CollectionConverters._
 import scala.reflect.ClassTag
@@ -96,6 +98,50 @@ object BspServerTestUtil {
     }
   }
 
+  def compareLogWithSnapshot(
+      log: String,
+      snapshotPath: os.Path,
+      ignoreLine: String => Boolean = _ => false
+  ): Unit = {
+
+    val logLines = log.linesIterator.filterNot(ignoreLine).toVector
+    val snapshotLinesOpt = Option.when(os.exists(snapshotPath))(os.read.lines(snapshotPath))
+
+    val matches = snapshotLinesOpt match {
+      case Some(snapshotLines) =>
+        if (snapshotLines.length == logLines.length)
+          snapshotLines.iterator
+            .zip(logLines.iterator)
+            .zipWithIndex
+            .map {
+              case ((snapshotLine, logLine), lineIdx) =>
+                val cmp = TestRunnerUtils.matchesGlob(snapshotLine)
+                cmp(logLine) || {
+                  System.err.println(s"Line ${lineIdx + 1} differs:")
+                  System.err.println(s"  Expected: $snapshotLine")
+                  System.err.println(s"  Got: $logLine")
+                  false
+                }
+            }
+            .foldLeft(true)(_ && _)
+        else {
+          System.err.println(s"Expected ${snapshotLines.length} lines, got ${logLines.length}")
+          false
+        }
+      case None =>
+        System.err.println(s"$snapshotPath not found")
+        false
+    }
+
+    if (updateSnapshots) {
+      if (!matches) {
+        System.err.println(s"Updating $snapshotPath")
+        os.write.over(snapshotPath, logLines.mkString(System.lineSeparator()), createFolders = true)
+      }
+    } else
+      assert(matches)
+  }
+
   val bspJsonrpcPool: ExecutorService = Executors.newCachedThreadPool(
     new ThreadFactory {
       val counter = new AtomicInteger
@@ -108,11 +154,16 @@ object BspServerTestUtil {
   )
 
   trait MillBuildServer extends b.BuildServer with b.JvmBuildServer
-      with b.JavaBuildServer with b.ScalaBuildServer
+      with b.JavaBuildServer with b.ScalaBuildServer {
+    @JsonRequest("millTest/loggingTest")
+    def loggingTest(): CompletableFuture[Object]
+  }
 
   def withBspServer[T](
       workspacePath: os.Path,
-      millTestSuiteEnv: Map[String, String]
+      millTestSuiteEnv: Map[String, String],
+      bspLog: Option[(Array[Byte], Int) => Unit] = None,
+      client: b.BuildClient = DummyBuildClient
   )(f: (MillBuildServer, b.InitializeBuildResult) => T): T = {
 
     val bspMetadataFile = workspacePath / Constants.bspDir / s"${Constants.serverName}.json"
@@ -131,16 +182,19 @@ object BspServerTestUtil {
     val proc = os.proc(bspCommand).spawn(
       cwd = workspacePath,
       stderr =
-        if (outputOnErrorOnly)
+        if (bspLog.isDefined || outputOnErrorOnly)
           os.ProcessOutput { (bytes, len) =>
-            stderr.write(bytes, 0, len)
+            if (outputOnErrorOnly)
+              stderr.write(bytes, 0, len)
+            else
+              System.err.write(bytes, 0, len)
+            for (f <- bspLog)
+              f(bytes, len)
           }
         else os.Inherit,
       env = millTestSuiteEnv
     )
 
-    val client: b.BuildClient = DummyBuildClient
-
     var success = false
     try {
       val launcher = new l.jsonrpc.Launcher.Builder[MillBuildServer]