Merge pull request #86 from jakubjanecek/StringInterpolation

String Interpolation

Author: analytically

README.md

@@ -23,7 +23,7 @@ if (logger.isDebugEnabled) logger.debug(s"Some $expensive message!")
 A compatible logging backend is [Logback](http://logback.qos.ch), add it to your sbt build definition:
 
 ```scala
-libraryDependencies += "ch.qos.logback" % "logback-classic" % "1.1.7"
+libraryDependencies += "ch.qos.logback" % "logback-classic" % "1.2.3"
 ```
 
 If you are looking for a version compatible with Scala 2.10, check out Scala Logging 2.x.
@@ -94,6 +94,28 @@ class MyClass extends LazyLogging {
  - SLF4J loggers and our Logger now survive serialization. By survive serialization, we mean that the
    deserialized logger instances are fully functional.
 
+## String Interpolation
+It is idiomatic to use Scala's string interpolation `logger.error(s"log $value")` instead of SLF4J string interpolation `logger.error("log {}", value)`.
+However there are some tools (such as [Sentry](https://sentry.io)) that use the log message format as grouping key. Therefore they do not work well with
+Scala's string interpolation.
+
+Scala Logging replaces simple string interpolations with their SLF4J counterparts like this:
+
+```scala
+logger.error(s"my log message: $arg1 $arg2 $arg3")
+```
+
+```scala
+logger.error("my log message: {} {} {}", arg1, arg2, arg3)
+```
+
+This has no effect on behavior and performace should be comparable (depends on the underlying logging library).
+
+### Limitations
+ - Works only when string interpolation is directly used inside the logging statement. That is when the log message is static (available at compile time).
+ - Works only for the `logger.<level>(message)` and `logger.<level>(marker, message)` logging methods. It does not work if you want to log an exception and
+ use string interpolation too (this is a limitation of the SLF4J API).
+
 ## Line numbers in log message?
 
 Using the [sourcecode](https://github.com/lihaoyi/sourcecode#logging) library, it's possible to add line number

src/main/scala/com/typesafe/scalalogging/LoggerMacro.scala

@@ -21,14 +21,15 @@ import scala.reflect.macros.blackbox.Context
 
 private object LoggerMacro {
 
+  private final val ArgumentMarker = "{}"
+
   type LoggerContext = Context { type PrefixType = Logger }
 
   // Error
 
   def errorMessage(c: LoggerContext)(message: c.Expr[String]) = {
-    import c.universe._
-    val underlying = q"${c.prefix}.underlying"
-    q"if ($underlying.isErrorEnabled) $underlying.error($message)"
+    val (messageFormat, args) = deconstructInterpolatedMessage(c)(message)
+    errorMessageArgs(c)(messageFormat, args: _*)
   }
 
   def errorMessageCause(c: LoggerContext)(message: c.Expr[String], cause: c.Expr[Throwable]) = {
@@ -47,9 +48,8 @@ private object LoggerMacro {
   }
 
   def errorMessageMarker(c: LoggerContext)(marker: c.Expr[Marker], message: c.Expr[String]) = {
-    import c.universe._
-    val underlying = q"${c.prefix}.underlying"
-    q"if ($underlying.isErrorEnabled) $underlying.error($marker, $message)"
+    val (messageFormat, args) = deconstructInterpolatedMessage(c)(message)
+    errorMessageArgsMarker(c)(marker, messageFormat, args: _*)
   }
 
   def errorMessageCauseMarker(c: LoggerContext)(marker: c.Expr[Marker], message: c.Expr[String], cause: c.Expr[Throwable]) = {
@@ -70,9 +70,8 @@ private object LoggerMacro {
   // Warn
 
   def warnMessage(c: LoggerContext)(message: c.Expr[String]) = {
-    import c.universe._
-    val underlying = q"${c.prefix}.underlying"
-    q"if ($underlying.isWarnEnabled) $underlying.warn($message)"
+    val (messageFormat, args) = deconstructInterpolatedMessage(c)(message)
+    warnMessageArgs(c)(messageFormat, args: _*)
   }
 
   def warnMessageCause(c: LoggerContext)(message: c.Expr[String], cause: c.Expr[Throwable]) = {
@@ -91,9 +90,8 @@ private object LoggerMacro {
   }
 
   def warnMessageMarker(c: LoggerContext)(marker: c.Expr[Marker], message: c.Expr[String]) = {
-    import c.universe._
-    val underlying = q"${c.prefix}.underlying"
-    q"if ($underlying.isWarnEnabled) $underlying.warn($marker, $message)"
+    val (messageFormat, args) = deconstructInterpolatedMessage(c)(message)
+    warnMessageArgsMarker(c)(marker, messageFormat, args: _*)
   }
 
   def warnMessageCauseMarker(c: LoggerContext)(marker: c.Expr[Marker], message: c.Expr[String], cause: c.Expr[Throwable]) = {
@@ -114,9 +112,8 @@ private object LoggerMacro {
   // Info
 
   def infoMessage(c: LoggerContext)(message: c.Expr[String]) = {
-    import c.universe._
-    val underlying = q"${c.prefix}.underlying"
-    q"if ($underlying.isInfoEnabled) $underlying.info($message)"
+    val (messageFormat, args) = deconstructInterpolatedMessage(c)(message)
+    infoMessageArgs(c)(messageFormat, args: _*)
   }
 
   def infoMessageCause(c: LoggerContext)(message: c.Expr[String], cause: c.Expr[Throwable]) = {
@@ -135,9 +132,8 @@ private object LoggerMacro {
   }
 
   def infoMessageMarker(c: LoggerContext)(marker: c.Expr[Marker], message: c.Expr[String]) = {
-    import c.universe._
-    val underlying = q"${c.prefix}.underlying"
-    q"if ($underlying.isInfoEnabled) $underlying.info($marker, $message)"
+    val (messageFormat, args) = deconstructInterpolatedMessage(c)(message)
+    infoMessageArgsMarker(c)(marker, messageFormat, args: _*)
   }
 
   def infoMessageCauseMarker(c: LoggerContext)(marker: c.Expr[Marker], message: c.Expr[String], cause: c.Expr[Throwable]) = {
@@ -158,9 +154,8 @@ private object LoggerMacro {
   // Debug
 
   def debugMessage(c: LoggerContext)(message: c.Expr[String]) = {
-    import c.universe._
-    val underlying = q"${c.prefix}.underlying"
-    q"if ($underlying.isDebugEnabled) $underlying.debug($message)"
+    val (messageFormat, args) = deconstructInterpolatedMessage(c)(message)
+    debugMessageArgs(c)(messageFormat, args: _*)
   }
 
   def debugMessageCause(c: LoggerContext)(message: c.Expr[String], cause: c.Expr[Throwable]) = {
@@ -179,9 +174,8 @@ private object LoggerMacro {
   }
 
   def debugMessageMarker(c: LoggerContext)(marker: c.Expr[Marker], message: c.Expr[String]) = {
-    import c.universe._
-    val underlying = q"${c.prefix}.underlying"
-    q"if ($underlying.isDebugEnabled) $underlying.debug($marker, $message)"
+    val (messageFormat, args) = deconstructInterpolatedMessage(c)(message)
+    debugMessageArgsMarker(c)(marker, messageFormat, args: _*)
   }
 
   def debugMessageCauseMarker(c: LoggerContext)(marker: c.Expr[Marker], message: c.Expr[String], cause: c.Expr[Throwable]) = {
@@ -202,9 +196,8 @@ private object LoggerMacro {
   // Trace
 
   def traceMessage(c: LoggerContext)(message: c.Expr[String]) = {
-    import c.universe._
-    val underlying = q"${c.prefix}.underlying"
-    q"if ($underlying.isTraceEnabled) $underlying.trace($message)"
+    val (messageFormat, args) = deconstructInterpolatedMessage(c)(message)
+    traceMessageArgs(c)(messageFormat, args: _*)
   }
 
   def traceMessageCause(c: LoggerContext)(message: c.Expr[String], cause: c.Expr[Throwable]) = {
@@ -223,9 +216,8 @@ private object LoggerMacro {
   }
 
   def traceMessageMarker(c: LoggerContext)(marker: c.Expr[Marker], message: c.Expr[String]) = {
-    import c.universe._
-    val underlying = q"${c.prefix}.underlying"
-    q"if ($underlying.isTraceEnabled) $underlying.trace($marker, $message)"
+    val (messageFormat, args) = deconstructInterpolatedMessage(c)(message)
+    traceMessageArgsMarker(c)(marker, messageFormat, args: _*)
   }
 
   def traceMessageCauseMarker(c: LoggerContext)(marker: c.Expr[Marker], message: c.Expr[String], cause: c.Expr[Throwable]) = {
@@ -243,4 +235,18 @@ private object LoggerMacro {
       q"if ($underlying.isTraceEnabled) $underlying.trace($marker, $message, ..$args)"
   }
 
+  /** Checks whether `messsage` is an interpolated string and transforms it into SLF4J string interpolation. */
+  private def deconstructInterpolatedMessage(c: LoggerContext)(message: c.Expr[String]) = {
+    import c.universe._
+
+    message.tree match {
+      case q"scala.StringContext.apply(..$parts).s(..$args)" =>
+        val strings = parts.collect { case Literal(Constant(s: String)) => s }
+        val messageFormat = strings.mkString(ArgumentMarker)
+        (c.Expr(q"$messageFormat"), args.map(arg => q"$arg").map(c.Expr[Any](_)))
+
+      case _ => (message, Seq.empty)
+    }
+  }
+
 }

src/test/scala/com/typesafe/scalalogging/LoggerSpec.scala

@@ -43,6 +43,20 @@ class LoggerSpec extends WordSpec with Matchers with MockitoSugar {
       logger.error(msg)
       verify(underlying, never).error(anyString)
     }
+
+    "call the underlying logger's error method with arguments if the error level is enabled and string is interpolated" in {
+      val f = fixture(_.isErrorEnabled, true)
+      import f._
+      logger.error(s"msg $arg1 $arg2 $arg3")
+      verify(underlying).error("msg {} {} {}", arg1, arg2, arg3)
+    }
+
+    "call the underlying logger's error method with two arguments if the error level is enabled and string is interpolated" in {
+      val f = fixture(_.isErrorEnabled, true)
+      import f._
+      logger.error(s"msg $arg1 $arg2")
+      verify(underlying).error("msg {} {}", List(arg1, arg2): _*)
+    }
   }
 
   "Calling error with a message and cause" should {
@@ -104,6 +118,13 @@ class LoggerSpec extends WordSpec with Matchers with MockitoSugar {
       logger.warn(msg)
       verify(underlying, never).warn(anyString)
     }
+
+    "call the underlying logger's warn method if the warn level is enabled and string is interpolated" in {
+      val f = fixture(_.isWarnEnabled, true)
+      import f._
+      logger.warn(s"msg $arg1 $arg2 $arg3")
+      verify(underlying).warn("msg {} {} {}", arg1, arg2, arg3)
+    }
   }
 
   "Calling warn with a message and cause" should {
@@ -165,6 +186,13 @@ class LoggerSpec extends WordSpec with Matchers with MockitoSugar {
       logger.info(msg)
       verify(underlying, never).info(anyString)
     }
+
+    "call the underlying logger's info method if the info level is enabled and string is interpolated" in {
+      val f = fixture(_.isInfoEnabled, true)
+      import f._
+      logger.info(s"msg $arg1 $arg2 $arg3")
+      verify(underlying).info("msg {} {} {}", arg1, arg2, arg3)
+    }
   }
 
   "Calling info with a message and cause" should {
@@ -226,6 +254,13 @@ class LoggerSpec extends WordSpec with Matchers with MockitoSugar {
       logger.debug(msg)
       verify(underlying, never).debug(anyString)
     }
+
+    "call the underlying logger's debug method if the debug level is enabled and string is interpolated" in {
+      val f = fixture(_.isDebugEnabled, true)
+      import f._
+      logger.debug(s"msg $arg1 $arg2 $arg3")
+      verify(underlying).debug("msg {} {} {}", arg1, arg2, arg3)
+    }
   }
 
   "Calling debug with a message and cause" should {
@@ -287,6 +322,13 @@ class LoggerSpec extends WordSpec with Matchers with MockitoSugar {
       logger.trace(msg)
       verify(underlying, never).trace(anyString)
     }
+
+    "call the underlying logger's trace method if the trace level is enabled and string is interpolated" in {
+      val f = fixture(_.isTraceEnabled, true)
+      import f._
+      logger.trace(s"msg $arg1 $arg2 $arg3")
+      verify(underlying).trace("msg {} {} {}", arg1, arg2, arg3)
+    }
   }
 
   "Calling trace with a message and cause" should {

src/test/scala/com/typesafe/scalalogging/LoggerWithMarkerSpec.scala

@@ -58,6 +58,13 @@ class LoggerWithMarkerSpec extends WordSpec with Matchers with MockitoSugar {
       logger.error(marker, msg)
       verify(underlying, never).error(refEq(DummyMarker), anyString)
     }
+
+    "call the underlying logger's error method if the error level is enabled and string is interpolated" in {
+      val f = fixture(_.isErrorEnabled, true)
+      import f._
+      logger.error(marker, s"msg $arg1 $arg2 $arg3")
+      verify(underlying).error(marker, "msg {} {} {}", arg1, arg2, arg3)
+    }
   }
 
   "Calling error with a marker and a message and cause" should {
@@ -119,6 +126,13 @@ class LoggerWithMarkerSpec extends WordSpec with Matchers with MockitoSugar {
       logger.warn(marker, msg)
       verify(underlying, never).warn(refEq(DummyMarker), anyString)
     }
+
+    "call the underlying logger's warn method if the warn level is enabled and string is interpolated" in {
+      val f = fixture(_.isWarnEnabled, true)
+      import f._
+      logger.warn(marker, s"msg $arg1 $arg2 $arg3")
+      verify(underlying).warn(marker, "msg {} {} {}", arg1, arg2, arg3)
+    }
   }
 
   "Calling warn with a marker and a message and cause" should {
@@ -180,6 +194,13 @@ class LoggerWithMarkerSpec extends WordSpec with Matchers with MockitoSugar {
       logger.info(marker, msg)
       verify(underlying, never).info(refEq(DummyMarker), anyString)
     }
+
+    "call the underlying logger's info method if the info level is enabled and string is interpolated" in {
+      val f = fixture(_.isInfoEnabled, true)
+      import f._
+      logger.info(marker, s"msg $arg1 $arg2 $arg3")
+      verify(underlying).info(marker, "msg {} {} {}", arg1, arg2, arg3)
+    }
   }
 
   "Calling info with a marker and a message and cause" should {
@@ -241,6 +262,13 @@ class LoggerWithMarkerSpec extends WordSpec with Matchers with MockitoSugar {
       logger.debug(marker, msg)
       verify(underlying, never).debug(refEq(DummyMarker), anyString)
     }
+
+    "call the underlying logger's debug method if the debug level is enabled and string is interpolated" in {
+      val f = fixture(_.isDebugEnabled, true)
+      import f._
+      logger.debug(marker, s"msg $arg1 $arg2 $arg3")
+      verify(underlying).debug(marker, "msg {} {} {}", arg1, arg2, arg3)
+    }
   }
 
   "Calling debug with a marker and a message and cause" should {
@@ -302,6 +330,13 @@ class LoggerWithMarkerSpec extends WordSpec with Matchers with MockitoSugar {
       logger.trace(marker, msg)
       verify(underlying, never).trace(refEq(DummyMarker), anyString)
     }
+
+    "call the underlying logger's trace method if the trace level is enabled and string is interpolated" in {
+      val f = fixture(_.isTraceEnabled, true)
+      import f._
+      logger.trace(marker, s"msg $arg1 $arg2 $arg3")
+      verify(underlying).trace(marker, "msg {} {} {}", arg1, arg2, arg3)
+    }
   }
 
   "Calling trace with a marker and a message and cause" should {