Debug logging in context

.drone.yml

@@ -4,9 +4,6 @@ matrix:
   TEST_BLOOP:
     - bin/sbt-ci.sh \
           "show version" \
-          "show dynverInstance" \
-          "show dynverGitDescribeOutput" \
-          "show dynverGitPreviousStableVersion" \
           "benchmarks/compile" \
           "jsonConfig210/test" \
           "jsonConfig211/test" \
@@ -21,6 +18,7 @@ matrix:
           "nativeBridge/test" \
           "jsBridge06/test" \
           "jsBridge10/test" \
+          "frontend/runMain bloop.util.CommandsDocGenerator --test" \
           "frontend/test" \
           "gradleBloop212/test" \
           "docs/makeSite"
@@ -37,9 +35,7 @@ matrix:
 
   PUBLISH_ARTIFACTS:
     - bin/sbt-ci-publish.sh \
-          "inspect version" \
-         "show dynverGitDescribeOutput" \
-         "show dynverGitPreviousStableVersion" \
+          "show version" \
           "set pgpPublicRing in Global := file(\"/drone/.gnupg/pubring.asc\")" \
           "set pgpSecretRing in Global := file(\"/drone/.gnupg/secring.asc\")" \
           "docs/ghpagesPushSite" \
@@ -102,13 +98,6 @@ pipeline:
       - git log --oneline --graph | head -n 20
       - . bin/set-up-dodo.sh # Source it because it exports variables
       - . bin/detect-community-build.sh # Source it because it exports variables
-      - git describe
-      - git tag -n9
-      - git fetch --tags --force
-      - git describe
-      - git tag -n9
-      - git describe --tags --abbrev=0 --always 9d7c2ce8e59131f8e7db9eaae5607a958e9370fe
-      - git --help
       - ${TEST_BLOOP}
 
   run_benchmarks_scripted:
@@ -166,9 +155,6 @@ pipeline:
         OS: linux
         OPS: basic
     commands:
-      - git tag -l
-      - git fetch --tags
-      - git tag -l
       - git log --oneline --graph | head -n 20
       # I have no idea why this has to be done manually... TODO: inspect why.
       - export DRONE_DIR="/drone"

backend/src/main/scala/bloop/DependencyResolution.scala

@@ -1,6 +1,6 @@
 package bloop
 
-import bloop.logging.Logger
+import bloop.logging.{ DebugFilter, Logger }
 import bloop.io.AbsolutePath
 
 import sbt.librarymanagement._
@@ -45,7 +45,7 @@ object DependencyResolution {
               version: String,
               logger: Logger,
               additionalRepositories: Seq[Repository] = Nil): Array[AbsolutePath] = {
-    logger.debug(s"Resolving $organization:$module:$version")
+    logger.debug(s"Resolving $organization:$module:$version")(DebugFilter.Compilation)
     val dependency = Dependency(Module(organization, module), version)
     val start = Resolution(Set(dependency))
     val repositories = {

backend/src/main/scala/bloop/ScalaInstance.scala

@@ -7,7 +7,7 @@ import java.nio.file.attribute.BasicFileAttributes
 import java.util.Properties
 
 import bloop.internal.build.BloopScalaInfo
-import bloop.logging.Logger
+import bloop.logging.{ DebugFilter, Logger }
 
 import scala.util.control.NonFatal
 
@@ -91,8 +91,9 @@ object ScalaInstance {
     val jarsKey = allJars.map(_.underlying).sortBy(_.toString).toList
     if (allJars.nonEmpty) {
       def newInstance = {
-        logger.debug(s"Cache miss for scala instance ${scalaOrg}:${scalaName}:${scalaVersion}.")
-        jarsKey.foreach(p => logger.debug(s"  => $p"))
+        logger.debug(s"Cache miss for scala instance ${scalaOrg}:${scalaName}:${scalaVersion}.")(
+          DebugFilter.Compilation)
+        jarsKey.foreach(p => logger.debug(s"  => $p")(DebugFilter.Compilation))
         new ScalaInstance(scalaOrg, scalaName, scalaVersion, allJars.map(_.toFile).toArray)
       }
 

backend/src/main/scala/bloop/io/Timer.scala

@@ -1,14 +1,14 @@
 package bloop.io
 
-import bloop.logging.Logger
+import bloop.logging.{ DebugFilter, Logger }
 
 object Timer {
   @inline def timed[T](logger: Logger, prefix: Option[String] = None)(op: => T): T = {
     val start = System.nanoTime()
     try op
     finally {
       val elapsed = (System.nanoTime() - start).toDouble / 1e6
-      logger.debug(s"Elapsed ${prefix.map(s => s"($s)").getOrElse("")}: $elapsed ms")
+      logger.debug(s"Elapsed ${prefix.map(s => s"($s)").getOrElse("")}: $elapsed ms")(DebugFilter.All)
     }
   }
 }

backend/src/main/scala/bloop/logging/BloopLogger.scala

@@ -1,43 +1,48 @@
 package bloop.logging
 
 import java.io.PrintStream
-import java.util.concurrent.atomic.AtomicInteger
 
 import scala.Console.{CYAN, GREEN, RED, RESET, YELLOW}
-import com.martiansoftware.nailgun.NGCommunicator
 
 /**
  * Creates a logger that writes to the given streams.
  *
- * @param name The name of this logger.
- * @param out  The stream to use to write `INFO` and `WARN` level messages.
- * @param err  The stream to use to write `FATAL`, `ERROR`, `DEBUG` and `TRACE` level messages.
- * @param colorOutput  print with or without color.
+ * @param name        The name of this logger.
+ * @param out         The stream to use to write `INFO` and `WARN` level messages.
+ * @param err         The stream to use to write `FATAL`, `ERROR`, `DEBUG` and `TRACE` level messages.
+ * @param colorOutput Print with or without color.
+ * @param debugFilter  Narrows logs to specified context.
  */
 final class BloopLogger(
     override val name: String,
     out: PrintStream,
     err: PrintStream,
     private val debugCount: Int,
-    colorOutput: Boolean
+    colorOutput: Boolean,
+    val debugFilter: DebugFilter
 ) extends Logger {
-
   override def ansiCodesSupported() = true
-  override def debug(msg: String): Unit = if (isVerbose) print(msg, printDebug)
+  override def debug(msg: String)(implicit ctx: DebugFilter): Unit =
+    if (isVerbose && debugFilter.isEnabledFor(ctx)) print(msg, printDebug)
   override def error(msg: String): Unit = print(msg, printError)
   override def warn(msg: String): Unit = print(msg, printWarning)
   override def trace(exception: Throwable): Unit = trace("", exception)
   override def info(msg: String): Unit = print(msg, printInfo)
 
+  override def asDiscrete: Logger = {
+    if (debugCount <= 0) this
+    else new BloopLogger(name, out, err, debugCount - 1, colorOutput, debugFilter)
+  }
+
   override def isVerbose: Boolean = debugCount > 0
-  override def asDiscrete: Logger =
-    if (debugCount > 0) new BloopLogger(name, out, err, debugCount - 1, colorOutput) else this
-  override def asVerbose: Logger = new BloopLogger(name, out, err, debugCount + 1, colorOutput)
+  override def asVerbose: Logger = {
+    new BloopLogger(name, out, err, debugCount + 1, colorOutput, debugFilter)
+  }
 
   @scala.annotation.tailrec
   private def trace(prefix: String, exception: Throwable): Unit = {
     if (isVerbose) {
-      print(prefix + exception.toString(), printTrace)
+      print(prefix + exception.toString, printTrace)
       exception.getStackTrace.foreach(ste => print("\t" + ste.toString, printTrace))
 
       val cause = exception.getCause
@@ -54,15 +59,14 @@ final class BloopLogger(
     out.println(line)
   }
 
-   private def colored(color: String, msg: String): String = {
-     if (colorOutput)
-        s"${RESET}${color}$msg${RESET}"
-     else
-       msg
-   }
-
+  private def colored(color: String, msg: String): String = {
+    if (colorOutput)
+      s"${RESET}${color}$msg${RESET}"
+    else
+      msg
+  }
 
-   private def printWarning(line: String): Unit = {
+  private def printWarning(line: String): Unit = {
     out.println(s"${colored(YELLOW, "[W]")} $line")
   }
 
@@ -74,8 +78,9 @@ final class BloopLogger(
     err.println(s"${colored(CYAN, "[T]")} $line")
   }
 
-  private def printDebug(line: String): Unit = {
-    err.println(s"${colored(GREEN, "[D]")} $line")
+  override private[logging] def printDebug(line: String): Unit = {
+    if (!isVerbose) ()
+    else err.println(s"${colored(GREEN, "[D]")} $line")
   }
 }
 
@@ -84,25 +89,38 @@ object BloopLogger {
   /**
    * Instantiates a new `BloopLogger` using the specified streams.
    *
-   * @param name      The name of the logger.
-   * @param out       The stream to use to write `INFO` and `WARN` level messages.
-   * @param err       The stream to use to write `FATAL`, `ERROR`, `DEBUG` and `TRACE` level messages.
-   * @param isVerbose Tells whether the logger is verbose or not.
+   * @param name       The name of the logger.
+   * @param out        The stream to use to write `INFO` and `WARN` level messages.
+   * @param err        The stream to use to write `FATAL`, `ERROR`, `DEBUG` and `TRACE` level messages.
+   * @param isVerbose  Tells whether the logger is verbose or not.
+   * @param filter     Filters that apply to all debug messages.
    * @return A `BloopLogger` whose output will be written in the specified streams.
    */
-  def at(name: String, out: PrintStream, err: PrintStream, isVerbose: Boolean, colorOutput: Boolean): BloopLogger =
-    new BloopLogger(name, out, err, if (isVerbose) 1 else 0, colorOutput )
+  def at(
+      name: String,
+      out: PrintStream,
+      err: PrintStream,
+      isVerbose: Boolean,
+      colorOutput: Boolean,
+      filter: DebugFilter
+  ): BloopLogger = new BloopLogger(name, out, err, if (isVerbose) 1 else 0, colorOutput, filter)
 
   /**
    * Instantiates a new `BloopLogger` using the specified streams.
    *
-   * @param name The name of the logger.
-   * @param out  The stream to use to write `INFO` and `WARN` level messages.
-   * @param err  The stream to use to write `FATAL`, `ERROR`, `DEBUG` and `TRACE` level messages.
+   * @param name       The name of the logger.
+   * @param out        The stream to use to write `INFO` and `WARN` level messages.
+   * @param err        The stream to use to write `FATAL`, `ERROR`, `DEBUG` and `TRACE` level messages.
+   * @param filter     Filters that apply to all debug messages.
    * @return A `BloopLogger` whose output will be written in the specified streams.
    */
-  def at(name: String, out: PrintStream, err: PrintStream, colorOutput: Boolean): BloopLogger =
-    at(name, out, err, false, colorOutput)
+  def at(
+      name: String,
+      out: PrintStream,
+      err: PrintStream,
+      colorOutput: Boolean,
+      filter: DebugFilter
+  ): BloopLogger = at(name, out, err, false, colorOutput, filter)
 
   /**
    * Instantiates a new `BloopLogger` that writes to stdout and stderr.
@@ -111,6 +129,6 @@ object BloopLogger {
    * @return A `BloopLogger` writing to stdout and stderr. Calling this method is equivalent to
    *         calling `at(name, System.out, System.err)`.
    */
-  def default(name: String): BloopLogger = at(name, System.out, System.err, false)
-
+  def default(name: String): BloopLogger =
+    at(name, System.out, System.err, false, DebugFilter.All)
 }

backend/src/main/scala/bloop/logging/DebugFilter.scala

@@ -0,0 +1,56 @@
+package bloop.logging
+
+sealed trait DebugFilter { self =>
+  private[logging] def isEnabledFor(other: DebugFilter): Boolean =
+    DebugFilter.checkSubsumption(self, other)
+}
+
+object DebugFilter {
+  final case object All extends DebugFilter
+  final case object Link extends DebugFilter
+  final case object Bsp extends DebugFilter
+  final case object Test extends DebugFilter
+  final case object Compilation extends DebugFilter
+  final case object FileWatching extends DebugFilter
+  final case class Aggregate(filters: List[DebugFilter]) extends DebugFilter
+
+  def toUniqueFilter(filters: List[DebugFilter]): DebugFilter = {
+    filters match {
+      case Nil => DebugFilter.All
+      case x :: Nil => DebugFilter.All
+      case xs =>
+        if (xs.contains(DebugFilter.All)) DebugFilter.All
+        else DebugFilter.Aggregate(xs)
+    }
+  }
+
+  /**
+   * Check if `filter1` subsumes `filter2`. Note that subsumption of debug filters is
+   * commutative so that if the debug filter of a logger is, say, `Compile`, the use
+   * sites can debug normal statements tagged as `DebugFilter.All`.
+   *
+   * @param filter1 The first filter to check for subsumption.
+   * @param filter2 The second filter to check for subsumption.
+   * @return Whether filter2 is subsumed in filter1 or viceversa.
+   */
+  private[bloop] def checkSubsumption(filter1: DebugFilter, filter2: DebugFilter): Boolean = {
+    def isFilterSubsumed(owner: DebugFilter, check: DebugFilter): Boolean = {
+      (owner, check) match {
+        case (DebugFilter.All, _) => true
+        case (_, DebugFilter.All) => true
+        case (ctx1, ctx2) if ctx1 == ctx2 => true
+        case _ => false
+      }
+    }
+
+    (filter1, filter2) match {
+      case (DebugFilter.Aggregate(filters), DebugFilter.Aggregate(filters2)) =>
+        filters.exists(filter => filters2.exists(filter2 => isFilterSubsumed(filter, filter2)))
+      case (DebugFilter.Aggregate(filters), target) =>
+        filters.exists(filter => isFilterSubsumed(filter, target))
+      case (target, DebugFilter.Aggregate(filters)) =>
+        filters.exists(filter => isFilterSubsumed(target, filter))
+      case (one, another) => isFilterSubsumed(one, another)
+    }
+  }
+}

backend/src/main/scala/bloop/logging/Logger.scala

@@ -1,7 +1,7 @@
 package bloop.logging
 import java.util.function.Supplier
 
-abstract class Logger extends xsbti.Logger with sbt.testing.Logger {
+abstract class Logger extends xsbti.Logger with BaseSbtLogger {
 
   /** The name of the logger */
   def name: String
@@ -15,11 +15,28 @@ abstract class Logger extends xsbti.Logger with sbt.testing.Logger {
   /** Return a logger that doesn't log verbose and debug events. */
   def asDiscrete: Logger
 
-  override def debug(msg: Supplier[String]): Unit = debug(msg.get())
+  /** Context for debug logging. */
+  def debugFilter: DebugFilter
+
+  /** Defines a debug function that takes a message and a filter from its use site. */
+  def debug(msg: String)(implicit ctx: DebugFilter): Unit
+
+  override def debug(msg: Supplier[String]): Unit = printDebug(msg.get())
   override def error(msg: Supplier[String]): Unit = error(msg.get())
   override def warn(msg: Supplier[String]): Unit = warn(msg.get())
   override def info(msg: Supplier[String]): Unit = info(msg.get)
   override def trace(exception: Supplier[Throwable]): Unit = trace(exception.get())
 
   def report(msg: String, t: Throwable): Unit = { error(msg); trace(t) }
 }
+
+/**
+  * Define an intermediary trait that extends sbt's Logger and overrides
+  * `debug` to help the linearized lookup find the `debug` that takes an
+  * implicit instead of sbt's `debug` that doesn't. This technique enables
+  * us avoid modifying the call-sites of `debug`.
+  */
+private[logging] trait BaseSbtLogger extends sbt.testing.Logger {
+  private[logging] def printDebug(line: String): Unit
+  override def debug(msg: String): Unit = printDebug(msg)
+}

backend/src/main/scala/bloop/logging/ProcessLogger.scala

@@ -21,7 +21,8 @@ class ProcessLogger(underlying: Logger, process: Process) {
   private[this] val processErr = process.getErrorStream
 
   def start(): Unit = {
-    underlying.debug("Starting to log output from process...")
+    implicit val ctx: DebugFilter = DebugFilter.All
+    underlying.printDebug("Starting to log output from process...")
     new StreamLogger(underlying.info, processOut).start()
     new StreamLogger(underlying.error, processErr).start()
   }

backend/src/main/scala/bloop/logging/Slf4jAdapter.scala

@@ -13,6 +13,7 @@ import org.slf4j.{Marker, Logger => Slf4jLogger}
  */
 final class Slf4jAdapter[L <: Logger](logger: L) extends Slf4jLogger {
   def underlying: L = logger
+  implicit val logContext: DebugFilter = logger.debugFilter
 
   override def getName: String = logger.name
   override def debug(msg: String): Unit = logger.debug(msg)