From 6c50a85f93a4d3c61e9f4d5c5fec09614e151b82 Mon Sep 17 00:00:00 2001 From: Ethan Atkins Date: Wed, 29 Jul 2020 14:55:19 -0700 Subject: [PATCH 1/4] Use a macro to create StringTypeTag instances Using the scala reflect library always introduces significant classloading overhead. We can eliminate the classloading overhead by generating StringTypeTags at compile time instead. This sped up average project loading time by a few hundred milliseconds on my computer. The ManagedLoggedReporter in zinc is still using the type tag based apis but after the next sbt release, we can upgrade the zinc apis. We also could consider breaking binary compatibility. --- build.sbt | 4 +- .../util/appmacro/StringTypeTag.scala | 27 ++++++++++ .../sbt/internal/util/ManagedLogger.scala | 50 ++++++++++++++----- .../sbt/internal/util/StringTypeTag.scala | 6 +++ .../src/main/scala/sbt/util/LogExchange.scala | 13 +++-- .../src/test/scala/LogExchangeSpec.scala | 14 ++++-- .../src/test/scala/ManagedLoggerSpec.scala | 2 +- .../sbt/internal/XMainConfiguration.scala | 2 - .../internal/server/BuildServerReporter.scala | 14 ++++-- 9 files changed, 102 insertions(+), 30 deletions(-) create mode 100644 core-macros/src/main/scala/sbt/internal/util/appmacro/StringTypeTag.scala diff --git a/build.sbt b/build.sbt index 0e84f284a..11c3cf8d6 100644 --- a/build.sbt +++ b/build.sbt @@ -359,7 +359,7 @@ lazy val utilPosition = (project in file("internal") / "util-position") lazy val utilLogging = (project in file("internal") / "util-logging") .enablePlugins(ContrabandPlugin, JsonCodecPlugin) - .dependsOn(utilInterface, collectionProj) + .dependsOn(utilInterface, collectionProj, coreMacrosProj) .settings( utilCommonSettings, name := "Util Logging", @@ -781,7 +781,7 @@ lazy val commandProj = (project in file("main-command")) lazy val coreMacrosProj = (project in file("core-macros")) .dependsOn(collectionProj) .settings( - baseSettings, + baseSettings :+ (crossScalaVersions := (scala212 :: scala213 :: Nil)), name := "Core Macros", libraryDependencies += "org.scala-lang" % "scala-compiler" % scalaVersion.value, mimaSettings, diff --git a/core-macros/src/main/scala/sbt/internal/util/appmacro/StringTypeTag.scala b/core-macros/src/main/scala/sbt/internal/util/appmacro/StringTypeTag.scala new file mode 100644 index 000000000..faeda9245 --- /dev/null +++ b/core-macros/src/main/scala/sbt/internal/util/appmacro/StringTypeTag.scala @@ -0,0 +1,27 @@ +/* + * sbt + * Copyright 2011 - 2018, Lightbend, Inc. + * Copyright 2008 - 2010, Mark Harrah + * Licensed under Apache License 2.0 (see LICENSE) + */ + +package sbt.internal.util.appmacro + +import scala.reflect.macros.blackbox + +object StringTypeTag { + def impl[A: c.WeakTypeTag](c: blackbox.Context): c.Tree = { + import c.universe._ + val tpe = weakTypeOf[A] + def typeToString(tpe: Type): String = tpe match { + case TypeRef(_, sym, args) if args.nonEmpty => + val typeCon = tpe.typeSymbol.fullName + val typeArgs = args map typeToString + s"""$typeCon[${typeArgs.mkString(",")}]""" + case _ => tpe.toString + } + + val key = Literal(Constant(typeToString(tpe))) + q"new sbt.internal.util.StringTypeTag[$tpe]($key)" + } +} 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 9bb00524f..67aefeb52 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,12 +7,12 @@ package sbt.internal.util -import sbt.util._ import org.apache.logging.log4j.{ Logger => XLogger } import org.apache.logging.log4j.message.ObjectMessage -import sjsonnew.JsonFormat -import scala.reflect.runtime.universe.TypeTag import sbt.internal.util.codec.JsonProtocol._ +import sbt.util._ +import scala.reflect.runtime.universe.TypeTag +import sjsonnew.JsonFormat /** * Delegates log events to the associated LogExchange. @@ -35,29 +35,53 @@ class ManagedLogger( ) } - private lazy val SuccessEventTag = scala.reflect.runtime.universe.typeTag[SuccessEvent] // send special event for success since it's not a real log level override def success(message: => String): Unit = { if (terminal.fold(true)(_.isSuccessEnabled)) { infoEvent[SuccessEvent](SuccessEvent(message))( implicitly[JsonFormat[SuccessEvent]], - SuccessEventTag + StringTypeTag.fast[SuccessEvent], ) } } - def registerStringCodec[A: ShowLines: TypeTag]: Unit = { + @deprecated("Use macro-powered StringTypeTag.fast instead", "1.4.0") + def registerStringCodec[A]( + s: ShowLines[A], + tt: scala.reflect.runtime.universe.TypeTag[A] + ): Unit = { + LogExchange.registerStringCodec[A](s, tt) + } + def registerStringCodec[A: ShowLines: StringTypeTag]: Unit = { LogExchange.registerStringCodec[A] } - final def debugEvent[A: JsonFormat: TypeTag](event: => A): Unit = logEvent(Level.Debug, event) - final def infoEvent[A: JsonFormat: TypeTag](event: => A): Unit = logEvent(Level.Info, event) - final def warnEvent[A: JsonFormat: TypeTag](event: => A): Unit = logEvent(Level.Warn, event) - final def errorEvent[A: JsonFormat: TypeTag](event: => A): Unit = logEvent(Level.Error, event) - def logEvent[A: JsonFormat: TypeTag](level: Level.Value, event: => A): Unit = { + @deprecated("Use macro-powered StringTypeTag.fast instead", "1.4.0") + final def debugEvent[A](event: => A, f: JsonFormat[A], t: TypeTag[A]): Unit = + debugEvent(event)(f, StringTypeTag.apply(t)) + @deprecated("Use macro-powered StringTypeTag.fast instead", "1.4.0") + final def infoEvent[A](event: => A, f: JsonFormat[A], t: TypeTag[A]): Unit = + infoEvent(event)(f, StringTypeTag.apply(t)) + @deprecated("Use macro-powered StringTypeTag.fast instead", "1.4.0") + final def warnEvent[A](event: => A, f: JsonFormat[A], t: TypeTag[A]): Unit = + warnEvent(event)(f, StringTypeTag.apply(t)) + @deprecated("Use macro-powered StringTypeTag.fast instead", "1.4.0") + final def errorEvent[A](event: => A, f: JsonFormat[A], t: TypeTag[A]): Unit = + errorEvent(event)(f, StringTypeTag.apply(t)) + + final def debugEvent[A: JsonFormat: StringTypeTag](event: => A): Unit = + logEvent(Level.Debug, event) + final def infoEvent[A: JsonFormat: StringTypeTag](event: => A): Unit = logEvent(Level.Info, event) + final def warnEvent[A: JsonFormat: StringTypeTag](event: => A): Unit = logEvent(Level.Warn, event) + final def errorEvent[A: JsonFormat: StringTypeTag](event: => A): Unit = + logEvent(Level.Error, event) + @deprecated("Use macro-powered StringTypeTag.fast instead", "1.4.0") + def logEvent[A](level: Level.Value, event: => A, f: JsonFormat[A], t: TypeTag[A]): Unit = + logEvent(level, event)(f, StringTypeTag.apply(t)) + def logEvent[A: JsonFormat](level: Level.Value, event: => A)( + implicit tag: StringTypeTag[A] + ): Unit = { val v: A = event - val tag = StringTypeTag[A] - LogExchange.getOrElseUpdateJsonCodec(tag.key, implicitly[JsonFormat[A]]) // println("logEvent " + tag.key) val entry: ObjectEvent[A] = ObjectEvent(level, v, channelName, execId, tag.key) xlogger.log( diff --git a/internal/util-logging/src/main/scala/sbt/internal/util/StringTypeTag.scala b/internal/util-logging/src/main/scala/sbt/internal/util/StringTypeTag.scala index 344d4c002..e2b54232a 100644 --- a/internal/util-logging/src/main/scala/sbt/internal/util/StringTypeTag.scala +++ b/internal/util-logging/src/main/scala/sbt/internal/util/StringTypeTag.scala @@ -7,6 +7,7 @@ package sbt.internal.util +import scala.language.experimental.macros import scala.reflect.runtime.universe._ /** This is used to carry type information in JSON. */ @@ -15,6 +16,10 @@ final case class StringTypeTag[A](key: String) { } object StringTypeTag { + + /** Generates a StringTypeTag for any type at compile time. */ + implicit def fast[A]: StringTypeTag[A] = macro appmacro.StringTypeTag.impl[A] + @deprecated("Prefer macro generated StringTypeTag", "1.4.0") def apply[A: TypeTag]: StringTypeTag[A] = synchronized { def doApply: StringTypeTag[A] = { @@ -38,6 +43,7 @@ object StringTypeTag { retry(3) } + @deprecated("Prefer macro generated StringTypeTag", "1.4.0") def typeToString(tpe: Type): String = tpe match { case TypeRef(_, sym, args) => 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 a1073b36f..326d23d3c 100644 --- a/internal/util-logging/src/main/scala/sbt/util/LogExchange.scala +++ b/internal/util-logging/src/main/scala/sbt/util/LogExchange.scala @@ -15,7 +15,6 @@ import org.apache.logging.log4j.core.config.{ AppenderRef, LoggerConfig } import org.apache.logging.log4j.core.layout.PatternLayout import scala.collection.JavaConverters._ import scala.collection.concurrent -import scala.reflect.runtime.universe.TypeTag import sjsonnew.JsonFormat // http://logging.apache.org/log4j/2.x/manual/customconfig.html @@ -114,9 +113,15 @@ sealed abstract class LogExchange { def getOrElseUpdateStringCodec[A](tag: String, v: ShowLines[A]): ShowLines[A] = stringCodecs.getOrElseUpdate(tag, v).asInstanceOf[ShowLines[A]] - def registerStringCodec[A: ShowLines: TypeTag]: Unit = { - val tag = StringTypeTag[A] - registerStringCodecByStringTypeTag(tag) + @deprecated("Prefer macro based registerStringCodec", "1.4.0") + def registerStringCodec[A]( + st: ShowLines[A], + tt: scala.reflect.runtime.universe.TypeTag[A] + ): Unit = { + registerStringCodecByStringTypeTag(StringTypeTag.apply[A](tt))(st) + } + private[sbt] def registerStringCodec[A: ShowLines: StringTypeTag]: Unit = { + registerStringCodecByStringTypeTag(implicitly[StringTypeTag[A]]) } private[sbt] def registerStringCodecByStringTypeTag[A: ShowLines](tag: StringTypeTag[A]): Unit = { diff --git a/internal/util-logging/src/test/scala/LogExchangeSpec.scala b/internal/util-logging/src/test/scala/LogExchangeSpec.scala index afdf7621b..3a26b44ab 100644 --- a/internal/util-logging/src/test/scala/LogExchangeSpec.scala +++ b/internal/util-logging/src/test/scala/LogExchangeSpec.scala @@ -14,9 +14,17 @@ import org.scalatest._ class LogExchangeSpec extends FlatSpec with Matchers { import LogExchange._ - checkTypeTag("stringTypeTagThrowable", stringTypeTagThrowable, StringTypeTag[Throwable]) - checkTypeTag("stringTypeTagTraceEvent", stringTypeTagTraceEvent, StringTypeTag[TraceEvent]) - checkTypeTag("stringTypeTagSuccessEvent", stringTypeTagSuccessEvent, StringTypeTag[SuccessEvent]) + checkTypeTag("stringTypeTagThrowable", stringTypeTagThrowable, StringTypeTag.fast[Throwable]) + checkTypeTag( + "stringTypeTagTraceEvent", + stringTypeTagTraceEvent, + StringTypeTag.fast[TraceEvent] + ) + checkTypeTag( + "stringTypeTagSuccessEvent", + stringTypeTagSuccessEvent, + StringTypeTag.fast[SuccessEvent] + ) private def checkTypeTag[A](name: String, inc: StringTypeTag[A], exp: StringTypeTag[A]): Unit = s"LogExchange.$name" should s"match real StringTypeTag[$exp]" in { diff --git a/internal/util-logging/src/test/scala/ManagedLoggerSpec.scala b/internal/util-logging/src/test/scala/ManagedLoggerSpec.scala index dcab747fa..b5c99ca38 100644 --- a/internal/util-logging/src/test/scala/ManagedLoggerSpec.scala +++ b/internal/util-logging/src/test/scala/ManagedLoggerSpec.scala @@ -84,7 +84,7 @@ class ManagedLoggerSpec extends FlatSpec with Matchers { } { pool.submit(new Runnable { def run(): Unit = { - val stringTypeTag = StringTypeTag[List[Int]] + val stringTypeTag = StringTypeTag.fast[List[Int]] val log = LogExchange.logger(s"foo$i") LogExchange.bindLoggerAppenders(s"foo$i", List(LogExchange.asyncStdout -> Level.Info)) if (i % 100 == 0) { diff --git a/main/src/main/scala/sbt/internal/XMainConfiguration.scala b/main/src/main/scala/sbt/internal/XMainConfiguration.scala index 1e72eb139..e4ebdf6bc 100644 --- a/main/src/main/scala/sbt/internal/XMainConfiguration.scala +++ b/main/src/main/scala/sbt/internal/XMainConfiguration.scala @@ -14,7 +14,6 @@ import java.util.concurrent.{ ExecutorService, Executors } import ClassLoaderClose.close import sbt.plugins.{ CorePlugin, IvyPlugin, JvmPlugin } -import sbt.util.LogExchange import xsbti._ private[internal] object ClassLoaderWarmup { @@ -29,7 +28,6 @@ private[internal] object ClassLoaderWarmup { () } - submit(LogExchange.context) submit(Class.forName("sbt.internal.parser.SbtParserInit").getConstructor().newInstance()) submit(CorePlugin.projectSettings) submit(IvyPlugin.projectSettings) diff --git a/main/src/main/scala/sbt/internal/server/BuildServerReporter.scala b/main/src/main/scala/sbt/internal/server/BuildServerReporter.scala index 5c7a7152f..10330d687 100644 --- a/main/src/main/scala/sbt/internal/server/BuildServerReporter.scala +++ b/main/src/main/scala/sbt/internal/server/BuildServerReporter.scala @@ -11,7 +11,7 @@ import java.io.File import sbt.StandardMain import sbt.internal.bsp._ -import sbt.internal.inc.ManagedLoggedReporter +import sbt.internal.inc.LoggedReporter import sbt.internal.util.ManagedLogger import xsbti.{ Problem, Severity, Position => XPosition } @@ -30,7 +30,11 @@ class BuildServerReporter( logger: ManagedLogger, sourcePositionMapper: XPosition => XPosition = identity[XPosition], sources: Seq[File] -) extends ManagedLoggedReporter(maximumErrors, logger, sourcePositionMapper) { +) extends LoggedReporter(maximumErrors, logger, sourcePositionMapper) { + import LoggedReporter.problemFormats._ + import LoggedReporter.problemStringFormats._ + logger.registerStringCodec[Problem] + import sbt.internal.bsp.codec.JsonProtocol._ import sbt.internal.inc.JavaInterfaceUtil._ @@ -55,21 +59,21 @@ class BuildServerReporter( publishDiagnostic(problem) // console channel can keep using the xsbi.Problem - super.logError(problem) + logger.errorEvent(problem) } override def logWarning(problem: Problem): Unit = { publishDiagnostic(problem) // console channel can keep using the xsbi.Problem - super.logWarning(problem) + logger.warnEvent(problem) } override def logInfo(problem: Problem): Unit = { publishDiagnostic(problem) // console channel can keep using the xsbi.Problem - super.logInfo(problem) + logger.infoEvent(problem) } private def publishDiagnostic(problem: Problem): Unit = { From 46724159daa3501529b552e940ec43177dc1398d Mon Sep 17 00:00:00 2001 From: Ethan Atkins Date: Wed, 29 Jul 2020 16:06:43 -0700 Subject: [PATCH 2/4] Stop filling json codec cache These were not actually used as far as I could tell. The json codecs cache showed up as taking up 30MB in a heap dump that I took after running compile 30 times in a clone of the repro project in https://github.com/sbt/sbt/issues/5508. --- .../src/main/scala/sbt/util/LogExchange.scala | 16 +++++++++------- 1 file changed, 9 insertions(+), 7 deletions(-) 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 326d23d3c..90e6cc39f 100644 --- a/internal/util-logging/src/main/scala/sbt/util/LogExchange.scala +++ b/internal/util-logging/src/main/scala/sbt/util/LogExchange.scala @@ -24,7 +24,6 @@ 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] val jsonCodecs: concurrent.Map[String, JsonFormat[_]] = concurrent.TrieMap() private[sbt] val stringCodecs: concurrent.Map[String, ShowLines[_]] = concurrent.TrieMap() def logger(name: String): ManagedLogger = logger(name, None, None) @@ -100,12 +99,15 @@ sealed abstract class LogExchange { lo } - def jsonCodec[A](tag: String): Option[JsonFormat[A]] = - jsonCodecs.get(tag) map { _.asInstanceOf[JsonFormat[A]] } - def hasJsonCodec(tag: String): Boolean = - jsonCodecs.contains(tag) - def getOrElseUpdateJsonCodec[A](tag: String, v: JsonFormat[A]): JsonFormat[A] = - jsonCodecs.getOrElseUpdate(tag, v).asInstanceOf[JsonFormat[A]] + @deprecated("It is now necessary to provide a json format instance", "1.4.0") + def jsonCodec[A](tag: String): Option[JsonFormat[A]] = None + @deprecated("Always returns false", "1.4.0") + def hasJsonCodec(tag: String): Boolean = false + @deprecated("This is a no-op", "1.4.0") + def getOrElseUpdateJsonCodec[A](tag: String, v: JsonFormat[A]): JsonFormat[A] = v + @deprecated("The log manager no longer caches jsonCodecs", "1.4.0") + def jsonCodecs(): concurrent.Map[String, JsonFormat[_]] = concurrent.TrieMap.empty + def stringCodec[A](tag: String): Option[ShowLines[A]] = stringCodecs.get(tag) map { _.asInstanceOf[ShowLines[A]] } def hasStringCodec(tag: String): Boolean = From 841b6dbfd843a8629bb6cfac54b88c8f87ee83a6 Mon Sep 17 00:00:00 2001 From: Ethan Atkins Date: Fri, 7 Aug 2020 13:58:23 -0700 Subject: [PATCH 3/4] Remove SetTerminal command Rather than relying on a command, I realized it makes more sense to explicitly set the terminal for the calling channel in MainLoop. By doing it this way, we can also ensure that we always reset it to the previous value. --- .../src/main/scala/sbt/internal/util/Terminal.scala | 4 ++-- .../src/main/scala/sbt/BasicCommandStrings.scala | 1 - main-command/src/main/scala/sbt/State.scala | 7 ++----- main/src/main/scala/sbt/Main.scala | 9 +-------- main/src/main/scala/sbt/MainLoop.scala | 12 +++++------- main/src/main/scala/sbt/internal/Continuous.scala | 7 +++---- .../main/scala/sbt/internal/FastTrackCommands.scala | 3 +-- .../scala/sbt/internal/nio/CheckBuildSources.scala | 8 ++------ 8 files changed, 16 insertions(+), 35 deletions(-) diff --git a/internal/util-logging/src/main/scala/sbt/internal/util/Terminal.scala b/internal/util-logging/src/main/scala/sbt/internal/util/Terminal.scala index e44573930..8b7a99df6 100644 --- a/internal/util-logging/src/main/scala/sbt/internal/util/Terminal.scala +++ b/internal/util-logging/src/main/scala/sbt/internal/util/Terminal.scala @@ -174,9 +174,9 @@ object Terminal { try Terminal.console.printStream.println(s"[info] $string") catch { case _: IOException => } } - private[sbt] def set(terminal: Terminal) = { - activeTerminal.set(terminal) + private[sbt] def set(terminal: Terminal): Terminal = { jline.TerminalFactory.set(terminal.toJLine) + activeTerminal.getAndSet(terminal) } implicit class TerminalOps(private val term: Terminal) extends AnyVal { def ansi(richString: => String, string: => String): String = diff --git a/main-command/src/main/scala/sbt/BasicCommandStrings.scala b/main-command/src/main/scala/sbt/BasicCommandStrings.scala index d00b756be..eef42b3cc 100644 --- a/main-command/src/main/scala/sbt/BasicCommandStrings.scala +++ b/main-command/src/main/scala/sbt/BasicCommandStrings.scala @@ -215,7 +215,6 @@ $AliasCommand name= def FailureWall: String = "resumeFromFailure" - def SetTerminal = "sbtSetTerminal" def ReportResult = "sbtReportResult" def CompleteExec = "sbtCompleteExec" def MapExec = "sbtMapExec" diff --git a/main-command/src/main/scala/sbt/State.scala b/main-command/src/main/scala/sbt/State.scala index a0d21b949..409bac887 100644 --- a/main-command/src/main/scala/sbt/State.scala +++ b/main-command/src/main/scala/sbt/State.scala @@ -21,7 +21,6 @@ import BasicCommandStrings.{ MapExec, PopOnFailure, ReportResult, - SetTerminal, StartServer, StashOnFailure, networkExecPrefix, @@ -314,10 +313,8 @@ object State { val stash = Exec(StashOnFailure, None) val failureWall = Exec(FailureWall, None) val pop = Exec(PopOnFailure, None) - val setTerm = Exec(s"$SetTerminal ${s.channelName}", None) - val setConsole = Exec(s"$SetTerminal console0", None) - val remaining = stash :: map :: cmd :: complete :: failureWall :: pop :: setConsole :: report :: xs - runCmd(setTerm, remaining) + val remaining = map :: cmd :: complete :: failureWall :: pop :: report :: xs + runCmd(stash, remaining) case _ => runCmd(x, xs) } } diff --git a/main/src/main/scala/sbt/Main.scala b/main/src/main/scala/sbt/Main.scala index f3a93ee2f..61777b2ec 100644 --- a/main/src/main/scala/sbt/Main.scala +++ b/main/src/main/scala/sbt/Main.scala @@ -15,7 +15,7 @@ import java.util.Properties import java.util.concurrent.ForkJoinPool import java.util.concurrent.atomic.AtomicBoolean -import sbt.BasicCommandStrings.{ SetTerminal, Shell, Shutdown, TemplateCommand, networkExecPrefix } +import sbt.BasicCommandStrings.{ Shell, Shutdown, TemplateCommand, networkExecPrefix } import sbt.Project.LoadAction import sbt.compiler.EvalImports import sbt.internal.Aggregation.AnyKeys @@ -311,7 +311,6 @@ object BuiltinCommands { NetworkChannel.disconnect, waitCmd, promptChannel, - setTerminalCommand, ) ++ allBasicCommands ++ ContinuousCommands.value def DefaultBootCommands: Seq[String] = @@ -960,12 +959,6 @@ object BuiltinCommands { Command.command(ClearCaches, help)(f) } - def setTerminalCommand = Command.arb(_ => BasicCommands.reportParser(SetTerminal)) { - (s, channel) => - StandardMain.exchange.channelForName(channel).foreach(c => Terminal.set(c.terminal)) - s - } - private[sbt] def waitCmd: Command = Command.arb( _ => ContinuousCommands.waitWatch.examples() ~> " ".examples() ~> matched(any.*).examples() diff --git a/main/src/main/scala/sbt/MainLoop.scala b/main/src/main/scala/sbt/MainLoop.scala index 99256ed79..b1822aa31 100644 --- a/main/src/main/scala/sbt/MainLoop.scala +++ b/main/src/main/scala/sbt/MainLoop.scala @@ -10,7 +10,7 @@ package sbt import java.io.PrintWriter import java.util.Properties -import sbt.BasicCommandStrings.{ SetTerminal, StashOnFailure, networkExecPrefix } +import sbt.BasicCommandStrings.{ StashOnFailure, networkExecPrefix } import sbt.internal.ShutdownHooks import sbt.internal.langserver.ErrorCodes import sbt.internal.protocol.JsonRpcResponseError @@ -202,6 +202,8 @@ 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) /* * FastTrackCommands.evaluate can be significantly faster than Command.process because * it avoids an expensive parsing step for internal commands that are easy to parse. @@ -212,8 +214,8 @@ object MainLoop { 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. - val terminal = channelName.flatMap(exchange.channelForName(_).map(_.terminal)) terminal.foreach(_.flush()) + prevTerminal.foreach(Terminal.set) if (exec.execId.fold(true)(!_.startsWith(networkExecPrefix)) && !exec.commandLine.startsWith(networkExecPrefix)) { val doneEvent = ExecStatusEvent( @@ -232,11 +234,7 @@ object MainLoop { state.get(CheckBuildSourcesKey) match { case Some(cbs) => if (!cbs.needsReload(state, exec)) process() - else { - val isSetTerminal = exec.commandLine.startsWith(SetTerminal) - if (isSetTerminal) exec +: Exec("reload", None) +: state.remove(CheckBuildSourcesKey) - else Exec("reload", None) +: exec +: state.remove(CheckBuildSourcesKey) - } + else Exec("reload", None) +: exec +: state.remove(CheckBuildSourcesKey) case _ => process() } } catch { diff --git a/main/src/main/scala/sbt/internal/Continuous.scala b/main/src/main/scala/sbt/internal/Continuous.scala index 39420a1fa..80cf2206b 100644 --- a/main/src/main/scala/sbt/internal/Continuous.scala +++ b/main/src/main/scala/sbt/internal/Continuous.scala @@ -1210,9 +1210,8 @@ private[sbt] object ContinuousCommands { state.get(watchStates).flatMap(_.get(channel)) match { case None => state case Some(cs) => - val pre = StashOnFailure :: s"$SetTerminal $channel" :: s"$preWatch $channel" :: Nil - val post = FailureWall :: PopOnFailure :: s"$SetTerminal ${ConsoleChannel.defaultName}" :: - s"$postWatch $channel" :: s"$waitWatch $channel" :: Nil + val pre = StashOnFailure :: s"$preWatch $channel" :: Nil + val post = FailureWall :: PopOnFailure :: s"$postWatch $channel" :: s"$waitWatch $channel" :: Nil pre ::: cs.commands.toList ::: post ::: state } } @@ -1251,7 +1250,7 @@ private[sbt] object ContinuousCommands { case Watch.Trigger => Right(s"$runWatch ${channel.name}") case Watch.Reload => val rewatch = s"$ContinuousExecutePrefix ${ws.count} ${cs.commands mkString "; "}" - stop.map(_ :: s"$SetTerminal ${channel.name}" :: "reload" :: rewatch :: Nil mkString "; ") + stop.map(_ :: "reload" :: rewatch :: Nil mkString "; ") case Watch.Prompt => stop.map(_ :: s"$PromptChannel ${channel.name}" :: Nil mkString ";") case Watch.Run(commands) => stop.map(_ +: commands.map(_.commandLine).filter(_.nonEmpty) mkString "; ") diff --git a/main/src/main/scala/sbt/internal/FastTrackCommands.scala b/main/src/main/scala/sbt/internal/FastTrackCommands.scala index 8c53f81de..13774fe7c 100644 --- a/main/src/main/scala/sbt/internal/FastTrackCommands.scala +++ b/main/src/main/scala/sbt/internal/FastTrackCommands.scala @@ -10,7 +10,7 @@ package internal import BasicCommandStrings._ import BasicCommands._ -import BuiltinCommands.{ setTerminalCommand, shell, waitCmd } +import BuiltinCommands.{ shell, waitCmd } import ContinuousCommands._ import sbt.internal.util.complete.Parser @@ -32,7 +32,6 @@ private[sbt] object FastTrackCommands { StashOnFailure -> fromCommand(StashOnFailure, stashOnFailure, arguments = false), PopOnFailure -> fromCommand(PopOnFailure, popOnFailure, arguments = false), Shell -> fromCommand(Shell, shell), - SetTerminal -> fromCommand(SetTerminal, setTerminalCommand), failWatch -> fromCommand(failWatch, failWatchCommand), preWatch -> fromCommand(preWatch, preWatchCommand), postWatch -> fromCommand(postWatch, postWatchCommand), diff --git a/main/src/main/scala/sbt/internal/nio/CheckBuildSources.scala b/main/src/main/scala/sbt/internal/nio/CheckBuildSources.scala index 95e64d22b..57be28464 100644 --- a/main/src/main/scala/sbt/internal/nio/CheckBuildSources.scala +++ b/main/src/main/scala/sbt/internal/nio/CheckBuildSources.scala @@ -10,7 +10,7 @@ package internal.nio import java.nio.file.Path import java.util.concurrent.atomic.{ AtomicBoolean, AtomicReference } -import sbt.BasicCommandStrings.{ RebootCommand, SetTerminal, Shutdown, TerminateAction } +import sbt.BasicCommandStrings.{ RebootCommand, Shutdown, TerminateAction } import sbt.Keys.{ baseDirectory, pollInterval, state } import sbt.Scope.Global import sbt.SlashSyntax0._ @@ -108,11 +108,7 @@ private[sbt] class CheckBuildSources extends AutoCloseable { state: State, exec: Exec ): Boolean = { - val isSetTerminal = exec.commandLine.startsWith(SetTerminal) - val name = - if (isSetTerminal) - exec.commandLine.split(s"$SetTerminal ").lastOption.filterNot(_.isEmpty) - else exec.source.map(_.channelName) + val name = exec.source.map(_.channelName) val loggerOrTerminal = name.flatMap(StandardMain.exchange.channelForName(_).map(_.terminal)) match { case Some(t) => Right(t) From 2e9805b9d01c6345214c14264c61692d9c21651c Mon Sep 17 00:00:00 2001 From: Ethan Atkins Date: Wed, 5 Aug 2020 11:23:35 -0700 Subject: [PATCH 4/4] 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() } }