First experiment with new event-based logging framework.

Step sbt#1 - All loggers fire events.  Registered Appender is
used to write to disk when it can.

Places a new logging package in sbt.internals with the
gunky details of logging using disruptors for
efficient eventing between threads.

project/Sbt.scala

@@ -63,7 +63,7 @@ object Sbt extends Build {
   // Command line-related utilities.
   lazy val completeSub = testedBaseProject(utilPath / "complete", "Completion") dependsOn (collectionSub, controlSub, ioSub) settings (jline)
   // logging
-  lazy val logSub = testedBaseProject(utilPath / "log", "Logging") dependsOn (interfaceSub, processSub) settings (jline)
+  lazy val logSub = testedBaseProject(utilPath / "log", "Logging") dependsOn (interfaceSub, processSub) settings (jline, disruptor)
   // Relation
   lazy val relationSub = testedBaseProject(utilPath / "relation", "Relation") dependsOn (interfaceSub, processSub)
   // class file reader and analyzer

project/Util.scala

@@ -166,6 +166,7 @@ object Common {
   def lib(m: ModuleID) = libraryDependencies += m
   lazy val jlineDep = "jline" % "jline" % "2.11"
   lazy val jline = lib(jlineDep)
+  lazy val disruptor = lib("com.lmax" % "disruptor" % "3.2.1")
   lazy val ivy = lib("org.scala-sbt.ivy" % "ivy" % "2.4.0-sbt-d6fca11d63402c92e4167cdf2da91a660d043392")
   lazy val httpclient = lib("commons-httpclient" % "commons-httpclient" % "3.1")
   lazy val jsch = lib("com.jcraft" % "jsch" % "0.1.46" intransitive ())

util/log/src/main/scala/sbt/EventPassingLogger.scala

@@ -0,0 +1,40 @@
+package sbt
+
+/**
+ * Represents a logger that turns all calls into
+ *  events and sends them down the internal logger.
+ *
+ *  This wraps a pure "LogEvent" API and provides
+ *  sbt's "AbstractLogger".
+ */
+final class EventPassingLogger(
+    delegate: sbt.internals.logging.EventLogger,
+    override val ansiCodesSupported: Boolean = false) extends AbstractLogger {
+  override def setLevel(newLevel: Level.Value): Unit =
+    delegate fire new SetLevel(newLevel)
+
+  override def setSuccessEnabled(flag: Boolean): Unit =
+    delegate fire new SetSuccess(flag)
+
+  override def setTrace(level: Int): Unit =
+    delegate fire new SetTrace(level)
+
+  override def trace(t: => Throwable): Unit =
+    delegate fire new Trace(t)
+  override def success(message: => String): Unit =
+    delegate fire new Success(message)
+  override def log(level: Level.Value, message: => String): Unit =
+    delegate fire new Log(level, message)
+  // TODO - this should send the sequence directly to the other API for performance reasons.
+  override def logAll(events: Seq[LogEvent]): Unit =
+    events foreach delegate.fire
+  override def control(event: ControlEvent.Value, message: => String): Unit =
+    delegate fire new ControlEvent(event, message)
+
+  // Note: We do not support this aspect of the API.
+  // Here we just try to keep everything as open as possible, as configuration
+  // will be in the log-appender downstream.
+  override def getLevel: sbt.Level.Value = Level.Debug
+  override def getTrace: Int = 0
+  override def successEnabled: Boolean = true
+}

util/log/src/main/scala/sbt/LogEvent.scala

@@ -3,6 +3,11 @@
  */
 package sbt
 
+/**
+ * Represents an event fired from a logger.
+ *
+ * This is used to in both log buffering and in async-based loggers.
+ */
 sealed trait LogEvent extends NotNull
 final class Success(val msg: String) extends LogEvent
 final class Log(val level: Level.Value, val msg: String) extends LogEvent

util/log/src/main/scala/sbt/internals/logging/DisruptiveLogger.scala

@@ -0,0 +1,113 @@
+package sbt
+package internals
+package logging
+
+import com.lmax.disruptor.{
+  RingBuffer,
+  EventFactory,
+  PhasedBackoffWaitStrategy,
+  BlockingWaitStrategy,
+  EventHandler
+}
+import com.lmax.disruptor.dsl.{
+  Disruptor,
+  ProducerType
+}
+import java.util.concurrent.{
+  TimeUnit,
+  Executors
+}
+import java.util.concurrent.ThreadFactory
+
+/**
+ * Represents a log event cell in a ring buffer.
+ *  Here we insert/remove data.
+ */
+private[logging] class LogEventCell[LogTarget] {
+
+  private var eventOpt: Option[FullLogEvent[LogTarget]] = None
+
+  // Here we assume there is an event in a cell.
+  def get: FullLogEvent[LogTarget] = eventOpt.get
+  def set(e: FullLogEvent[LogTarget]): Unit = {
+    eventOpt = Some(e)
+  }
+
+}
+/** Represents the full logging information we send over our event queues. */
+private[logging] case class FullLogEvent[LogTarget](source: LogTarget, event: LogEvent)
+
+/**
+ * Internal implementation of loggers as simple event producers.
+ *
+ * TODO - Better log event, possibly including the "source"
+ */
+private[logging] class DisruptiveLogger[LogTarget](source: LogTarget, buffer: RingBuffer[LogEventCell[LogTarget]])
+    extends EventLogger {
+  /** Fires the given log event. */
+  def fire(event: LogEvent): Unit =
+    pushEvent(FullLogEvent(source, event))
+
+  private def pushEvent(event: FullLogEvent[LogTarget]): Boolean = {
+    // Note: we push any back-off strategy onto the disruptor lib
+    val idx = buffer.next()
+    try buffer.get(idx).set(event)
+    finally buffer.publish(idx)
+    true
+  }
+}
+
+/**
+ * A manager for creating loggers which feed their events through a disruptor into
+ *  a single appender thread, in control of all back-end files.
+ */
+private[logging] final class DisruptiveLogManager[LogTarget](name: String, appender: LogAppender[LogTarget]) extends LogManager[LogTarget] {
+
+  // TODO - All this setup should be configurable...
+  private val waitStrategy =
+    new PhasedBackoffWaitStrategy(
+      10, // spin timeout
+      100, // yield timeout
+      TimeUnit.NANOSECONDS,
+      new BlockingWaitStrategy() // Block when done.
+    )
+  private object cellFactory extends EventFactory[LogEventCell[LogTarget]] {
+    def newInstance: LogEventCell[LogTarget] = new LogEventCell
+  }
+  private val ringSize = 2048
+  private object namedThreadFactory extends ThreadFactory {
+    override def newThread(r: Runnable): Thread =
+      new Thread(r, s"log-appender-${name}")
+  }
+  private val executor = Executors.newSingleThreadExecutor(namedThreadFactory)
+  // Construct a disruptor (pattern) which will allow us to concurrently fire log events
+  // and handle them in a central location.
+  private val disruptor = new Disruptor(
+    cellFactory,
+    ringSize,
+    executor,
+    ProducerType.MULTI,
+    waitStrategy
+  )
+  disruptor.handleEventsWith(new EventHandler[LogEventCell[LogTarget]] {
+    def onEvent(event: LogEventCell[LogTarget], sequence: Long, endOfBatch: Boolean): Unit = {
+      appender.handleNext(event.get, endOfBatch)
+    }
+  })
+  // TODO - do this here?
+  disruptor.start()
+
+  // The buffer used to publish logs.
+  private[internals] val buffer = disruptor.getRingBuffer
+
+  // Public API which allows users to create loggers.
+  final def createLogger(target: LogTarget): EventLogger =
+    new DisruptiveLogger(target, buffer)
+
+  /** Closes all the resources we hold open*/
+  final def close(): Unit = {
+    disruptor.shutdown()
+    executor.shutdown()
+  }
+
+}

util/log/src/main/scala/sbt/internals/logging/EventLogger.scala

@@ -0,0 +1,12 @@
+package sbt
+package internals
+package logging
+
+/**
+ * Internal implementation of loggers as simple
+ *  event producers.
+ */
+trait EventLogger {
+  /** Fires the given log event. */
+  def fire(event: LogEvent): Unit
+}

util/log/src/main/scala/sbt/internals/logging/LogManager.scala

@@ -0,0 +1,39 @@
+package sbt
+package internals
+package logging
+
+/**
+ * This represents a factory for generating
+ *  logger instances that target some kind of backend.
+ */
+trait LogManager[LogTarget] extends java.io.Closeable {
+  /**
+   * Construct a new thread-safe logger which will log its events into
+   * the desired target.
+   */
+  def createLogger(target: LogTarget): EventLogger
+}
+object LogManager {
+  /** Factory function to create the default log manager for sbt projects. */
+  def apply[LogTarget](name: String, appender: LogAppender[LogTarget]): LogManager[LogTarget] =
+    disruptor(name, appender)
+
+  //TODO - disruptor specific config options
+  def disruptor[LogTarget](name: String, appender: LogAppender[LogTarget]): LogManager[LogTarget] =
+    new DisruptiveLogManager(name, appender)
+}
+
+/**
+ * A strategy for how to append logs to streams.
+ *
+ *  This will be used in a single-threaded context.
+ */
+private[sbt] trait LogAppender[LogTarget] extends java.io.Closeable {
+  /**
+   * Consume and do something useful with the next log event.
+   *
+   *  @param e The log event *and* the target for the log, i.e. which stream/file the info needs to go out.
+   *  @param endOfBatch  Represents whether this is the last log event from the current batch of blasted events.
+   */
+  def handleNext(e: FullLogEvent[LogTarget], endOfBatch: Boolean): Unit
+}

util/log/src/test/scala/LogGen.scala

@@ -0,0 +1,82 @@
+package sbt
+
+import org.scalacheck._
+import Arbitrary.{ arbitrary => arb, _ }
+import Gen.{ listOfN, oneOf }
+import Prop._
+
+object LogGen {
+  final val MaxLines = 100
+  final val MaxSegments = 10
+  /* The following are implicit generators to build up a write sequence.
+	* ToLog represents a written segment.  NewLine represents one of the possible
+	* newline separators.  A List[ToLog] represents a full line and always includes a
+	* final ToLog with a trailing '\n'.  Newline characters are otherwise not present in
+	* the `content` of a ToLog instance.*/
+
+  implicit lazy val arbOut: Arbitrary[Output] = Arbitrary(genOutput)
+  implicit lazy val arbLog: Arbitrary[ToLog] = Arbitrary(genLog)
+  implicit lazy val arbLine: Arbitrary[List[ToLog]] = Arbitrary(genLine)
+  implicit lazy val arbNewLine: Arbitrary[NewLine] = Arbitrary(genNewLine)
+  implicit lazy val arbLevel: Arbitrary[Level.Value] = Arbitrary(genLevel)
+
+  implicit def genLine(implicit logG: Gen[ToLog]): Gen[List[ToLog]] =
+    for (l <- listOf[ToLog](MaxSegments); last <- logG) yield (addNewline(last) :: l.filter(!_.content.isEmpty)).reverse
+
+  implicit def genLog(implicit content: Arbitrary[String], byChar: Arbitrary[Boolean]): Gen[ToLog] =
+    for (c <- content.arbitrary; by <- byChar.arbitrary) yield {
+      assert(c != null)
+      new ToLog(removeNewlines(c), by)
+    }
+
+  implicit lazy val genNewLine: Gen[NewLine] =
+    for (str <- oneOf("\n", "\r", "\r\n")) yield new NewLine(str)
+
+  implicit lazy val genLevel: Gen[Level.Value] =
+    oneOf(Level.values.toSeq)
+
+  implicit lazy val genOutput: Gen[Output] =
+    for (ls <- listOf[List[ToLog]](MaxLines); lv <- genLevel) yield new Output(ls, lv)
+
+  def removeNewlines(s: String) = s.replaceAll("""[\n\r]+""", "")
+  def addNewline(l: ToLog): ToLog =
+    new ToLog(l.content + "\n", l.byCharacter) // \n will be replaced by a random line terminator for all lines
+
+  def listOf[T](max: Int)(implicit content: Arbitrary[T]): Gen[List[T]] =
+    Gen.choose(0, max) flatMap { sz => listOfN(sz, content.arbitrary) }
+}
+
+/* Helper classes*/
+
+final class Output(val lines: List[List[ToLog]], val level: Level.Value) extends NotNull {
+  override def toString =
+    "Level: " + level + "\n" + lines.map(_.mkString).mkString("\n")
+}
+final class NewLine(val str: String) extends NotNull {
+  override def toString = Escape(str)
+}
+final class ToLog(val content: String, val byCharacter: Boolean) extends NotNull {
+  def contentOnly = Escape.newline(content, "")
+  override def toString = if (content.isEmpty) "" else "ToLog('" + Escape(contentOnly) + "', " + byCharacter + ")"
+}
+/** Defines some utility methods for escaping unprintable characters.*/
+object Escape {
+  /** Escapes characters with code less than 20 by printing them as unicode escapes.*/
+  def apply(s: String): String =
+    {
+      val builder = new StringBuilder(s.length)
+      for (c <- s) {
+        def escaped = pad(c.toInt.toHexString.toUpperCase, 4, '0')
+        if (c < 20) builder.append("\\u").append(escaped) else builder.append(c)
+      }
+      builder.toString
+    }
+  def pad(s: String, minLength: Int, extra: Char) =
+    {
+      val diff = minLength - s.length
+      if (diff <= 0) s else List.make(diff, extra).mkString("", "", s)
+    }
+  /** Replaces a \n character at the end of a string `s` with `nl`.*/
+  def newline(s: String, nl: String): String =
+    if (s.endsWith("\n")) s.substring(0, s.length - 1) + nl else s
+}