Cleanup stream handling in PrintLogger to try and avoid over-written …

…lines (#2428)

Right now, if we add a `println` inside `evaluateGroupCached` for
debugging purposes:

```
diff --git a/main/core/src/mill/eval/Evaluator.scala b/main/core/src/mill/eval/Evaluator.scala
index 6805efd41..1fe1e5b02 100644
--- a/main/core/src/mill/eval/Evaluator.scala
+++ b/main/core/src/mill/eval/Evaluator.scala
@@ -306,7 +306,7 @@ class Evaluator private (
       testReporter: TestReporter,
       logger: ColorLogger
   ): Evaluated = {
-
+    println("evaluateGroupCached")
     val externalInputsHash = scala.util.hashing.MurmurHash3.orderedHash(
       group.items.flatMap(_.inputs).filter(!group.contains(_))
         .flatMap(results(_).asSuccess.map(_.value._2))
```

It gets over-written by the ticker in the terminal and not reliably
shown:

```
$ rm -rf example/basic/1-hello-world/out && ./mill -i dev.run example/basic/1-hello-world -i run --text hello
evaluateGroupCached
[35/48] finalMainClassOpt
[36/48] finalMainClass
[37/48] resources
[38/48] localClasspath
[39/48] transitiveLocalClasspath
[40/48] runIvyDeps
[41/48] resolvedRunIvyDeps
[42/48] upstreamAssemblyClasspath
[43/48] runClasspath
[44/48] forkArgs
[45/48] forkEnv
[46/48] forkWorkingDir
[47/48] runUseArgsFile
[48/48] run
<h1>hello</h1>
```

With this PR, the `println` is reliably shown

```
$ rm -rf example/basic/1-hello-world/out && ./mill -i dev.run example/basic/1-hello-world -i run --text hello
evaluateGroupCached
[35/48] finalMainClassOpt
evaluateGroupCached
[36/48] finalMainClass
evaluateGroupCached
[37/48] resources
evaluateGroupCached
[38/48] localClasspath
evaluateGroupCached
[39/48] transitiveLocalClasspath
evaluateGroupCached
[40/48] runIvyDeps
evaluateGroupCached
[41/48] resolvedRunIvyDeps
evaluateGroupCached
[42/48] upstreamAssemblyClasspath
evaluateGroupCached
[43/48] runClasspath
evaluateGroupCached
[44/48] forkArgs
evaluateGroupCached
[45/48] forkEnv
evaluateGroupCached
[46/48] forkWorkingDir
evaluateGroupCached
[47/48] runUseArgsFile
evaluateGroupCached
[48/48] run
<h1>hello</h1>
```

The basic problem is that the `PrintLogger` uses its own internal
`printState` variable to keep track of what's been printed so far, and
whether it needs to put the next progress ticker entry on a new line,
but anything printed outside the evaluation of a target ends up
bypassing this logic and not properly recorded. Thus any debugging
`println`s you put inside Mill are prone to being over-written by the
ticker as your build progresses. Furthermore, anyone who ends up copying
or creating new `PrintLogger`s will have a different inconsistent
`printState`, which also can cause lines to be incorrectly overwritten.

This PR lifts the ticker `printState` variable out of the `printLogger`
and instantiates it in `MillMain.scala`, and immediately overrides all
System streams to make use of wrappers that correctly update this
`printLoggerState` as they print things. This ensures that all
`println`s throughout the Mill codebase will correctly interact with the
ticker, and your debug `println`s you scatter throughout Mill won't be
incorrectly over-written in the terminal

I also took the opportunity for some cleanups:

1. Broke out a `Util.withStreams` helper, that we can use in various
parts of the codebase to perform our stdout/stderr/stdin redirection in
a consistent way

2. Broke up `Loggers.scala` into a bunch of separate files, since it had
grown huge and unwieldy

3. Refactored `Logger` to use `SystemStreams` rather than passing around
the three streams separately

4. Removed `PrintLogger.infoStream`, which was not serving any real
purpose

The specific issue that is fixed here isn't easily covered by automated
tests, since it requires adding `println`s to the Mill codebase, which
is not something we can easily do in integration tests. The parts that
are easy to test (e.g. `println`s in target definitions) aren't
currently broken, so I didn't see the need to add tests for that. For
now I just tested this PR manually.

bsp/src/mill/bsp/BSP.scala

@@ -3,13 +3,13 @@ package mill.bsp
 import java.io.{InputStream, PrintStream}
 import scala.concurrent.{Await, Promise}
 import scala.concurrent.duration.Duration
-import mill.api.{Ctx, DummyInputStream, Logger, PathRef, Result}
+import mill.api.{Ctx, DummyInputStream, Logger, PathRef, Result, SystemStreams}
 import mill.{Agg, T, BuildInfo => MillBuildInfo}
 import mill.define.{Command, Discover, ExternalModule, Task}
 import mill.eval.Evaluator
 import mill.main.{BspServerHandle, BspServerResult, BspServerStarter}
 import mill.scalalib.{CoursierModule, Dep}
-import mill.util.{PrintLogger, SystemStreams}
+import mill.util.PrintLogger
 import os.Path
 
 object BSP extends ExternalModule with CoursierModule with BspServerStarter {
@@ -85,9 +85,12 @@ object BSP extends ExternalModule with CoursierModule with BspServerStarter {
       // This all goes to the BSP log file mill-bsp.stderr
       override def log: Logger = new Logger {
         override def colored: Boolean = false
-        override def errorStream: PrintStream = streams.err
-        override def outputStream: PrintStream = streams.err
-        override def inStream: InputStream = DummyInputStream
+
+        override def systemStreams: SystemStreams = new SystemStreams(
+          streams.err,
+          streams.err,
+          DummyInputStream
+        )
         override def info(s: String): Unit = streams.err.println(s)
         override def error(s: String): Unit = streams.err.println(s)
         override def ticker(s: String): Unit = streams.err.println(s)

bsp/src/mill/bsp/BspWorker.scala

@@ -5,7 +5,7 @@ import mill.api.{Ctx, PathRef, Result, internal}
 import mill.define.Task
 import mill.eval.Evaluator
 import mill.main.{BspServerHandle, BspServerResult}
-import mill.util.SystemStreams
+import mill.api.SystemStreams
 
 import java.io.{InputStream, PrintStream}
 import java.net.URL

bsp/worker/src/mill/bsp/worker/BspWorkerImpl.scala

@@ -7,7 +7,7 @@ import mill.bsp.{BSP, BspWorker, Constants}
 import mill.define.Task
 import mill.eval.Evaluator
 import mill.main.{BspServerHandle, BspServerResult}
-import mill.util.SystemStreams
+import mill.api.SystemStreams
 import org.eclipse.lsp4j.jsonrpc.Launcher
 
 import java.io.{InputStream, PrintStream, PrintWriter}

build.sc

@@ -573,6 +573,7 @@ object main extends MillModule {
     override def ivyDeps = Agg(
       Deps.osLib,
       Deps.upickle,
+      Deps.fansi,
       Deps.sbtTestInterface
     )
   }

integration/src/mill/integration/IntegrationTestSuite.scala

@@ -4,7 +4,8 @@ import mainargs.Flag
 import mill.MillCliConfig
 import mill.define.SelectMode
 import mill.runner.{MillBuildBootstrap, MillMain, RunnerState, Watching}
-import mill.util.SystemStreams
+import mill.api.SystemStreams
+import mill.util.PrintLogger
 import os.Path
 import utest._
 
@@ -42,66 +43,64 @@ abstract class IntegrationTestSuite extends TestSuite {
   var runnerState = RunnerState.empty
 
   private def runnerStdout(stdout: PrintStream, stderr: PrintStream, s: Seq[String]) = {
-
     val streams = new SystemStreams(stdout, stderr, stdIn)
-    val config = MillCliConfig(
-      debugLog = Flag(debugLog),
-      keepGoing = Flag(keepGoing),
-      disableTicker = Flag(disableTicker)
-    )
-    val logger = mill.runner.MillMain.getLogger(
-      streams,
-      config,
-      mainInteractive = false,
-      enableTicker = Some(false)
-    )
-
-    val (isSuccess, newRunnerState) = Watching.watchLoop(
-      logger = logger,
-      ringBell = config.ringBell.value,
-      watch = config.watch.value,
-      streams = streams,
-      setIdle = _ => (),
-      evaluate = (prevStateOpt: Option[RunnerState]) => {
-        MillMain.adjustJvmProperties(userSpecifiedProperties, sys.props.toMap)
-        new MillBuildBootstrap(
-          projectRoot = wd,
-          config = config,
-          env = Map.empty,
-          threadCount = threadCount,
-          targetsAndParams = s.toList,
-          prevRunnerState = runnerState,
-          logger = logger
-        ).evaluate()
-      }
-    )
+    mill.util.Util.withStreams(streams) {
+      val config = MillCliConfig(
+        debugLog = Flag(debugLog),
+        keepGoing = Flag(keepGoing),
+        disableTicker = Flag(disableTicker)
+      )
+      val logger = mill.runner.MillMain.getLogger(
+        streams,
+        config,
+        mainInteractive = false,
+        enableTicker = Some(false),
+        new PrintLogger.State()
+      )
 
-    runnerState = newRunnerState
+      val (isSuccess, newRunnerState) = Watching.watchLoop(
+        logger = logger,
+        ringBell = config.ringBell.value,
+        watch = config.watch.value,
+        streams = streams,
+        setIdle = _ => (),
+        evaluate = (prevStateOpt: Option[RunnerState]) => {
+          MillMain.adjustJvmProperties(userSpecifiedProperties, sys.props.toMap)
+          new MillBuildBootstrap(
+            projectRoot = wd,
+            config = config,
+            env = Map.empty,
+            threadCount = threadCount,
+            targetsAndParams = s.toList,
+            prevRunnerState = runnerState,
+            logger = logger
+          ).evaluate()
+        }
+      )
 
-    (isSuccess, newRunnerState)
+      runnerState = newRunnerState
+      (isSuccess, newRunnerState)
+    }
   }
 
   def eval(s: String*): Boolean = {
     if (integrationTestMode == "local") runnerStdout(System.out, System.err, s)._1
     else evalFork(os.Inherit, os.Inherit, s)
   }
 
+  class ByteArrayOutputPrintStreams() {
+    val byteArrayOutputStream = new ByteArrayOutputStream
+    val printStream = new PrintStream(byteArrayOutputStream)
+    def text() = byteArrayOutputStream.toString("UTF-8").linesIterator.mkString("\n")
+  }
+
   def evalStdout(s: String*): IntegrationTestSuite.EvalResult = {
     if (integrationTestMode == "local") {
-      val outputStream = new ByteArrayOutputStream
-      val errorStream = new ByteArrayOutputStream
-      val printOutStream = new PrintStream(outputStream)
-      val printErrStream = new PrintStream(errorStream)
-      val result = runnerStdout(printOutStream, printErrStream, s.toList)
-      val stdoutArray = outputStream.toByteArray
-      val stdout: Seq[String] =
-        if (stdoutArray.isEmpty) Seq.empty
-        else new String(stdoutArray).split('\n')
-      val stderrArray = errorStream.toByteArray
-      val stderr: Seq[String] =
-        if (stderrArray.isEmpty) Seq.empty
-        else new String(stderrArray).split('\n')
-      IntegrationTestSuite.EvalResult(result._1, stdout.mkString("\n"), stderr.mkString("\n"))
+      val outputStream = new ByteArrayOutputPrintStreams()
+      val errorStream = new ByteArrayOutputPrintStreams()
+      val result = runnerStdout(outputStream.printStream, errorStream.printStream, s.toList)
+
+      IntegrationTestSuite.EvalResult(result._1, outputStream.text(), errorStream.text())
     } else {
       val output = Seq.newBuilder[String]
       val error = Seq.newBuilder[String]

main/api/src/mill/api/Logger.scala

@@ -27,9 +27,11 @@ import java.io.{InputStream, PrintStream}
 trait Logger {
   def colored: Boolean
 
-  def errorStream: PrintStream
-  def outputStream: PrintStream
-  def inStream: InputStream
+  def systemStreams: SystemStreams
+
+  def errorStream: PrintStream = systemStreams.err
+  def outputStream: PrintStream = systemStreams.out
+  def inStream: InputStream = systemStreams.in
 
   def info(s: String): Unit
   def error(s: String): Unit

main/util/src/mill/util/SystemStreams.scala → main/api/src/mill/api/SystemStreams.scala

@@ -1,4 +1,4 @@
-package mill.util
+package mill.api
 
 import java.io.{InputStream, PrintStream}
 

main/util/test/src/mill/util/VersionTests.scala → main/api/test/src/mill/util/VersionTests.scala

@@ -1,4 +1,4 @@
-package mill.util
+package mill.api
 
 import utest.{assert, TestSuite, Tests, test}
 

main/core/src/mill/eval/Evaluator.scala

@@ -578,29 +578,17 @@ class Evaluator private (
           val out = System.out
           val in = System.in
           val err = System.err
-          try {
-            System.setIn(multiLogger.inStream)
-            System.setErr(multiLogger.errorStream)
-            System.setOut(multiLogger.outputStream)
-            Console.withIn(multiLogger.inStream) {
-              Console.withOut(multiLogger.outputStream) {
-                Console.withErr(multiLogger.errorStream) {
-                  try task.evaluate(args)
-                  catch {
-                    case NonFatal(e) =>
-                      mill.api.Result.Exception(
-                        e,
-                        new OuterStack(new Exception().getStackTrace.toIndexedSeq)
-                      )
-                  }
-                }
-              }
+          mill.util.Util.withStreams(multiLogger.systemStreams){
+            try task.evaluate(args)
+            catch {
+              case NonFatal(e) =>
+                mill.api.Result.Exception(
+                  e,
+                  new OuterStack(new Exception().getStackTrace.toIndexedSeq)
+                )
             }
-          } finally {
-            System.setErr(err)
-            System.setOut(out)
-            System.setIn(in)
           }
+
         }
 
       newResults(task) = for (v <- res) yield {
@@ -632,7 +620,7 @@ class Evaluator private (
           logger,
           // we always enable debug here, to get some more context in log files
           new FileLogger(logger.colored, path, debugEnabled = true),
-          logger.inStream,
+          logger.systemStreams.in,
           debugEnabled = logger.debugEnabled
         )
     }

main/src/mill/main/BspServerStarter.scala

@@ -1,7 +1,7 @@
 package mill.main
 
 import mill.eval.Evaluator
-import mill.util.SystemStreams
+import mill.api.SystemStreams
 
 import java.io.{InputStream, PrintStream}
 import scala.concurrent.Promise

main/src/mill/main/MainModule.scala

@@ -250,7 +250,7 @@ trait MainModule extends mill.Module {
         // When using `show`, redirect all stdout of the evaluated tasks so the
         // printed JSON is the only thing printed to stdout.
         evaluator.baseLogger match {
-          case p: PrintLogger => p.withOutStream(p.errStream)
+          case p: PrintLogger => p.withOutStream(p.errorStream)
           case l => l
         }
       ),
@@ -278,7 +278,7 @@ trait MainModule extends mill.Module {
         // When using `show`, redirect all stdout of the evaluated tasks so the
         // printed JSON is the only thing printed to stdout.
         evaluator.baseLogger match {
-          case p: PrintLogger => p.withOutStream(outStream = p.errStream)
+          case p: PrintLogger => p.withOutStream(outStream = p.errorStream)
           case l => l
         }
       ),

main/testkit/src/mill/testkit/MillTestkit.scala

@@ -1,15 +1,16 @@
 package mill.testkit
 
 import mill.define._
-import mill.api.Result
+import mill.api.{DummyInputStream, Result, SystemStreams}
 import mill.api.Result.OuterStack
 import mill.api.Strict.Agg
+
 import java.io.{InputStream, PrintStream}
 import mill.define.{Input, Task}
 import mill.eval.Evaluator
-import language.experimental.macros
-import mill.api.{DummyInputStream, Result}
+import mill.util.PrintLogger
 
+import language.experimental.macros
 import scala.collection.mutable
 
 trait MillTestKit {
@@ -81,12 +82,10 @@ trait MillTestKit {
       enableTicker = true,
       mill.util.Colors.Default.info,
       mill.util.Colors.Default.error,
-      outStream,
-      outStream,
-      outStream,
-      inStream,
+      new SystemStreams(outStream, outStream, inStream),
       debugEnabled = debugEnabled,
-      context = ""
+      context = "",
+      new PrintLogger.State()
     ) {
       val prefix = {
         val idx = fullName.value.lastIndexOf(".")

main/util/src/mill/util/AnsiNav.scala

@@ -0,0 +1,45 @@
+package mill.util
+
+import java.io.Writer
+
+class AnsiNav(output: Writer) {
+  def control(n: Int, c: Char) = output.write("\u001b[" + n + c)
+
+  /**
+   * Move up `n` squares
+   */
+  def up(n: Int) = if (n == 0) "" else control(n, 'A')
+
+  /**
+   * Move down `n` squares
+   */
+  def down(n: Int) = if (n == 0) "" else control(n, 'B')
+
+  /**
+   * Move right `n` squares
+   */
+  def right(n: Int) = if (n == 0) "" else control(n, 'C')
+
+  /**
+   * Move left `n` squares
+   */
+  def left(n: Int) = if (n == 0) "" else control(n, 'D')
+
+  /**
+   * Clear the screen
+   *
+   * n=0: clear from cursor to end of screen
+   * n=1: clear from cursor to start of screen
+   * n=2: clear entire screen
+   */
+  def clearScreen(n: Int) = control(n, 'J')
+
+  /**
+   * Clear the current line
+   *
+   * n=0: clear from cursor to end of line
+   * n=1: clear from cursor to start of line
+   * n=2: clear entire line
+   */
+  def clearLine(n: Int) = control(n, 'K')
+}

main/util/src/mill/util/ColorLogger.scala

@@ -0,0 +1,10 @@
+package mill.util
+
+import mill.api.Logger
+
+
+trait ColorLogger extends Logger {
+  def infoColor: fansi.Attrs
+  def errorColor: fansi.Attrs
+}
+

main/util/src/mill/util/DummyLogger.scala

@@ -0,0 +1,22 @@
+package mill.util
+
+import mill.api.{Logger, SystemStreams}
+
+import java.io.{ByteArrayInputStream, PrintStream}
+
+
+object DummyLogger extends Logger {
+  def colored = false
+
+  val systemStreams = new SystemStreams(
+    new PrintStream(_ => ()),
+    new PrintStream(_ => ()),
+    new ByteArrayInputStream(Array())
+  )
+
+  def info(s: String) = ()
+  def error(s: String) = ()
+  def ticker(s: String) = ()
+  def debug(s: String) = ()
+  override val debugEnabled: Boolean = false
+}