Merge pull request #121 from eed3si9n/wip/npe

Attempt to solve the logger NPE issue

internal/util-logging/src/main/scala/sbt/internal/util/ManagedLogger.scala

@@ -5,9 +5,6 @@ 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.ThrowableShowLines._
-import sbt.internal.util.codec.TraceEventShowLines._
-import sbt.internal.util.codec.SuccessEventShowLines._
 import sbt.internal.util.codec.JsonProtocol._
 
 /**
@@ -34,14 +31,9 @@ class ManagedLogger(
   }
 
   def registerStringCodec[A: ShowLines: TypeTag]: Unit = {
-    val tag = StringTypeTag[A]
-    val ev = implicitly[ShowLines[A]]
-    // println(s"registerStringCodec ${tag.key}")
-    val _ = LogExchange.getOrElseUpdateStringCodec(tag.key, ev)
+    LogExchange.registerStringCodec[A]
   }
-  registerStringCodec[Throwable]
-  registerStringCodec[TraceEvent]
-  registerStringCodec[SuccessEvent]
+
   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)

internal/util-logging/src/main/scala/sbt/internal/util/StringTypeTag.scala

@@ -8,13 +8,29 @@ final case class StringTypeTag[A](key: String) {
 }
 
 object StringTypeTag {
-  def apply[A: TypeTag]: StringTypeTag[A] = {
-    val tag = implicitly[TypeTag[A]]
-    val tpe = tag.tpe
-    val k = typeToString(tpe)
-    // println(tpe.getClass.toString + " " + k)
-    StringTypeTag[A](k)
-  }
+  def apply[A: TypeTag]: StringTypeTag[A] =
+    synchronized {
+      def doApply: StringTypeTag[A] = {
+        val tag = implicitly[TypeTag[A]]
+        val tpe = tag.tpe
+        val k = typeToString(tpe)
+        // println(tpe.getClass.toString + " " + k)
+        StringTypeTag[A](k)
+      }
+      def retry(n: Int): StringTypeTag[A] =
+        try {
+          doApply
+        } catch {
+          case e: NullPointerException =>
+            if (n < 1) throw new RuntimeException("NPE in StringTypeTag", e)
+            else {
+              Thread.sleep(1)
+              retry(n - 1)
+            }
+        }
+      retry(3)
+    }
+
   def typeToString(tpe: Type): String =
     tpe match {
       case TypeRef(_, sym, args) =>

internal/util-logging/src/main/scala/sbt/util/LogExchange.scala

@@ -8,6 +8,7 @@ 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
@@ -15,6 +16,7 @@ import sjsonnew.JsonFormat
 
 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()
@@ -22,6 +24,7 @@ sealed abstract class LogExchange {
   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(
@@ -57,6 +60,16 @@ sealed abstract class LogExchange {
     config.getLoggerConfig(loggerName)
   }
 
+  private[sbt] def initStringCodecs(): Unit = {
+    import sbt.internal.util.codec.ThrowableShowLines._
+    import sbt.internal.util.codec.TraceEventShowLines._
+    import sbt.internal.util.codec.SuccessEventShowLines._
+
+    registerStringCodec[Throwable]
+    registerStringCodec[TraceEvent]
+    registerStringCodec[SuccessEvent]
+  }
+
   // This is a dummy layout to avoid casting error during PatternLayout.createDefaultLayout()
   // that was originally used for ConsoleAppender.
   // The stacktrace shows it's having issue initializing default DefaultConfiguration.
@@ -85,6 +98,12 @@ 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]
+    val ev = implicitly[ShowLines[A]]
+    val _ = getOrElseUpdateStringCodec(tag.key, ev)
+  }
+
   private[sbt] def buildAsyncStdout: AsyncAppender = {
     val ctx = XLogManager.getContext(false) match { case x: LoggerContext => x }
     val config = ctx.getConfiguration

internal/util-logging/src/test/scala/ManagedLoggerSpec.scala

@@ -20,6 +20,13 @@ class ManagedLoggerSpec extends FlatSpec with Matchers {
     log.infoEvent(1)
   }
 
+  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))
+    log.infoEvent(SuccessEvent("yes"))
+  }
+
   it should "allow registering Show[Int]" in {
     import sjsonnew.BasicJsonProtocol._
     val log = LogExchange.logger("foo")
@@ -50,6 +57,28 @@ class ManagedLoggerSpec extends FlatSpec with Matchers {
     log.infoEvent(Vector(Vector(1, 2, 3)))
   }
 
+  it should "be thread safe" in {
+    import java.util.concurrent.{ Executors, TimeUnit }
+    val pool = Executors.newFixedThreadPool(100)
+    for {
+      i <- 1 to 10000
+    } {
+      pool.submit(new Runnable {
+        def run(): Unit = {
+          val stringTypeTag = StringTypeTag[List[Int]]
+          val log = LogExchange.logger(s"foo$i")
+          LogExchange.bindLoggerAppenders(s"foo$i", List(LogExchange.asyncStdout -> Level.Info))
+          if (i % 100 == 0) {
+            log.info(s"foo$i test $stringTypeTag")
+          }
+          Thread.sleep(1)
+        }
+      })
+    }
+    pool.shutdown
+    pool.awaitTermination(30, TimeUnit.SECONDS)
+  }
+
   "global logging" should "log immediately after initialization" in {
     // this is passed into State normally
     val global0 = initialGlobalLogging