Upgrade Logging facility (#488)

* Upgrade Logging facility
Make thread-safe
Make logging by package name work
Use caching of class names to level for performance
Make some tests to show this working

* quick fix for dynamic logging variable

* A number of changes based on Adam's suggestions
Default LoggerState
But there is an invoke method now to handle threading issues.  This should be propagated to other
projects Driver.execute methods

* Add built-in support for string capture of Logging

* Usability fixes for logging stuff.  Settings made to the logger prior to execute/invoke will be passed along if possible.

* A couple style fixes
Comment and privatize Logger state

* Name and save string buffers used for logging

* Fix default logging state setting
Fix logging test, did not have change to command argument

* comment out logging in InlineInstanceTests

* Changed invoke to makeScope
Nested makeScopes share same state object
Removed earlier named string buffer implementation

* Better name for captor get data

* Add trace tests to make sure it works too

* Fix call into logger settings

2 files changed, 333 insertions, 13 deletions

diff --git a/src/test/scala/firrtlTests/InlineInstancesTests.scala b/src/test/scala/firrtlTests/InlineInstancesTests.scala
index a3b7386d..9e8f8054 100644
--- a/src/test/scala/firrtlTests/InlineInstancesTests.scala
+++ b/src/test/scala/firrtlTests/InlineInstancesTests.scala
@@ -5,19 +5,12 @@ package firrtlTests
 import org.scalatest.FlatSpec
 import org.scalatest.Matchers
 import org.scalatest.junit.JUnitRunner
-
 import firrtl.ir.Circuit
-import firrtl.{Parser, AnnotationMap}
+import firrtl.{AnnotationMap, Parser}
 import firrtl.passes.PassExceptions
-import firrtl.annotations.{
-   Named,
-   CircuitName,
-   ModuleName,
-   ComponentName,
-   Annotation
-}
-import firrtl.passes.{InlineInstances, InlineAnnotation}
-import logger.Logger
+import firrtl.annotations.{Annotation, CircuitName, ComponentName, ModuleName, Named}
+import firrtl.passes.{InlineAnnotation, InlineInstances}
+import logger.{LogLevel, Logger}
 import logger.LogLevel.Debug
 
 
@@ -26,8 +19,8 @@ import logger.LogLevel.Debug
  */
 class InlineInstancesTests extends LowTransformSpec {
    def transform = new InlineInstances
-   // Set this to debug
-   // Logger.setClassLogLevels(Map(this.getClass.getName -> Debug))
+   // Set this to debug, this will apply to all tests
+   // Logger.setLevel(this.getClass, Debug)
    "The module Inline" should "be inlined" in {
       val input =
          """circuit Top :
diff --git a/src/test/scala/loggertests/LoggerSpec.scala b/src/test/scala/loggertests/LoggerSpec.scala
new file mode 100644
index 00000000..0a9aaa51
--- /dev/null
+++ b/src/test/scala/loggertests/LoggerSpec.scala
@@ -0,0 +1,327 @@
+// See LICENSE for license details.
+
+package loggertests
+
+import logger.Logger.OutputCaptor
+import logger.{LazyLogging, LogLevel, Logger}
+import org.scalatest.{FreeSpec, Matchers, OneInstancePerTest}
+
+object LoggerSpec {
+  val ErrorMsg = "message error"
+  val WarnMsg = "message warn"
+  val InfoMsg = "message info"
+  val DebugMsg = "message debug"
+  val TraceMsg = "message trace"
+}
+
+class Logger1 extends LazyLogging {
+  def run(): Unit = {
+    logger.error(LoggerSpec.ErrorMsg)
+    logger.warn(LoggerSpec.WarnMsg)
+    logger.info(LoggerSpec.InfoMsg)
+    logger.debug(LoggerSpec.DebugMsg)
+    logger.trace(LoggerSpec.TraceMsg)
+  }
+}
+
+class LogsInfo2 extends LazyLogging {
+  def run(): Unit = {
+    logger.info("logger2")
+  }
+}
+class LogsInfo3 extends LazyLogging {
+  def run(): Unit = {
+    logger.info("logger3")
+  }
+}
+class LoggerSpec extends FreeSpec with Matchers with OneInstancePerTest with LazyLogging {
+  "Logger is a simple but powerful logging system" - {
+    "Following tests show how global level can control logging" - {
+      "only error shows up by default" in {
+        Logger.makeScope() {
+          val captor = new OutputCaptor
+          Logger.setOutput(captor.printStream)
+
+          val r1 = new Logger1
+          r1.run()
+          val messagesLogged = captor.getOutputAsString
+
+          messagesLogged.contains(LoggerSpec.ErrorMsg) should be(true)
+          messagesLogged.contains(LoggerSpec.WarnMsg) should be(false)
+          messagesLogged.contains(LoggerSpec.InfoMsg) should be(false)
+          messagesLogged.contains(LoggerSpec.DebugMsg) should be(false)
+          messagesLogged.contains(LoggerSpec.TraceMsg) should be(false)
+        }
+      }
+
+      "setting level to warn will result in error and warn messages" in {
+        Logger.makeScope() {
+          val captor = new OutputCaptor
+          Logger.setOutput(captor.printStream)
+          Logger.setLevel(LogLevel.Warn)
+
+          val r1 = new Logger1
+          r1.run()
+          val messagesLogged = captor.getOutputAsString
+
+          messagesLogged.contains(LoggerSpec.ErrorMsg) should be(true)
+          messagesLogged.contains(LoggerSpec.WarnMsg) should be(true)
+          messagesLogged.contains(LoggerSpec.InfoMsg) should be(false)
+          messagesLogged.contains(LoggerSpec.DebugMsg) should be(false)
+        }
+      }
+      "setting level to info will result in error, info, and warn messages" in {
+        Logger.makeScope() {
+          val captor = new OutputCaptor
+          Logger.setOutput(captor.printStream)
+          Logger.setLevel(LogLevel.Info)
+
+          val r1 = new Logger1
+          r1.run()
+          val messagesLogged = captor.getOutputAsString
+
+          messagesLogged.contains(LoggerSpec.ErrorMsg) should be(true)
+          messagesLogged.contains(LoggerSpec.WarnMsg) should be(true)
+          messagesLogged.contains(LoggerSpec.InfoMsg) should be(true)
+          messagesLogged.contains(LoggerSpec.DebugMsg) should be(false)
+        }
+      }
+      "setting level to debug will result in error, info, debug, and warn messages" in {
+        Logger.makeScope() {
+          val captor = new OutputCaptor
+          Logger.setOutput(captor.printStream)
+
+          Logger.setLevel(LogLevel.Error)
+          Logger.setOutput(captor.printStream)
+          Logger.setLevel(LogLevel.Debug)
+
+          val r1 = new Logger1
+          r1.run()
+          val messagesLogged = captor.getOutputAsString
+
+          messagesLogged.contains(LoggerSpec.ErrorMsg) should be(true)
+          messagesLogged.contains(LoggerSpec.WarnMsg) should be(true)
+          messagesLogged.contains(LoggerSpec.InfoMsg) should be(true)
+          messagesLogged.contains(LoggerSpec.DebugMsg) should be(true)
+          messagesLogged.contains(LoggerSpec.TraceMsg) should be(false)
+        }
+      }
+      "setting level to trace will result in error, info, debug, trace, and warn messages" in {
+        Logger.makeScope() {
+          val captor = new OutputCaptor
+          Logger.setOutput(captor.printStream)
+
+          Logger.setLevel(LogLevel.Error)
+          Logger.setOutput(captor.printStream)
+          Logger.setLevel(LogLevel.Trace)
+
+          val r1 = new Logger1
+          r1.run()
+          val messagesLogged = captor.getOutputAsString
+
+          messagesLogged.contains(LoggerSpec.ErrorMsg) should be(true)
+          messagesLogged.contains(LoggerSpec.WarnMsg) should be(true)
+          messagesLogged.contains(LoggerSpec.InfoMsg) should be(true)
+          messagesLogged.contains(LoggerSpec.DebugMsg) should be(true)
+          messagesLogged.contains(LoggerSpec.TraceMsg) should be(true)
+        }
+      }
+    }
+    "the following tests show how logging can be controlled by package and class name" - {
+      "only capture output by class name" - {
+        "capture logging from LogsInfo2" in {
+          Logger.makeScope() {
+            val captor = new OutputCaptor
+            Logger.setOutput(captor.printStream)
+
+            Logger.setLevel("loggertests.LogsInfo2", LogLevel.Info)
+
+            val r2 = new LogsInfo2
+            val r3 = new LogsInfo3
+            r3.run()
+            r2.run()
+
+            val messagesLogged = captor.getOutputAsString
+
+            messagesLogged.contains("logger3") should be(false)
+            messagesLogged.contains("logger2") should be(true)
+          }
+        }
+        "capture logging from LogsInfo2 using class" in {
+          Logger.makeScope() {
+            val captor = new OutputCaptor
+            Logger.setOutput(captor.printStream)
+
+            Logger.setLevel(classOf[LogsInfo2], LogLevel.Info)
+
+            val r2 = new LogsInfo2
+            val r3 = new LogsInfo3
+            r3.run()
+            r2.run()
+
+            val messagesLogged = captor.getOutputAsString
+
+            messagesLogged.contains("logger3") should be(false)
+            messagesLogged.contains("logger2") should be(true)
+          }
+        }
+        "capture logging from LogsInfo3" in {
+          Logger.makeScope() {
+            val captor = new OutputCaptor
+            Logger.setOutput(captor.printStream)
+
+            Logger.setLevel("loggertests.LogsInfo3", LogLevel.Info)
+
+            val r2 = new LogsInfo2
+            val r3 = new LogsInfo3
+            r2.run()
+            r3.run()
+
+            val messagesLogged = captor.getOutputAsString
+
+            messagesLogged.contains("logger2") should be(false)
+            messagesLogged.contains("logger3") should be(true)
+          }
+        }
+      }
+      "log based on package name" - {
+        "both log because of package, also showing re-run after change works" in {
+          Logger.makeScope() {
+            val captor = new OutputCaptor
+            Logger.setOutput(captor.printStream)
+
+            Logger.setLevel(LogLevel.Error)
+            Logger.setLevel("loggertests", LogLevel.Error)
+
+            val r2 = new LogsInfo2
+            val r3 = new LogsInfo3
+            r2.run()
+            r3.run()
+
+            var messagesLogged = captor.getOutputAsString
+
+            messagesLogged.contains("logger2") should be(false)
+            messagesLogged.contains("logger3") should be(false)
+
+            Logger.setLevel("loggertests", LogLevel.Debug)
+
+            r2.run()
+            r3.run()
+
+            messagesLogged = captor.getOutputAsString
+
+            messagesLogged.contains("logger2") should be(true)
+            messagesLogged.contains("logger3") should be(true)
+          }
+        }
+      }
+      "check for false positives" in {
+        Logger.makeScope() {
+          val captor = new OutputCaptor
+          Logger.setOutput(captor.printStream)
+
+          Logger.setLevel("bad-loggertests", LogLevel.Info)
+
+          val r2 = new LogsInfo2
+          val r3 = new LogsInfo3
+          r2.run()
+          r3.run()
+
+          val messagesLogged = captor.getOutputAsString
+
+          messagesLogged.contains("logger2") should be(false)
+          messagesLogged.contains("logger3") should be(false)
+        }
+      }
+      "show that class specific level supercedes global level" in {
+        Logger.makeScope() {
+          val captor = new OutputCaptor
+          Logger.setOutput(captor.printStream)
+
+
+          Logger.setLevel(LogLevel.Info)
+          Logger.setLevel("loggertests.LogsInfo2", LogLevel.Error)
+
+          val r2 = new LogsInfo2
+          val r3 = new LogsInfo3
+          r2.run()
+          r3.run()
+
+          val messagesLogged = captor.getOutputAsString
+
+          messagesLogged.contains("logger2") should be(false)
+          messagesLogged.contains("logger3") should be(true)
+        }
+      }
+      "Show logging can be set with command options" in {
+        val captor = new Logger.OutputCaptor
+
+        Logger.makeScope(Array("--class-log-level", "loggertests.LogsInfo3:info")) {
+          Logger.setOutput(captor.printStream)
+          val r2 = new LogsInfo2
+          val r3 = new LogsInfo3
+          r2.run()
+          r3.run()
+
+          val messagesLogged = captor.getOutputAsString
+
+          messagesLogged.contains("logger2") should be(false)
+          messagesLogged.contains("logger3") should be(true)
+        }
+      }
+      "Show that printstream remains across makeScopes" in {
+        Logger.makeScope() {
+          val captor = new Logger.OutputCaptor
+          Logger.setOutput(captor.printStream)
+
+          logger.error("message 1")
+          Logger.makeScope() {
+            logger.error("message 2")
+          }
+
+          val logText = captor.getOutputAsString
+          logText should include ("message 1")
+          logText should include ("message 2")
+        }
+      }
+      "Show that nested makeScopes share same state" in {
+        Logger.getGlobalLevel should be (LogLevel.None)
+
+        Logger.makeScope() {
+          Logger.setLevel(LogLevel.Info)
+
+          Logger.getGlobalLevel should be (LogLevel.Info)
+
+          Logger.makeScope() {
+            Logger.getGlobalLevel should be (LogLevel.Info)
+          }
+
+          Logger.makeScope() {
+            Logger.setLevel(LogLevel.Debug)
+            Logger.getGlobalLevel should be (LogLevel.Debug)
+          }
+
+          Logger.getGlobalLevel should be (LogLevel.Debug)
+        }
+
+        Logger.getGlobalLevel should be (LogLevel.None)
+      }
+
+      "Show that first makeScope starts with fresh state" in {
+        Logger.getGlobalLevel should be (LogLevel.None)
+
+        Logger.setLevel(LogLevel.Warn)
+        Logger.getGlobalLevel should be (LogLevel.Warn)
+
+        Logger.makeScope() {
+          Logger.getGlobalLevel should be (LogLevel.None)
+
+          Logger.setLevel(LogLevel.Trace)
+          Logger.getGlobalLevel should be (LogLevel.Trace)
+        }
+
+        Logger.getGlobalLevel should be (LogLevel.Warn)
+      }
+    }
+  }
+}