From 2e9805b9d01c6345214c14264c61692d9c21651c Mon Sep 17 00:00:00 2001 From: Ethan Atkins Date: Wed, 5 Aug 2020 11:23:35 -0700 Subject: [PATCH] Add internal multi logger implementation Prior to these changes, sbt was leaking large amounts of memory via log4j appenders. sbt has an unusual use case for log4j because it creates many ephemeral loggers while also having a global logger that is supposed to work for the duration of the sbt session. There is a lot of shared global state in log4j and properly cleaning up the ephemeral task appenders would break global logging. This commit fixes the behavior by introducing an alternate logging implementation. Users can still use the old log4j logging implementation but it will be off by default. The internal implementation is very simple: it just blocks the current thread and writes to all of the appenders. Nevertheless, I found the performance to be roughly identical to that of log4j in my sample project. As an experiment, I did the appending on a thread pool and got a significant performance improvement but I'll defer that to a later PR since parallel io is harder to reason about. Background: I was testing sbt performance in https://github.com/jtjeferreira/sbt-multi-module-sample and noticed that performance rapidly degraded after I ran compile a few times. I took a heap dump and it became obvious that sbt was leaking console appenders. Further investigation revealed that all of the leaking appenders in the project were coming from task streams. This made me think that the fix would be to track what loggers were created during task evaluation and clear them out when task evaluation completed. That almost worked except that log4j has an internal append only data structure containing logger names. Since we create unique logger names for each run, that internal data structure grew without bound. It looked like this could be worked around by creating a new log4j Configuration (where that data structure was stored) but while creating new configurations with each task runs did fix the leak, it also broke global logging, which was using a different configuration. At this point, I decided to write an alternate implementation of the appender api where I could be sure that the appenders were cleaned up without breaking global logging. Implementation: I made ConsoleAppender a trait and made it no longer extends log4j AbstractAppender. To do this, I had to remove the one log4j specific method, append(LogEvent). ConsoleAppender now has a method toLog4J that, in most cases, will return a log4j Appender that is almost identical to the Appenders that we previously used. To manage the loggers created during task evaluation, I introduce a new class, LoggerContext. The LoggerContext determines which logging backend to use and keeps track of what appenders and loggers have been created. We can create a fresh LoggerContext before each task evaluation and clear it out, cleaning up all of its resources after task evaluation concludes. In order to make this work, there were many places where we need to either pass in a LoggerContext or create a new one. The main magic is happening in the `next(State)` method in Main. This is where we create a new LoggerContext prior to command evaluation and clean it up after the evaluation completes. Users can toggle log4j using the new useLog4J key. They also can set the system property, sbt.log.uselog4j. The global logger will use the sbt internal implementation unless the system property is set. There are a fairly significant number of mima issues since I changed the type of ConsoleAppender. All of the mima changes were in the sbt.internal package so I think this should be ok. Effects: the memory leaks are gone. I successfully ran 5000 no-op compiles in the sbt-multi-module-sample above with no degradation of performace. There was a noticeable degradation after 30 no-op compiles before. During the refactor, I had to work on TestLogger and in doing so I also fixed https://github.com/sbt/sbt/issues/4480. This also should fix https://github.com/sbt/sbt/issues/4773 --- build.sbt | 13 ++ .../sbt/internal/util/BufferedLogger.scala | 68 +++++-- .../sbt/internal/util/ConsoleAppender.scala | 135 +++++++++---- .../sbt/internal/util/GlobalLogging.scala | 9 +- .../scala/sbt/internal/util/MainLogging.scala | 41 ++-- .../sbt/internal/util/ManagedLogger.scala | 34 ++-- .../src/main/scala/sbt/util/LogExchange.scala | 114 +++++------ .../main/scala/sbt/util/LoggerContext.scala | 189 ++++++++++++++++++ .../src/test/scala/ManagedLoggerSpec.scala | 41 ++-- .../sbt/internal/scripted/ScriptedTests.scala | 55 +++-- main/src/main/scala/sbt/Defaults.scala | 19 +- main/src/main/scala/sbt/Keys.scala | 12 +- main/src/main/scala/sbt/Main.scala | 5 +- main/src/main/scala/sbt/MainLoop.scala | 54 +++-- .../main/scala/sbt/internal/Continuous.scala | 12 +- .../DefaultBackgroundJobService.scala | 19 +- .../main/scala/sbt/internal/LogManager.scala | 97 +++++---- .../scala/sbt/internal/RelayAppender.scala | 41 +--- .../src/main/scala/sbt/internal/SysProp.scala | 1 + .../test/scala/sbt/RunFromSourceMain.scala | 28 ++- .../sbt/internal/testing/TestLogger.scala | 33 +-- 21 files changed, 694 insertions(+), 326 deletions(-) create mode 100644 internal/util-logging/src/main/scala/sbt/util/LoggerContext.scala diff --git a/build.sbt b/build.sbt index 11c3cf8d6..582a7ef93 100644 --- a/build.sbt +++ b/build.sbt @@ -410,6 +410,16 @@ lazy val utilLogging = (project in file("internal") / "util-logging") exclude[InheritedNewAbstractMethodProblem]( "sbt.internal.util.codec.JsonProtocol.ProgressEventFormat" ), + exclude[DirectMissingMethodProblem]("sbt.internal.util.MainAppender.*"), + exclude[IncompatibleMethTypeProblem]("sbt.internal.util.BufferedAppender.*"), + exclude[IncompatibleMethTypeProblem]("sbt.internal.util.ManagedLogger.this"), + exclude[IncompatibleMethTypeProblem]("sbt.internal.util.ManagedLogger.this"), + exclude[IncompatibleMethTypeProblem]("sbt.internal.util.MainAppender*"), + exclude[IncompatibleMethTypeProblem]("sbt.internal.util.GlobalLogging.*"), + exclude[IncompatibleSignatureProblem]("sbt.internal.util.GlobalLogging.*"), + exclude[IncompatibleSignatureProblem]("sbt.internal.util.MainAppender*"), + exclude[MissingTypesProblem]("sbt.internal.util.ConsoleAppender"), + exclude[MissingTypesProblem]("sbt.internal.util.BufferedAppender"), ), ) .configure(addSbtIO) @@ -1004,6 +1014,9 @@ lazy val mainProj = (project in file("main")) exclude[DirectMissingMethodProblem]("sbt.Classpaths.productsTask"), exclude[DirectMissingMethodProblem]("sbt.Classpaths.jarProductsTask"), exclude[DirectMissingMethodProblem]("sbt.StandardMain.cache"), + // internal logging apis, + exclude[IncompatibleSignatureProblem]("sbt.internal.LogManager*"), + exclude[MissingTypesProblem]("sbt.internal.RelayAppender"), ) ) .configure( diff --git a/internal/util-logging/src/main/scala/sbt/internal/util/BufferedLogger.scala b/internal/util-logging/src/main/scala/sbt/internal/util/BufferedLogger.scala index d4d1dc7fd..827cfa82f 100644 --- a/internal/util-logging/src/main/scala/sbt/internal/util/BufferedLogger.scala +++ b/internal/util-logging/src/main/scala/sbt/internal/util/BufferedLogger.scala @@ -9,10 +9,11 @@ package sbt.internal.util import sbt.util._ import scala.collection.mutable.ListBuffer -import org.apache.logging.log4j.core.{ LogEvent => XLogEvent, Appender } +import org.apache.logging.log4j.core.{ LogEvent => XLogEvent } import org.apache.logging.log4j.core.appender.AbstractAppender import org.apache.logging.log4j.core.layout.PatternLayout import java.util.concurrent.atomic.AtomicInteger +import java.util.concurrent.atomic.AtomicReference object BufferedAppender { def generateName: String = @@ -23,11 +24,8 @@ object BufferedAppender { def apply(delegate: Appender): BufferedAppender = apply(generateName, delegate) - def apply(name: String, delegate: Appender): BufferedAppender = { - val appender = new BufferedAppender(name, delegate) - appender.start - appender - } + def apply(name: String, delegate: Appender): BufferedAppender = + new BufferedAppender(name, delegate) } /** @@ -37,17 +35,52 @@ object BufferedAppender { * The logging level set at the time a message is originally logged is used, not * the level at the time 'play' is called. */ -class BufferedAppender private[BufferedAppender] (name: String, delegate: Appender) - extends AbstractAppender(name, null, PatternLayout.createDefaultLayout(), true, Array.empty) { +class BufferedAppender(override val name: String, delegate: Appender) extends Appender { + override def close(): Unit = log4j.get match { + case null => + case a => a.stop() + } + override private[sbt] def properties: ConsoleAppender.Properties = delegate.properties + override private[sbt] def suppressedMessage: SuppressedTraceContext => Option[String] = + delegate.suppressedMessage + private[this] val log4j = new AtomicReference[AbstractAppender] + override private[sbt] def toLog4J = log4j.get match { + case null => + val a = new AbstractAppender( + delegate.name + "-log4j", + null, + PatternLayout.createDefaultLayout(), + true, + Array.empty + ) { + start() + override def append(event: XLogEvent): Unit = { + if (recording) { + Util.ignoreResult(buffer.add(Left(event.toImmutable))) + } else { + delegate.toLog4J.append(event) + } + } + } + log4j.set(a) + a + case a => a + } - private[this] val buffer = new ListBuffer[XLogEvent] + private[this] val buffer = + new java.util.Vector[Either[XLogEvent, (Level.Value, Option[String], Option[ObjectEvent[_]])]] private[this] var recording = false - def append(event: XLogEvent): Unit = { - if (recording) { - buffer += event.toImmutable - } else delegate.append(event) - () + override def appendLog(level: Level.Value, message: => String): Unit = { + if (recording) Util.ignoreResult(buffer.add(Right((level, Some(message), None)))) + else delegate.appendLog(level, message) + } + override private[sbt] def appendObjectEvent[T]( + level: Level.Value, + message: => ObjectEvent[T] + ): Unit = { + if (recording) Util.ignoreResult(buffer.add(Right(((level, None, Some(message)))))) + else delegate.appendObjectEvent(level, message) } /** Enables buffering. */ @@ -80,8 +113,11 @@ class BufferedAppender private[BufferedAppender] (name: String, delegate: Append */ def play(): Unit = synchronized { - buffer.toList foreach { - delegate.append + buffer.forEach { + case Right((l, Some(m), _)) => delegate.appendLog(l, m) + case Right((l, _, Some(oe))) => delegate.appendObjectEvent(l, oe) + case Left(x) => delegate.toLog4J.append(x) + case _ => } buffer.clear() } diff --git a/internal/util-logging/src/main/scala/sbt/internal/util/ConsoleAppender.scala b/internal/util-logging/src/main/scala/sbt/internal/util/ConsoleAppender.scala index c6eac168a..d8230c95a 100644 --- a/internal/util-logging/src/main/scala/sbt/internal/util/ConsoleAppender.scala +++ b/internal/util-logging/src/main/scala/sbt/internal/util/ConsoleAppender.scala @@ -13,11 +13,14 @@ import java.nio.channels.ClosedChannelException import java.util.concurrent.atomic.{ AtomicBoolean, AtomicInteger } import org.apache.logging.log4j.core.appender.AbstractAppender -import org.apache.logging.log4j.core.{ LogEvent => XLogEvent } +import org.apache.logging.log4j.core.{ Appender => XAppender, LogEvent => XLogEvent } import org.apache.logging.log4j.message.{ Message, ObjectMessage, ReusableObjectMessage } import org.apache.logging.log4j.{ Level => XLevel } import sbt.internal.util.ConsoleAppender._ import sbt.util._ +import org.apache.logging.log4j.core.AbstractLogEvent +import org.apache.logging.log4j.message.StringFormatterMessageFactory +import java.util.concurrent.atomic.AtomicReference object ConsoleLogger { // These are provided so other modules do not break immediately. @@ -80,7 +83,7 @@ class ConsoleLogger private[ConsoleLogger] ( suppressedMessage: SuppressedTraceContext => Option[String] ) extends BasicLogger { - private[sbt] val appender: ConsoleAppender = + private[sbt] val appender: Appender = ConsoleAppender(generateName(), out, ansiCodesSupported, useFormat, suppressedMessage) override def control(event: ControlEvent.Value, message: => String): Unit = @@ -117,12 +120,12 @@ object ConsoleAppender { private[this] val showProgressHolder: AtomicBoolean = new AtomicBoolean(false) def setShowProgress(b: Boolean): Unit = showProgressHolder.set(b) def showProgress: Boolean = showProgressHolder.get - private[ConsoleAppender] trait Properties { + private[sbt] trait Properties { def isAnsiSupported: Boolean def isColorEnabled: Boolean def out: ConsoleOut } - object Properties { + private[sbt] object Properties { def from(terminal: Terminal): Properties = new Properties { override def isAnsiSupported: Boolean = terminal.isAnsiSupported override def isColorEnabled: Boolean = terminal.isColorEnabled @@ -187,7 +190,7 @@ object ConsoleAppender { * * @return A new `ConsoleAppender` that writes to standard output. */ - def apply(): ConsoleAppender = apply(ConsoleOut.systemOut) + def apply(): Appender = apply(ConsoleOut.systemOut) /** * A new `ConsoleAppender` that appends log message to `out`. @@ -195,7 +198,7 @@ object ConsoleAppender { * @param out Where to write messages. * @return A new `ConsoleAppender`. */ - def apply(out: PrintStream): ConsoleAppender = apply(ConsoleOut.printStreamOut(out)) + def apply(out: PrintStream): Appender = apply(ConsoleOut.printStreamOut(out)) /** * A new `ConsoleAppender` that appends log messages to `out`. @@ -203,7 +206,7 @@ object ConsoleAppender { * @param out Where to write messages. * @return A new `ConsoleAppender`. */ - def apply(out: PrintWriter): ConsoleAppender = apply(ConsoleOut.printWriterOut(out)) + def apply(out: PrintWriter): Appender = apply(ConsoleOut.printWriterOut(out)) /** * A new `ConsoleAppender` that writes to `out`. @@ -211,7 +214,7 @@ object ConsoleAppender { * @param out Where to write messages. * @return A new `ConsoleAppender that writes to `out`. */ - def apply(out: ConsoleOut): ConsoleAppender = apply(generateName(), out) + def apply(out: ConsoleOut): Appender = apply(generateName(), out) /** * A new `ConsoleAppender` identified by `name`, and that writes to standard output. @@ -219,7 +222,7 @@ object ConsoleAppender { * @param name An identifier for the `ConsoleAppender`. * @return A new `ConsoleAppender` that writes to standard output. */ - def apply(name: String): ConsoleAppender = apply(name, ConsoleOut.systemOut) + def apply(name: String): Appender = apply(name, ConsoleOut.systemOut) /** * A new `ConsoleAppender` identified by `name`, and that writes to `out`. @@ -228,7 +231,7 @@ object ConsoleAppender { * @param out Where to write messages. * @return A new `ConsoleAppender` that writes to `out`. */ - def apply(name: String, out: ConsoleOut): ConsoleAppender = apply(name, out, formatEnabledInEnv) + def apply(name: String, out: ConsoleOut): Appender = apply(name, out, formatEnabledInEnv) /** * A new `ConsoleAppender` identified by `name`, and that writes to `out`. @@ -242,7 +245,7 @@ object ConsoleAppender { name: String, out: ConsoleOut, suppressedMessage: SuppressedTraceContext => Option[String] - ): ConsoleAppender = + ): Appender = apply(name, out, formatEnabledInEnv, formatEnabledInEnv, suppressedMessage) /** @@ -253,7 +256,7 @@ object ConsoleAppender { * @param useFormat `true` to enable format (color, bold, etc.), `false` to remove formatting. * @return A new `ConsoleAppender` that writes to `out`. */ - def apply(name: String, out: ConsoleOut, useFormat: Boolean): ConsoleAppender = + def apply(name: String, out: ConsoleOut, useFormat: Boolean): Appender = apply(name, out, useFormat || formatEnabledInEnv, useFormat, noSuppressedMessage) /** @@ -263,10 +266,8 @@ object ConsoleAppender { * @param terminal The terminal to which this appender corresponds * @return A new `ConsoleAppender` that writes to `out`. */ - def apply(name: String, terminal: Terminal): ConsoleAppender = { - val appender = new ConsoleAppender(name, Properties.from(terminal), noSuppressedMessage) - appender.start() - appender + def apply(name: String, terminal: Terminal): Appender = { + new ConsoleAppender(name, Properties.from(terminal), noSuppressedMessage) } /** @@ -281,10 +282,8 @@ object ConsoleAppender { name: String, terminal: Terminal, suppressedMessage: SuppressedTraceContext => Option[String] - ): ConsoleAppender = { - val appender = new ConsoleAppender(name, Properties.from(terminal), suppressedMessage) - appender.start() - appender + ): Appender = { + new ConsoleAppender(name, Properties.from(terminal), suppressedMessage) } /** @@ -303,10 +302,12 @@ object ConsoleAppender { ansiCodesSupported: Boolean, useFormat: Boolean, suppressedMessage: SuppressedTraceContext => Option[String] - ): ConsoleAppender = { - val appender = new ConsoleAppender(name, out, ansiCodesSupported, useFormat, suppressedMessage) - appender.start - appender + ): Appender = { + new ConsoleAppender( + name, + Properties.from(out, ansiCodesSupported, useFormat), + suppressedMessage + ) } /** @@ -356,18 +357,38 @@ object ConsoleAppender { * * This logger is not thread-safe. */ -class ConsoleAppender private[ConsoleAppender] ( - name: String, - properties: Properties, - suppressedMessage: SuppressedTraceContext => Option[String] -) extends AbstractAppender(name, null, LogExchange.dummyLayout, true, Array.empty) { - def this( - name: String, - out: ConsoleOut, - ansiCodesSupported: Boolean, - useFormat: Boolean, - suppressedMessage: SuppressedTraceContext => Option[String] - ) = this(name, Properties.from(out, ansiCodesSupported, useFormat), suppressedMessage) +class ConsoleAppender( + override private[sbt] val name: String, + override private[sbt] val properties: Properties, + override private[sbt] val suppressedMessage: SuppressedTraceContext => Option[String] +) extends Appender { + private[this] val log4j = new AtomicReference[XAppender](null) + override private[sbt] lazy val toLog4J = log4j.get match { + case null => + log4j.synchronized { + log4j.get match { + case null => + val l = new Log4JConsoleAppender(name, properties, suppressedMessage, { event => + val level = ConsoleAppender.toLevel(event.getLevel) + val message = event.getMessage + try appendMessage(level, message) + catch { case _: ClosedChannelException => } + }) + log4j.set(l) + l + case l => l + } + } + } + override def close(): Unit = log4j.get match { + case null => + case a => a.stop() + } +} +trait Appender extends AutoCloseable { + private[sbt] def name: String + private[sbt] def properties: Properties + private[sbt] def suppressedMessage: SuppressedTraceContext => Option[String] import scala.Console.{ BLUE, GREEN, RED, YELLOW } private[util] def out: ConsoleOut = properties.out @@ -392,12 +413,7 @@ class ConsoleAppender private[ConsoleAppender] ( */ def getTrace: Int = synchronized { traceEnabledVar } - override def append(event: XLogEvent): Unit = { - val level = ConsoleAppender.toLevel(event.getLevel) - val message = event.getMessage - try appendMessage(level, message) - catch { case _: ClosedChannelException => } - } + private[sbt] def toLog4J: XAppender /** * Logs the stack trace of `t`, possibly shortening it. @@ -497,7 +513,7 @@ class ConsoleAppender private[ConsoleAppender] ( out.println(toWrite) } - private def appendMessage(level: Level.Value, msg: Message): Unit = + private[util] def appendMessage(level: Level.Value, msg: Message): Unit = msg match { case o: ObjectMessage => appendMessageContent(level, o.getParameter) case o: ReusableObjectMessage => appendMessageContent(level, o.getParameter) @@ -550,6 +566,39 @@ class ConsoleAppender private[ConsoleAppender] ( case _ => Vector(o.toString) foreach { appendLog(level, _) } } } + private[sbt] def appendObjectEvent[T](level: Level.Value, message: => ObjectEvent[T]): Unit = + appendMessageContent(level, message) + +} +private[internal] class Log4JConsoleAppender( + override private[sbt] val name: String, + override private[sbt] val properties: Properties, + override private[sbt] val suppressedMessage: SuppressedTraceContext => Option[String], + appendEvent: XLogEvent => Unit, +) extends AbstractAppender(name, null, LogExchange.dummyLayout, true, Array.empty) + with Appender { + start() + override def close(): Unit = stop() + override private[sbt] def toLog4J: XAppender = this + override def append(event: XLogEvent): Unit = appendEvent(event) +} +private[sbt] class ConsoleAppenderFromLog4J( + override private[sbt] val name: String, + override private[sbt] val properties: Properties, + override private[sbt] val suppressedMessage: SuppressedTraceContext => Option[String], + val delegate: XAppender, +) extends Appender { + def this(name: String, delegate: XAppender) = + this(name, Properties.from(Terminal.get), _ => None, delegate) + override def close(): Unit = delegate.stop() + private[sbt] def toLog4J: XAppender = delegate + override def appendLog(level: sbt.util.Level.Value, message: => String): Unit = { + delegate.append(new AbstractLogEvent { + override def getLevel(): XLevel = ConsoleAppender.toXLevel(level) + override def getMessage(): Message = + StringFormatterMessageFactory.INSTANCE.newMessage(message.toString, Array.empty) + }) + } } final class SuppressedTraceContext(val traceLevel: Int, val useFormat: Boolean) diff --git a/internal/util-logging/src/main/scala/sbt/internal/util/GlobalLogging.scala b/internal/util-logging/src/main/scala/sbt/internal/util/GlobalLogging.scala index 8ecef1db7..9be015da7 100644 --- a/internal/util-logging/src/main/scala/sbt/internal/util/GlobalLogging.scala +++ b/internal/util-logging/src/main/scala/sbt/internal/util/GlobalLogging.scala @@ -9,7 +9,6 @@ package sbt.internal.util import sbt.util._ import java.io.{ File, PrintWriter } -import org.apache.logging.log4j.core.Appender /** * Provides the current global logging configuration. @@ -25,7 +24,7 @@ final case class GlobalLogging( console: ConsoleOut, backed: Appender, backing: GlobalLogBacking, - newAppender: (ManagedLogger, PrintWriter, GlobalLogBacking) => GlobalLogging + newAppender: (ManagedLogger, PrintWriter, GlobalLogBacking, LoggerContext) => GlobalLogging ) final case class GlobalLogging1( @@ -78,14 +77,14 @@ object GlobalLogging { } def initial( - newAppender: (ManagedLogger, PrintWriter, GlobalLogBacking) => GlobalLogging, + newAppender: (ManagedLogger, PrintWriter, GlobalLogBacking, LoggerContext) => GlobalLogging, newBackingFile: => File, console: ConsoleOut ): GlobalLogging = { val loggerName = generateName - val log = LogExchange.logger(loggerName) + val log = LoggerContext.globalContext.logger(loggerName, None, None) val appender = ConsoleAppender(ConsoleAppender.generateName, console) - LogExchange.bindLoggerAppenders(loggerName, List(appender -> Level.Info)) + LoggerContext.globalContext.addAppender(loggerName, appender -> Level.Info) GlobalLogging(log, console, appender, GlobalLogBacking(newBackingFile), newAppender) } } diff --git a/internal/util-logging/src/main/scala/sbt/internal/util/MainLogging.scala b/internal/util-logging/src/main/scala/sbt/internal/util/MainLogging.scala index b58fd97d2..d5573b6dc 100644 --- a/internal/util-logging/src/main/scala/sbt/internal/util/MainLogging.scala +++ b/internal/util-logging/src/main/scala/sbt/internal/util/MainLogging.scala @@ -9,7 +9,6 @@ package sbt.internal.util import sbt.util._ import java.io.PrintWriter -import org.apache.logging.log4j.core.Appender object MainAppender { import java.util.concurrent.atomic.AtomicInteger @@ -17,38 +16,36 @@ object MainAppender { "GlobalBacking" + generateId.incrementAndGet private val generateId: AtomicInteger = new AtomicInteger - def multiLogger(log: ManagedLogger, config: MainAppenderConfig): ManagedLogger = { + def multiLogger( + log: ManagedLogger, + config: MainAppenderConfig, + context: LoggerContext + ): ManagedLogger = { import config._ // TODO // backed setTrace backingTrace // multi: Logger - LogExchange.unbindLoggerAppenders(log.name) - LogExchange.bindLoggerAppenders( - log.name, - (consoleOpt.toList map { appender => - appender match { - case a: ConsoleAppender => - a.setTrace(screenTrace) - case _ => () - } - appender -> screenLevel - }) ::: - List(backed -> backingLevel) ::: - (extra map { x => - (x -> Level.Info) - }) - ) + context.clearAppenders(log.name) + consoleOpt match { + case Some(a: ConsoleAppender) => + a.setTrace(screenTrace) + context.addAppender(log.name, a -> screenLevel) + case _ => + } + context.addAppender(log.name, backed -> backingLevel) + extra.foreach(a => context.addAppender(log.name, a -> Level.Info)) log } def globalDefault( console: ConsoleOut - ): (ManagedLogger, PrintWriter, GlobalLogBacking) => GlobalLogging = { - lazy val newAppender: (ManagedLogger, PrintWriter, GlobalLogBacking) => GlobalLogging = - (log, writer, backing) => { + ): (ManagedLogger, PrintWriter, GlobalLogBacking, LoggerContext) => GlobalLogging = { + lazy val newAppender + : (ManagedLogger, PrintWriter, GlobalLogBacking, LoggerContext) => GlobalLogging = + (log, writer, backing, lc) => { val backed: Appender = defaultBacked(generateGlobalBackingName)(writer) - val full = multiLogger(log, defaultMultiConfig(Option(console), backed, Nil)) + val full = multiLogger(log, defaultMultiConfig(Option(console), backed, Nil), lc) GlobalLogging(full, console, backed, backing, newAppender) } newAppender diff --git a/internal/util-logging/src/main/scala/sbt/internal/util/ManagedLogger.scala b/internal/util-logging/src/main/scala/sbt/internal/util/ManagedLogger.scala index 67aefeb52..21e2bbfa6 100644 --- a/internal/util-logging/src/main/scala/sbt/internal/util/ManagedLogger.scala +++ b/internal/util-logging/src/main/scala/sbt/internal/util/ManagedLogger.scala @@ -7,13 +7,16 @@ package sbt.internal.util -import org.apache.logging.log4j.{ Logger => XLogger } -import org.apache.logging.log4j.message.ObjectMessage import sbt.internal.util.codec.JsonProtocol._ import sbt.util._ import scala.reflect.runtime.universe.TypeTag import sjsonnew.JsonFormat +private[sbt] trait MiniLogger { + def log[T](level: Level.Value, message: ObjectEvent[T]): Unit + def log(level: Level.Value, message: => String): Unit +} + /** * Delegates log events to the associated LogExchange. */ @@ -21,19 +24,21 @@ class ManagedLogger( val name: String, val channelName: Option[String], val execId: Option[String], - xlogger: XLogger, - terminal: Option[Terminal] + xlogger: MiniLogger, + terminal: Option[Terminal], + private[sbt] val context: LoggerContext, ) extends Logger { - def this(name: String, channelName: Option[String], execId: Option[String], xlogger: XLogger) = - this(name, channelName, execId, xlogger, None) + def this( + name: String, + channelName: Option[String], + execId: Option[String], + xlogger: MiniLogger + ) = + this(name, channelName, execId, xlogger, None, LoggerContext.globalContext) override def trace(t: => Throwable): Unit = logEvent(Level.Error, TraceEvent("Error", t, channelName, execId)) - override def log(level: Level.Value, message: => String): Unit = { - xlogger.log( - ConsoleAppender.toXLevel(level), - new ObjectMessage(StringEvent(level.toString, message, channelName, execId)) - ) - } + override def log(level: Level.Value, message: => String): Unit = + xlogger.log(level, message) // send special event for success since it's not a real log level override def success(message: => String): Unit = { @@ -84,10 +89,7 @@ class ManagedLogger( val v: A = event // println("logEvent " + tag.key) val entry: ObjectEvent[A] = ObjectEvent(level, v, channelName, execId, tag.key) - xlogger.log( - ConsoleAppender.toXLevel(level), - new ObjectMessage(entry) - ) + xlogger.log(level, entry) } @deprecated("No longer used.", "1.0.0") diff --git a/internal/util-logging/src/main/scala/sbt/util/LogExchange.scala b/internal/util-logging/src/main/scala/sbt/util/LogExchange.scala index 90e6cc39f..9c5d3c34a 100644 --- a/internal/util-logging/src/main/scala/sbt/util/LogExchange.scala +++ b/internal/util-logging/src/main/scala/sbt/util/LogExchange.scala @@ -7,64 +7,71 @@ package sbt.util -import sbt.internal.util._ +import java.util.concurrent.ConcurrentHashMap import org.apache.logging.log4j.{ LogManager => XLogManager, Level => XLevel } -import org.apache.logging.log4j.core._ -import org.apache.logging.log4j.core.appender.AsyncAppender +import org.apache.logging.log4j.core.{ Appender => XAppender, LoggerContext => XLoggerContext } import org.apache.logging.log4j.core.config.{ AppenderRef, LoggerConfig } import org.apache.logging.log4j.core.layout.PatternLayout -import scala.collection.JavaConverters._ +import sbt.internal.util._ import scala.collection.concurrent import sjsonnew.JsonFormat +import org.apache.logging.log4j.core.appender.AsyncAppender // http://logging.apache.org/log4j/2.x/manual/customconfig.html // https://logging.apache.org/log4j/2.x/log4j-core/apidocs/index.html sealed abstract class LogExchange { - private[sbt] lazy val context: LoggerContext = init() - private[sbt] lazy val builtInStringCodecs: Unit = initStringCodecs() - private[sbt] lazy val asyncStdout: AsyncAppender = buildAsyncStdout + private[sbt] lazy val context: XLoggerContext = init() private[sbt] val stringCodecs: concurrent.Map[String, ShowLines[_]] = concurrent.TrieMap() + private[sbt] val builtInStringCodecs: Unit = initStringCodecs() + private[util] val configs = new ConcurrentHashMap[String, LoggerConfig] + private[util] def addConfig(name: String, config: LoggerConfig): Unit = + Util.ignoreResult(configs.putIfAbsent(name, config)) + private[util] def removeConfig(name: String): Option[LoggerConfig] = Option(configs.remove(name)) + @deprecated("Use LoggerContext to create loggers", "1.4.0") def logger(name: String): ManagedLogger = logger(name, None, None) - def logger(name: String, channelName: Option[String], execId: Option[String]): ManagedLogger = { - val _ = context - val codecs = builtInStringCodecs - val ctx = XLogManager.getContext(false) match { case x: LoggerContext => x } - val config = ctx.getConfiguration - val loggerConfig = LoggerConfig.createLogger( - false, - XLevel.DEBUG, - name, - // disable the calculation of caller location as it is very expensive - // https://issues.apache.org/jira/browse/LOG4J2-153 - "false", - Array[AppenderRef](), - null, - config, - null - ) - config.addLogger(name, loggerConfig) - ctx.updateLoggers - val logger = ctx.getLogger(name) - new ManagedLogger(name, channelName, execId, logger, Some(Terminal.get)) - } + @deprecated("Use LoggerContext to create loggers", "1.4.0") + def logger(name: String, channelName: Option[String], execId: Option[String]): ManagedLogger = + LoggerContext.globalContext.logger(name, channelName, execId) + @deprecated("Use LoggerContext to unbind appenders", "1.4.0") def unbindLoggerAppenders(loggerName: String): Unit = { - val lc = loggerConfig(loggerName) - lc.getAppenders.asScala foreach { - case (k, v) => lc.removeAppender(k) + LoggerContext.globalContext.clearAppenders(loggerName) + } + @deprecated("Use LoggerContext to bind appenders", "1.4.0") + def bindLoggerAppenders( + loggerName: String, + appenders: List[(XAppender, Level.Value)] + ): Unit = { + appenders.foreach { + case (a, l) => + LoggerContext.globalContext + .addAppender(loggerName, new ConsoleAppenderFromLog4J(loggerName, a) -> l) } } - def bindLoggerAppenders(loggerName: String, appenders: List[(Appender, Level.Value)]): Unit = { - val lc = loggerConfig(loggerName) - appenders foreach { - case (x, lv) => lc.addAppender(x, ConsoleAppender.toXLevel(lv), null) - } - } - def loggerConfig(loggerName: String): LoggerConfig = { - val ctx = XLogManager.getContext(false) match { case x: LoggerContext => x } + @deprecated("unused", "1.4.0") + def loggerConfig(loggerName: String): LoggerConfig = configs.get(loggerName) + + @deprecated("unused", "1.4.0") + lazy val asyncStdout = buildAsyncStdout + @deprecated("unused", "1.4.0") + private[sbt] def buildAsyncStdout: AsyncAppender = { + val ctx = XLogManager.getContext(false) match { case x: XLoggerContext => x } val config = ctx.getConfiguration - config.getLoggerConfig(loggerName) + val appender = ConsoleAppender("Stdout").toLog4J + // CustomConsoleAppender.createAppender("Stdout", layout, null, null) + appender.start + config.addAppender(appender) + val asyncAppender: AsyncAppender = AsyncAppender + .newBuilder() + .setName("AsyncStdout") + .setAppenderRefs(Array(AppenderRef.createAppenderRef("Stdout", XLevel.DEBUG, null))) + .setBlocking(false) + .setConfiguration(config) + .build + asyncAppender.start + config.addAppender(asyncAppender) + asyncAppender } // Construct these StringTypeTags manually, because they're used at the very startup of sbt @@ -90,7 +97,7 @@ sealed abstract class LogExchange { // Since we currently do not use Layout inside ConsoleAppender, the actual pattern is not relevant. private[sbt] lazy val dummyLayout: PatternLayout = { val _ = context - val ctx = XLogManager.getContext(false) match { case x: LoggerContext => x } + val ctx = XLogManager.getContext(false) match { case x: XLoggerContext => x } val config = ctx.getConfiguration val lo = PatternLayout.newBuilder .withConfiguration(config) @@ -131,31 +138,14 @@ sealed abstract class LogExchange { val _ = getOrElseUpdateStringCodec(tag.key, ev) } - private[sbt] def buildAsyncStdout: AsyncAppender = { - val ctx = XLogManager.getContext(false) match { case x: LoggerContext => x } - val config = ctx.getConfiguration - val appender = ConsoleAppender("Stdout") - // CustomConsoleAppenderImpl.createAppender("Stdout", layout, null, null) - appender.start - config.addAppender(appender) - val asyncAppender: AsyncAppender = AsyncAppender - .newBuilder() - .setName("AsyncStdout") - .setAppenderRefs(Array(AppenderRef.createAppenderRef("Stdout", XLevel.DEBUG, null))) - .setBlocking(false) - .setConfiguration(config) - .build - asyncAppender.start - config.addAppender(asyncAppender) - asyncAppender - } - private[sbt] def init(): LoggerContext = { + private[sbt] def init(): XLoggerContext = { import org.apache.logging.log4j.core.config.builder.api.ConfigurationBuilderFactory import org.apache.logging.log4j.core.config.Configurator val builder = ConfigurationBuilderFactory.newConfigurationBuilder builder.setConfigurationName("sbt.util.logging") val ctx = Configurator.initialize(builder.build()) - ctx match { case x: LoggerContext => x } + ctx match { case x: XLoggerContext => x } } + private[sbt] def init(name: String): XLoggerContext = new XLoggerContext(name) } object LogExchange extends LogExchange diff --git a/internal/util-logging/src/main/scala/sbt/util/LoggerContext.scala b/internal/util-logging/src/main/scala/sbt/util/LoggerContext.scala new file mode 100644 index 000000000..8fa789765 --- /dev/null +++ b/internal/util-logging/src/main/scala/sbt/util/LoggerContext.scala @@ -0,0 +1,189 @@ +/* + * sbt + * Copyright 2011 - 2018, Lightbend, Inc. + * Copyright 2008 - 2010, Mark Harrah + * Licensed under Apache License 2.0 (see LICENSE) + */ + +package sbt.util + +import java.util.concurrent.ConcurrentHashMap +import java.util.concurrent.atomic.AtomicBoolean +import org.apache.logging.log4j.{ Level => XLevel } +import org.apache.logging.log4j.core.{ Appender => XAppender, LoggerContext => XLoggerContext } +import org.apache.logging.log4j.core.config.{ AppenderRef, LoggerConfig } +import sbt.internal.util._ +import scala.collection.JavaConverters._ +import org.apache.logging.log4j.core.config.AbstractConfiguration +import org.apache.logging.log4j.message.ObjectMessage + +/** + * Provides a context for generating loggers during task evaluation. The logger context + * can be initialized for a single command evaluation run and all of the resources + * created (such as cached logger appenders) can be cleaned up after task evaluation. + * This trait evolved out of LogExchange when it became clear that it was very difficult + * to manage the loggers and appenders without introducing memory leaks. + */ +sealed trait LoggerContext extends AutoCloseable { + def logger(name: String, channelName: Option[String], execId: Option[String]): ManagedLogger + def clearAppenders(loggerName: String): Unit + def addAppender( + loggerName: String, + appender: (Appender, Level.Value) + ): Unit + def appenders(loggerName: String): Seq[Appender] + def remove(name: String): Unit +} +object LoggerContext { + private[this] val useLog4J = System.getProperty("sbt.log.uselog4j", "false") == "true" + private[this] lazy val global = new LoggerContext.LoggerContextImpl + private[this] lazy val globalLog4J = new LoggerContext.Log4JLoggerContext(LogExchange.context) + private[sbt] lazy val globalContext = if (useLog4J) globalLog4J else global + private[util] class Log4JLoggerContext(val xlc: XLoggerContext) extends LoggerContext { + private val config = xlc.getConfiguration match { + case a: AbstractConfiguration => a + case _ => throw new IllegalStateException("") + } + val loggers = new java.util.Vector[String] + private[this] val closed = new AtomicBoolean(false) + override def logger( + name: String, + channelName: Option[String], + execId: Option[String] + ): ManagedLogger = { + if (closed.get) { + throw new IllegalStateException("Tried to create logger for closed LoggerContext") + } + val loggerConfig = LoggerConfig.createLogger( + false, + XLevel.DEBUG, + name, + // disable the calculation of caller location as it is very expensive + // https://issues.apache.org/jira/browse/LOG4J2-153 + "false", + Array[AppenderRef](), + null, + config, + null + ) + config.addLogger(name, loggerConfig) + val logger = xlc.getLogger(name) + LogExchange.addConfig(name, loggerConfig) + loggers.add(name) + val xlogger = new MiniLogger { + def log(level: Level.Value, message: => String): Unit = + logger.log( + ConsoleAppender.toXLevel(level), + new ObjectMessage(StringEvent(level.toString, message, channelName, execId)) + ) + def log[T](level: Level.Value, message: ObjectEvent[T]): Unit = + logger.log(ConsoleAppender.toXLevel(level), new ObjectMessage(message)) + } + new ManagedLogger(name, channelName, execId, xlogger, Some(Terminal.get), this) + } + override def clearAppenders(loggerName: String): Unit = { + val lc = config.getLoggerConfig(loggerName) + lc.getAppenders.asScala foreach { + case (name, a) => + a.stop() + lc.removeAppender(name) + } + } + override def addAppender( + loggerName: String, + appender: (Appender, Level.Value) + ): Unit = { + val lc = config.getLoggerConfig(loggerName) + appender match { + case (x: XAppender, lv) => lc.addAppender(x, ConsoleAppender.toXLevel(lv), null) + case (x, lv) => lc.addAppender(x.toLog4J, ConsoleAppender.toXLevel(lv), null) + } + } + override def appenders(loggerName: String): Seq[Appender] = { + val lc = config.getLoggerConfig(loggerName) + lc.getAppenders.asScala.collect { case (name, ca: ConsoleAppender) => ca }.toVector + } + override def remove(name: String): Unit = { + val lc = config.getLoggerConfig(name) + config.removeLogger(name) + } + def close(): Unit = if (closed.compareAndSet(false, true)) { + loggers.forEach(l => remove(l)) + loggers.clear() + } + } + private[util] class LoggerContextImpl extends LoggerContext { + private class Log extends MiniLogger { + private val consoleAppenders: java.util.Vector[(Appender, Level.Value)] = + new java.util.Vector + def log(level: Level.Value, message: => String): Unit = + consoleAppenders.forEach { + case (a, l) => + if (level.compare(l) >= 0) a.appendLog(level, message) + } + def log[T](level: Level.Value, message: ObjectEvent[T]): Unit = { + consoleAppenders.forEach { + case (a, l) => + if (level.compare(l) >= 0) a.appendObjectEvent(level, message) + } + } + def addAppender(newAppender: (Appender, Level.Value)): Unit = + Util.ignoreResult(consoleAppenders.add(newAppender)) + def clearAppenders(): Unit = { + consoleAppenders.forEach { case (a, _) => a.close() } + consoleAppenders.clear() + } + def appenders: Seq[Appender] = consoleAppenders.asScala.map(_._1).toVector + } + private[this] val loggers = new ConcurrentHashMap[String, Log] + private[this] val closed = new AtomicBoolean(false) + override def logger( + name: String, + channelName: Option[String], + execId: Option[String] + ): ManagedLogger = { + if (closed.get) { + throw new IllegalStateException("Tried to create logger for closed LoggerContext") + } + val xlogger = new Log + loggers.put(name, xlogger) + new ManagedLogger(name, channelName, execId, xlogger, Some(Terminal.get), this) + } + override def clearAppenders(loggerName: String): Unit = { + loggers.get(loggerName) match { + case null => + case l => l.clearAppenders() + } + } + override def addAppender( + loggerName: String, + appender: (Appender, Level.Value) + ): Unit = { + if (closed.get) { + throw new IllegalStateException("Tried to add appender for closed LoggerContext") + } + loggers.get(loggerName) match { + case null => + case l => l.addAppender(appender) + } + } + override def appenders(loggerName: String): Seq[Appender] = { + loggers.get(loggerName) match { + case null => Nil + case l => l.appenders + } + } + override def remove(name: String): Unit = { + loggers.remove(name) match { + case null => + case l => l.clearAppenders() + } + } + def close(): Unit = { + loggers.forEach((name, l) => l.clearAppenders()) + loggers.clear() + } + } + private[sbt] def apply(useLog4J: Boolean) = + if (useLog4J) new Log4JLoggerContext(LogExchange.context) else new LoggerContextImpl +} diff --git a/internal/util-logging/src/test/scala/ManagedLoggerSpec.scala b/internal/util-logging/src/test/scala/ManagedLoggerSpec.scala index b5c99ca38..7586cfbce 100644 --- a/internal/util-logging/src/test/scala/ManagedLoggerSpec.scala +++ b/internal/util-logging/src/test/scala/ManagedLoggerSpec.scala @@ -11,25 +11,30 @@ import org.scalatest._ import sbt.util._ import java.io.{ File, PrintWriter } import sbt.io.Using +import com.github.ghik.silencer.silent class ManagedLoggerSpec extends FlatSpec with Matchers { + val context = LoggerContext(useLog4J = true) + @silent + val asyncStdout = new ConsoleAppenderFromLog4J("asyncStdout", LogExchange.asyncStdout) + def newLogger(name: String): ManagedLogger = context.logger(name, None, None) "ManagedLogger" should "log to console" in { - val log = LogExchange.logger("foo") - LogExchange.bindLoggerAppenders("foo", List(LogExchange.asyncStdout -> Level.Info)) + val log = newLogger("foo") + context.addAppender("foo", asyncStdout -> Level.Info) log.info("test") log.debug("test") } it should "support event logging" in { import sjsonnew.BasicJsonProtocol._ - val log = LogExchange.logger("foo") - LogExchange.bindLoggerAppenders("foo", List(LogExchange.asyncStdout -> Level.Info)) + val log = newLogger("foo") + context.addAppender("foo", asyncStdout -> Level.Info) log.infoEvent(1) } it should "validate performance improvement of disabling location calculation for async loggers" in { - val log = LogExchange.logger("foo") - LogExchange.bindLoggerAppenders("foo", List(LogExchange.asyncStdout -> Level.Info)) + val log = newLogger("foo") + context.addAppender("foo", asyncStdout -> Level.Info) val before = System.currentTimeMillis() 1 to 10000 foreach { _ => log.debug("test") @@ -41,15 +46,15 @@ class ManagedLoggerSpec extends FlatSpec with Matchers { it should "support logging Throwable out of the box" in { import sbt.internal.util.codec.JsonProtocol._ - val log = LogExchange.logger("foo") - LogExchange.bindLoggerAppenders("foo", List(LogExchange.asyncStdout -> Level.Info)) + val log = newLogger("foo") + context.addAppender("foo", asyncStdout -> Level.Info) log.infoEvent(SuccessEvent("yes")) } it should "allow registering Show[Int]" in { import sjsonnew.BasicJsonProtocol._ - val log = LogExchange.logger("foo") - LogExchange.bindLoggerAppenders("foo", List(LogExchange.asyncStdout -> Level.Info)) + val log = newLogger("foo") + context.addAppender("foo", asyncStdout -> Level.Info) implicit val intShow: ShowLines[Int] = ShowLines((x: Int) => Vector(s"String representation of $x")) log.registerStringCodec[Int] @@ -58,8 +63,8 @@ class ManagedLoggerSpec extends FlatSpec with Matchers { it should "allow registering Show[Array[Int]]" in { import sjsonnew.BasicJsonProtocol._ - val log = LogExchange.logger("foo") - LogExchange.bindLoggerAppenders("foo", List(LogExchange.asyncStdout -> Level.Info)) + val log = newLogger("foo") + context.addAppender("foo", asyncStdout -> Level.Info) implicit val intArrayShow: ShowLines[Array[Int]] = ShowLines((x: Array[Int]) => Vector(s"String representation of ${x.mkString}")) log.registerStringCodec[Array[Int]] @@ -68,8 +73,8 @@ class ManagedLoggerSpec extends FlatSpec with Matchers { it should "allow registering Show[Vector[Vector[Int]]]" in { import sjsonnew.BasicJsonProtocol._ - val log = LogExchange.logger("foo") - LogExchange.bindLoggerAppenders("foo", List(LogExchange.asyncStdout -> Level.Info)) + val log = newLogger("foo") + context.addAppender("foo", asyncStdout -> Level.Info) implicit val intVectorShow: ShowLines[Vector[Vector[Int]]] = ShowLines((xss: Vector[Vector[Int]]) => Vector(s"String representation of $xss")) log.registerStringCodec[Vector[Vector[Int]]] @@ -85,8 +90,8 @@ class ManagedLoggerSpec extends FlatSpec with Matchers { pool.submit(new Runnable { def run(): Unit = { val stringTypeTag = StringTypeTag.fast[List[Int]] - val log = LogExchange.logger(s"foo$i") - LogExchange.bindLoggerAppenders(s"foo$i", List(LogExchange.asyncStdout -> Level.Info)) + val log = newLogger(s"foo$i") + context.addAppender(s"foo$i", asyncStdout -> Level.Info) if (i % 100 == 0) { log.info(s"foo$i test $stringTypeTag") } @@ -113,7 +118,7 @@ class ManagedLoggerSpec extends FlatSpec with Matchers { val logBacking0 = global0.backing val global1 = Using.fileWriter(append = true)(logBacking0.file) { writer => val out = new PrintWriter(writer) - val g = global0.newAppender(global0.full, out, logBacking0) + val g = global0.newAppender(global0.full, out, logBacking0, context) val full = g.full (1 to 3).toList foreach (x => full.info(s"newAppender $x")) assert(logBacking0.file.exists) @@ -122,7 +127,7 @@ class ManagedLoggerSpec extends FlatSpec with Matchers { val logBacking1 = global1.backing Using.fileWriter(append = true)(logBacking1.file) { writer => val out = new PrintWriter(writer) - val g = global1.newAppender(global1.full, out, logBacking1) + val g = global1.newAppender(global1.full, out, logBacking1, context) val full = g.full (1 to 3).toList foreach (x => full.info(s"newAppender $x")) // println(logBacking.file) diff --git a/internal/util-scripted/src/main/scala/sbt/internal/scripted/ScriptedTests.scala b/internal/util-scripted/src/main/scala/sbt/internal/scripted/ScriptedTests.scala index 12dc82c6f..ffdd4e685 100644 --- a/internal/util-scripted/src/main/scala/sbt/internal/scripted/ScriptedTests.scala +++ b/internal/util-scripted/src/main/scala/sbt/internal/scripted/ScriptedTests.scala @@ -10,8 +10,8 @@ package internal package scripted import java.io.File -import sbt.util.{ Logger, LogExchange, Level } -import sbt.internal.util.{ ManagedLogger, ConsoleAppender, BufferedAppender } +import sbt.util.{ Logger, LoggerContext, Level } +import sbt.internal.util.{ Appender, ManagedLogger, ConsoleAppender, BufferedAppender } import sbt.io.IO.wrapNull import sbt.io.{ DirectoryFilter, HiddenFileFilter } import sbt.io.syntax._ @@ -25,11 +25,13 @@ object ScriptedRunnerImpl { tests: Array[String], handlersProvider: HandlersProvider ): Unit = { + val context = + LoggerContext(useLog4J = System.getProperty("sbt.log.uselog4j", "false") == "true") val runner = new ScriptedTests(resourceBaseDirectory, bufferLog, handlersProvider) - val logger = newLogger + val logger = newLogger(context) val allTests = get(tests, resourceBaseDirectory, logger) flatMap { case ScriptedTest(group, name) => - runner.scriptedTest(group, name, logger) + runner.scriptedTest(group, name, logger, context) } runAll(allTests) } @@ -48,10 +50,9 @@ object ScriptedRunnerImpl { ScriptedTest(group, name) } private[sbt] val generateId: AtomicInteger = new AtomicInteger - private[sbt] def newLogger: ManagedLogger = { + private[sbt] def newLogger(context: LoggerContext): ManagedLogger = { val loggerName = "scripted-" + generateId.incrementAndGet - val x = LogExchange.logger(loggerName) - x + context.logger(loggerName, None, None) } } @@ -64,7 +65,7 @@ final class ScriptedTests( def this(resourceBaseDirectory: File, bufferLog: Boolean, handlersProvider: HandlersProvider) = this(resourceBaseDirectory, bufferLog, handlersProvider, true) private val testResources = new Resources(resourceBaseDirectory) - private val consoleAppender: ConsoleAppender = ConsoleAppender() + private val appender: Appender = ConsoleAppender() val ScriptFilename = "test" val PendingScriptFilename = "pending" @@ -72,14 +73,35 @@ final class ScriptedTests( def scriptedTest(group: String, name: String, log: xsbti.Logger): Seq[() => Option[String]] = scriptedTest(group, name, Logger.xlog2Log(log)) - def scriptedTest(group: String, name: String, log: ManagedLogger): Seq[() => Option[String]] = - scriptedTest(group, name, (_ => ()), log) + @deprecated("Use scriptedTest that takes a LoggerContext", "1.4.0") + def scriptedTest( + group: String, + name: String, + log: ManagedLogger, + ): Seq[() => Option[String]] = + scriptedTest(group, name, (_ => ()), log, LoggerContext.globalContext) + def scriptedTest( + group: String, + name: String, + log: ManagedLogger, + context: LoggerContext + ): Seq[() => Option[String]] = + scriptedTest(group, name, (_ => ()), log, context) + @deprecated("Use scriptedTest that provides LoggerContext", "1.4.0") def scriptedTest( group: String, name: String, prescripted: File => Unit, - log: ManagedLogger + log: ManagedLogger, + ): Seq[() => Option[String]] = + scriptedTest(group, name, prescripted, log, LoggerContext.globalContext) + def scriptedTest( + group: String, + name: String, + prescripted: File => Unit, + log: ManagedLogger, + context: LoggerContext, ): Seq[() => Option[String]] = { for (groupDir <- (resourceBaseDirectory * group).get; nme <- (groupDir * name).get) yield { val g = groupDir.getName @@ -94,7 +116,7 @@ final class ScriptedTests( None } else { try { - scriptedTest(str, testDirectory, prescripted, log); None + scriptedTest(str, testDirectory, prescripted, log, context); None } catch { case _: TestException | _: PendingTestSuccessException => Some(str) } @@ -108,11 +130,12 @@ final class ScriptedTests( label: String, testDirectory: File, prescripted: File => Unit, - log: ManagedLogger + log: ManagedLogger, + context: LoggerContext, ): Unit = { - val buffered = BufferedAppender(consoleAppender) - LogExchange.unbindLoggerAppenders(log.name) - LogExchange.bindLoggerAppenders(log.name, (buffered -> Level.Debug) :: Nil) + val buffered = BufferedAppender(appender) + context.clearAppenders(log.name) + context.addAppender(log.name, (buffered -> Level.Debug)) if (bufferLog) { buffered.record() } diff --git a/main/src/main/scala/sbt/Defaults.scala b/main/src/main/scala/sbt/Defaults.scala index 360564cfb..4173b0b68 100644 --- a/main/src/main/scala/sbt/Defaults.scala +++ b/main/src/main/scala/sbt/Defaults.scala @@ -17,6 +17,7 @@ import lmcoursier.CoursierDependencyResolution import lmcoursier.definitions.{ Configuration => CConfiguration } import org.apache.ivy.core.module.descriptor.ModuleDescriptor import org.apache.ivy.core.module.id.ModuleRevisionId +import org.apache.logging.log4j.core.{ Appender => XAppender } import org.scalasbt.ipcsocket.Win32SecurityLevel import sbt.Def.{ Initialize, ScopedKey, Setting, SettingsDefinition } import sbt.Keys._ @@ -359,9 +360,19 @@ object Defaults extends BuildCommon { try onUnload.value(s) finally IO.delete(taskTemporaryDirectory.value) }, - extraLoggers :== { _ => + // extraLoggers is deprecated + SettingKey[ScopedKey[_] => Seq[XAppender]]("extraLoggers") :== { _ => Nil }, + extraAppenders := { + val f = SettingKey[ScopedKey[_] => Seq[XAppender]]("extraLoggers").value + s => + f(s).map { + case a: Appender => a + case a => new ConsoleAppenderFromLog4J(a.getName, a) + } + }, + useLog4J :== SysProp.useLog4J, watchSources :== Nil, // Although this is deprecated, it can't be removed or it breaks += for legacy builds. skip :== false, taskTemporaryDirectory := { @@ -441,7 +452,7 @@ object Defaults extends BuildCommon { // TODO: This should be on the new default settings for a project. def projectCore: Seq[Setting[_]] = Seq( name := thisProject.value.id, - logManager := LogManager.defaults(extraLoggers.value, ConsoleOut.terminalOut), + logManager := LogManager.defaults(extraAppenders.value, ConsoleOut.terminalOut), onLoadMessage := (onLoadMessage or Def.setting { s"set current project to ${name.value} (in build ${thisProjectRef.value.build})" @@ -1046,13 +1057,15 @@ object Defaults extends BuildCommon { inTask(key)( Seq( testListeners := { + val stateLogLevel = state.value.get(Keys.logLevel.key).getOrElse(Level.Info) TestLogger.make( streams.value.log, closeableTestLogger( streamsManager.value, test in resolvedScoped.value.scope, logBuffered.value - ) + ), + Keys.logLevel.?.value.getOrElse(stateLogLevel), ) +: new TestStatusReporter(succeededFile(streams.in(test).value.cacheDirectory)) +: testListeners.in(TaskZero).value diff --git a/main/src/main/scala/sbt/Keys.scala b/main/src/main/scala/sbt/Keys.scala index 504b69a74..70b0127aa 100644 --- a/main/src/main/scala/sbt/Keys.scala +++ b/main/src/main/scala/sbt/Keys.scala @@ -15,7 +15,7 @@ import lmcoursier.definitions.{ CacheLogger, ModuleMatchers, Reconciliation } import lmcoursier.{ CoursierConfiguration, FallbackDependency } import org.apache.ivy.core.module.descriptor.ModuleDescriptor import org.apache.ivy.core.module.id.ModuleRevisionId -import org.apache.logging.log4j.core.Appender +import org.apache.logging.log4j.core.{ Appender => XAppender } import sbt.BuildSyntax._ import sbt.Def.ScopedKey import sbt.KeyRanks._ @@ -27,7 +27,7 @@ import sbt.internal.io.WatchState import sbt.internal.librarymanagement.{ CompatibilityWarningOptions, IvySbt } import sbt.internal.remotecache.RemoteCacheArtifact import sbt.internal.server.ServerHandler -import sbt.internal.util.{ AttributeKey, ProgressState, SourcePosition } +import sbt.internal.util.{ Appender, AttributeKey, ProgressState, SourcePosition } import sbt.io._ import sbt.librarymanagement.Configurations.CompilerPlugin import sbt.librarymanagement.LibraryManagementCodec._ @@ -35,7 +35,7 @@ import sbt.librarymanagement._ import sbt.librarymanagement.ivy.{ Credentials, IvyConfiguration, IvyPaths, UpdateOptions } import sbt.nio.file.Glob import sbt.testing.Framework -import sbt.util.{ Level, Logger } +import sbt.util.{ Level, Logger, LoggerContext } import xsbti.{ FileConverter, VirtualFile } import xsbti.compile._ import xsbti.compile.analysis.ReadStamps @@ -59,8 +59,12 @@ object Keys { val showSuccess = settingKey[Boolean]("If true, displays a success message after running a command successfully.").withRank(CSetting) val showTiming = settingKey[Boolean]("If true, the command success message includes the completion time.").withRank(CSetting) val timingFormat = settingKey[java.text.DateFormat]("The format used for displaying the completion time.").withRank(CSetting) - val extraLoggers = settingKey[ScopedKey[_] => Seq[Appender]]("A function that provides additional loggers for a given setting.").withRank(DSetting) + @deprecated("", "1.4.0") + val extraLoggers = settingKey[ScopedKey[_] => Seq[XAppender]]("A function that provides additional loggers for a given setting.").withRank(DSetting) + val extraAppenders = settingKey[ScopedKey[_] => Seq[Appender]]("A function that provides additional loggers for a given setting.").withRank(DSetting) + val useLog4J = settingKey[Boolean]("Toggles whether or not to use log4j for sbt internal loggers.").withRank(Invisible) val logManager = settingKey[LogManager]("The log manager, which creates Loggers for different contexts.").withRank(DSetting) + private[sbt] val loggerContext = AttributeKey[LoggerContext]("sbt-logger-context", "The logger config which creates Loggers for different contexts.", Int.MaxValue) val logBuffered = settingKey[Boolean]("True if logging should be buffered until work completes.").withRank(CSetting) val sLog = settingKey[Logger]("Logger usable by settings during project loading.").withRank(CSetting) val serverLog = taskKey[Unit]("A dummy task to set server log level using Global / serverLog / logLevel.").withRank(CTask) diff --git a/main/src/main/scala/sbt/Main.scala b/main/src/main/scala/sbt/Main.scala index 61777b2ec..70e291940 100644 --- a/main/src/main/scala/sbt/Main.scala +++ b/main/src/main/scala/sbt/Main.scala @@ -930,8 +930,9 @@ object BuiltinCommands { val session = Load.initialSession(structure, eval, s0) SessionSettings.checkSession(session, s2) val s3 = addCacheStoreFactoryFactory(Project.setProject(session, structure, s2)) - val s4 = setupGlobalFileTreeRepository(s3) - CheckBuildSources.init(LintUnused.lintUnusedFunc(s4)) + val s4 = s3.put(Keys.useLog4J.key, Project.extract(s3).get(Keys.useLog4J)) + val s5 = setupGlobalFileTreeRepository(s4) + CheckBuildSources.init(LintUnused.lintUnusedFunc(s5)) } private val setupGlobalFileTreeRepository: State => State = { state => diff --git a/main/src/main/scala/sbt/MainLoop.scala b/main/src/main/scala/sbt/MainLoop.scala index b1822aa31..0d2f57c2e 100644 --- a/main/src/main/scala/sbt/MainLoop.scala +++ b/main/src/main/scala/sbt/MainLoop.scala @@ -19,7 +19,7 @@ import sbt.internal.util.{ ErrorHandling, GlobalLogBacking, Terminal } import sbt.internal.{ ConsoleUnpromptEvent, ShutdownHooks } import sbt.io.{ IO, Using } import sbt.protocol._ -import sbt.util.Logger +import sbt.util.{ Logger, LoggerContext } import scala.annotation.tailrec import scala.util.control.NonFatal @@ -63,7 +63,7 @@ object MainLoop { } /** Runs the next sequence of commands, cleaning up global logging after any exceptions. */ - def runAndClearLast(state: State, logBacking: GlobalLogBacking): RunNext = + def runAndClearLast(state: State, logBacking: GlobalLogBacking): RunNext = { try runWithNewLog(state, logBacking) catch { case e: xsbti.FullReload => @@ -80,6 +80,7 @@ object MainLoop { deleteLastLog(logBacking) throw e } + } /** Deletes the previous global log file. */ def deleteLastLog(logBacking: GlobalLogBacking): Unit = @@ -108,16 +109,20 @@ object MainLoop { } /** Runs the next sequence of commands with global logging in place. */ - def runWithNewLog(state: State, logBacking: GlobalLogBacking): RunNext = + def runWithNewLog(state: State, logBacking: GlobalLogBacking): RunNext = { Using.fileWriter(append = true)(logBacking.file) { writer => val out = new PrintWriter(writer) val full = state.globalLogging.full - val newLogging = state.globalLogging.newAppender(full, out, logBacking) + val newLogging = + state.globalLogging.newAppender(full, out, logBacking, LoggerContext.globalContext) // transferLevels(state, newLogging) val loggedState = state.copy(globalLogging = newLogging) try run(loggedState) - finally out.close() + finally { + out.close() + } } + } // /** Transfers logging and trace levels from the old global loggers to the new ones. */ // private[this] def transferLevels(state: State, logging: GlobalLogging): Unit = { @@ -143,15 +148,16 @@ object MainLoop { case ret: State.Return => new Return(ret.result) } - def next(state: State): State = + def next(state: State): State = { + val context = LoggerContext(useLog4J = state.get(Keys.useLog4J.key).getOrElse(false)) try { ErrorHandling.wideConvert { - state.process(processCommand) + state.put(Keys.loggerContext, context).process(processCommand) } match { - case Right(s) => s + case Right(s) => s.remove(Keys.loggerContext) case Left(t: xsbti.FullReload) => throw t case Left(t: RebootCurrent) => throw t - case Left(t) => state.handleError(t) + case Left(t) => state.remove(Keys.loggerContext).handleError(t) } } catch { case oom: OutOfMemoryError @@ -180,7 +186,8 @@ object MainLoop { state.log.error(msg) state.log.error("\n") state.handleError(oom) - } + } finally context.close() + } /** This is the main function State transfer function of the sbt command processing. */ def processCommand(exec: Exec, state: State): State = { @@ -202,20 +209,31 @@ object MainLoop { StandardMain.exchange.setState(progressState) StandardMain.exchange.setExec(Some(exec)) StandardMain.exchange.unprompt(ConsoleUnpromptEvent(exec.source)) - val terminal = channelName.flatMap(exchange.channelForName(_).map(_.terminal)) - val prevTerminal = terminal.map(Terminal.set) + val restoreTerminal = channelName.flatMap(exchange.channelForName) match { + case Some(c) => + val prevTerminal = Terminal.set(c.terminal) + () => { + Terminal.set(prevTerminal) + c.terminal.flush() + } + case _ => () => () + } /* * FastTrackCommands.evaluate can be significantly faster than Command.process because * it avoids an expensive parsing step for internal commands that are easy to parse. * Dropping (FastTrackCommands.evaluate ... getOrElse) should be functionally identical * but slower. */ - val newState = FastTrackCommands.evaluate(progressState, exec.commandLine) getOrElse - Command.process(exec.commandLine, progressState) - // Flush the terminal output after command evaluation to ensure that all output - // is displayed in the thin client before we report the command status. - terminal.foreach(_.flush()) - prevTerminal.foreach(Terminal.set) + val newState = try { + FastTrackCommands + .evaluate(progressState, exec.commandLine) + .getOrElse(Command.process(exec.commandLine, progressState)) + } finally { + // Flush the terminal output after command evaluation to ensure that all output + // is displayed in the thin client before we report the command status. Also + // set the promt to whatever it was before we started evaluating the task. + restoreTerminal() + } if (exec.execId.fold(true)(!_.startsWith(networkExecPrefix)) && !exec.commandLine.startsWith(networkExecPrefix)) { val doneEvent = ExecStatusEvent( diff --git a/main/src/main/scala/sbt/internal/Continuous.scala b/main/src/main/scala/sbt/internal/Continuous.scala index 80cf2206b..0f13a36b4 100644 --- a/main/src/main/scala/sbt/internal/Continuous.scala +++ b/main/src/main/scala/sbt/internal/Continuous.scala @@ -258,14 +258,16 @@ private[sbt] object Continuous extends DeprecatedContinuous { commands: Seq[String], fileStampCache: FileStamp.Cache, dynamicInputs: mutable.Set[DynamicInput], + context: LoggerContext ): Callbacks = { implicit val extracted: Extracted = Project.extract(s) - implicit val logger: Logger = LogExchange.logger(channel.name + "-watch") + implicit val logger: Logger = + context.logger(channel.name + "-watch", None, None) validateCommands(s, commands) val configs = getAllConfigs(s, commands, dynamicInputs) val appender = ConsoleAppender(channel.name + "-watch", channel.terminal) val level = configs.minBy(_.watchSettings.logLevel).watchSettings.logLevel - LogExchange.bindLoggerAppenders(channel.name + "-watch", (appender -> level) :: Nil) + context.addAppender(channel.name + "-watch", appender -> level) aggregate( configs, logger, @@ -1141,8 +1143,9 @@ private[sbt] object ContinuousCommands { .channelForName(channelName) .getOrElse(throw new IllegalStateException(s"No channel with name $channelName")) val dynamicInputs = mutable.Set.empty[DynamicInput] + val context = LoggerContext(useLog4J = state.get(Keys.useLog4J.key).getOrElse(false)) def cb: Continuous.Callbacks = - Continuous.getCallbacks(state, channel, commands, cache, dynamicInputs) + Continuous.getCallbacks(state, channel, commands, cache, dynamicInputs, context) val s = new ContinuousState( count = count, @@ -1178,8 +1181,9 @@ private[sbt] object ContinuousCommands { restoredState.remove(persistentFileStampCache).remove(Continuous.DynamicInputs) }, afterWatch = state => { - LogExchange.unbindLoggerAppenders(channelName + "-watch") + context.clearAppenders(channelName + "-watch") repo.close() + context.close() state.get(watchStates) match { case None => state case Some(ws) => state.put(watchStates, ws - channelName) diff --git a/main/src/main/scala/sbt/internal/DefaultBackgroundJobService.scala b/main/src/main/scala/sbt/internal/DefaultBackgroundJobService.scala index 92cfd75f9..357e398a2 100644 --- a/main/src/main/scala/sbt/internal/DefaultBackgroundJobService.scala +++ b/main/src/main/scala/sbt/internal/DefaultBackgroundJobService.scala @@ -21,10 +21,11 @@ import sbt.internal.inc.classpath.ClasspathFilter import sbt.internal.util.{ Attributed, ManagedLogger } import sbt.io.syntax._ import sbt.io.{ Hash, IO } -import sbt.util.{ LogExchange, Logger } +import sbt.util.Logger import scala.concurrent.ExecutionContext import scala.util.Try +import sbt.util.LoggerContext /** * Interface between sbt and a thing running in the background. @@ -63,6 +64,7 @@ private[sbt] abstract class AbstractBackgroundJobService extends BackgroundJobSe private val pool = new BackgroundThreadPool() private[sbt] def serviceTempDirBase: File + private[sbt] def useLog4J: Boolean private val serviceTempDirRef = new AtomicReference[File] private def serviceTempDir: File = serviceTempDirRef.synchronized { serviceTempDirRef.get match { @@ -76,6 +78,7 @@ private[sbt] abstract class AbstractBackgroundJobService extends BackgroundJobSe // hooks for sending start/stop events protected def onAddJob(@deprecated("unused", "") job: JobHandle): Unit = () protected def onRemoveJob(@deprecated("unused", "") job: JobHandle): Unit = () + private val context = LoggerContext(useLog4J) // this mutable state could conceptually go on State except // that then every task that runs a background job would have @@ -111,7 +114,8 @@ private[sbt] abstract class AbstractBackgroundJobService extends BackgroundJobSe // logger.close() removeJob(this) IO.delete(workingDirectory) - LogExchange.unbindLoggerAppenders(logger.name) + context.clearAppenders(logger.name) + context.close() } addJob(this) override final def equals(other: Any): Boolean = other match { @@ -472,10 +476,12 @@ private[sbt] class BackgroundThreadPool extends java.io.Closeable { } } -private[sbt] class DefaultBackgroundJobService(private[sbt] val serviceTempDirBase: File) - extends AbstractBackgroundJobService { +private[sbt] class DefaultBackgroundJobService( + private[sbt] val serviceTempDirBase: File, + override private[sbt] val useLog4J: Boolean +) extends AbstractBackgroundJobService { @deprecated("Use the constructor that specifies the background job temporary directory", "1.4.0") - def this() = this(IO.createTemporaryDirectory) + def this() = this(IO.createTemporaryDirectory, false) override def makeContext(id: Long, spawningTask: ScopedKey[_], state: State): ManagedLogger = { val extracted = Project.extract(state) LogManager.constructBackgroundLog(extracted.structure.data, state)(spawningTask) @@ -491,7 +497,8 @@ private[sbt] object DefaultBackgroundJobService { private[sbt] lazy val backgroundJobServiceSetting: Setting[_] = (Keys.bgJobService in GlobalScope) := { val path = (sbt.Keys.bgJobServiceDirectory in GlobalScope).value - val newService = new DefaultBackgroundJobService(path) + val useLog4J = (Keys.useLog4J in GlobalScope).value + val newService = new DefaultBackgroundJobService(path, useLog4J) backgroundJobServices.putIfAbsent(path, newService) match { case null => newService case s => diff --git a/main/src/main/scala/sbt/internal/LogManager.scala b/main/src/main/scala/sbt/internal/LogManager.scala index a9db8d34b..99722dbf6 100644 --- a/main/src/main/scala/sbt/internal/LogManager.scala +++ b/main/src/main/scala/sbt/internal/LogManager.scala @@ -10,23 +10,38 @@ package internal import java.io.PrintWriter -import org.apache.logging.log4j.core.Appender import sbt.Def.ScopedKey import sbt.Keys._ import sbt.Scope.GlobalScope import sbt.internal.util.MainAppender._ import sbt.internal.util._ -import sbt.util.{ Level, LogExchange, Logger } +import sbt.util.{ Level, LogExchange, Logger, LoggerContext } sealed abstract class LogManager { def apply( data: Settings[Scope], state: State, task: ScopedKey[_], - writer: PrintWriter + writer: PrintWriter, + context: LoggerContext, ): ManagedLogger + @deprecated("Use alternate apply that provides a LoggerContext", "1.4.0") + def apply( + data: Settings[Scope], + state: State, + task: ScopedKey[_], + writer: PrintWriter + ): ManagedLogger = apply(data, state, task, writer, LoggerContext.globalContext) - def backgroundLog(data: Settings[Scope], state: State, task: ScopedKey[_]): ManagedLogger + def backgroundLog( + data: Settings[Scope], + state: State, + task: ScopedKey[_], + context: LoggerContext + ): ManagedLogger + @deprecated("Use alternate background log that provides a LoggerContext", "1.4.0") + final def backgroundLog(data: Settings[Scope], state: State, task: ScopedKey[_]): ManagedLogger = + backgroundLog(data, state, task, LoggerContext.globalContext) } object LogManager { @@ -34,14 +49,16 @@ object LogManager { private val generateId: AtomicInteger = new AtomicInteger // This is called by mkStreams + // def construct( data: Settings[Scope], state: State ): (ScopedKey[_], PrintWriter) => ManagedLogger = (task: ScopedKey[_], to: PrintWriter) => { + val context = state.get(Keys.loggerContext).getOrElse(LoggerContext.globalContext) val manager: LogManager = (logManager in task.scope).get(data) getOrElse defaultManager(state.globalLogging.console) - manager(data, state, task, to) + manager(data, state, task, to, context) } def constructBackgroundLog( @@ -51,7 +68,8 @@ object LogManager { (task: ScopedKey[_]) => { val manager: LogManager = (logManager in task.scope).get(data) getOrElse defaultManager(state.globalLogging.console) - manager.backgroundLog(data, state, task) + val context = state.get(Keys.loggerContext).getOrElse(LoggerContext.globalContext) + manager.backgroundLog(data, state, task, context) } def defaultManager(console: ConsoleOut): LogManager = @@ -84,7 +102,8 @@ object LogManager { data: Settings[Scope], state: State, task: ScopedKey[_], - to: PrintWriter + to: PrintWriter, + context: LoggerContext, ): ManagedLogger = defaultLogger( data, @@ -93,12 +112,18 @@ object LogManager { screen(task, state), backed(to), relay(()), - extra(task).toList + extra(task).toList, + context, ) - def backgroundLog(data: Settings[Scope], state: State, task: ScopedKey[_]): ManagedLogger = { + def backgroundLog( + data: Settings[Scope], + state: State, + task: ScopedKey[_], + context: LoggerContext + ): ManagedLogger = { val console = screen(task, state) - LogManager.backgroundLog(data, state, task, console, relay(())) + LogManager.backgroundLog(data, state, task, console, relay(()), context) } } @@ -112,7 +137,7 @@ object LogManager { ): T = data.get(scope, key) orElse state.get(key) getOrElse default - // This is the main function that is used to generate the logger for tasks. + @deprecated("Use defaultLogger that provides a LoggerContext", "1.4.0") def defaultLogger( data: Settings[Scope], state: State, @@ -121,12 +146,24 @@ object LogManager { backed: Appender, relay: Appender, extra: List[Appender] + ): ManagedLogger = + defaultLogger(data, state, task, console, backed, relay, extra, LoggerContext.globalContext) + // This is the main function that is used to generate the logger for tasks. + def defaultLogger( + data: Settings[Scope], + state: State, + task: ScopedKey[_], + console: Appender, + backed: Appender, + relay: Appender, + extra: List[Appender], + context: LoggerContext, ): ManagedLogger = { val execOpt = state.currentCommand val loggerName: String = s"${task.key.label}-${generateId.incrementAndGet}" val channelName: Option[String] = execOpt flatMap (_.source map (_.channelName)) val execId: Option[String] = execOpt flatMap { _.execId } - val log = LogExchange.logger(loggerName, channelName, execId) + val log = context.logger(loggerName, channelName, execId) val scope = task.scope val screenLevel = getOr(logLevel.key, data, scope, state, Level.Info) val backingLevel = getOr(persistLogLevel.key, data, scope, state, Level.Debug) @@ -143,7 +180,7 @@ object LogManager { screenTrace, backingTrace ) - multiLogger(log, config) + multiLogger(log, config, context) } // Return None if the exec is not from console origin. @@ -191,6 +228,7 @@ object LogManager { console: Appender, /* TODO: backed: Appender,*/ relay: Appender, + context: LoggerContext, ): ManagedLogger = { val scope = task.scope val screenLevel = getOr(logLevel.key, data, scope, state, Level.Info) @@ -200,18 +238,16 @@ object LogManager { val loggerName: String = s"bg-${task.key.label}-${generateId.incrementAndGet}" val channelName: Option[String] = execOpt flatMap (_.source map (_.channelName)) // val execId: Option[String] = execOpt flatMap { _.execId } - val log = LogExchange.logger(loggerName, channelName, None) - LogExchange.unbindLoggerAppenders(loggerName) + val log = context.logger(loggerName, channelName, None) + context.clearAppenders(loggerName) val consoleOpt = consoleLocally(state, console) map { - case a: ConsoleAppender => + case a: Appender => a.setTrace(screenTrace) a case a => a } - LogExchange.bindLoggerAppenders( - loggerName, - (consoleOpt.toList map { _ -> screenLevel }) ::: (relay -> backingLevel) :: Nil - ) + consoleOpt.foreach(a => context.addAppender(loggerName, a -> screenLevel)) + context.addAppender(loggerName, relay -> backingLevel) log } @@ -238,30 +274,23 @@ object LogManager { def setGlobalLogLevel(s: State, level: Level.Value): State = { val s1 = s.put(BasicKeys.explicitGlobalLogLevels, true).put(Keys.logLevel.key, level) val gl = s1.globalLogging - LogExchange.unbindLoggerAppenders(gl.full.name) - LogExchange.bindLoggerAppenders(gl.full.name, (gl.backed -> level) :: Nil) + LoggerContext.globalContext.clearAppenders(gl.full.name) + LoggerContext.globalContext.addAppender(gl.full.name, gl.backed -> level) s1 } @deprecated("No longer used.", "1.4.0") - private[sbt] def progressLogger(appender: Appender): ManagedLogger = { + private[sbt] def progressLogger(appender: ConsoleAppender): ManagedLogger = { val log = LogExchange.logger("progress", None, None) - LogExchange.unbindLoggerAppenders("progress") - LogExchange.bindLoggerAppenders( - "progress", - List(appender -> Level.Info) - ) + LoggerContext.globalContext.clearAppenders("progress") + LoggerContext.globalContext.addAppender("progress", appender -> Level.Info) log } // This is the default implementation for the relay appender - val defaultRelay: Unit => Appender = _ => defaultRelayImpl + val defaultRelay: Unit => ConsoleAppender = _ => defaultRelayImpl - private[this] lazy val defaultRelayImpl: RelayAppender = { - val appender = new RelayAppender("Relay0") - appender.start() - appender - } + private[this] lazy val defaultRelayImpl: ConsoleAppender = new RelayAppender("Relay0") private[sbt] def settingsLogger(state: State): Def.Setting[_] = // strict to avoid retaining a reference to `state` diff --git a/main/src/main/scala/sbt/internal/RelayAppender.scala b/main/src/main/scala/sbt/internal/RelayAppender.scala index e140754b6..ed9355b37 100644 --- a/main/src/main/scala/sbt/internal/RelayAppender.scala +++ b/main/src/main/scala/sbt/internal/RelayAppender.scala @@ -8,45 +8,18 @@ package sbt package internal -import org.apache.logging.log4j.message._ -import org.apache.logging.log4j.core.{ LogEvent => XLogEvent } -import org.apache.logging.log4j.core.appender.AbstractAppender -import org.apache.logging.log4j.core.layout.PatternLayout -import org.apache.logging.log4j.core.async.RingBufferLogEvent -import org.apache.logging.log4j.core.config.Property -import sbt.util.Level import sbt.internal.util._ import sbt.protocol.LogEvent +import sbt.util.Level -class RelayAppender(name: String) - extends AbstractAppender( +class RelayAppender(override val name: String) + extends ConsoleAppender( name, - null, - PatternLayout.createDefaultLayout(), - true, - Property.EMPTY_ARRAY + ConsoleAppender.Properties.from(ConsoleOut.globalProxy, true, true), + _ => None ) { lazy val exchange = StandardMain.exchange - - def append(event: XLogEvent): Unit = { - val level = ConsoleAppender.toLevel(event.getLevel) - val message = event.getMessage - message match { - case o: ObjectMessage => appendEvent(o.getParameter) - case p: ParameterizedMessage => appendLog(level, p.getFormattedMessage) - case r: RingBufferLogEvent => appendLog(level, r.getFormattedMessage) - case _ => appendLog(level, message.toString) - } + override def appendLog(level: Level.Value, message: => String): Unit = { + exchange.logMessage(LogEvent(level = level.toString, message = message)) } - def appendLog(level: Level.Value, message: => String): Unit = { - exchange.logMessage(LogEvent(level.toString, message)) - } - def appendEvent(event: AnyRef): Unit = - event match { - case x: StringEvent => exchange.logMessage(LogEvent(level = x.level, message = x.message)) - case x: ObjectEvent[_] => // ignore object events - case _ => - println(s"appendEvent: ${event.getClass}") - () - } } diff --git a/main/src/main/scala/sbt/internal/SysProp.scala b/main/src/main/scala/sbt/internal/SysProp.scala index 15c971af4..c02038e87 100644 --- a/main/src/main/scala/sbt/internal/SysProp.scala +++ b/main/src/main/scala/sbt/internal/SysProp.scala @@ -115,6 +115,7 @@ object SysProp { def banner: Boolean = getOrTrue("sbt.banner") + def useLog4J: Boolean = getOrFalse("sbt.log.uselog4j") def turbo: Boolean = getOrFalse("sbt.turbo") def pipelining: Boolean = getOrFalse("sbt.pipelining") diff --git a/sbt/src/test/scala/sbt/RunFromSourceMain.scala b/sbt/src/test/scala/sbt/RunFromSourceMain.scala index 67d00c322..e53ae2b79 100644 --- a/sbt/src/test/scala/sbt/RunFromSourceMain.scala +++ b/sbt/src/test/scala/sbt/RunFromSourceMain.scala @@ -10,10 +10,11 @@ package sbt import java.io.File.pathSeparator import sbt.internal.scriptedtest.ScriptedLauncher -import sbt.util.LogExchange +import sbt.util.LoggerContext import scala.annotation.tailrec import scala.sys.process.Process +import sbt.internal.SysProp object RunFromSourceMain { def fork( @@ -43,8 +44,10 @@ object RunFromSourceMain { implicit val runner = new ForkRun(fo) val options = Vector(workingDirectory.toString, scalaVersion, sbtVersion, cp.mkString(pathSeparator)) - val log = LogExchange.logger("RunFromSourceMain.fork", None, None) - runner.fork("sbt.RunFromSourceMain", cp, options, log) + val context = LoggerContext(useLog4J = SysProp.useLog4J) + val log = context.logger("RunFromSourceMain.fork", None, None) + try runner.fork("sbt.RunFromSourceMain", cp, options, log) + finally context.close() } def main(args: Array[String]): Unit = args match { @@ -54,7 +57,9 @@ object RunFromSourceMain { ) case Array(wd, scalaVersion, sbtVersion, classpath, args @ _*) => System.setProperty("jna.nosys", "true") - run(file(wd), scalaVersion, sbtVersion, classpath, args) + val context = LoggerContext(useLog4J = SysProp.useLog4J) + try run(file(wd), scalaVersion, sbtVersion, classpath, args, context) + finally context.close() } // this arrangement is because Scala does not always properly optimize away @@ -65,9 +70,10 @@ object RunFromSourceMain { sbtVersion: String, classpath: String, args: Seq[String], + context: LoggerContext ): Unit = - runImpl(baseDir, scalaVersion, sbtVersion, classpath, args) match { - case Some((baseDir, args)) => run(baseDir, scalaVersion, sbtVersion, classpath, args) + runImpl(baseDir, scalaVersion, sbtVersion, classpath, args, context: LoggerContext) match { + case Some((baseDir, args)) => run(baseDir, scalaVersion, sbtVersion, classpath, args, context) case None => () } @@ -77,8 +83,9 @@ object RunFromSourceMain { sbtVersion: String, classpath: String, args: Seq[String], + context: LoggerContext, ): Option[(File, Seq[String])] = { - try launch(defaultBootDirectory, baseDir, scalaVersion, sbtVersion, classpath, args) map exit + try launch(defaultBootDirectory, baseDir, scalaVersion, sbtVersion, classpath, args, context) map exit catch { case r: xsbti.FullReload => Some((baseDir, r.arguments())) case scala.util.control.NonFatal(e) => e.printStackTrace(); errorAndExit(e.toString) @@ -92,10 +99,11 @@ object RunFromSourceMain { sbtVersion: String, classpath: String, arguments: Seq[String], + context: LoggerContext, ): Option[Int] = { ScriptedLauncher .launch( - scalaHome(bootDirectory, scalaVersion), + scalaHome(bootDirectory, scalaVersion, context), sbtVersion, scalaVersion, bootDirectory, @@ -112,8 +120,8 @@ object RunFromSourceMain { private lazy val defaultBootDirectory: File = file(sys.props("user.home")) / ".sbt" / "scripted" / "boot" - private def scalaHome(bootDirectory: File, scalaVersion: String): File = { - val log = sbt.util.LogExchange.logger("run-from-source") + private def scalaHome(bootDirectory: File, scalaVersion: String, context: LoggerContext): File = { + val log = context.logger("run-from-source", None, None) val scalaHome0 = bootDirectory / s"scala-$scalaVersion" if ((scalaHome0 / "lib" / "scala-library.jar").exists) scalaHome0 else { diff --git a/testing/src/main/scala/sbt/internal/testing/TestLogger.scala b/testing/src/main/scala/sbt/internal/testing/TestLogger.scala index 62da7f6d8..0b094eaad 100644 --- a/testing/src/main/scala/sbt/internal/testing/TestLogger.scala +++ b/testing/src/main/scala/sbt/internal/testing/TestLogger.scala @@ -10,10 +10,9 @@ package internal.testing import testing.{ Logger => TLogger } import sbt.internal.util.{ BufferedAppender, ConsoleAppender, ManagedLogger } -import sbt.util.{ Level, LogExchange, ShowLines } +import sbt.util.{ Level, ShowLines } import sbt.protocol.testing._ import java.util.concurrent.atomic.AtomicInteger -import scala.collection.JavaConverters._ object TestLogger { import sbt.protocol.testing.codec.JsonProtocol._ @@ -35,20 +34,28 @@ object TestLogger { val buffered: Boolean ) - def make(global: ManagedLogger, perTest: TestDefinition => PerTest): TestLogger = { + @deprecated("Use make variant that accepts a log level.", "1.4.0") + def make( + global: ManagedLogger, + perTest: TestDefinition => PerTest, + ): TestLogger = make(global, perTest, Level.Debug) + + def make( + global: ManagedLogger, + perTest: TestDefinition => PerTest, + level: Level.Value + ): TestLogger = { + val context = global.context + val as = context.appenders(global.name) def makePerTest(tdef: TestDefinition): ContentLogger = { val per = perTest(tdef) val l0 = per.log - val config = LogExchange.loggerConfig(l0.name) - val as = config.getAppenders.asScala - val buffs: List[BufferedAppender] = (as map { - case (_, v) => BufferedAppender(generateBufferName, v) - }).toList - val newLog = LogExchange.logger(generateName, l0.channelName, l0.execId) - LogExchange.unbindLoggerAppenders(newLog.name) - LogExchange.bindLoggerAppenders(newLog.name, buffs map { x => - (x, Level.Debug) - }) + val buffs = as.map(a => BufferedAppender(generateBufferName, a)).toList + val newLog = context.logger(generateName, l0.channelName, l0.execId) + context.clearAppenders(newLog.name) + buffs.foreach { b => + context.addAppender(newLog.name, b -> level) + } if (per.buffered) { buffs foreach { _.record() } }